Re: loop-AES: timer softirq blocked after USB disconnect?

[Matthias Kaehlcke <mkaehlcke@xxxxxxx>]

Matthias Kaehlcke wrote:
> hi,
>
> Matthias Kaehlcke wrote:
>
> > i use loop-AES on a USB flash device. when unplugging the device while 
> > reading from it, the execution of the timer softirq (and others?) 
> > seems to be blocked for 250ms. our device has a hardware watchdog that 
> > relies on a kernel timer to be triggered. i don't observe this 
> > behaviour without encryption.
> >
> > the platform is ep9307 (ARM) based, running a linux 2.6.20 and 
> > loop-AES 3.2c
> >
> > below some traces:
> >
> > [   89.890000] __run_timers()
> > [   89.900000] __run_timers()
> > [   89.910000] __run_timers()
> > [   89.920000] __run_timers()
> > [   89.930000] __run_timers()
> > [   89.930000] usb 1-3: USB disconnect, address 2
> > [   89.940000] __run_timers()
> > [   89.940000] sd 0:0:0:0: SCSI error: return code = 0x00010000
> > [   89.940000] end_request: I/O error, dev sda, sector 6981704
> > [   89.950000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> > [   89.950000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> > [   89.960000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> > [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> > [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> > [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> > [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> > [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> > [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> > [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> > [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> > [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> > [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> > [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> > [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> > [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> > [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> > [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> > [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> > [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> > [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> > [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> > [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> > [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> > [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> > [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> > [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> > [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> > [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> > [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> > [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> > [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> > [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> > [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> > [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> > [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> > [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> > [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> > [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> > [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> > [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> > [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> > [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> > [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> > [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> > [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> > [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> > [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> > [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> > [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> > [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> > [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> > [   90.230000] __run_timers()
> > [   90.230000] sd 0:0:0:0: SCSI error: return code = 0x00010000
> > [   90.240000] end_request: I/O error, dev sda, sector 6981736
> > [   90.240000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> > [   90.250000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> > [   90.250000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> > [   90.260000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> > [   90.260000] __run_timers()
> > [   90.280000] __run_timers()
> > [   90.290000] __run_timers()
> > [   90.300000] __run_timers()
> > [   90.310000] __run_timers()
> > [   90.320000] __run_timers()
> > [   90.330000] __run_timers()
> > [   90.340000] __run_timers()
>
> using ftrace and printk i have been able to figure out something more 
> about the behaviour. it's not only the timer softirq that's not 
> executing, all interrupts are disabled for 250ms.
>
> the execution path is:
>
> scsi_run_queue
>   blk_run_queue
>     __blk_run_queue
>       scsi_request_fn
>         elv_next_request
>           end_queued_request
>             __blk_end_request
>               __end_that_request_first
>                 req_bio_endio
>                   bio_endio
>                     loop_end_io_transfer
>
> blk_run_queue() acquires the spin lock of the request queue and disables 
> interrupts. at the end of the call chain loop_end_io_transfer() calls 
> printk() in case of error. these (+/- 50) invokations of printk() seem 
> to cause a significant delay while interrupts remain disabled. when 
> commenting printk() in loop_end_io_transfer() the system behaves normally.
>
> that's how far i could get with my limited knowledge of kernel 
> internals. the easy solution for my problem is commenting the printk() 
> call, but i think it would be interesting to know what's the root of the 
> problem

fyi, i just found the following thread about calling printk() with 
interrupts disabled:

http://kerneltrap.org/mailarchive/linux-kernel/2008/1/23/595569

seems that until now no solution has been mainlined :(
begin:vcard
fn:Matthias Kaehlcke
n:Kaehlcke;Matthias
org:Electronic Engineering Solutions;Dept. de Software
adr:;;C/ Sant Ferran, 10-16 bajos;Barcelona;;08031;Spain
email;internet:mkaehlcke@xxxxxxx
title:Ingeniero de Firmware
tel;work:93 407 30 80
tel;fax:93 433 56 71
x-mozilla-html:FALSE
url:http://www.e2s.net
version:2.1
end:vcard