Re: 3.8.2: stale pci device info for a previously inserted express card

Re: 3.8.2: stale pci device info for a previously inserted express card

[Bjorn Helgaas]

[+cc linux-pci, Sarah, Alan]

On Mon, Mar 11, 2013 at 10:02 AM, Martin Mokrejs
<mmokrejs@fold.natur.cuni.cz> wrote:
> [re-sending to you all three directly, looks the original email did not make it into linux-pci
> through some filters]
>
>   I use for my daily work acpiphp to manage express cards in Dell Vostro 3550.
> I have never seen something like this before and believe this is some new regression
> in 3.8 series. I had in teh a USB3 card and ejected it. Then I inserted a
> SATA Sil3132 card but it is not detected and dmesg still ends with last lines
> added when the USB card was being removed. The funny thing is that lspci reports
> a mixture of USB-card properties with NEC chips along with Silicon Image eSATA card.

I don't know anything about the kmemleaks mentioned elsewhere in this
thread, but the idea of "stale PCI device info" seems possibly related
to some acpiphp issues we've been working on recently.

Starting with v3.9, we don't handle ACPI Bus Check notifications to
host bridges correctly, and the result is that when we're using
acpiphp, we don't notice when PCI devices are added or removed. There
are more details in https://bugzilla.kernel.org/show_bug.cgi?id=57961

It looks like your Vostro 3550 uses acpiphp, so maybe there's a
connection.  Can you try a current Linus upstream kernel (v3.10-rc1
should be released in the next day or two) and apply the v3.10 patch
from the bugzilla, and collect a complete dmesg log after you try a
couple hotplug events?

Bjorn

Re: 3.8.2: stale pci device info for a previously inserted express card

[Martin Mokrejs]

[-- Attachment #1: Type: text/plain, Size: 10981 bytes --]

Hi everybody,

Bjorn Helgaas wrote:
> [+cc linux-pci, Sarah, Alan]
> 
> On Mon, Mar 11, 2013 at 10:02 AM, Martin Mokrejs
> <mmokrejs@fold.natur.cuni.cz> wrote:
>> [re-sending to you all three directly, looks the original email did not make it into linux-pci
>> through some filters]
>>
>>   I use for my daily work acpiphp to manage express cards in Dell Vostro 3550.
>> I have never seen something like this before and believe this is some new regression
>> in 3.8 series. I had in teh a USB3 card and ejected it. Then I inserted a
>> SATA Sil3132 card but it is not detected and dmesg still ends with last lines
>> added when the USB card was being removed. The funny thing is that lspci reports
>> a mixture of USB-card properties with NEC chips along with Silicon Image eSATA card.
> 
> I don't know anything about the kmemleaks mentioned elsewhere in this
> thread, but the idea of "stale PCI device info" seems possibly related
> to some acpiphp issues we've been working on recently.
> 
> Starting with v3.9, we don't handle ACPI Bus Check notifications to
> host bridges correctly, and the result is that when we're using
> acpiphp, we don't notice when PCI devices are added or removed. There
> are more details in https://bugzilla.kernel.org/show_bug.cgi?id=57961

Looks to me it is already in 3.10-rc4 which I tested now. No, I still do see
same problem like before: a hotremoval of NEC-based xHCI express card is detected
on every second eject. But, sometimes it seems it is only delayed by some 25-30
seconds. Would have to do more testing. However, there are some *new* kmemleaks
reported by kernel related to acpiphpp bu xhci_hcd. That could a hint why
the hotremoval sometimes proceeds delayed but sometimes maybe not at all or at
least not *immediately* like for any other device?

However, the stale sysfs entries for partially removed device SiI3132 (sata_sil24
driver) are NOT appearing anymore, good. That used to be associated with
'sata_sil24: IRQ status == 0xffffffff, PCI fault or device removal?' line.
Now, I see under 3.10-rc4 the extra message about 'ACPI: Device does not support D3cold'.
would be nice if it said what device is it talking about? About upstream root port
or about my end device (express card)? Is it related by pcie_aspm= kernel
commandline option? If yes, please include the relevant info the message text.
referring to this being affected by the particular value. At the moment I used:
pcie_aspm=off

--- dmesg_initial__inserted_eSATA__ejected__inserted__ejected__inserted.txt     2013-06-07 02:53:56.000000000 +0200
+++ dmesg_initial__inserted_eSATA__ejected__inserted__ejected__inserted__ejected.txt    2013-06-07 02:54:09.000000000 +0200
@@ -1439,3 +1439,5 @@
 [  254.317365] ata12: SATA max UDMA/100 host m128@0xf6c04000 port 0xf6c02000 irq 19
 [  256.400454] ata11: SATA link down (SStatus 0 SControl 0)
 [  258.493027] ata12: SATA link down (SStatus 0 SControl 0)
+[  267.116723] sata_sil24: IRQ status == 0xffffffff, PCI fault or device removal?
+[  267.117779] ACPI: Device does not support D3cold


So, in my eyes the "stale pci info" issue is fixed in 3.10-rc4 at least under acpiphp and pcie_aspm=off.



> 
> It looks like your Vostro 3550 uses acpiphp, so maybe there's a
> connection.  Can you try a current Linus upstream kernel (v3.10-rc1
> should be released in the next day or two) and apply the v3.10 patch
> from the bugzilla, and collect a complete dmesg log after you try a
> couple hotplug events?

I opened a bug https://bugzilla.kernel.org/show_bug.cgi?id=59411 .
I wanted to report individual tests but as overnight kernel reported
kmemleaks with interesting stacktraces I took the lazy approach and
uploaded the kmemleaks file and dmesg from the morning without further
splitting the stuff. However, I have step-by-step collected data for
everything in the dmesg since bootup, sadly except the very last
hotremoval. But hope that is not a big loss.
;-)


The SiI3132 card handled by sata_sil24 is treated differently:

# prev='/dev/null'; ls -latr dmesg* | awk '{print $9}' | while read cur; do diff -u -w $prev $cur; echo ""; echo ""; prev=$cur; done | grep "enabling device"
+[   87.551260] firewire_ohci 0000:11:00.0: enabling device (0100 -> 0103)
+[  110.223677] firewire_ohci 0000:11:00.0: enabling device (0100 -> 0103)
+[  143.649295] sata_sil24 0000:11:00.0: enabling device (0100 -> 0103)
+[  172.391223] sata_sil24 0000:11:00.0: enabling device (0100 -> 0103)
+[  208.367596] firewire_ohci 0000:11:00.0: enabling device (0100 -> 0103)
+[  242.299044] firewire_ohci 0000:11:00.0: enabling device (0100 -> 0103)
+[  277.412231] pci 0000:11:00.0: enabling device (0100 -> 0102)
+[  400.101571] pci 0000:11:00.0: enabling device (0100 -> 0102)
+[  458.763955] pci 0000:11:00.0: enabling device (0100 -> 0102)
#

I think the eSATA card hotremoval leaves acpiphp in a broken state.
That breaks in turn the NEC-based xHCI card hotplug removal detection while
NOT VIA-based FireWire card which can somehow overcome that.
What one can see in logs that xhci_hcd started to complain:


Hotinsert+removal of a firewire card, note "PME# disabled" line.

[  110.222507] pci 0000:11:00.0: [1106:3403] type 00 class 0x0c0010
[  110.222550] pci 0000:11:00.0: reg 10: [mem 0x00000000-0x000007ff 64bit]
[  110.222569] pci 0000:11:00.0: reg 18: [io  0x0000-0x00ff]
[  110.222746] pci 0000:11:00.0: supports D2
[  110.222747] pci 0000:11:00.0: PME# supported from D2 D3hot D3cold
[  110.222755] pci 0000:11:00.0: PME# disabled
[  110.223273] pci 0000:11:00.0: BAR 0: assigned [mem 0xf6c00000-0xf6c007ff 64bit]
[  110.223294] pci 0000:11:00.0: BAR 0: set to [mem 0xf6c00000-0xf6c007ff 64bit] (PCI address [0xf6c00000-0xf6c007ff])
[  110.223296] pci 0000:11:00.0: BAR 2: assigned [io  0xc000-0xc0ff]
[  110.223302] pci 0000:11:00.0: BAR 2: set to [io  0xc000-0xc0ff] (PCI address [0xc000-0xc0ff])
[  110.223677] firewire_ohci 0000:11:00.0: enabling device (0100 -> 0103)
[  110.224296] firewire_ohci 0000:11:00.0: calling quirk_via_vlink+0x0/0xae
[  110.224301] firewire_ohci 0000:11:00.0: enabling bus mastering
[  110.319376] firewire_ohci 0000:11:00.0: added OHCI v1.10 device as card 1, 4 IR + 8 IT contexts, quirks 0x11
[  110.820445] firewire_core 0000:11:00.0: created device fw0: GUID 0011066600000003, S400
[  120.739684] firewire_ohci 0000:11:00.0: PME# disabled
[  120.741121] firewire_ohci 0000:11:00.0: removed fw-ohci device
[  120.741349] ACPI: Device does not support D3cold


A following hotinsert+removal of a SiI3132 card, note "nothing about PME# logged" by pci core. Why?
Is this related to my pcie_aspm=off?

[  143.558781] pci 0000:11:00.0: [1095:3132] type 00 class 0x018000
[  143.558827] pci 0000:11:00.0: reg 10: [mem 0x00000000-0x0000007f 64bit]
[  143.558859] pci 0000:11:00.0: reg 18: [mem 0x00000000-0x00003fff 64bit]
[  143.558880] pci 0000:11:00.0: reg 20: [io  0x0000-0x007f]
[  143.558922] pci 0000:11:00.0: reg 30: [mem 0x00000000-0x0007ffff pref]
[  143.559037] pci 0000:11:00.0: supports D1 D2
[  143.559503] pci 0000:11:00.0: BAR 6: assigned [mem 0xf0000000-0xf007ffff pref]
[  143.559506] pci 0000:11:00.0: BAR 2: assigned [mem 0xf6c00000-0xf6c03fff 64bit]
[  143.559527] pci 0000:11:00.0: BAR 2: set to [mem 0xf6c00000-0xf6c03fff 64bit] (PCI address [0xf6c00000-0xf6c03fff])
[  143.559529] pci 0000:11:00.0: BAR 0: assigned [mem 0xf6c04000-0xf6c0407f 64bit]
[  143.559551] pci 0000:11:00.0: BAR 0: set to [mem 0xf6c04000-0xf6c0407f 64bit] (PCI address [0xf6c04000-0xf6c0407f])
[  143.559552] pci 0000:11:00.0: BAR 4: assigned [io  0xc000-0xc07f]
[  143.559560] pci 0000:11:00.0: BAR 4: set to [io  0xc000-0xc07f] (PCI address [0xc000-0xc07f])
[  143.649276] sata_sil24 0000:11:00.0: version 1.1
[  143.649295] sata_sil24 0000:11:00.0: enabling device (0100 -> 0103)
[  143.650045] sata_sil24 0000:11:00.0: enabling bus mastering
[  143.652840] scsi6 : sata_sil24
[  143.653497] scsi7 : sata_sil24
[  143.654042] ata7: SATA max UDMA/100 host m128@0xf6c04000 port 0xf6c00000 irq 19
[  143.654045] ata8: SATA max UDMA/100 host m128@0xf6c04000 port 0xf6c02000 irq 19
[  145.737258] ata7: SATA link down (SStatus 0 SControl 0)
[  147.828753] ata8: SATA link down (SStatus 0 SControl 0)
[  163.534474] sata_sil24: IRQ status == 0xffffffff, PCI fault or device removal?
[  163.535550] ACPI: Device does not support D3cold


Finally, a third one to compare to, a hotinsert+hotremoval of NEC-based USB3 card.
Note, no line saying "pci 0000:11:00.0: supports ...":

