Hey Alan,
On Mo, 2013-12-23 at 15:38 -0500, Alan Stern wrote:
> On Mon, 23 Dec 2013, Matthias [ISO-8859-1] Blsing wrote:
> > Looking at the strace alone, I see, that the USBDEVFS_SETCONFIGURATION
> > ioctl calls take excessive time.
> >
>
> You're right; those calls took an excessively long time. The usbmon
> traces show that the communication with the device was very quick. I
> don't know where the rest of the time was spent.
>
> The most likely possibility is locking the bandwidth mutex. But that
> wouldn't require much time either, unless something else was going on
> at the same time.
>
> You could try adding a few statements of the form
>
> dev_info(&dev->dev, "[Your message here]\n");
>
> at various spots inside drivers/usb/core/message.c's
> usb_reset_configuration() routine. Maybe you'll be able to see where
> everything slows down. (Be sure to set CONFIG_PRINTK_TIME when you
> build the kernel.)
>
The slow down can be tracked to:
usb_enable_interface(dev, intf, true);
I springled comments like this:
dev_info(&dev->dev, "T1\n");
/* re-init hc/hcd interface/endpoint state */
for (i = 0; i < config->desc.bNumInterfaces; i++) {
struct usb_interface *intf = config->interface[i];
struct usb_host_interface *alt;
dev_info(&dev->dev, "T2-1\n");
alt = usb_altnum_to_altsetting(intf, 0);
dev_info(&dev->dev, "T2-2\n");
/* No altsetting 0? We'll assume the first altsetting.
* We could use a GetInterface call, but if a device is
* so non-compliant that it doesn't have altsetting 0
* then I wouldn't trust its reply anyway.
*/
if (!alt)
alt = &intf->altsetting[0];
if (alt != intf->cur_altsetting) {
dev_info(&dev->dev, "T2-X1\n");
remove_intf_ep_devs(intf);
dev_info(&dev->dev, "T2-X2\n");
usb_remove_sysfs_intf_files(intf);
dev_info(&dev->dev, "T2-X3\n");
}
intf->cur_altsetting = alt;
dev_info(&dev->dev, "T2-3\n");
usb_enable_interface(dev, intf, true);
dev_info(&dev->dev, "T2-4\n");
if (device_is_registered(&intf->dev)) {
dev_info(&dev->dev, "T2-5\n");
usb_create_sysfs_intf_files(intf);
dev_info(&dev->dev, "T2-6\n");
create_intf_ep_devs(intf);
dev_info(&dev->dev, "T2-7\n");
}
}
dev_info(&dev->dev, "T3\n");
And got the attached log (minus my inline comments). As you can see it
starts in the 5. call there it starts with a 5 second delay betewen T2-3
and T2-4. In the next round 15s is reached and there it stays.
My tests of a second run support this and are finalized by xsane
freezing and the final GPF.
Maybe this helps.
Greetings
Matthias
=> Start
Dec 25 21:16:09 athena kernel: [ 104.886377] usb 3-2: T1
Dec 25 21:16:09 athena kernel: [ 104.886380] usb 3-2: T2-1
Dec 25 21:16:09 athena kernel: [ 104.886381] usb 3-2: T2-2
Dec 25 21:16:09 athena kernel: [ 104.886382] usb 3-2: T2-3
Dec 25 21:16:09 athena kernel: [ 104.886647] usb 3-2: T2-4
Dec 25 21:16:09 athena kernel: [ 104.886648] usb 3-2: T2-5
Dec 25 21:16:09 athena kernel: [ 104.886649] usb 3-2: T2-6
Dec 25 21:16:09 athena kernel: [ 104.886650] usb 3-2: T2-7
Dec 25 21:16:09 athena kernel: [ 104.886651] usb 3-2: T3
Dec 25 21:16:15 athena kernel: [ 111.329474] usb 3-2: T1
Dec 25 21:16:15 athena kernel: [ 111.329478] usb 3-2: T2-1
Dec 25 21:16:15 athena kernel: [ 111.329479] usb 3-2: T2-2
Dec 25 21:16:15 athena kernel: [ 111.329481] usb 3-2: T2-3
Dec 25 21:16:15 athena kernel: [ 111.329756] usb 3-2: T2-4
Dec 25 21:16:15 athena kernel: [ 111.329758] usb 3-2: T2-5
Dec 25 21:16:15 athena kernel: [ 111.329760] usb 3-2: T2-6
Dec 25 21:16:15 athena kernel: [ 111.329762] usb 3-2: T2-7
Dec 25 21:16:15 athena kernel: [ 111.329763] usb 3-2: T3
Dec 25 21:16:15 athena kernel: [ 111.390151] usb 3-2: T1
Dec 25 21:16:15 athena kernel: [ 111.390154] usb 3-2: T2-1
Dec 25 21:16:15 athena kernel: [ 111.390155] usb 3-2: T2-2
Dec 25 21:16:15 athena kernel: [ 111.390156] usb 3-2: T2-3
Dec 25 21:16:15 athena kernel: [ 111.390428] usb 3-2: T2-4
Dec 25 21:16:15 athena kernel: [ 111.390429] usb 3-2: T2-5
Dec 25 21:16:15 athena kernel: [ 111.390430] usb 3-2: T2-6
Dec 25 21:16:15 athena kernel: [ 111.390431] usb 3-2: T2-7
Dec 25 21:16:15 athena kernel: [ 111.390432] usb 3-2: T3
Dec 25 21:16:15 athena kernel: [ 111.470847] usb 3-2: T1
Dec 25 21:16:15 athena kernel: [ 111.470850] usb 3-2: T2-1
Dec 25 21:16:15 athena kernel: [ 111.470851] usb 3-2: T2-2
Dec 25 21:16:15 athena kernel: [ 111.470852] usb 3-2: T2-3
Dec 25 21:16:15 athena kernel: [ 111.471119] usb 3-2: T2-4
Dec 25 21:16:15 athena kernel: [ 111.471120] usb 3-2: T2-5
Dec 25 21:16:15 athena kernel: [ 111.471121] usb 3-2: T2-6
Dec 25 21:16:15 athena kernel: [ 111.471122] usb 3-2: T2-7
Dec 25 21:16:15 athena kernel: [ 111.471123] usb 3-2: T3
Dec 25 21:16:15 athena kernel: [ 111.472106] usb 3-2: T1
Dec 25 21:16:15 athena kernel: [ 111.472108] usb 3-2: T2-1
Dec 25 21:16:15 athena kernel: [ 111.472108] usb 3-2: T2-2
Dec 25 21:16:15 athena kernel: [ 111.472109] usb 3-2: T2-3
Dec 25 21:16:20 athena kernel: [ 116.463105] usb 3-2: T2-4
Dec 25 21:16:20 athena kernel: [ 116.463113] usb 3-2: T2-5
Dec 25 21:16:20 athena kernel: [ 116.463117] usb 3-2: T2-6
Dec 25 21:16:20 athena kernel: [ 116.463122] usb 3-2: T2-7
Dec 25 21:16:20 athena kernel: [ 116.463130] usb 3-2: T3
Dec 25 21:16:20 athena kernel: [ 116.477395] usb 3-2: T1
Dec 25 21:16:20 athena kernel: [ 116.477400] usb 3-2: T2-1
Dec 25 21:16:20 athena kernel: [ 116.477403] usb 3-2: T2-2
Dec 25 21:16:20 athena kernel: [ 116.477405] usb 3-2: T2-3
Dec 25 21:16:35 athena kernel: [ 131.457025] usb 3-2: T2-4
Dec 25 21:16:35 athena kernel: [ 131.457032] usb 3-2: T2-5
Dec 25 21:16:35 athena kernel: [ 131.457034] usb 3-2: T2-6
Dec 25 21:16:35 athena kernel: [ 131.457037] usb 3-2: T2-7
Dec 25 21:16:35 athena kernel: [ 131.457039] usb 3-2: T3
Dec 25 21:16:36 athena kernel: [ 131.625721] usb 3-2: T1
Dec 25 21:16:36 athena kernel: [ 131.625724] usb 3-2: T2-1
Dec 25 21:16:36 athena kernel: [ 131.625725] usb 3-2: T2-2
Dec 25 21:16:36 athena kernel: [ 131.625726] usb 3-2: T2-3
Dec 25 21:16:51 athena kernel: [ 146.606709] usb 3-2: T2-4
Dec 25 21:16:51 athena kernel: [ 146.606727] usb 3-2: T2-5
Dec 25 21:16:51 athena kernel: [ 146.606729] usb 3-2: T2-6
Dec 25 21:16:51 athena kernel: [ 146.606731] usb 3-2: T2-7
Dec 25 21:16:51 athena kernel: [ 146.606732] usb 3-2: T3
=> Beendet
=> 2. Start
Dec 25 21:19:11 athena kernel: [ 287.094610] usb 3-2: T1
Dec 25 21:19:11 athena kernel: [ 287.094613] usb 3-2: T2-1
Dec 25 21:19:11 athena kernel: [ 287.094614] usb 3-2: T2-2
Dec 25 21:19:11 athena kernel: [ 287.094615] usb 3-2: T2-3
Dec 25 21:19:26 athena kernel: [ 302.075353] usb 3-2: T2-4
Dec 25 21:19:26 athena kernel: [ 302.075361] usb 3-2: T2-5
Dec 25 21:19:26 athena kernel: [ 302.075364] usb 3-2: T2-6
Dec 25 21:19:26 athena kernel: [ 302.075368] usb 3-2: T2-7
Dec 25 21:19:26 athena kernel: [ 302.075371] usb 3-2: T3
Dec 25 21:19:32 athena kernel: [ 307.500604] usb 3-2: T1
Dec 25 21:19:32 athena kernel: [ 307.500608] usb 3-2: T2-1
Dec 25 21:19:32 athena kernel: [ 307.500610] usb 3-2: T2-2
Dec 25 21:19:32 athena kernel: [ 307.500612] usb 3-2: T2-3
Dec 25 21:19:47 athena kernel: [ 322.482794] usb 3-2: T2-4
Dec 25 21:19:47 athena kernel: [ 322.482800] usb 3-2: T2-5
Dec 25 21:19:47 athena kernel: [ 322.482803] usb 3-2: T2-6
Dec 25 21:19:47 athena kernel: [ 322.482805] usb 3-2: T2-7
Dec 25 21:19:47 athena kernel: [ 322.482807] usb 3-2: T3
Dec 25 21:19:47 athena kernel: [ 322.550781] usb 3-2: T1
Dec 25 21:19:47 athena kernel: [ 322.550785] usb 3-2: T2-1
Dec 25 21:19:47 athena kernel: [ 322.550787] usb 3-2: T2-2
Dec 25 21:19:47 athena kernel: [ 322.550789] usb 3-2: T2-3
Dec 25 21:20:02 athena kernel: [ 337.532626] usb 3-2: T2-4
Dec 25 21:20:02 athena kernel: [ 337.532632] usb 3-2: T2-5
Dec 25 21:20:02 athena kernel: [ 337.532634] usb 3-2: T2-6
Dec 25 21:20:02 athena kernel: [ 337.532636] usb 3-2: T2-7
Dec 25 21:20:02 athena kernel: [ 337.532638] usb 3-2: T3
Dec 25 21:20:02 athena kernel: [ 337.640193] usb 3-2: T1
Dec 25 21:20:02 athena kernel: [ 337.640197] usb 3-2: T2-1
Dec 25 21:20:02 athena kernel: [ 337.640198] usb 3-2: T2-2
Dec 25 21:20:02 athena kernel: [ 337.640200] usb 3-2: T2-3
Dec 25 21:20:17 athena kernel: [ 352.618278] usb 3-2: T2-4
Dec 25 21:20:17 athena kernel: [ 352.618284] usb 3-2: T2-5
Dec 25 21:20:17 athena kernel: [ 352.618286] usb 3-2: T2-6
Dec 25 21:20:17 athena kernel: [ 352.618289] usb 3-2: T2-7
Dec 25 21:20:17 athena kernel: [ 352.618291] usb 3-2: T3
Dec 25 21:20:17 athena kernel: [ 352.620500] usb 3-2: T1
Dec 25 21:20:17 athena kernel: [ 352.620503] usb 3-2: T2-1
Dec 25 21:20:17 athena kernel: [ 352.620505] usb 3-2: T2-2
Dec 25 21:20:17 athena kernel: [ 352.620506] usb 3-2: T2-3
Dec 25 21:20:32 athena kernel: [ 367.600327] usb 3-2: T2-4
Dec 25 21:20:32 athena kernel: [ 367.600332] usb 3-2: T2-5
Dec 25 21:20:32 athena kernel: [ 367.600334] usb 3-2: T2-6
Dec 25 21:20:32 athena kernel: [ 367.600336] usb 3-2: T2-7
Dec 25 21:20:32 athena kernel: [ 367.600338] usb 3-2: T3
Dec 25 21:20:32 athena kernel: [ 367.613182] usb 3-2: T1
Dec 25 21:20:32 athena kernel: [ 367.613185] usb 3-2: T2-1
Dec 25 21:20:32 athena kernel: [ 367.613187] usb 3-2: T2-2
Dec 25 21:20:32 athena kernel: [ 367.613188] usb 3-2: T2-3
Dec 25 21:20:47 athena kernel: [ 382.594294] usb 3-2: T2-4
Dec 25 21:20:47 athena kernel: [ 382.594299] usb 3-2: T2-5
Dec 25 21:20:47 athena kernel: [ 382.594301] usb 3-2: T2-6
Dec 25 21:20:47 athena kernel: [ 382.594302] usb 3-2: T2-7
Dec 25 21:20:47 athena kernel: [ 382.594304] usb 3-2: T3
Dec 25 21:20:47 athena kernel: [ 382.631819] BUG: unable to handle kernel NULL pointer dereference at 0000000000000009
Dec 25 21:20:47 athena kernel: [ 382.631854] IP: [<ffffffff8116fc85>] __anon_vma_interval_tree_augment_rotate+0x15/0x60
Dec 25 21:20:47 athena kernel: [ 382.631885] PGD 20eed2067 PUD 1f94a8067 PMD 0
Dec 25 21:20:47 athena kernel: [ 382.631903] Oops: 0000 [#1] SMP
Dec 25 21:20:47 athena kernel: [ 382.631917] Modules linked in: snd_hrtimer(F) pci_stub(F) vboxpci(OF) vboxnetadp(OF) vboxnetflt(OF) vboxdrv(OF) rfcomm(F) bnep(F) binfmt_misc(F) dm_crypt(F) joydev(F) x86_pkg_temp_thermal(F) intel_powerclamp(F) coretemp(F) kvm_intel(F) kvm(F) uvcvideo(F) btusb(F) videobuf2_vmalloc(F) videobuf2_memops(F) videobuf2_core(F) arc4(F) iwldvm(F) snd_hda_codec_hdmi(F) bluetooth(F) snd_hda_codec_idt(F) mac80211(F) crct10dif_pclmul(F) snd_hda_intel(F) crc32_pclmul(F) ghash_clmulni_intel(F) aesni_intel(F) snd_hda_codec(F) videodev(F) snd_usb_audio(F) aes_x86_64(F) snd_usbmidi_lib(F) lrw(F) gf128mul(F) glue_helper(F) snd_hwdep(F) snd_pcm(F) ablk_helper(F) cryptd(F) snd_page_alloc(F) snd_seq_midi(F) snd_seq_midi_event(F) snd_rawmidi(F) snd_seq(F) iwlwifi(F) dell_wmi(F) dell_laptop(F) snd_seq_device(F) microcode(F) snd_timer(F) sparse_keymap(F) mei_me(F) ppdev(F) dcdbas(F) psmouse(F) cfg80211(F) snd(F) mei(F) soundcore(F) parport_pc(F) mac_hid(F) tpm_tis(F) serio_raw(F) lp(F) lpc_ich(F) parpo
Dec 25 21:20:47 athena kernel: rt(F) hid_generic(F) usbhid(F) hid(F) ahci(F) libahci(F) tg3(F) ptp(F) i915(F) pps_core(F) sdhci_pci(F) sdhci(F) i2c_algo_bit(F) drm_kms_helper(F) drm(F) wmi(F) video(F)
Dec 25 21:20:47 athena kernel: [ 382.632308] CPU: 1 PID: 2295 Comm: xsane Tainted: GF O 3.13.0-rc5 #5
Dec 25 21:20:47 athena kernel: [ 382.632331] Hardware name: Dell Inc. Latitude E5530 non-vPro/0VP63H, BIOS A12 08/07/2013
Dec 25 21:20:47 athena kernel: [ 382.632357] task: ffff8801f95e1800 ti: ffff8801f2cf0000 task.ti: ffff8801f2cf0000
Dec 25 21:20:47 athena kernel: [ 382.632381] RIP: 0010:[<ffffffff8116fc85>] [<ffffffff8116fc85>] __anon_vma_interval_tree_augment_rotate+0x15/0x60
Dec 25 21:20:47 athena kernel: [ 382.632417] RSP: 0000:ffff8801f2cf1d18 EFLAGS: 00010246
Dec 25 21:20:47 athena kernel: [ 382.632435] RAX: 0000000000000000 RBX: ffff88020eec05a0 RCX: 0000000000000000
Dec 25 21:20:47 athena kernel: [ 382.632457] RDX: 0000000000000001 RSI: ffff88020eec02a0 RDI: ffff88020eec05a0
Dec 25 21:20:47 athena kernel: [ 382.632480] RBP: ffff8801f2cf1d18 R08: ffff88020eec05a0 R09: 00000000000028ef
Dec 25 21:20:47 athena kernel: [ 382.632502] R10: 00000000000028cf R11: ffff8800d8f39280 R12: ffff8800cba2d760
Dec 25 21:20:47 athena kernel: [ 382.632525] R13: ffff8801f96417f0 R14: 0000000000000000 R15: ffff8801f2cedfdc
Dec 25 21:20:47 athena kernel: [ 382.632549] FS: 00007ff8f85eb980(0000) GS:ffff88021e280000(0000) knlGS:0000000000000000
Dec 25 21:20:47 athena kernel: [ 382.632575] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
Dec 25 21:20:47 athena kernel: [ 382.632594] CR2: 0000000000000009 CR3: 00000001f949c000 CR4: 00000000001407e0
Dec 25 21:20:47 athena kernel: [ 382.632617] Stack:
Dec 25 21:20:47 athena kernel: [ 382.632624] ffff8801f2cf1d48 ffffffff81379fff ffffffff8116fc70 ffff8801f956aa10
Dec 25 21:20:47 athena kernel: [ 382.632652] ffff8801f96417c0 ffff8800d8f39280 ffff8801f2cf1d58 ffffffff8117016b
Dec 25 21:20:47 athena kernel: [ 382.632679] ffff8801f2cf1d90 ffffffff81181626 00000000028cf048 ffff8801f956aa10
Dec 25 21:20:47 athena kernel: [ 382.632706] Call Trace:
Dec 25 21:20:47 athena kernel: [ 382.632721] [<ffffffff81379fff>] __rb_insert_augmented+0x8f/0x1f0
Dec 25 21:20:47 athena kernel: [ 382.632744] [<ffffffff8116fc70>] ? vma_interval_tree_augment_rotate+0x60/0x60
Dec 25 21:20:47 athena kernel: [ 382.632770] [<ffffffff8117016b>] anon_vma_interval_tree_insert+0x8b/0x90
Dec 25 21:20:47 athena kernel: [ 382.632794] [<ffffffff81181626>] anon_vma_prepare+0xc6/0x170
Dec 25 21:20:47 athena kernel: [ 382.632816] [<ffffffff811767bb>] handle_mm_fault+0xafb/0xe30
Dec 25 21:20:47 athena kernel: [ 382.632837] [<ffffffff810759a8>] ? ptrace_do_notify+0x88/0xa0
Dec 25 21:20:47 athena kernel: [ 382.632858] [<ffffffff8172cf1c>] __do_page_fault+0x16c/0x560
Dec 25 21:20:47 athena kernel: [ 382.632880] [<ffffffff8110ecac>] ? acct_account_cputime+0x1c/0x20
Dec 25 21:20:47 athena kernel: [ 382.632904] [<ffffffff8109a9dc>] ? account_user_time+0x8c/0xa0
Dec 25 21:20:47 athena kernel: [ 382.632926] [<ffffffff8109aff4>] ? vtime_account_user+0x54/0x60
Dec 25 21:20:47 athena kernel: [ 382.632948] [<ffffffff8172d32a>] do_page_fault+0x1a/0x70
Dec 25 21:20:47 athena kernel: [ 382.632968] [<ffffffff81729788>] page_fault+0x28/0x30
Dec 25 21:20:47 athena kernel: [ 382.632985] Code: 48 0f 42 c2 48 89 47 18 5d c3 66 66 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 44 00 00 48 8b 47 18 55 48 89 e5 48 89 46 18 48 8b 57 e0 <48> 8b 42 08 48 2b 02 48 8b 8a 98 00 00 00 48 8b 57 10 48 c1 e8
Dec 25 21:20:47 athena kernel: [ 382.633095] RIP [<ffffffff8116fc85>] __anon_vma_interval_tree_augment_rotate+0x15/0x60
Dec 25 21:20:47 athena kernel: [ 382.633125] RSP <ffff8801f2cf1d18>
Dec 25 21:20:47 athena kernel: [ 382.633137] CR2: 0000000000000009
Dec 25 21:20:47 athena kernel: [ 382.638491] ---[ end trace d8def2988fc96ec8 ]---
