Bug 10887

Summary: Kernel report fake device busy intermittently
Product: IO/Storage Reporter: Masanari Iida (standby24x7)
Component: IDEAssignee: Bartlomiej Zolnierkiewicz (bzolnier)
Status: CLOSED CODE_FIX    
Severity: normal    
Priority: P1    
Hardware: All   
OS: Linux   
Kernel Version: 2.6.25 Subsystem:
Regression: --- Bisected commit-id:
Attachments: [PATCH] ide: increase timeout in wait_drive_not_busy()

Description Masanari Iida 2008-06-09 03:41:02 UTC
Distribution: RHEL4 + vanilla kernel (2.6.25)
Hardware Environment:TEAC DV-W28ECW
Software Environment:
Problem Description: When I access /proc/ide/hda/identify,
following error is seen intermittently.

 kernel: hda: task_in_intr: status=0xd0 { Busy }
 kernel: hda: task_in_intr: error=0xd0LastFailedSense 0x0d

Steps to reproduce:
# cat /proc/ide/hda/identify

This symptom occured very rare.
(ex) 22 times in 60000 access.

Analyze:
After DVD drive return the identify data, the linux kernel
wait 1ms to see if the drive status back to "Ready".
But this TEAC DV-W28ECW drive, average retry count was 22 times.
But in some cases, it exceed the 1ms (100 times), but it just 
takes a bit longer time... 6m sec. 

drivers/ide/ide-taskfile.c
static u8 wait_drive_not_busy(ide_drive_t *drive)
{
        int retries;
        u8 stat;

        /*
         * Last sector was transfered, wait until drive is ready.
         * This can take up to 10 usec, but we will wait max 1 ms.
         */
        for (retries = 0; retries < 100; retries++) {
                stat = ide_read_status(drive);

                if (stat & BUSY_STAT)
                        udelay(10);
                else
                        break;
        }

        if (stat & BUSY_STAT)
                printk(KERN_ERR "%s: drive still BUSY!\n", drive->name);

        return stat;
}


>         * Last sector was transfered, wait until drive is ready.
>         * This can take up to 10 usec, but we will wait max 1 ms.

This part is not documented within ATAPI specification.
So the Drive vender never take care of the retry.
In order to support some corner cases drive, I expect retry count 
in the loop need to be adjustable by /proc or /sys.
Then just set the same value, 100 as a default.
Comment 1 Andrew Morton 2008-06-09 03:52:42 UTC
Reassigned to IO/storage:IDE
Comment 2 Masanari Iida 2008-06-11 21:59:49 UTC
Let me ask you a question.
The linux kernel retry 100 times, so wait 1m sec to monitor
the status.  But why the developer chose 100 times retries?
Is this documented on ATAPI paper?
Comment 3 Bartlomiej Zolnierkiewicz 2008-06-15 11:19:20 UTC
Created attachment 16492 [details]
[PATCH] ide: increase timeout in wait_drive_not_busy()

Hi, please see if the attached patch fixes the problem.

w.r.t. timeout value: according to the comment we already use value greater than defined in the ATA/ATAPI spec (but it would be great if somebody can re-check it)
Comment 4 Masanari Iida 2008-06-16 03:21:27 UTC
Thank you for supporting this issue. I was uncomfortable in simply
increasing this retry count because I did not consider adding any form
of delay in to code that executes within an interrupt context a good
idea; 
I would like to show you call flow as shown by systemtap collected on 
a RHEL4 kernel. Vanilla kernel should work as same as this.