[  277.411123] pci 0000:11:00.0: [1033:0194] type 00 class 0x0c0330
[  277.411178] pci 0000:11:00.0: reg 10: [mem 0x00000000-0x00001fff 64bit]
[  277.411439] pci 0000:11:00.0: PME# supported from D0 D3hot
[  277.411450] pci 0000:11:00.0: PME# disabled
[  277.412021] pci 0000:11:00.0: BAR 0: assigned [mem 0xf6c00000-0xf6c01fff 64bit]
[  277.412049] pci 0000:11:00.0: BAR 0: set to [mem 0xf6c00000-0xf6c01fff 64bit] (PCI address [0xf6c00000-0xf6c01fff])
[  277.412218] pci 0000:11:00.0: calling quirk_usb_early_handoff+0x0/0x65a
[  277.412231] pci 0000:11:00.0: enabling device (0100 -> 0102)
[  277.414428] xhci_hcd 0000:11:00.0: enabling bus mastering
[  277.414452] xhci_hcd 0000:11:00.0: xHCI Host Controller
[  277.414501] xhci_hcd 0000:11:00.0: new USB bus registered, assigned bus number 5
[  277.414925] xhci_hcd 0000:11:00.0: enabling Mem-Wr-Inval
[  277.414931] xhci_hcd 0000:11:00.0: supports USB remote wakeup
[  277.415073] xhci_hcd 0000:11:00.0: irq 48 for MSI/MSI-X
[  277.415121] xhci_hcd 0000:11:00.0: irq 49 for MSI/MSI-X
[  277.415168] xhci_hcd 0000:11:00.0: irq 50 for MSI/MSI-X
[  277.417049] xHCI xhci_add_endpoint called for root hub
[  277.417050] xHCI xhci_check_bandwidth called for root hub
[  277.418987] xhci_hcd 0000:11:00.0: xHCI Host Controller
[  277.419028] xhci_hcd 0000:11:00.0: new USB bus registered, assigned bus number 6
[  277.419051] xhci_hcd 0000:11:00.0: supports USB remote wakeup
[  277.420411] xHCI xhci_add_endpoint called for root hub
[  277.420412] xHCI xhci_check_bandwidth called for root hub
[  293.398490] xhci_hcd 0000:11:00.0: PME# disabled
[  293.398765] xhci_hcd 0000:11:00.0: remove, state 4
[  293.398833] xhci_hcd 0000:11:00.0: roothub graceful disconnect
[  293.400107] xHCI xhci_drop_endpoint called for root hub
[  293.400108] xHCI xhci_check_bandwidth called for root hub
[  293.401695] xhci_hcd 0000:11:00.0: Host not halted after 16000 microseconds.
[  293.401735] xhci_hcd 0000:11:00.0: USB bus 6 deregistered
[  293.401754] xhci_hcd 0000:11:00.0: remove, state 4
[  293.401766] xhci_hcd 0000:11:00.0: roothub graceful disconnect
[  293.402479] xHCI xhci_drop_endpoint called for root hub
[  293.402480] xHCI xhci_check_bandwidth called for root hub
[  293.403302] xhci_hcd 0000:11:00.0: Host not halted after 16000 microseconds.
[  293.403707] xhci_hcd 0000:11:00.0: USB bus 5 deregistered
[  293.448715] ACPI: Device does not support D3cold



Martin
To attract Google search engine and your eyes I am attaching the kmemleak
file to this email. ;-)


