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

[Matthias Kaehlcke <mkaehlcke@xxxxxxx>]

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
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