## Good request trace:


     0 swapper(0): -> ide_intr (1243213214313202), cpu# 1
    10 swapper(0):  -> drive_is_ready (1243213214335822), cpu# 1
    20 swapper(0):   -> ide_inb (1243213214361474), cpu# 1
    31 swapper(0):   <- ide_inb (1243213214386490), cpu# 1
    39 swapper(0):  <- drive_is_ready (1243213214405662), cpu# 1
    49 swapper(0):  -> task_in_intr (1243213214430530), cpu# 1
    60 swapper(0):   -> ide_inb (1243213214455770), cpu# 1
    70 swapper(0):   <- ide_inb (1243213214480618), cpu# 1
    81 swapper(0):   -> task_buffer_sectors (1243213214506462), cpu# 1
    94 swapper(0):    -> taskfile_input_data (1243213214539922), cpu# 1
   107 swapper(0):     -> ata_input_data (1243213214571146), cpu# 1
   121 swapper(0):      -> ide_insw (1243213214605714), cpu# 1
   386 swapper(0):      <- ide_insw (1243213215242606), cpu# 1
   396 swapper(0):     <- ata_input_data (1243213215264574), cpu# 1
   405 swapper(0):    <- taskfile_input_data (1243213215288010), cpu# 1
   414 swapper(0):   <- task_buffer_sectors (1243213215306626), cpu# 1
   425 swapper(0):   -> wait_drive_not_busy (1243213215333458), cpu# 1
   437 swapper(0):    -> ide_inb (1243213215361894), cpu# 1
   447 swapper(0):    <- ide_inb (1243213215387442), cpu# 1
   468 swapper(0):    -> ide_inb (1243213215436266), cpu# 1

.........  success after 11 retries

  743 swapper(0):    -> ide_inb (1243213216095630), cpu# 1
   753 swapper(0):    <- ide_inb (1243213216121602), cpu# 1
   773 swapper(0):    -> ide_inb (1243213216169802), cpu# 1
   784 swapper(0):    <- ide_inb (1243213216194814), cpu# 1
   792 swapper(0):   <- wait_drive_not_busy (1243213216214366), cpu# 1
   803 swapper(0):   -> task_end_request (1243213216239386), cpu# 1
   814 swapper(0):    -> default_end_request (1243213216266998), cpu# 1
   827 swapper(0):     -> ide_end_request (1243213216299342), cpu# 1
   839 swapper(0):      -> __ide_end_request (1243213216330186), cpu# 1
   853 swapper(0):      <- __ide_end_request (1243213216365674), cpu# 1
   864 swapper(0):     <- ide_end_request (1243213216388058), cpu# 1
   872 swapper(0):    <- default_end_request (1243213216407238), cpu# 1
   881 swapper(0):   <- task_end_request (1243213216427218), cpu# 1
   889 swapper(0):  <- task_in_intr (1243213216445942), cpu# 1
   899 swapper(0):  -> ide_do_request (1243213216471294), cpu# 1
   909 swapper(0):  <- ide_do_request (1243213216493054), cpu# 1
  1011 swapper(0): <- ide_intr (1243213216738754), cpu# 1
     0 swapper(0): -> ide_intr (1243213216762710), cpu# 1
    11 swapper(0):  -> ide_inb (1243213216788322), cpu# 1
    21 swapper(0):  <- ide_inb (1243213216812170), cpu# 1
    29 swapper(0): <- ide_intr (1243213216830854), cpu# 1




## Bad trace case:

     0 swapper(0): -> ide_intr (1243481579247902), cpu# 1
    11 swapper(0):  -> drive_is_ready (1243481579271978), cpu# 1
    22 swapper(0):   -> ide_inb (1243481579299038), cpu# 1
    32 swapper(0):   <- ide_inb (1243481579324874), cpu# 1
    42 swapper(0):  <- drive_is_ready (1243481579346102), cpu# 1
    52 swapper(0):  -> task_in_intr (1243481579371050), cpu# 1
    63 swapper(0):   -> ide_inb (1243481579400282), cpu# 1
    75 swapper(0):   <- ide_inb (1243481579425914), cpu# 1
    85 swapper(0):   -> task_buffer_sectors (1243481579450638), cpu# 1
    97 swapper(0):    -> taskfile_input_data (1243481579480066), cpu# 1
   108 swapper(0):     -> ata_input_data (1243481579508678), cpu# 1
   121 swapper(0):      -> ide_insw (1243481579538806), cpu# 1
   392 swapper(0):      <- ide_insw (1243481580189762), cpu# 1
   401 swapper(0):     <- ata_input_data (1243481580212802), cpu# 1
   411 swapper(0):    <- taskfile_input_data (1243481580234210), cpu# 1
   419 swapper(0):   <- task_buffer_sectors (1243481580252390), cpu# 1
   430 swapper(0):   -> wait_drive_not_busy (1243481580277614), cpu# 1
   441 swapper(0):    -> ide_inb (1243481580304758), cpu# 1
   451 swapper(0):    <- ide_inb (1243481580330622), cpu# 1