[-- Attachment #2: kmemleak --]
[-- Type: text/plain, Size: 40313 bytes --]

unreferenced object 0xffff88040b2ef690 (size 256):
  comm "swapper/0", pid 1, jiffies 4294937684 (age 28068.730s)
  hex dump (first 32 bytes):
    00 00 00 00 ad 4e ad de ff ff ff ff 00 00 00 00  .....N..........
    ff ff ff ff ff ff ff ff f8 89 6d 82 ff ff ff ff  ..........m.....
  backtrace:
    [<ffffffff816b46ae>] kmemleak_alloc+0x21/0x3e
    [<ffffffff81162847>] slab_post_alloc_hook+0x28/0x2a
    [<ffffffff811648c9>] kmem_cache_alloc+0xb0/0xc0
    [<ffffffff813e7f6e>] device_private_init+0x1b/0x68
    [<ffffffff813ea120>] dev_set_drvdata+0x28/0x31
    [<ffffffff814975fb>] i801_probe+0x4d/0x40a
    [<ffffffff812df27e>] local_pci_probe+0x39/0x61
    [<ffffffff812df4a6>] pci_device_probe+0xba/0xe0
    [<ffffffff813ea752>] driver_probe_device+0x99/0x1c7
    [<ffffffff813ea8ce>] __driver_attach+0x4e/0x6f
    [<ffffffff813e8e02>] bus_for_each_dev+0x57/0x89
    [<ffffffff813ea24e>] driver_attach+0x19/0x1b
    [<ffffffff813e9eef>] bus_add_driver+0xe7/0x20c
    [<ffffffff813eae53>] driver_register+0x8e/0x114
    [<ffffffff812de8f2>] __pci_register_driver+0x5d/0x62
    [<ffffffff81b4527a>] i2c_i801_init+0xaa/0xc9
unreferenced object 0xffff8804095e6090 (size 4096):
  comm "kworker/0:0", pid 4, jiffies 4294946028 (age 27985.300s)
  hex dump (first 32 bytes):
    00 01 10 00 00 00 ad de 00 02 20 00 00 00 ad de  .......... .....
    38 69 f5 0c 04 88 ff ff 00 00 00 00 00 00 00 00  8i..............
  backtrace:
    [<ffffffff816b46ae>] kmemleak_alloc+0x21/0x3e
    [<ffffffff81162847>] slab_post_alloc_hook+0x28/0x2a
    [<ffffffff811648c9>] kmem_cache_alloc+0xb0/0xc0
    [<ffffffff812d8baa>] alloc_pci_dev+0x15/0x2e
    [<ffffffff816b4714>] pci_scan_single_device+0x49/0x99
    [<ffffffff812d9972>] pci_scan_slot+0x52/0xf6
    [<ffffffff816b5523>] enable_device+0xdb/0x393
    [<ffffffff812ed278>] acpiphp_enable_slot+0xcb/0x130
    [<ffffffff812ed454>] acpiphp_check_bridge+0x6e/0xd4
    [<ffffffff812ed812>] _handle_hotplug_event_bridge+0xc8/0x218
    [<ffffffff810d8463>] process_one_work+0x1cb/0x2dd
    [<ffffffff810d8936>] worker_thread+0x12f/0x1fc
    [<ffffffff810dd519>] kthread+0xac/0xb4
    [<ffffffff816cbd2c>] ret_from_fork+0x7c/0xb0
    [<ffffffffffffffff>] 0xffffffffffffffff
unreferenced object 0xffff880407f59a28 (size 16):
  comm "kworker/0:0", pid 4, jiffies 4294946028 (age 27985.300s)
  hex dump (first 16 bytes):
    30 30 30 30 3a 31 31 3a 30 30 2e 30 00 6b 6b a5  0000:11:00.0.kk.
  backtrace:
    [<ffffffff816b46ae>] kmemleak_alloc+0x21/0x3e
    [<ffffffff81162847>] slab_post_alloc_hook+0x28/0x2a
    [<ffffffff81165ccf>] __kmalloc_track_caller+0xdd/0x118
    [<ffffffff812c2727>] kvasprintf+0x4b/0x74
    [<ffffffff812b916d>] kobject_set_name_vargs+0x21/0x56
    [<ffffffff813e6e44>] dev_set_name+0x3c/0x3e
    [<ffffffff812d951b>] pci_setup_device+0xfc/0x3b5
    [<ffffffff816b473a>] pci_scan_single_device+0x6f/0x99
    [<ffffffff812d9972>] pci_scan_slot+0x52/0xf6
    [<ffffffff816b5523>] enable_device+0xdb/0x393
    [<ffffffff812ed278>] acpiphp_enable_slot+0xcb/0x130
    [<ffffffff812ed454>] acpiphp_check_bridge+0x6e/0xd4
    [<ffffffff812ed812>] _handle_hotplug_event_bridge+0xc8/0x218
    [<ffffffff810d8463>] process_one_work+0x1cb/0x2dd
    [<ffffffff810d8936>] worker_thread+0x12f/0x1fc
    [<ffffffff810dd519>] kthread+0xac/0xb4
unreferenced object 0xffff88040a1925d8 (size 64):
  comm "kworker/0:0", pid 4, jiffies 4294946028 (age 27985.310s)
  hex dump (first 32 bytes):
    00 00 00 00 00 00 00 00 08 69 5e 09 04 88 ff ff  .........i^.....
    10 00 00 00 0e 00 00 00 00 00 00 00 00 00 00 00  ................
  backtrace:
    [<ffffffff816b46ae>] kmemleak_alloc+0x21/0x3e
    [<ffffffff81162847>] slab_post_alloc_hook+0x28/0x2a
    [<ffffffff81164702>] __kmalloc+0xde/0x118
    [<ffffffff812dbc16>] kzalloc.constprop.32+0xe/0x10
    [<ffffffff812dbcb4>] pci_add_cap_save_buffer.part.16+0x1f/0x62
    [<ffffffff812dd825>] pci_allocate_cap_save_buffers+0x29/0x82
    [<ffffffff812d9877>] pci_device_add+0xa3/0x14c
    [<ffffffff816b4756>] pci_scan_single_device+0x8b/0x99
    [<ffffffff812d9972>] pci_scan_slot+0x52/0xf6
    [<ffffffff816b5523>] enable_device+0xdb/0x393
    [<ffffffff812ed278>] acpiphp_enable_slot+0xcb/0x130
    [<ffffffff812ed454>] acpiphp_check_bridge+0x6e/0xd4
    [<ffffffff812ed812>] _handle_hotplug_event_bridge+0xc8/0x218
    [<ffffffff810d8463>] process_one_work+0x1cb/0x2dd
    [<ffffffff810d8936>] worker_thread+0x12f/0x1fc
    [<ffffffff810dd519>] kthread+0xac/0xb4
unreferenced object 0xffff880408619578 (size 256):
  comm "kworker/0:0", pid 4, jiffies 4294946028 (age 27985.310s)
  hex dump (first 32 bytes):
    05 05 00 00 ad 4e ad de ff ff ff ff 00 00 00 00  .....N..........
    ff ff ff ff ff ff ff ff f8 89 6d 82 ff ff ff ff  ..........m.....
  backtrace:
    [<ffffffff816b46ae>] kmemleak_alloc+0x21/0x3e
    [<ffffffff81162847>] slab_post_alloc_hook+0x28/0x2a
    [<ffffffff811648c9>] kmem_cache_alloc+0xb0/0xc0
    [<ffffffff813e7f6e>] device_private_init+0x1b/0x68
    [<ffffffff813e8006>] device_add+0x4b/0x5d2
    [<ffffffff812d98fb>] pci_device_add+0x127/0x14c
    [<ffffffff816b4756>] pci_scan_single_device+0x8b/0x99
    [<ffffffff812d9972>] pci_scan_slot+0x52/0xf6
    [<ffffffff816b5523>] enable_device+0xdb/0x393
    [<ffffffff812ed278>] acpiphp_enable_slot+0xcb/0x130
    [<ffffffff812ed454>] acpiphp_check_bridge+0x6e/0xd4
    [<ffffffff812ed812>] _handle_hotplug_event_bridge+0xc8/0x218
    [<ffffffff810d8463>] process_one_work+0x1cb/0x2dd
    [<ffffffff810d8936>] worker_thread+0x12f/0x1fc
    [<ffffffff810dd519>] kthread+0xac/0xb4
    [<ffffffff816cbd2c>] ret_from_fork+0x7c/0xb0
unreferenced object 0xffff8804095e2030 (size 4096):
  comm "kworker/0:0", pid 4, jiffies 4294948304 (age 27962.550s)
  hex dump (first 32 bytes):
    00 01 10 00 00 00 ad de 00 02 20 00 00 00 ad de  .......... .....
    38 69 f5 0c 04 88 ff ff 00 00 00 00 00 00 00 00  8i..............
  backtrace:
    [<ffffffff816b46ae>] kmemleak_alloc+0x21/0x3e
    [<ffffffff81162847>] slab_post_alloc_hook+0x28/0x2a
    [<ffffffff811648c9>] kmem_cache_alloc+0xb0/0xc0
    [<ffffffff812d8baa>] alloc_pci_dev+0x15/0x2e
    [<ffffffff816b4714>] pci_scan_single_device+0x49/0x99
    [<ffffffff812d9972>] pci_scan_slot+0x52/0xf6
    [<ffffffff816b5523>] enable_device+0xdb/0x393
    [<ffffffff812ed278>] acpiphp_enable_slot+0xcb/0x130
    [<ffffffff812ed454>] acpiphp_check_bridge+0x6e/0xd4
    [<ffffffff812ed812>] _handle_hotplug_event_bridge+0xc8/0x218
    [<ffffffff810d8463>] process_one_work+0x1cb/0x2dd
    [<ffffffff810d8936>] worker_thread+0x12f/0x1fc
    [<ffffffff810dd519>] kthread+0xac/0xb4
    [<ffffffff816cbd2c>] ret_from_fork+0x7c/0xb0
    [<ffffffffffffffff>] 0xffffffffffffffff
unreferenced object 0xffff880407f59d20 (size 16):
  comm "kworker/0:0", pid 4, jiffies 4294948304 (age 27962.550s)
  hex dump (first 16 bytes):
    30 30 30 30 3a 31 31 3a 30 30 2e 30 00 6b 6b a5  0000:11:00.0.kk.
  backtrace:
    [<ffffffff816b46ae>] kmemleak_alloc+0x21/0x3e
    [<ffffffff81162847>] slab_post_alloc_hook+0x28/0x2a
    [<ffffffff81165ccf>] __kmalloc_track_caller+0xdd/0x118
    [<ffffffff812c2727>] kvasprintf+0x4b/0x74
    [<ffffffff812b916d>] kobject_set_name_vargs+0x21/0x56
    [<ffffffff813e6e44>] dev_set_name+0x3c/0x3e
    [<ffffffff812d951b>] pci_setup_device+0xfc/0x3b5
    [<ffffffff816b473a>] pci_scan_single_device+0x6f/0x99
    [<ffffffff812d9972>] pci_scan_slot+0x52/0xf6
    [<ffffffff816b5523>] enable_device+0xdb/0x393
    [<ffffffff812ed278>] acpiphp_enable_slot+0xcb/0x130
    [<ffffffff812ed454>] acpiphp_check_bridge+0x6e/0xd4
    [<ffffffff812ed812>] _handle_hotplug_event_bridge+0xc8/0x218
    [<ffffffff810d8463>] process_one_work+0x1cb/0x2dd
    [<ffffffff810d8936>] worker_thread+0x12f/0x1fc
    [<ffffffff810dd519>] kthread+0xac/0xb4
unreferenced object 0xffff8804077bef78 (size 64):
  comm "kworker/0:0", pid 4, jiffies 4294948304 (age 27962.550s)
  hex dump (first 32 bytes):
    00 00 00 00 00 00 00 00 a8 28 5e 09 04 88 ff ff  .........(^.....
    10 00 00 00 0e 00 00 00 00 00 00 00 00 00 00 00  ................
  backtrace:
    [<ffffffff816b46ae>] kmemleak_alloc+0x21/0x3e
    [<ffffffff81162847>] slab_post_alloc_hook+0x28/0x2a
    [<ffffffff81164702>] __kmalloc+0xde/0x118
    [<ffffffff812dbc16>] kzalloc.constprop.32+0xe/0x10
    [<ffffffff812dbcb4>] pci_add_cap_save_buffer.part.16+0x1f/0x62
    [<ffffffff812dd825>] pci_allocate_cap_save_buffers+0x29/0x82
    [<ffffffff812d9877>] pci_device_add+0xa3/0x14c
    [<ffffffff816b4756>] pci_scan_single_device+0x8b/0x99
    [<ffffffff812d9972>] pci_scan_slot+0x52/0xf6
    [<ffffffff816b5523>] enable_device+0xdb/0x393
    [<ffffffff812ed278>] acpiphp_enable_slot+0xcb/0x130
    [<ffffffff812ed454>] acpiphp_check_bridge+0x6e/0xd4
    [<ffffffff812ed812>] _handle_hotplug_event_bridge+0xc8/0x218
    [<ffffffff810d8463>] process_one_work+0x1cb/0x2dd
    [<ffffffff810d8936>] worker_thread+0x12f/0x1fc
    [<ffffffff810dd519>] kthread+0xac/0xb4
unreferenced object 0xffff88040749b690 (size 256):
  comm "kworker/0:0", pid 4, jiffies 4294948304 (age 27962.550s)
  hex dump (first 32 bytes):
    05 05 00 00 ad 4e ad de ff ff ff ff 00 00 00 00  .....N..........
    ff ff ff ff ff ff ff ff f8 89 6d 82 ff ff ff ff  ..........m.....
  backtrace:
    [<ffffffff816b46ae>] kmemleak_alloc+0x21/0x3e
    [<ffffffff81162847>] slab_post_alloc_hook+0x28/0x2a
    [<ffffffff811648c9>] kmem_cache_alloc+0xb0/0xc0
    [<ffffffff813e7f6e>] device_private_init+0x1b/0x68
    [<ffffffff813e8006>] device_add+0x4b/0x5d2
    [<ffffffff812d98fb>] pci_device_add+0x127/0x14c
    [<ffffffff816b4756>] pci_scan_single_device+0x8b/0x99
    [<ffffffff812d9972>] pci_scan_slot+0x52/0xf6
    [<ffffffff816b5523>] enable_device+0xdb/0x393
    [<ffffffff812ed278>] acpiphp_enable_slot+0xcb/0x130
    [<ffffffff812ed454>] acpiphp_check_bridge+0x6e/0xd4
    [<ffffffff812ed812>] _handle_hotplug_event_bridge+0xc8/0x218
    [<ffffffff810d8463>] process_one_work+0x1cb/0x2dd
    [<ffffffff810d8936>] worker_thread+0x12f/0x1fc
    [<ffffffff810dd519>] kthread+0xac/0xb4
    [<ffffffff816cbd2c>] ret_from_fork+0x7c/0xb0
unreferenced object 0xffff8804095e4060 (size 4096):
  comm "kworker/0:0", pid 4, jiffies 4294951635 (age 27929.250s)
  hex dump (first 32 bytes):
    00 01 10 00 00 00 ad de 00 02 20 00 00 00 ad de  .......... .....
    38 69 f5 0c 04 88 ff ff 00 00 00 00 00 00 00 00  8i..............
  backtrace:
    [<ffffffff816b46ae>] kmemleak_alloc+0x21/0x3e
    [<ffffffff81162847>] slab_post_alloc_hook+0x28/0x2a
    [<ffffffff811648c9>] kmem_cache_alloc+0xb0/0xc0
    [<ffffffff812d8baa>] alloc_pci_dev+0x15/0x2e
    [<ffffffff816b4714>] pci_scan_single_device+0x49/0x99
    [<ffffffff812d9972>] pci_scan_slot+0x52/0xf6
    [<ffffffff816b5523>] enable_device+0xdb/0x393
    [<ffffffff812ed278>] acpiphp_enable_slot+0xcb/0x130
    [<ffffffff812ed454>] acpiphp_check_bridge+0x6e/0xd4
    [<ffffffff812ed812>] _handle_hotplug_event_bridge+0xc8/0x218
    [<ffffffff810d8463>] process_one_work+0x1cb/0x2dd
    [<ffffffff810d8936>] worker_thread+0x12f/0x1fc
    [<ffffffff810dd519>] kthread+0xac/0xb4
    [<ffffffff816cbd2c>] ret_from_fork+0x7c/0xb0
    [<ffffffffffffffff>] 0xffffffffffffffff
unreferenced object 0xffff880407f59960 (size 16):
  comm "kworker/0:0", pid 4, jiffies 4294951635 (age 27929.250s)
  hex dump (first 16 bytes):
    30 30 30 30 3a 31 31 3a 30 30 2e 30 00 6b 6b a5  0000:11:00.0.kk.
  backtrace:
    [<ffffffff816b46ae>] kmemleak_alloc+0x21/0x3e
    [<ffffffff81162847>] slab_post_alloc_hook+0x28/0x2a
    [<ffffffff81165ccf>] __kmalloc_track_caller+0xdd/0x118
    [<ffffffff812c2727>] kvasprintf+0x4b/0x74
    [<ffffffff812b916d>] kobject_set_name_vargs+0x21/0x56
    [<ffffffff813e6e44>] dev_set_name+0x3c/0x3e
    [<ffffffff812d951b>] pci_setup_device+0xfc/0x3b5
    [<ffffffff816b473a>] pci_scan_single_device+0x6f/0x99
    [<ffffffff812d9972>] pci_scan_slot+0x52/0xf6
    [<ffffffff816b5523>] enable_device+0xdb/0x393
    [<ffffffff812ed278>] acpiphp_enable_slot+0xcb/0x130
    [<ffffffff812ed454>] acpiphp_check_bridge+0x6e/0xd4
    [<ffffffff812ed812>] _handle_hotplug_event_bridge+0xc8/0x218
    [<ffffffff810d8463>] process_one_work+0x1cb/0x2dd
    [<ffffffff810d8936>] worker_thread+0x12f/0x1fc
    [<ffffffff810dd519>] kthread+0xac/0xb4
unreferenced object 0xffff8804077bee18 (size 64):
  comm "kworker/0:0", pid 4, jiffies 4294951635 (age 27929.250s)
  hex dump (first 32 bytes):
    00 00 00 00 00 00 00 00 d8 48 5e 09 04 88 ff ff  .........H^.....
    10 00 00 00 0e 00 00 00 00 00 00 00 00 00 00 00  ................
  backtrace:
    [<ffffffff816b46ae>] kmemleak_alloc+0x21/0x3e
    [<ffffffff81162847>] slab_post_alloc_hook+0x28/0x2a
    [<ffffffff81164702>] __kmalloc+0xde/0x118
    [<ffffffff812dbc16>] kzalloc.constprop.32+0xe/0x10
    [<ffffffff812dbcb4>] pci_add_cap_save_buffer.part.16+0x1f/0x62
    [<ffffffff812dd825>] pci_allocate_cap_save_buffers+0x29/0x82
    [<ffffffff812d9877>] pci_device_add+0xa3/0x14c
    [<ffffffff816b4756>] pci_scan_single_device+0x8b/0x99
    [<ffffffff812d9972>] pci_scan_slot+0x52/0xf6
    [<ffffffff816b5523>] enable_device+0xdb/0x393
    [<ffffffff812ed278>] acpiphp_enable_slot+0xcb/0x130
    [<ffffffff812ed454>] acpiphp_check_bridge+0x6e/0xd4
    [<ffffffff812ed812>] _handle_hotplug_event_bridge+0xc8/0x218
    [<ffffffff810d8463>] process_one_work+0x1cb/0x2dd
    [<ffffffff810d8936>] worker_thread+0x12f/0x1fc
    [<ffffffff810dd519>] kthread+0xac/0xb4
unreferenced object 0xffff880408619460 (size 256):
  comm "kworker/0:0", pid 4, jiffies 4294951635 (age 27929.260s)
  hex dump (first 32 bytes):
    04 04 00 00 ad 4e ad de ff ff ff ff 00 00 00 00  .....N..........
    ff ff ff ff ff ff ff ff f8 89 6d 82 ff ff ff ff  ..........m.....
  backtrace:
    [<ffffffff816b46ae>] kmemleak_alloc+0x21/0x3e
    [<ffffffff81162847>] slab_post_alloc_hook+0x28/0x2a
    [<ffffffff811648c9>] kmem_cache_alloc+0xb0/0xc0
    [<ffffffff813e7f6e>] device_private_init+0x1b/0x68
    [<ffffffff813e8006>] device_add+0x4b/0x5d2
    [<ffffffff812d98fb>] pci_device_add+0x127/0x14c
    [<ffffffff816b4756>] pci_scan_single_device+0x8b/0x99
    [<ffffffff812d9972>] pci_scan_slot+0x52/0xf6
    [<ffffffff816b5523>] enable_device+0xdb/0x393
    [<ffffffff812ed278>] acpiphp_enable_slot+0xcb/0x130
    [<ffffffff812ed454>] acpiphp_check_bridge+0x6e/0xd4
    [<ffffffff812ed812>] _handle_hotplug_event_bridge+0xc8/0x218
    [<ffffffff810d8463>] process_one_work+0x1cb/0x2dd
    [<ffffffff810d8936>] worker_thread+0x12f/0x1fc
    [<ffffffff810dd519>] kthread+0xac/0xb4
    [<ffffffff816cbd2c>] ret_from_fork+0x7c/0xb0
unreferenced object 0xffff880409246090 (size 4096):
  comm "kworker/0:0", pid 4, jiffies 4294954516 (age 27900.450s)
  hex dump (first 32 bytes):
    00 01 10 00 00 00 ad de 00 02 20 00 00 00 ad de  .......... .....
    38 69 f5 0c 04 88 ff ff 00 00 00 00 00 00 00 00  8i..............
  backtrace:
    [<ffffffff816b46ae>] kmemleak_alloc+0x21/0x3e
    [<ffffffff81162847>] slab_post_alloc_hook+0x28/0x2a
    [<ffffffff811648c9>] kmem_cache_alloc+0xb0/0xc0
    [<ffffffff812d8baa>] alloc_pci_dev+0x15/0x2e
    [<ffffffff816b4714>] pci_scan_single_device+0x49/0x99
    [<ffffffff812d9972>] pci_scan_slot+0x52/0xf6
    [<ffffffff816b5523>] enable_device+0xdb/0x393
    [<ffffffff812ed278>] acpiphp_enable_slot+0xcb/0x130
    [<ffffffff812ed454>] acpiphp_check_bridge+0x6e/0xd4
    [<ffffffff812ed812>] _handle_hotplug_event_bridge+0xc8/0x218
    [<ffffffff810d8463>] process_one_work+0x1cb/0x2dd
    [<ffffffff810d8936>] worker_thread+0x12f/0x1fc
    [<ffffffff810dd519>] kthread+0xac/0xb4
    [<ffffffff816cbd2c>] ret_from_fork+0x7c/0xb0
    [<ffffffffffffffff>] 0xffffffffffffffff
unreferenced object 0xffff8804077e8fc8 (size 16):
  comm "kworker/0:0", pid 4, jiffies 4294954516 (age 27900.450s)
  hex dump (first 16 bytes):
    30 30 30 30 3a 31 31 3a 30 30 2e 30 00 6b 6b a5  0000:11:00.0.kk.
  backtrace:
    [<ffffffff816b46ae>] kmemleak_alloc+0x21/0x3e
    [<ffffffff81162847>] slab_post_alloc_hook+0x28/0x2a
    [<ffffffff81165ccf>] __kmalloc_track_caller+0xdd/0x118
    [<ffffffff812c2727>] kvasprintf+0x4b/0x74
    [<ffffffff812b916d>] kobject_set_name_vargs+0x21/0x56
    [<ffffffff813e6e44>] dev_set_name+0x3c/0x3e
    [<ffffffff812d951b>] pci_setup_device+0xfc/0x3b5
    [<ffffffff816b473a>] pci_scan_single_device+0x6f/0x99
    [<ffffffff812d9972>] pci_scan_slot+0x52/0xf6
    [<ffffffff816b5523>] enable_device+0xdb/0x393
    [<ffffffff812ed278>] acpiphp_enable_slot+0xcb/0x130
    [<ffffffff812ed454>] acpiphp_check_bridge+0x6e/0xd4
    [<ffffffff812ed812>] _handle_hotplug_event_bridge+0xc8/0x218
    [<ffffffff810d8463>] process_one_work+0x1cb/0x2dd
    [<ffffffff810d8936>] worker_thread+0x12f/0x1fc
    [<ffffffff810dd519>] kthread+0xac/0xb4
unreferenced object 0xffff880404403000 (size 64):
  comm "kworker/0:0", pid 4, jiffies 4294954516 (age 27900.450s)
  hex dump (first 32 bytes):
    00 00 00 00 00 00 00 00 08 69 24 09 04 88 ff ff  .........i$.....
    10 00 00 00 0e 00 00 00 00 00 00 00 00 00 00 00  ................
  backtrace:
    [<ffffffff816b46ae>] kmemleak_alloc+0x21/0x3e
    [<ffffffff81162847>] slab_post_alloc_hook+0x28/0x2a
    [<ffffffff81164702>] __kmalloc+0xde/0x118
    [<ffffffff812dbc16>] kzalloc.constprop.32+0xe/0x10
    [<ffffffff812dbcb4>] pci_add_cap_save_buffer.part.16+0x1f/0x62
    [<ffffffff812dd825>] pci_allocate_cap_save_buffers+0x29/0x82
    [<ffffffff812d9877>] pci_device_add+0xa3/0x14c
    [<ffffffff816b4756>] pci_scan_single_device+0x8b/0x99
    [<ffffffff812d9972>] pci_scan_slot+0x52/0xf6
    [<ffffffff816b5523>] enable_device+0xdb/0x393
    [<ffffffff812ed278>] acpiphp_enable_slot+0xcb/0x130
    [<ffffffff812ed454>] acpiphp_check_bridge+0x6e/0xd4
    [<ffffffff812ed812>] _handle_hotplug_event_bridge+0xc8/0x218
    [<ffffffff810d8463>] process_one_work+0x1cb/0x2dd
    [<ffffffff810d8936>] worker_thread+0x12f/0x1fc
    [<ffffffff810dd519>] kthread+0xac/0xb4
unreferenced object 0xffff880404574118 (size 256):
  comm "kworker/0:0", pid 4, jiffies 4294954516 (age 27900.450s)
  hex dump (first 32 bytes):
    04 04 00 00 ad 4e ad de ff ff ff ff 00 00 00 00  .....N..........
    ff ff ff ff ff ff ff ff f8 89 6d 82 ff ff ff ff  ..........m.....
  backtrace:
    [<ffffffff816b46ae>] kmemleak_alloc+0x21/0x3e
    [<ffffffff81162847>] slab_post_alloc_hook+0x28/0x2a
    [<ffffffff811648c9>] kmem_cache_alloc+0xb0/0xc0
    [<ffffffff813e7f6e>] device_private_init+0x1b/0x68
    [<ffffffff813e8006>] device_add+0x4b/0x5d2
    [<ffffffff812d98fb>] pci_device_add+0x127/0x14c
    [<ffffffff816b4756>] pci_scan_single_device+0x8b/0x99
    [<ffffffff812d9972>] pci_scan_slot+0x52/0xf6
    [<ffffffff816b5523>] enable_device+0xdb/0x393
    [<ffffffff812ed278>] acpiphp_enable_slot+0xcb/0x130
    [<ffffffff812ed454>] acpiphp_check_bridge+0x6e/0xd4
    [<ffffffff812ed812>] _handle_hotplug_event_bridge+0xc8/0x218
    [<ffffffff810d8463>] process_one_work+0x1cb/0x2dd
    [<ffffffff810d8936>] worker_thread+0x12f/0x1fc
    [<ffffffff810dd519>] kthread+0xac/0xb4
    [<ffffffff816cbd2c>] ret_from_fork+0x7c/0xb0
unreferenced object 0xffff880409241018 (size 4096):
  comm "kworker/0:0", pid 4, jiffies 4294958111 (age 27864.500s)
  hex dump (first 32 bytes):
    00 01 10 00 00 00 ad de 00 02 20 00 00 00 ad de  .......... .....
    38 69 f5 0c 04 88 ff ff 00 00 00 00 00 00 00 00  8i..............
  backtrace:
    [<ffffffff816b46ae>] kmemleak_alloc+0x21/0x3e
    [<ffffffff81162847>] slab_post_alloc_hook+0x28/0x2a
    [<ffffffff811648c9>] kmem_cache_alloc+0xb0/0xc0
    [<ffffffff812d8baa>] alloc_pci_dev+0x15/0x2e
    [<ffffffff816b4714>] pci_scan_single_device+0x49/0x99
    [<ffffffff812d9972>] pci_scan_slot+0x52/0xf6
    [<ffffffff816b5523>] enable_device+0xdb/0x393
    [<ffffffff812ed278>] acpiphp_enable_slot+0xcb/0x130
    [<ffffffff812ed454>] acpiphp_check_bridge+0x6e/0xd4
    [<ffffffff812ed812>] _handle_hotplug_event_bridge+0xc8/0x218
    [<ffffffff810d8463>] process_one_work+0x1cb/0x2dd
    [<ffffffff810d8936>] worker_thread+0x12f/0x1fc
    [<ffffffff810dd519>] kthread+0xac/0xb4
    [<ffffffff816cbd2c>] ret_from_fork+0x7c/0xb0
    [<ffffffffffffffff>] 0xffffffffffffffff
unreferenced object 0xffff880407f59988 (size 16):
  comm "kworker/0:0", pid 4, jiffies 4294958111 (age 27864.510s)
  hex dump (first 16 bytes):
    30 30 30 30 3a 31 31 3a 30 30 2e 30 00 6b 6b a5  0000:11:00.0.kk.
  backtrace:
    [<ffffffff816b46ae>] kmemleak_alloc+0x21/0x3e
    [<ffffffff81162847>] slab_post_alloc_hook+0x28/0x2a
    [<ffffffff81165ccf>] __kmalloc_track_caller+0xdd/0x118
    [<ffffffff812c2727>] kvasprintf+0x4b/0x74
    [<ffffffff812b916d>] kobject_set_name_vargs+0x21/0x56
    [<ffffffff813e6e44>] dev_set_name+0x3c/0x3e
    [<ffffffff812d951b>] pci_setup_device+0xfc/0x3b5
    [<ffffffff816b473a>] pci_scan_single_device+0x6f/0x99
    [<ffffffff812d9972>] pci_scan_slot+0x52/0xf6
    [<ffffffff816b5523>] enable_device+0xdb/0x393
    [<ffffffff812ed278>] acpiphp_enable_slot+0xcb/0x130
    [<ffffffff812ed454>] acpiphp_check_bridge+0x6e/0xd4
    [<ffffffff812ed812>] _handle_hotplug_event_bridge+0xc8/0x218
    [<ffffffff810d8463>] process_one_work+0x1cb/0x2dd
    [<ffffffff810d8936>] worker_thread+0x12f/0x1fc
    [<ffffffff810dd519>] kthread+0xac/0xb4
unreferenced object 0xffff880404403370 (size 64):
  comm "kworker/0:0", pid 4, jiffies 4294958111 (age 27864.510s)
  hex dump (first 32 bytes):
    00 00 00 00 00 00 00 00 90 18 24 09 04 88 ff ff  ..........$.....
    10 00 00 00 0e 00 00 00 00 00 00 00 00 00 00 00  ................
  backtrace:
    [<ffffffff816b46ae>] kmemleak_alloc+0x21/0x3e
    [<ffffffff81162847>] slab_post_alloc_hook+0x28/0x2a
    [<ffffffff81164702>] __kmalloc+0xde/0x118
    [<ffffffff812dbc16>] kzalloc.constprop.32+0xe/0x10
    [<ffffffff812dbcb4>] pci_add_cap_save_buffer.part.16+0x1f/0x62
    [<ffffffff812dd825>] pci_allocate_cap_save_buffers+0x29/0x82
    [<ffffffff812d9877>] pci_device_add+0xa3/0x14c
    [<ffffffff816b4756>] pci_scan_single_device+0x8b/0x99
    [<ffffffff812d9972>] pci_scan_slot+0x52/0xf6
    [<ffffffff816b5523>] enable_device+0xdb/0x393
    [<ffffffff812ed278>] acpiphp_enable_slot+0xcb/0x130
    [<ffffffff812ed454>] acpiphp_check_bridge+0x6e/0xd4
    [<ffffffff812ed812>] _handle_hotplug_event_bridge+0xc8/0x218
    [<ffffffff810d8463>] process_one_work+0x1cb/0x2dd
    [<ffffffff810d8936>] worker_thread+0x12f/0x1fc
    [<ffffffff810dd519>] kthread+0xac/0xb4
unreferenced object 0xffff8804044008c0 (size 256):
  comm "kworker/0:0", pid 4, jiffies 4294958111 (age 27864.510s)
  hex dump (first 32 bytes):
    05 05 00 00 ad 4e ad de ff ff ff ff 00 00 00 00  .....N..........
    ff ff ff ff ff ff ff ff f8 89 6d 82 ff ff ff ff  ..........m.....
  backtrace:
    [<ffffffff816b46ae>] kmemleak_alloc+0x21/0x3e
    [<ffffffff81162847>] slab_post_alloc_hook+0x28/0x2a
    [<ffffffff811648c9>] kmem_cache_alloc+0xb0/0xc0
    [<ffffffff813e7f6e>] device_private_init+0x1b/0x68
    [<ffffffff813e8006>] device_add+0x4b/0x5d2
    [<ffffffff812d98fb>] pci_device_add+0x127/0x14c
    [<ffffffff816b4756>] pci_scan_single_device+0x8b/0x99
    [<ffffffff812d9972>] pci_scan_slot+0x52/0xf6
    [<ffffffff816b5523>] enable_device+0xdb/0x393
    [<ffffffff812ed278>] acpiphp_enable_slot+0xcb/0x130
    [<ffffffff812ed454>] acpiphp_check_bridge+0x6e/0xd4
    [<ffffffff812ed812>] _handle_hotplug_event_bridge+0xc8/0x218
    [<ffffffff810d8463>] process_one_work+0x1cb/0x2dd
    [<ffffffff810d8936>] worker_thread+0x12f/0x1fc
    [<ffffffff810dd519>] kthread+0xac/0xb4
    [<ffffffff816cbd2c>] ret_from_fork+0x7c/0xb0
unreferenced object 0xffff880409243048 (size 4096):
  comm "kworker/0:0", pid 4, jiffies 4294961501 (age 27830.610s)
  hex dump (first 32 bytes):
    00 01 10 00 00 00 ad de 00 02 20 00 00 00 ad de  .......... .....
    38 69 f5 0c 04 88 ff ff 00 00 00 00 00 00 00 00  8i..............
  backtrace:
    [<ffffffff816b46ae>] kmemleak_alloc+0x21/0x3e
    [<ffffffff81162847>] slab_post_alloc_hook+0x28/0x2a
    [<ffffffff811648c9>] kmem_cache_alloc+0xb0/0xc0
    [<ffffffff812d8baa>] alloc_pci_dev+0x15/0x2e
    [<ffffffff816b4714>] pci_scan_single_device+0x49/0x99
    [<ffffffff812d9972>] pci_scan_slot+0x52/0xf6
    [<ffffffff816b5523>] enable_device+0xdb/0x393
    [<ffffffff812ed278>] acpiphp_enable_slot+0xcb/0x130
    [<ffffffff812ed454>] acpiphp_check_bridge+0x6e/0xd4
    [<ffffffff812ed812>] _handle_hotplug_event_bridge+0xc8/0x218
    [<ffffffff810d8463>] process_one_work+0x1cb/0x2dd
    [<ffffffff810d8936>] worker_thread+0x12f/0x1fc
    [<ffffffff810dd519>] kthread+0xac/0xb4
    [<ffffffff816cbd2c>] ret_from_fork+0x7c/0xb0
    [<ffffffffffffffff>] 0xffffffffffffffff
unreferenced object 0xffff880407f594d8 (size 16):
  comm "kworker/0:0", pid 4, jiffies 4294961501 (age 27830.610s)
  hex dump (first 16 bytes):
    30 30 30 30 3a 31 31 3a 30 30 2e 30 00 6b 6b a5  0000:11:00.0.kk.
  backtrace:
    [<ffffffff816b46ae>] kmemleak_alloc+0x21/0x3e
    [<ffffffff81162847>] slab_post_alloc_hook+0x28/0x2a
    [<ffffffff81165ccf>] __kmalloc_track_caller+0xdd/0x118
    [<ffffffff812c2727>] kvasprintf+0x4b/0x74
    [<ffffffff812b916d>] kobject_set_name_vargs+0x21/0x56
    [<ffffffff813e6e44>] dev_set_name+0x3c/0x3e
    [<ffffffff812d951b>] pci_setup_device+0xfc/0x3b5
    [<ffffffff816b473a>] pci_scan_single_device+0x6f/0x99
    [<ffffffff812d9972>] pci_scan_slot+0x52/0xf6
    [<ffffffff816b5523>] enable_device+0xdb/0x393
    [<ffffffff812ed278>] acpiphp_enable_slot+0xcb/0x130
    [<ffffffff812ed454>] acpiphp_check_bridge+0x6e/0xd4
    [<ffffffff812ed812>] _handle_hotplug_event_bridge+0xc8/0x218
    [<ffffffff810d8463>] process_one_work+0x1cb/0x2dd
    [<ffffffff810d8936>] worker_thread+0x12f/0x1fc
    [<ffffffff810dd519>] kthread+0xac/0xb4
unreferenced object 0xffff8804095f1f78 (size 64):
  comm "kworker/0:0", pid 4, jiffies 4294961501 (age 27830.610s)
  hex dump (first 32 bytes):
    00 00 00 00 00 00 00 00 c0 38 24 09 04 88 ff ff  .........8$.....
    10 00 00 00 0e 00 00 00 00 00 00 00 00 00 00 00  ................
  backtrace:
    [<ffffffff816b46ae>] kmemleak_alloc+0x21/0x3e
    [<ffffffff81162847>] slab_post_alloc_hook+0x28/0x2a
    [<ffffffff81164702>] __kmalloc+0xde/0x118
    [<ffffffff812dbc16>] kzalloc.constprop.32+0xe/0x10
    [<ffffffff812dbcb4>] pci_add_cap_save_buffer.part.16+0x1f/0x62
    [<ffffffff812dd825>] pci_allocate_cap_save_buffers+0x29/0x82
    [<ffffffff812d9877>] pci_device_add+0xa3/0x14c
    [<ffffffff816b4756>] pci_scan_single_device+0x8b/0x99
    [<ffffffff812d9972>] pci_scan_slot+0x52/0xf6
    [<ffffffff816b5523>] enable_device+0xdb/0x393
    [<ffffffff812ed278>] acpiphp_enable_slot+0xcb/0x130
    [<ffffffff812ed454>] acpiphp_check_bridge+0x6e/0xd4
    [<ffffffff812ed812>] _handle_hotplug_event_bridge+0xc8/0x218
    [<ffffffff810d8463>] process_one_work+0x1cb/0x2dd
    [<ffffffff810d8936>] worker_thread+0x12f/0x1fc
    [<ffffffff810dd519>] kthread+0xac/0xb4
unreferenced object 0xffff8804044009d8 (size 256):
  comm "kworker/0:0", pid 4, jiffies 4294961501 (age 27830.620s)
  hex dump (first 32 bytes):
    05 05 00 00 ad 4e ad de ff ff ff ff 00 00 00 00  .....N..........
    ff ff ff ff ff ff ff ff f8 89 6d 82 ff ff ff ff  ..........m.....
  backtrace:
    [<ffffffff816b46ae>] kmemleak_alloc+0x21/0x3e
    [<ffffffff81162847>] slab_post_alloc_hook+0x28/0x2a
    [<ffffffff811648c9>] kmem_cache_alloc+0xb0/0xc0
    [<ffffffff813e7f6e>] device_private_init+0x1b/0x68
    [<ffffffff813e8006>] device_add+0x4b/0x5d2
    [<ffffffff812d98fb>] pci_device_add+0x127/0x14c
    [<ffffffff816b4756>] pci_scan_single_device+0x8b/0x99
    [<ffffffff812d9972>] pci_scan_slot+0x52/0xf6
    [<ffffffff816b5523>] enable_device+0xdb/0x393
    [<ffffffff812ed278>] acpiphp_enable_slot+0xcb/0x130
    [<ffffffff812ed454>] acpiphp_check_bridge+0x6e/0xd4
    [<ffffffff812ed812>] _handle_hotplug_event_bridge+0xc8/0x218
    [<ffffffff810d8463>] process_one_work+0x1cb/0x2dd
    [<ffffffff810d8936>] worker_thread+0x12f/0x1fc
    [<ffffffff810dd519>] kthread+0xac/0xb4
    [<ffffffff816cbd2c>] ret_from_fork+0x7c/0xb0
unreferenced object 0xffff880409245078 (size 4096):
  comm "kworker/0:0", pid 4, jiffies 4294965008 (age 27795.550s)
  hex dump (first 32 bytes):
    00 01 10 00 00 00 ad de 00 02 20 00 00 00 ad de  .......... .....
    38 69 f5 0c 04 88 ff ff 00 00 00 00 00 00 00 00  8i..............
  backtrace:
    [<ffffffff816b46ae>] kmemleak_alloc+0x21/0x3e
    [<ffffffff81162847>] slab_post_alloc_hook+0x28/0x2a
    [<ffffffff811648c9>] kmem_cache_alloc+0xb0/0xc0
    [<ffffffff812d8baa>] alloc_pci_dev+0x15/0x2e
    [<ffffffff816b4714>] pci_scan_single_device+0x49/0x99
    [<ffffffff812d9972>] pci_scan_slot+0x52/0xf6
    [<ffffffff816b5523>] enable_device+0xdb/0x393
    [<ffffffff812ed278>] acpiphp_enable_slot+0xcb/0x130
    [<ffffffff812ed454>] acpiphp_check_bridge+0x6e/0xd4
    [<ffffffff812ed812>] _handle_hotplug_event_bridge+0xc8/0x218
    [<ffffffff810d8463>] process_one_work+0x1cb/0x2dd
    [<ffffffff810d8936>] worker_thread+0x12f/0x1fc
    [<ffffffff810dd519>] kthread+0xac/0xb4
    [<ffffffff816cbd2c>] ret_from_fork+0x7c/0xb0
    [<ffffffffffffffff>] 0xffffffffffffffff
unreferenced object 0xffff880407f59500 (size 16):
  comm "kworker/0:0", pid 4, jiffies 4294965008 (age 27795.550s)
  hex dump (first 16 bytes):
    30 30 30 30 3a 31 31 3a 30 30 2e 30 00 6b 6b a5  0000:11:00.0.kk.
  backtrace:
    [<ffffffff816b46ae>] kmemleak_alloc+0x21/0x3e
    [<ffffffff81162847>] slab_post_alloc_hook+0x28/0x2a
    [<ffffffff81165ccf>] __kmalloc_track_caller+0xdd/0x118
    [<ffffffff812c2727>] kvasprintf+0x4b/0x74
    [<ffffffff812b916d>] kobject_set_name_vargs+0x21/0x56
    [<ffffffff813e6e44>] dev_set_name+0x3c/0x3e
    [<ffffffff812d951b>] pci_setup_device+0xfc/0x3b5
    [<ffffffff816b473a>] pci_scan_single_device+0x6f/0x99
    [<ffffffff812d9972>] pci_scan_slot+0x52/0xf6
    [<ffffffff816b5523>] enable_device+0xdb/0x393
    [<ffffffff812ed278>] acpiphp_enable_slot+0xcb/0x130
    [<ffffffff812ed454>] acpiphp_check_bridge+0x6e/0xd4
    [<ffffffff812ed812>] _handle_hotplug_event_bridge+0xc8/0x218
    [<ffffffff810d8463>] process_one_work+0x1cb/0x2dd
    [<ffffffff810d8936>] worker_thread+0x12f/0x1fc
    [<ffffffff810dd519>] kthread+0xac/0xb4
unreferenced object 0xffff8804095f19a0 (size 64):
  comm "kworker/0:0", pid 4, jiffies 4294965008 (age 27795.550s)
  hex dump (first 32 bytes):
    00 00 00 00 00 00 00 00 f0 58 24 09 04 88 ff ff  .........X$.....
    10 00 00 00 0e 00 00 00 00 00 00 00 00 00 00 00  ................
  backtrace:
    [<ffffffff816b46ae>] kmemleak_alloc+0x21/0x3e
    [<ffffffff81162847>] slab_post_alloc_hook+0x28/0x2a
    [<ffffffff81164702>] __kmalloc+0xde/0x118
    [<ffffffff812dbc16>] kzalloc.constprop.32+0xe/0x10
    [<ffffffff812dbcb4>] pci_add_cap_save_buffer.part.16+0x1f/0x62
    [<ffffffff812dd825>] pci_allocate_cap_save_buffers+0x29/0x82
    [<ffffffff812d9877>] pci_device_add+0xa3/0x14c
    [<ffffffff816b4756>] pci_scan_single_device+0x8b/0x99
    [<ffffffff812d9972>] pci_scan_slot+0x52/0xf6
    [<ffffffff816b5523>] enable_device+0xdb/0x393
    [<ffffffff812ed278>] acpiphp_enable_slot+0xcb/0x130
    [<ffffffff812ed454>] acpiphp_check_bridge+0x6e/0xd4
    [<ffffffff812ed812>] _handle_hotplug_event_bridge+0xc8/0x218
    [<ffffffff810d8463>] process_one_work+0x1cb/0x2dd
    [<ffffffff810d8936>] worker_thread+0x12f/0x1fc
    [<ffffffff810dd519>] kthread+0xac/0xb4
unreferenced object 0xffff880404400460 (size 256):
  comm "kworker/0:0", pid 4, jiffies 4294965008 (age 27795.550s)
  hex dump (first 32 bytes):
    04 04 00 00 ad 4e ad de ff ff ff ff 00 00 00 00  .....N..........
    ff ff ff ff ff ff ff ff f8 89 6d 82 ff ff ff ff  ..........m.....
  backtrace:
    [<ffffffff816b46ae>] kmemleak_alloc+0x21/0x3e
    [<ffffffff81162847>] slab_post_alloc_hook+0x28/0x2a
    [<ffffffff811648c9>] kmem_cache_alloc+0xb0/0xc0
    [<ffffffff813e7f6e>] device_private_init+0x1b/0x68
    [<ffffffff813e8006>] device_add+0x4b/0x5d2
    [<ffffffff812d98fb>] pci_device_add+0x127/0x14c
    [<ffffffff816b4756>] pci_scan_single_device+0x8b/0x99
    [<ffffffff812d9972>] pci_scan_slot+0x52/0xf6
    [<ffffffff816b5523>] enable_device+0xdb/0x393
    [<ffffffff812ed278>] acpiphp_enable_slot+0xcb/0x130
    [<ffffffff812ed454>] acpiphp_check_bridge+0x6e/0xd4
    [<ffffffff812ed812>] _handle_hotplug_event_bridge+0xc8/0x218
    [<ffffffff810d8463>] process_one_work+0x1cb/0x2dd
    [<ffffffff810d8936>] worker_thread+0x12f/0x1fc
    [<ffffffff810dd519>] kthread+0xac/0xb4
    [<ffffffff816cbd2c>] ret_from_fork+0x7c/0xb0
unreferenced object 0xffff88040af38860 (size 512):
  comm "kworker/0:0", pid 4, jiffies 4294965009 (age 27795.540s)
  hex dump (first 32 bytes):
    10 51 24 09 04 88 ff ff 06 00 00 00 00 00 00 00  .Q$.............
    00 95 f5 07 04 88 ff ff 01 00 00 04 ff ff ff ff  ................
  backtrace:
    [<ffffffff816b46ae>] kmemleak_alloc+0x21/0x3e
    [<ffffffff81162847>] slab_post_alloc_hook+0x28/0x2a
    [<ffffffff81164702>] __kmalloc+0xde/0x118
    [<ffffffff81449d90>] usb_create_shared_hcd+0x30/0x206
    [<ffffffff81474363>] xhci_pci_probe+0x5a/0xd1
    [<ffffffff812df27e>] local_pci_probe+0x39/0x61
    [<ffffffff812df4a6>] pci_device_probe+0xba/0xe0
    [<ffffffff813ea752>] driver_probe_device+0x99/0x1c7
    [<ffffffff813ea914>] __device_attach+0x25/0x38
    [<ffffffff813e8d6f>] bus_for_each_drv+0x4f/0x8b
    [<ffffffff813ea67c>] device_attach+0x66/0x87
    [<ffffffff812d828b>] pci_bus_add_device+0x32/0x54
    [<ffffffff812d83d6>] pci_bus_add_devices+0x29/0x7d
    [<ffffffff816b577c>] enable_device+0x334/0x393
    [<ffffffff812ed278>] acpiphp_enable_slot+0xcb/0x130
    [<ffffffff812ed454>] acpiphp_check_bridge+0x6e/0xd4
unreferenced object 0xffff8804095e0000 (size 4096):
  comm "kworker/0:0", pid 4, jiffies 4294977262 (age 27673.040s)
  hex dump (first 32 bytes):
    00 01 10 00 00 00 ad de 00 02 20 00 00 00 ad de  .......... .....
    38 69 f5 0c 04 88 ff ff 00 00 00 00 00 00 00 00  8i..............
  backtrace:
    [<ffffffff816b46ae>] kmemleak_alloc+0x21/0x3e
    [<ffffffff81162847>] slab_post_alloc_hook+0x28/0x2a
    [<ffffffff811648c9>] kmem_cache_alloc+0xb0/0xc0
    [<ffffffff812d8baa>] alloc_pci_dev+0x15/0x2e
    [<ffffffff816b4714>] pci_scan_single_device+0x49/0x99
    [<ffffffff812d9972>] pci_scan_slot+0x52/0xf6
    [<ffffffff816b5523>] enable_device+0xdb/0x393
    [<ffffffff812ed278>] acpiphp_enable_slot+0xcb/0x130
    [<ffffffff812ed454>] acpiphp_check_bridge+0x6e/0xd4
    [<ffffffff812ed812>] _handle_hotplug_event_bridge+0xc8/0x218
    [<ffffffff810d8463>] process_one_work+0x1cb/0x2dd
    [<ffffffff810d8936>] worker_thread+0x12f/0x1fc
    [<ffffffff810dd519>] kthread+0xac/0xb4
    [<ffffffff816cbd2c>] ret_from_fork+0x7c/0xb0
    [<ffffffffffffffff>] 0xffffffffffffffff
unreferenced object 0xffff8804077e8460 (size 16):
  comm "kworker/0:0", pid 4, jiffies 4294977262 (age 27673.040s)
  hex dump (first 16 bytes):
    30 30 30 30 3a 31 31 3a 30 30 2e 30 00 6b 6b a5  0000:11:00.0.kk.
  backtrace:
    [<ffffffff816b46ae>] kmemleak_alloc+0x21/0x3e
    [<ffffffff81162847>] slab_post_alloc_hook+0x28/0x2a
    [<ffffffff81165ccf>] __kmalloc_track_caller+0xdd/0x118
    [<ffffffff812c2727>] kvasprintf+0x4b/0x74
    [<ffffffff812b916d>] kobject_set_name_vargs+0x21/0x56
    [<ffffffff813e6e44>] dev_set_name+0x3c/0x3e
    [<ffffffff812d951b>] pci_setup_device+0xfc/0x3b5
    [<ffffffff816b473a>] pci_scan_single_device+0x6f/0x99
    [<ffffffff812d9972>] pci_scan_slot+0x52/0xf6
    [<ffffffff816b5523>] enable_device+0xdb/0x393
    [<ffffffff812ed278>] acpiphp_enable_slot+0xcb/0x130
    [<ffffffff812ed454>] acpiphp_check_bridge+0x6e/0xd4
    [<ffffffff812ed812>] _handle_hotplug_event_bridge+0xc8/0x218
    [<ffffffff810d8463>] process_one_work+0x1cb/0x2dd
    [<ffffffff810d8936>] worker_thread+0x12f/0x1fc
    [<ffffffff810dd519>] kthread+0xac/0xb4
unreferenced object 0xffff880401d98478 (size 64):
  comm "kworker/0:0", pid 4, jiffies 4294977262 (age 27673.040s)
  hex dump (first 32 bytes):
    00 00 00 00 00 00 00 00 78 08 5e 09 04 88 ff ff  ........x.^.....
    10 00 00 00 0e 00 00 00 00 00 00 00 00 00 00 00  ................
  backtrace:
    [<ffffffff816b46ae>] kmemleak_alloc+0x21/0x3e
    [<ffffffff81162847>] slab_post_alloc_hook+0x28/0x2a
    [<ffffffff81164702>] __kmalloc+0xde/0x118
    [<ffffffff812dbc16>] kzalloc.constprop.32+0xe/0x10
    [<ffffffff812dbcb4>] pci_add_cap_save_buffer.part.16+0x1f/0x62
    [<ffffffff812dd825>] pci_allocate_cap_save_buffers+0x29/0x82
    [<ffffffff812d9877>] pci_device_add+0xa3/0x14c
    [<ffffffff816b4756>] pci_scan_single_device+0x8b/0x99
    [<ffffffff812d9972>] pci_scan_slot+0x52/0xf6
    [<ffffffff816b5523>] enable_device+0xdb/0x393
    [<ffffffff812ed278>] acpiphp_enable_slot+0xcb/0x130
    [<ffffffff812ed454>] acpiphp_check_bridge+0x6e/0xd4
    [<ffffffff812ed812>] _handle_hotplug_event_bridge+0xc8/0x218
    [<ffffffff810d8463>] process_one_work+0x1cb/0x2dd
    [<ffffffff810d8936>] worker_thread+0x12f/0x1fc
    [<ffffffff810dd519>] kthread+0xac/0xb4
unreferenced object 0xffff880404574c08 (size 256):
  comm "kworker/0:0", pid 4, jiffies 4294977262 (age 27673.040s)
  hex dump (first 32 bytes):
    04 04 00 00 ad 4e ad de ff ff ff ff 00 00 00 00  .....N..........
    ff ff ff ff ff ff ff ff f8 89 6d 82 ff ff ff ff  ..........m.....
  backtrace:
    [<ffffffff816b46ae>] kmemleak_alloc+0x21/0x3e
    [<ffffffff81162847>] slab_post_alloc_hook+0x28/0x2a
    [<ffffffff811648c9>] kmem_cache_alloc+0xb0/0xc0
    [<ffffffff813e7f6e>] device_private_init+0x1b/0x68
    [<ffffffff813e8006>] device_add+0x4b/0x5d2
    [<ffffffff812d98fb>] pci_device_add+0x127/0x14c
    [<ffffffff816b4756>] pci_scan_single_device+0x8b/0x99
    [<ffffffff812d9972>] pci_scan_slot+0x52/0xf6
    [<ffffffff816b5523>] enable_device+0xdb/0x393
    [<ffffffff812ed278>] acpiphp_enable_slot+0xcb/0x130
    [<ffffffff812ed454>] acpiphp_check_bridge+0x6e/0xd4
    [<ffffffff812ed812>] _handle_hotplug_event_bridge+0xc8/0x218
    [<ffffffff810d8463>] process_one_work+0x1cb/0x2dd
    [<ffffffff810d8936>] worker_thread+0x12f/0x1fc
    [<ffffffff810dd519>] kthread+0xac/0xb4
    [<ffffffff816cbd2c>] ret_from_fork+0x7c/0xb0
unreferenced object 0xffff88040afd8218 (size 512):
  comm "kworker/0:0", pid 4, jiffies 4294977263 (age 27673.030s)
  hex dump (first 32 bytes):
    98 00 5e 09 04 88 ff ff 06 00 00 00 00 00 00 00  ..^.............
    60 84 7e 07 04 88 ff ff 01 00 00 04 ff ff ff ff  `.~.............
  backtrace:
    [<ffffffff816b46ae>] kmemleak_alloc+0x21/0x3e
    [<ffffffff81162847>] slab_post_alloc_hook+0x28/0x2a
    [<ffffffff81164702>] __kmalloc+0xde/0x118
    [<ffffffff81449d90>] usb_create_shared_hcd+0x30/0x206
    [<ffffffff81474363>] xhci_pci_probe+0x5a/0xd1
    [<ffffffff812df27e>] local_pci_probe+0x39/0x61
    [<ffffffff812df4a6>] pci_device_probe+0xba/0xe0
    [<ffffffff813ea752>] driver_probe_device+0x99/0x1c7
    [<ffffffff813ea914>] __device_attach+0x25/0x38
    [<ffffffff813e8d6f>] bus_for_each_drv+0x4f/0x8b
    [<ffffffff813ea67c>] device_attach+0x66/0x87
    [<ffffffff812d828b>] pci_bus_add_device+0x32/0x54
    [<ffffffff812d83d6>] pci_bus_add_devices+0x29/0x7d
    [<ffffffff816b577c>] enable_device+0x334/0x393
    [<ffffffff812ed278>] acpiphp_enable_slot+0xcb/0x130
    [<ffffffff812ed454>] acpiphp_check_bridge+0x6e/0xd4
unreferenced object 0xffff88040a19f4f0 (size 512):
  comm "kworker/0:1", pid 3682, jiffies 4294983122 (age 27614.440s)
  hex dump (first 32 bytes):
    c8 20 24 09 04 88 ff ff 06 00 00 00 00 00 00 00  . $.............
    a8 87 7e 07 04 88 ff ff 01 00 00 04 ff ff ff ff  ..~.............
  backtrace:
    [<ffffffff816b46ae>] kmemleak_alloc+0x21/0x3e
    [<ffffffff81162847>] slab_post_alloc_hook+0x28/0x2a
    [<ffffffff81164702>] __kmalloc+0xde/0x118
    [<ffffffff81449d90>] usb_create_shared_hcd+0x30/0x206
    [<ffffffff81474363>] xhci_pci_probe+0x5a/0xd1
    [<ffffffff812df27e>] local_pci_probe+0x39/0x61
    [<ffffffff812df4a6>] pci_device_probe+0xba/0xe0
    [<ffffffff813ea752>] driver_probe_device+0x99/0x1c7
    [<ffffffff813ea914>] __device_attach+0x25/0x38
    [<ffffffff813e8d6f>] bus_for_each_drv+0x4f/0x8b
    [<ffffffff813ea67c>] device_attach+0x66/0x87
    [<ffffffff812d828b>] pci_bus_add_device+0x32/0x54
    [<ffffffff812d83d6>] pci_bus_add_devices+0x29/0x7d
    [<ffffffff816b577c>] enable_device+0x334/0x393
    [<ffffffff812ed278>] acpiphp_enable_slot+0xcb/0x130
    [<ffffffff812ed454>] acpiphp_check_bridge+0x6e/0xd4

Re: 3.8.2: stale pci device info for a previously inserted express card

[Martin Mokrejs]

Martin Mokrejs wrote:
> Hi everybody,
> 
> Bjorn Helgaas wrote:
>> [+cc linux-pci, Sarah, Alan]
>>
>> On Mon, Mar 11, 2013 at 10:02 AM, Martin Mokrejs
>> <mmokrejs@fold.natur.cuni.cz> wrote:
>>> [re-sending to you all three directly, looks the original email did not make it into linux-pci
>>> through some filters]
>>>
>>>   I use for my daily work acpiphp to manage express cards in Dell Vostro 3550.
>>> I have never seen something like this before and believe this is some new regression
>>> in 3.8 series. I had in teh a USB3 card and ejected it. Then I inserted a
>>> SATA Sil3132 card but it is not detected and dmesg still ends with last lines
>>> added when the USB card was being removed. The funny thing is that lspci reports
>>> a mixture of USB-card properties with NEC chips along with Silicon Image eSATA card.
>>
>> I don't know anything about the kmemleaks mentioned elsewhere in this
>> thread, but the idea of "stale PCI device info" seems possibly related
>> to some acpiphp issues we've been working on recently.
>>
>> Starting with v3.9, we don't handle ACPI Bus Check notifications to
>> host bridges correctly, and the result is that when we're using
>> acpiphp, we don't notice when PCI devices are added or removed. There
>> are more details in https://bugzilla.kernel.org/show_bug.cgi?id=57961
> 
> Looks to me it is already in 3.10-rc4 which I tested now. No, I still do see
> same problem like before: a hotremoval of NEC-based xHCI express card is detected
> on every second eject. But, sometimes it seems it is only delayed by some 25-30
> seconds. Would have to do more testing. However, there are some *new* kmemleaks
> reported by kernel related to acpiphpp bu xhci_hcd. That could a hint why
> the hotremoval sometimes proceeds delayed but sometimes maybe not at all or at
> least not *immediately* like for any other device?
> 
> However, the stale sysfs entries for partially removed device SiI3132 (sata_sil24
> driver) are NOT appearing anymore, good. That used to be associated with
> 'sata_sil24: IRQ status == 0xffffffff, PCI fault or device removal?' line.
> Now, I see under 3.10-rc4 the extra message about 'ACPI: Device does not support D3cold'.
> would be nice if it said what device is it talking about? About upstream root port
> or about my end device (express card)? Is it related by pcie_aspm= kernel
> commandline option? If yes, please include the relevant info the message text.
> referring to this being affected by the particular value. At the moment I used:
> pcie_aspm=off
> 
> --- dmesg_initial__inserted_eSATA__ejected__inserted__ejected__inserted.txt     2013-06-07 02:53:56.000000000 +0200
> +++ dmesg_initial__inserted_eSATA__ejected__inserted__ejected__inserted__ejected.txt    2013-06-07 02:54:09.000000000 +0200
> @@ -1439,3 +1439,5 @@
>  [  254.317365] ata12: SATA max UDMA/100 host m128@0xf6c04000 port 0xf6c02000 irq 19
>  [  256.400454] ata11: SATA link down (SStatus 0 SControl 0)
>  [  258.493027] ata12: SATA link down (SStatus 0 SControl 0)
> +[  267.116723] sata_sil24: IRQ status == 0xffffffff, PCI fault or device removal?
> +[  267.117779] ACPI: Device does not support D3cold
> 
> 
> So, in my eyes the "stale pci info" issue is fixed in 3.10-rc4 at least under acpiphp and pcie_aspm=off.

And to be even more exact, I had CONFIG_HOTPLUG_PCI_ACPI=y as I see now an updated
v2 patch from Yinghai:
[PATCH v3.9 stable] PCI: acpiphp: Re-enumerate devices when host bridge receives Bus Check

Please make sure that whatever I tested in plain 3.10-rc4 is what you had in those bugzilla patches
under https://bugzilla.kernel.org/show_bug.cgi?id=57961 or what Yinghai posted as an update.
Just in case are tested a different version.

Martin

Re: 3.8.2: stale pci device info for a previously inserted express card

[Martin Mokrejs]

Martin Mokrejs wrote:
> Martin Mokrejs wrote:
>> Hi everybody,
>>
>> Bjorn Helgaas wrote:
>>> [+cc linux-pci, Sarah, Alan]
>>>
>>> On Mon, Mar 11, 2013 at 10:02 AM, Martin Mokrejs
>>> <mmokrejs@fold.natur.cuni.cz> wrote:
>>>> [re-sending to you all three directly, looks the original email did not make it into linux-pci
>>>> through some filters]
>>>>
>>>>   I use for my daily work acpiphp to manage express cards in Dell Vostro 3550.
>>>> I have never seen something like this before and believe this is some new regression
>>>> in 3.8 series. I had in teh a USB3 card and ejected it. Then I inserted a
>>>> SATA Sil3132 card but it is not detected and dmesg still ends with last lines
>>>> added when the USB card was being removed. The funny thing is that lspci reports
>>>> a mixture of USB-card properties with NEC chips along with Silicon Image eSATA card.
>>>
>>> I don't know anything about the kmemleaks mentioned elsewhere in this
>>> thread, but the idea of "stale PCI device info" seems possibly related
>>> to some acpiphp issues we've been working on recently.
>>>
>>> Starting with v3.9, we don't handle ACPI Bus Check notifications to
>>> host bridges correctly, and the result is that when we're using
>>> acpiphp, we don't notice when PCI devices are added or removed. There
>>> are more details in https://bugzilla.kernel.org/show_bug.cgi?id=57961
>>
>> Looks to me it is already in 3.10-rc4 which I tested now. No, I still do see
>> same problem like before: a hotremoval of NEC-based xHCI express card is detected
>> on every second eject. But, sometimes it seems it is only delayed by some 25-30
>> seconds. Would have to do more testing. However, there are some *new* kmemleaks
>> reported by kernel related to acpiphpp bu xhci_hcd. That could a hint why
>> the hotremoval sometimes proceeds delayed but sometimes maybe not at all or at
>> least not *immediately* like for any other device?
>>
>> However, the stale sysfs entries for partially removed device SiI3132 (sata_sil24
>> driver) are NOT appearing anymore, good. That used to be associated with
>> 'sata_sil24: IRQ status == 0xffffffff, PCI fault or device removal?' line.
>> Now, I see under 3.10-rc4 the extra message about 'ACPI: Device does not support D3cold'.
>> would be nice if it said what device is it talking about? About upstream root port
>> or about my end device (express card)? Is it related by pcie_aspm= kernel
>> commandline option? If yes, please include the relevant info the message text.
>> referring to this being affected by the particular value. At the moment I used:
>> pcie_aspm=off
>>
>> --- dmesg_initial__inserted_eSATA__ejected__inserted__ejected__inserted.txt     2013-06-07 02:53:56.000000000 +0200
>> +++ dmesg_initial__inserted_eSATA__ejected__inserted__ejected__inserted__ejected.txt    2013-06-07 02:54:09.000000000 +0200
>> @@ -1439,3 +1439,5 @@
>>  [  254.317365] ata12: SATA max UDMA/100 host m128@0xf6c04000 port 0xf6c02000 irq 19
>>  [  256.400454] ata11: SATA link down (SStatus 0 SControl 0)
>>  [  258.493027] ata12: SATA link down (SStatus 0 SControl 0)
>> +[  267.116723] sata_sil24: IRQ status == 0xffffffff, PCI fault or device removal?
>> +[  267.117779] ACPI: Device does not support D3cold
>>
>>
>> So, in my eyes the "stale pci info" issue is fixed in 3.10-rc4 at least under acpiphp and pcie_aspm=off.

No, it is not. :(

> 
> And to be even more exact, I had CONFIG_HOTPLUG_PCI_ACPI=y as I see now an updated
> v2 patch from Yinghai:
> [PATCH v3.9 stable] PCI: acpiphp: Re-enumerate devices when host bridge receives Bus Check
> 
> Please make sure that whatever I tested in plain 3.10-rc4 is what you had in those bugzilla patches
> under https://bugzilla.kernel.org/show_bug.cgi?id=57961 or what Yinghai posted as an update.
> Just in case are tested a different version.


Sorry, I was "able" to plugin a firewire card into express card slot faster
than xhci_hcd released resource of the to be yet hotremoved NEC-based xHCI
card. So, like in older kernels, lspci reports chimeric entry 11:00 of the
NEC card and of the VIA-based firewire card. Upon eject of the VIA card
xhci_hcd released resources with usual messages, including the complaint
that 'xhci_hcd 0000:11:00.0: Host not halted after 16000 microseconds.'
Nothing new in dmesg, I would just say that whatever makes xhci_hcd or pcieport
slow in turning PME# to disabled is efectively blocked if I plugin some card back
into the express slot. It seems to me the "conclusion" in the past in Jan-April
was that pcieport is to blame and not xhci_hcd, and it always seemed to proceed
smoothly once 'PME# disabled' appeared in dmesg.



> 
> Martin
> --
> To unsubscribe from this list: send the line "unsubscribe linux-pci" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html
> 
> 

Re: 3.8.2: stale pci device info for a previously inserted express card

[Alan Stern]

On Mon, 11 Mar 2013, Martin Mokrejs wrote:

> Alan Stern wrote:
> > On Mon, 11 Mar 2013, Martin Mokrejs wrote:
> > 
> >>> Did you check to see if there were any hung processes?
> >>
> >> I did not reboot yet. What commands?
> > 
> > Alt-SysRq-W from a VT console.
> 
> Attached.

No processes are hung up.  So much for that idea.

Alan Stern

Re: 3.8.2: stale pci device info for a previously inserted express card

[Alan Stern]

On Mon, 11 Mar 2013, Martin Mokrejs wrote:

> Hi,
>   I use for my daily work acpiphp to manage express cards in Dell Vostro 3550.
> I have never seen something like this before and believe this is some new regression
> in 3.8 series. I had in teh a USB3 card and ejected it. Then I inserted a
> SATA Sil3132 card but it is not detected and dmesg still ends with last lines
> added when the USB card was being removed. The funny thing is that lspci reports
> a mixture of USB-card properties with NEC chips along with Silicon Image eSATA card.

...

When did you run this lspci command?  After inserting the SATA card?

Did you check to see if there were any hung processes?

>   I think as a guide you can take the kmemleak report showing that USB did not
> release its resources completely? Did I screw something with having USB HID generic
> driver?

Is this repeatable?  It would be more meaningful to see a kmemleak
report for immediately after the USB-3 card is removed.  The leak may
be related to these two lines in the log (they occurred only once):

[ 8768.825242] xhci_hcd 0000:11:00.0: Abort command ring failed
[ 8768.825244] xhci_hcd 0000:11:00.0: HC died; cleaning up

Perhaps cleaning up after a dead controller doesn't deallocate all that
it should.  Quite possibly this is connected with the fact that on this
attempt, you removed the USB-3 card while the WD disk drive was plugged
into it.

Alan Stern

Re: 3.8.2: stale pci device info for a previously inserted express card

[Martin Mokrejs]

Hi Alan,

Alan Stern wrote:
> On Mon, 11 Mar 2013, Martin Mokrejs wrote:
> 
>> Hi,
>>   I use for my daily work acpiphp to manage express cards in Dell Vostro 3550.
>> I have never seen something like this before and believe this is some new regression
>> in 3.8 series. I had in the a USB3 card and ejected it. Then I inserted a
>> SATA Sil3132 card but it is not detected and dmesg still ends with last lines
>> added when the USB card was being removed. The funny thing is that lspci reports
>> a mixture of USB-card properties with NEC chips along with Silicon Image eSATA card.
> 
> ...
> 
> When did you run this lspci command?  After inserting the SATA card?

Yes, because I did not see anything new the eSATA being picked up in dmesg.

> 
> Did you check to see if there were any hung processes?

I did not reboot yet. What commands?

> 
>>   I think as a guide you can take the kmemleak report showing that USB did not
>> release its resources completely? Did I screw something with having USB HID generic
>> driver?
> 
> Is this repeatable?  It would be more meaningful to see a kmemleak

No idea, saw it for the first time. Nobody ever told me whether kmemleak is
able to report the leak immediately or whether that is some background process
which is always lagging, by definition. If the latter is true, it could be
I have meanwhile done something else (popped in or out another card). Until
I know what to expect I am just lost with what I see logged.

> report for immediately after the USB-3 card is removed.  The leak may
> be related to these two lines in the log (they occurred only once):
> 
> [ 8768.825242] xhci_hcd 0000:11:00.0: Abort command ring failed
> [ 8768.825244] xhci_hcd 0000:11:00.0: HC died; cleaning up
> 
> Perhaps cleaning up after a dead controller doesn't deallocate all that
> it should.  Quite possibly this is connected with the fact that on this
> attempt, you removed the USB-3 card while the WD disk drive was plugged
> into it.

I am not that skilled but I believe somebody could help me to provide you
with the current time value in the epoch way to translate two lines
  comm "kworker/0:1", pid 675, jiffies 4295795189 (age 58365.960s)
  comm "kworker/0:1", pid 675, jiffies 4295809367 (age 58224.180s)
into human date. Same for the timestamps in dmesg output.

Well, from the

[ 8770.143509] usb usb6: bus auto-suspend, wakeup 1
[ 8770.243135] hub 5-0:1.0: state 7 ports 2 chg 0002 evt 0000
[ 8770.243168] hub 5-0:1.0: port 1, status 0101, change 0000, 12 Mb/s
[ 8770.362933] usb 5-1: new high-speed USB device number 2 using xhci_hcd
[ 8770.385501] usb 5-1: skipped 1 descriptor after interface
[ 8770.386048] usb 5-1: default language 0x0409
[ 8770.387954] usb 5-1: udev 2, busnum 5, minor = 513
[ 8770.387956] usb 5-1: New USB device found, idVendor=13fd, idProduct=0550
[ 8770.387958] usb 5-1: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[ 8770.387959] usb 5-1: Product: WD3200BEVE-00A0H
[ 8770.387960] usb 5-1: Manufacturer: Initio  
[ 8770.387961] usb 5-1: SerialNumber: 00101005500011B80
[ 8770.388445] usb 5-1: usb_probe_device
[ 8770.388447] usb 5-1: configuration #1 chosen from 1 choice
[ 8770.388906] usb 5-1: Successful Endpoint Configure command
[ 8770.389186] usb 5-1: adding 5-1:1.0 (config #1, interface 0)
[ 8770.389442] usb-storage 5-1:1.0: usb_probe_interface
[ 8770.389445] usb-storage 5-1:1.0: usb_probe_interface - got id
[ 8770.389627] scsi7 : usb-storage 5-1:1.0
[ 8770.390563] usb 5-1: adding 5-1:1.1 (config #1, interface 1)
[ 8770.390783] usbhid 5-1:1.1: usb_probe_interface
[ 8770.390784] usbhid 5-1:1.1: usb_probe_interface - got id
[ 8770.393386] usbhid 5-1:1.1: looking for a minor, starting at 0
[ 8770.394586] hid-generic 0003:13FD:0550.0004: hiddev0,hidraw2: USB HID v1.10 Device [Initio   WD3200BEVE-00A0H] on usb-0000:11:00.0-1/input1
[ 8771.382843] scsi 7:0:0:0: Direct-Access     Initio   WD3200BEVE-00A0H 3.12 PQ: 0 ANSI: 0
[ 8771.384510] sd 7:0:0:0: Attached scsi generic sg2 type 0
[ 8771.385463] sd 7:0:0:0: [sdb] 625142448 512-byte logical blocks: (320 GB/298 GiB)
[ 8771.386350] sd 7:0:0:0: [sdb] Write Protect is off
[ 8771.386353] sd 7:0:0:0: [sdb] Mode Sense: 86 0b 00 02
[ 8771.387198] sd 7:0:0:0: [sdb] No Caching mode page present
[ 8771.387200] sd 7:0:0:0: [sdb] Assuming drive cache: write through
[ 8771.392420] sd 7:0:0:0: [sdb] No Caching mode page present
[ 8771.392423] sd 7:0:0:0: [sdb] Assuming drive cache: write through
[ 8771.405239]  sdb: sdb1
[ 8771.411001] sd 7:0:0:0: [sdb] No Caching mode page present
[ 8771.411002] sd 7:0:0:0: [sdb] Assuming drive cache: write through
[ 8771.411006] sd 7:0:0:0: [sdb] Attached SCSI disk
[ 9893.877224] kmemleak: 1 new suspected memory leaks (see /sys/kernel/debug/kmemleak)
[11735.840095] kmemleak: 1 new suspected memory leaks (see /sys/kernel/debug/kmemleak)
[16849.168366] hub 5-0:1.0: state 7 ports 2 chg 0000 evt 0002
[16849.168467] hub 5-0:1.0: port 1, status 0100, change 0001, 12 Mb/s
[16849.168470] usb 5-1: USB disconnect, device number 2
[16849.168472] usb 5-1: unregistering device
[16849.168473] usb 5-1: unregistering interface 5-1:1.0
[16849.172371] usb 5-1: unregistering interface 5-1:1.1
[16849.172594] usbhid 5-1:1.1: removing 0 minor
[16849.173256] usb 5-1: usb_disable_device nuking all URBs
[16849.173843] usb 5-1: Successful Endpoint Configure command
[16849.336164] hub 5-0:1.0: debounce: port 1: total 100ms stable 100ms status 0x100

I bet both kmemleaks happened before I ejected the USB card (at about [16849.168366]).
But why the two kmemleak lines are so much lagging after any previous log lines
I don't know but I am repeating here myself. The system is 99% idle. What process
shoudl I be looking for? Or you mean some SysRq magic?

Martin

Re: 3.8.2: stale pci device info for a previously inserted express card

[Alan Stern]

On Mon, 11 Mar 2013, Martin Mokrejs wrote:

> > Did you check to see if there were any hung processes?
> 
> I did not reboot yet. What commands?

Alt-SysRq-W from a VT console.

> > Is this repeatable?  It would be more meaningful to see a kmemleak
> 
> No idea, saw it for the first time. Nobody ever told me whether kmemleak is
> able to report the leak immediately or whether that is some background process
> which is always lagging, by definition. If the latter is true, it could be
> I have meanwhile done something else (popped in or out another card). Until
> I know what to expect I am just lost with what I see logged.

kmemleak is described in the Documentation directory.  As I understand
it, there is a background process which wakes up from time to time and
looks for leaks, and there is a way to ask it to wake up and look
whenever you want.

> > report for immediately after the USB-3 card is removed.  The leak may
> > be related to these two lines in the log (they occurred only once):
> > 
> > [ 8768.825242] xhci_hcd 0000:11:00.0: Abort command ring failed
> > [ 8768.825244] xhci_hcd 0000:11:00.0: HC died; cleaning up
> > 
> > Perhaps cleaning up after a dead controller doesn't deallocate all that
> > it should.  Quite possibly this is connected with the fact that on this
> > attempt, you removed the USB-3 card while the WD disk drive was plugged
> > into it.
> 
> I am not that skilled but I believe somebody could help me to provide you
> with the current time value in the epoch way to translate two lines
>   comm "kworker/0:1", pid 675, jiffies 4295795189 (age 58365.960s)
>   comm "kworker/0:1", pid 675, jiffies 4295809367 (age 58224.180s)
> into human date. Same for the timestamps in dmesg output.

Those values probably wouldn't mean much.  In fact, I don't see how the 
process's age (58365 seconds) could be larger than the time since 
boot-up (either 9893 or 11735 seconds).

> Well, from the

...
> [ 9893.877224] kmemleak: 1 new suspected memory leaks (see /sys/kernel/debug/kmemleak)
> [11735.840095] kmemleak: 1 new suspected memory leaks (see /sys/kernel/debug/kmemleak)
...
> 
> I bet both kmemleaks happened before I ejected the USB card (at about [16849.168366]).

I suspect they happened during the eject at about 8763 -- that's when 
the "HC died" message occurred.

> But why the two kmemleak lines are so much lagging after any previous log lines
> I don't know but I am repeating here myself. The system is 99% idle. What process
> shoudl I be looking for? Or you mean some SysRq magic?

Read Documentation/kmemleak.txt.

Alan Stern

Re: 3.8.2: stale pci device info for a previously inserted express card

[Sarah Sharp]

On Mon, Mar 11, 2013 at 11:26:26AM -0400, Alan Stern wrote:
> On Mon, 11 Mar 2013, Martin Mokrejs wrote:
> 
> > Hi,
> >   I use for my daily work acpiphp to manage express cards in Dell Vostro 3550.
> > I have never seen something like this before and believe this is some new regression
> > in 3.8 series. I had in teh a USB3 card and ejected it. Then I inserted a
> > SATA Sil3132 card but it is not detected and dmesg still ends with last lines
> > added when the USB card was being removed. The funny thing is that lspci reports
> > a mixture of USB-card properties with NEC chips along with Silicon Image eSATA card.
> 
> ...
> 
> When did you run this lspci command?  After inserting the SATA card?
> 
> Did you check to see if there were any hung processes?
> 
> >   I think as a guide you can take the kmemleak report showing that USB did not
> > release its resources completely? Did I screw something with having USB HID generic
> > driver?
> 
> Is this repeatable?  It would be more meaningful to see a kmemleak
> report for immediately after the USB-3 card is removed.  The leak may
> be related to these two lines in the log (they occurred only once):
> 
> [ 8768.825242] xhci_hcd 0000:11:00.0: Abort command ring failed
> [ 8768.825244] xhci_hcd 0000:11:00.0: HC died; cleaning up
> 
> Perhaps cleaning up after a dead controller doesn't deallocate all that
> it should.  Quite possibly this is connected with the fact that on this
> attempt, you removed the USB-3 card while the WD disk drive was plugged
> into it.

I have a note to myself that the xHCI driver leaks memory on an endpoint
stall, but I can't remember exactly where.  It's possible that the
device stalled, and the host died before we could clean it up.  It's
also possible that the memory leak is somewhere else entirely.

Sarah Sharp

Re: 3.8.2: stale pci device info for a previously inserted express card

[Alan Stern]

On Mon, 11 Mar 2013, Sarah Sharp wrote:

> > Is this repeatable?  It would be more meaningful to see a kmemleak
> > report for immediately after the USB-3 card is removed.  The leak may
> > be related to these two lines in the log (they occurred only once):
> > 
> > [ 8768.825242] xhci_hcd 0000:11:00.0: Abort command ring failed
> > [ 8768.825244] xhci_hcd 0000:11:00.0: HC died; cleaning up
> > 
> > Perhaps cleaning up after a dead controller doesn't deallocate all that
> > it should.  Quite possibly this is connected with the fact that on this
> > attempt, you removed the USB-3 card while the WD disk drive was plugged
> > into it.
> 
> I have a note to myself that the xHCI driver leaks memory on an endpoint
> stall, but I can't remember exactly where.  It's possible that the
> device stalled, and the host died before we could clean it up.  It's
> also possible that the memory leak is somewhere else entirely.

I don't think this memory leak has anything to do with endpoints.  
Martin's kmemleak report indicated that the memory was originally
allocated near the start of usb_create_shared_hcd(), which means it was
a whole usb_hcd structure.

Alan Stern