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

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

 



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


[Index of Archives]     [Kernel]     [Linux Crypto]     [Gnu Crypto]     [Gnu Classpath]     [Netfilter]     [Bugtraq]
  Powered by Linux