........ exceeded the 100 retries

  3592 swapper(0):    -> ide_inb (1243481587868790), cpu# 1
  3602 swapper(0):    <- ide_inb (1243481587894306), cpu# 1
  3611 swapper(0):   <- wait_drive_not_busy (1243481587914714), cpu# 1
  3622 swapper(0):   -> ide_cdrom_error (1243481587941562), cpu# 1



By increasing the retry count, we could end up running this interrupt
handler for up to 10ms. This seems to contravene all the rules of
writing good interrupt handlers.    Shouldn't this kind of activity be
potentially deferred to a tasklet or workqueue??  What happens to our
other handlers during this time, for example, clock or disk...??

Admittedly this increased delay loop only happens corner cases,
 but poor code design is poor code design....??

Thanks
Comment 5 Bartlomiej Zolnierkiewicz 2008-06-16 06:12:39 UTC
> By increasing the retry count, we could end up running this interrupt
> handler for up to 10ms. This seems to contravene all the rules of
> writing good interrupt handlers.    Shouldn't this kind of activity be
> potentially deferred to a tasklet or workqueue??  What happens to our
> other handlers during this time, for example, clock or disk...??

Usually we unmask other IRQs while running IRQ handler so they also
have a chance to be serviced (hdparm -u command, some host drivers
enable it by default) but ideally PIO handling should be done using
tasklet or workqueue (as you've noticed).

> Admittedly this increased delay loop only happens corner cases,
>  but poor code design is poor code design....??

Fully agreed and patches to improve the current situation are always
welcomed.  In the meantime fixing the bug by increasing timeout is OK.
Comment 6 Masanari Iida 2008-06-26 22:20:25 UTC
I have confirmed increase the retry count from 100 to 1000
fixed my problem.
The test was done with TEAC DV-W28ECW.
Comment 7 Masanari Iida 2008-07-07 23:26:57 UTC
Will you include this patch into Linus's tree?
Let me know if this happen on current -rc series, or
after the official 2.6.26 release.

Tested-by: Masanari Iida <standby24x7@gmail.com>
Comment 8 Masanari Iida 2008-07-15 23:15:45 UTC
I have confirmed this one was fixed on kernel 2.6.26.
You may close this bug.
Thank you.
Comment 9 Bartlomiej Zolnierkiewicz 2008-07-16 05:04:03 UTC
Thank you for verifying the fix and sorry for the late update.

The commit in Linus' tree is:

commit f54feafa6d47d0aa1a96adefdc763b708b02f94f
Author: Bartlomiej Zolnierkiewicz <bzolnier@gmail.com>
Date:   Fri Jun 20 20:53:33 2008 +0200

    ide: increase timeout in wait_drive_not_busy()

    Some ATAPI devices take longer than the current max timeout value to
    become ready (i.e. TEAC DV-W28ECW takes 6 ms) so increase the timeout
    value to 10 ms.

    This fixes kernel.org bugzilla bug #10887:
    http://bugzilla.kernel.org/show_bug.cgi?id=10887

    Reported-by: Masanari Iida <standby24x7@gmail.com>
    Signed-off-by: Bartlomiej Zolnierkiewicz <bzolnier@gmail.com>

I'm closing the bug.