Message-ID: <CANK3SE0SWLpnETpwVZsM2BRsH8jfOt59=fBLf8JshwRVPVOOYw@mail.gmail.com>
Date:	Wed, 30 Jan 2013 23:43:26 +0000
From:	Mark Einon <mark.einon@...il.com>
To:	Stefan Richter <stefanr@...6.in-berlin.de>
Cc:	linux1394-devel@...ts.sourceforge.net,
	linux-kernel@...r.kernel.org, linux-pm@...r.kernel.org
Subject: Re: [PATCH] firewire: Fix ohci free_irq() warning

On 29 January 2013 16:04, Stefan Richter <stefanr@...6.in-berlin.de> wrote:
> Added Cc: linux-pm.
>
> On Jan 29 Mark Einon wrote:
>> On 28 January 2013 23:01, Stefan Richter <stefanr@...6.in-berlin.de> wrote:
>> > On Jan 28 Mark Einon wrote:
>> >> This patch fixes the kernel warning generated when putting an MSI MS-1727
>> >> GT740 laptop into suspend mode. The call sequence in this case calls
>> >> free_irq() twice, once in pci_remove() and once then in pci_suspend().
>> >
>> > You mean /first/ in pci_suspend() and /then/ in pci_remove() on the
>> > already suspended devices, right?
>>
>> Yes, I did. The call sequence is suspend then resume. My bad.

Correction above : s/resume/remove

>>
>> >
>> > Because the other way around, first pci_remove(), then pci_suspend(),
>> > surely must not appen.  And if it does, the bug is elsewhere but not in
>> > firewire-ohci.
>> >
>> > On that note, is pci_suspend() -> pci_remove() actually a legal state
>> > transition that must be handled by drivers?
>>
>> It's happening on the Ubuntu 12.10 distro which performs the suspend
>> then remove sequence. I assumed that was normal.
>
> Maybe a parent device (PCI bridge or the likes) of the OHCI is
> requested to be removed during suspend or is being removed during
> resume, thereby causing a removal request to the OHCI?
>
> Or the suspend method of firewire-ohci exited with an error return code...
> but then the suspend sequence would be rolled back, not the offending
> device be removed, right?
>
> In any case, could you check the dmesg right before the warning which you
> already posted --- and right after it too --- whether there is an
> indication what else was going on?

It looks like the remove call actually happens on the wakeup sequence
- although I've not yet found the time to investigate further. The
lines preceding the crash are:

Jan 30 23:22:53 msilap kernel: [ 7682.288190] ACPI: Low-level resume complete
Jan 30 23:22:53 msilap kernel: [ 7682.288228] PM: Restoring platform NVS memory
Jan 30 23:22:53 msilap kernel: [ 7682.288644] Enabling non-boot CPUs ...
Jan 30 23:22:53 msilap kernel: [ 7682.288713] smpboot: Booting Node 0
Processor 1 APIC 0x2
Jan 30 23:22:53 msilap kernel: [ 7682.301963] hpet: hpet3 irq 41 for MSI
Jan 30 23:22:53 msilap kernel: [ 7682.301978] CPU1 is up
Jan 30 23:22:53 msilap kernel: [ 7682.302040] smpboot: Booting Node 0
Processor 2 APIC 0x4
Jan 30 23:22:53 msilap kernel: [ 7682.315394] hpet: hpet4 irq 42 for MSI
Jan 30 23:22:53 msilap kernel: [ 7682.315408] CPU2 is up
Jan 30 23:22:53 msilap kernel: [ 7682.315470] smpboot: Booting Node 0
Processor 3 APIC 0x6
Jan 30 23:22:53 msilap kernel: [ 7682.328815] hpet: hpet5 irq 43 for MSI
Jan 30 23:22:53 msilap kernel: [ 7682.328828] CPU3 is up
Jan 30 23:22:53 msilap kernel: [ 7682.328882] smpboot: Booting Node 0
Processor 4 APIC 0x1
Jan 30 23:22:53 msilap kernel: [ 7682.342256] hpet: hpet6 irq 44 for MSI
Jan 30 23:22:53 msilap kernel: [ 7682.342269] CPU4 is up
Jan 30 23:22:53 msilap kernel: [ 7682.342327] smpboot: Booting Node 0
Processor 5 APIC 0x3
Jan 30 23:22:53 msilap kernel: [ 7682.355737] CPU5 is up
Jan 30 23:22:53 msilap kernel: [ 7682.355797] smpboot: Booting Node 0
Processor 6 APIC 0x5
Jan 30 23:22:53 msilap kernel: [ 7682.369213] CPU6 is up
Jan 30 23:22:53 msilap kernel: [ 7682.369272] smpboot: Booting Node 0
Processor 7 APIC 0x7
Jan 30 23:22:53 msilap kernel: [ 7682.382720] CPU7 is up
Jan 30 23:22:53 msilap kernel: [ 7682.388801] ACPI: Waking up from
system sleep state S3
Jan 30 23:22:53 msilap kernel: [ 7682.403997] ------------[ cut here
]------------
Jan 30 23:22:53 msilap kernel: [ 7682.404007] WARNING: at
/home/mark/Source/linux/kernel/irq/manage.c:1248
__free_irq+0xa3/0x1e0()
<snip>

then after the first crash trace:

Jan 30 23:22:53 msilap kernel: [ 7682.404181] ---[ end trace
1a4f0a37b1022aad ]---
Jan 30 23:22:53 msilap kernel: [ 7682.404211] firewire_ohci
0000:07:00.0: removed fw-ohci device
Jan 30 23:22:53 msilap kernel: [ 7682.404327] ------------[ cut here
]------------
Jan 30 23:22:53 msilap kernel: [ 7682.404330] WARNING: at
/home/mark/Source/linux/kernel/irq/manage.c:1248
__free_irq+0xa3/0x1e0()
Jan 30 23:22:53 msilap kernel: [ 7682.404330] Hardware name: MS-1727
Jan 30 23:22:53 msilap kernel: [ 7682.404331] Trying to free already-free IRQ 16
Jan 30 23:22:53 msilap kernel: [ 7682.404363] Modules linked in:
ip6table_filter ip6_tables ebtable_nat ebtables nf_conntrack_ipv4
nf_defrag_ipv4 xt_state nf_conntrack ipt_REJECT xt_CHECKSUM
iptable_mangle xt_tcpudp iptable_filter bnep rfcomm ip_tables
bluetooth x_tables bridge stp llc parport_pc ppdev binfmt_misc arc4
nouveau iwldvm mac80211 snd_hda_codec_hdmi snd_hda_codec_realtek
snd_hda_intel snd_hda_codec iwlwifi coretemp kvm_intel snd_hwdep kvm
snd_pcm ttm cfg80211 snd_seq_midi snd_rawmidi drm_kms_helper
snd_seq_midi_event drm snd_seq snd_timer snd_seq_device joydev snd
microcode i7core_edac i2c_algo_bit psmouse soundcore edac_core
jmb38x_ms msi_wmi serio_raw video memstick mxm_wmi lpc_ich
sparse_keymap mac_hid wmi snd_page_alloc acpiphp lp parport r8169
firewire_ohci(O) sdhci_pci firewire_core(O) sdhci crc_itu_t
Jan 30 23:22:53 msilap kernel: [ 7682.404365] Pid: 5968, comm:
kworker/0:2 Tainted: G        W  O 3.8.0-rc5-next-20130128+ #6
Jan 30 23:22:53 msilap kernel: [ 7682.404366] Call Trace:
Jan 30 23:22:53 msilap kernel: [ 7682.404369]  [<ffffffff810589af>]
warn_slowpath_common+0x7f/0xc0
Jan 30 23:22:53 msilap kernel: [ 7682.404371]  [<ffffffff81058aa6>]
warn_slowpath_fmt+0x46/0x50
Jan 30 23:22:53 msilap kernel: [ 7682.404374]  [<ffffffff81044c69>] ?
default_spin_lock_flags+0x9/0x10
Jan 30 23:22:53 msilap kernel: [ 7682.404376]  [<ffffffff810eabc3>]
__free_irq+0xa3/0x1e0
Jan 30 23:22:53 msilap kernel: [ 7682.404378]  [<ffffffff810ead54>]
free_irq+0x54/0xc0
Jan 30 23:22:53 msilap kernel: [ 7682.404384]  [<ffffffffa000968a>]
sdhci_remove_host+0x6a/0x190 [sdhci]
Jan 30 23:22:53 msilap kernel: [ 7682.404389]  [<ffffffffa002f3ff>]
sdhci_pci_remove_slot+0x4f/0xc0 [sdhci_pci]
Jan 30 23:22:53 msilap kernel: [ 7682.404394]  [<ffffffffa002fa70>]
sdhci_pci_remove+0x50/0xa0 [sdhci_pci]
Jan 30 23:22:53 msilap kernel: [ 7682.404398]  [<ffffffff8137ff26>]
pci_device_remove+0x46/0xc0
Jan 30 23:22:53 msilap kernel: [ 7682.404402]  [<ffffffff81456f3c>]
__device_release_driver+0x7c/0xe0
Jan 30 23:22:53 msilap kernel: [ 7682.404404]  [<ffffffff814571ac>]
device_release_driver+0x2c/0x40
Jan 30 23:22:53 msilap kernel: [ 7682.404406]  [<ffffffff814569b1>]
bus_remove_device+0xe1/0x120
Jan 30 23:22:53 msilap kernel: [ 7682.404409]  [<ffffffff8145403a>]
device_del+0x11a/0x1b0
Jan 30 23:22:53 msilap kernel: [ 7682.404411]  [<ffffffff81379d94>]
pci_stop_bus_device+0x94/0xa0
Jan 30 23:22:53 msilap kernel: [ 7682.404414]  [<ffffffff81379f36>]
pci_stop_and_remove_bus_device+0x16/0x30
Jan 30 23:22:53 msilap kernel: [ 7682.404419]  [<ffffffffa0028b36>]
acpiphp_disable_slot+0xf6/0x1a0 [acpiphp]
Jan 30 23:22:53 msilap kernel: [ 7682.404424]  [<ffffffffa0027716>] ?
get_slot_status+0x46/0xc0 [acpiphp]
Jan 30 23:22:53 msilap kernel: [ 7682.404428]  [<ffffffffa0028c0d>]
acpiphp_check_bridge.isra.13+0x2d/0xf0 [acpiphp]
Jan 30 23:22:53 msilap kernel: [ 7682.404433]  [<ffffffffa0029247>]
_handle_hotplug_event_bridge+0x2e7/0x410 [acpiphp]
Jan 30 23:22:53 msilap kernel: [ 7682.404436]  [<ffffffff813bdc64>] ?
acpi_os_execute_deferred+0x2d/0x32
Jan 30 23:22:53 msilap kernel: [ 7682.404439]  [<ffffffff8117df25>] ?
kfree+0x105/0x140
Jan 30 23:22:53 msilap kernel: [ 7682.404441]  [<ffffffff81077249>]
process_one_work+0x159/0x4c0
Jan 30 23:22:53 msilap kernel: [ 7682.404444]  [<ffffffff8107895e>]
worker_thread+0x15e/0x4a0
Jan 30 23:22:53 msilap kernel: [ 7682.404446]  [<ffffffff81078800>] ?
manage_workers+0x2a0/0x2a0
Jan 30 23:22:53 msilap kernel: [ 7682.404448]  [<ffffffff8107df60>]
kthread+0xc0/0xd0
Jan 30 23:22:53 msilap kernel: [ 7682.404450]  [<ffffffff8107dea0>] ?
kthread_create_on_node+0x130/0x130
Jan 30 23:22:53 msilap kernel: [ 7682.404452]  [<ffffffff816d756c>]
ret_from_fork+0x7c/0xb0
Jan 30 23:22:53 msilap kernel: [ 7682.404454]  [<ffffffff8107dea0>] ?
kthread_create_on_node+0x130/0x130
Jan 30 23:22:53 msilap kernel: [ 7682.404456] ---[ end trace
1a4f0a37b1022aae ]---


>
> Also, what are the parent devices of the OHCI according to "lspci -tv" (or
> what else can show PCI topology)?

I ran 'lshw' on the machine, which may be of more use. The relevant
output is (removing parts not associated with the firewire device):

msilap
    description: Notebook
    product: MS-1727 (To be filled by O.E.M.)
    vendor: MICRO-STAR INTERNATIONAL CO., LTD
    version: REV:1.0
    serial: FFFFFFFF
    width: 64 bits
    capabilities: smbios-2.6 dmi-2.6 vsyscall32
    configuration: boot=normal chassis=notebook family=To be filled by
O.E.M. sku=To be filled by O.E.M.
uuid=00020003-0004-0005-0006-000700080009
  *-core
       description: Motherboard
       product: MS-1727
       vendor: MICRO-STAR INTERNATIONAL CO., LTD
       physical id: 0
       version: REV:1.0
       serial: BSS-0123456789
       slot: To be filled by O.E.M.
     *-pci:0
          description: Host bridge
          product: Core Processor DMI
          vendor: Intel Corporation
          physical id: 100
          bus info: pci@...0:00:00.0
          version: 11
          width: 32 bits
          clock: 33MHz
        *-pci:4
             description: PCI bridge
             product: 5 Series/3400 Series Chipset PCI Express Root Port 5
             vendor: Intel Corporation
             physical id: 1c.4
             bus info: pci@...0:00:1c.4
             version: 05
             width: 32 bits
             clock: 33MHz
             capabilities: pci pciexpress msi pm normal_decode
bus_master cap_list
             configuration: driver=pcieport
             resources: irq:16 ioport:9000(size=4096)
memory:d4600000-d59fffff ioport:d9d00000(size=2097152)
           *-firewire
                description: FireWire (IEEE 1394)
                product: IEEE 1394 Host Controller
                vendor: JMicron Technology Corp.
                physical id: 0
                bus info: pci@...0:07:00.0
                version: 00
                width: 32 bits
                clock: 33MHz
                capabilities: pm pciexpress msi ohci bus_master cap_list
                configuration: driver=firewire_ohci latency=0
                resources: irq:16 memory:d4607000-d46077ff
memory:d4606000-d460607f memory:d4605000-d460507f
memory:d4604000-d460407f
           *-generic:0
                description: System peripheral
                product: SD/MMC Host Controller
                vendor: JMicron Technology Corp.
                physical id: 0.1
                bus info: pci@...0:07:00.1
                version: 00
                width: 32 bits
                clock: 33MHz
                capabilities: pm pciexpress msi bus_master cap_list
                configuration: driver=sdhci-pci latency=0
                resources: irq:16 memory:d4603000-d46030ff
           *-generic:1 UNCLAIMED
                description: SD Host controller
                product: Standard SD Host Controller
                vendor: JMicron Technology Corp.
                physical id: 0.2
                bus info: pci@...0:07:00.2
                version: 00
                width: 32 bits
                clock: 33MHz
                capabilities: pm pciexpress msi cap_list
                configuration: latency=0
                resources: memory:d4602000-d46020ff
           *-generic:2
                description: System peripheral
                product: MS Host Controller
                vendor: JMicron Technology Corp.
                physical id: 0.3
                bus info: pci@...0:07:00.3
                version: 00
                width: 32 bits
                clock: 33MHz
                capabilities: pm pciexpress msi bus_master cap_list
                configuration: driver=jmb38x_ms latency=0
                resources: irq:16 memory:d4601000-d46010ff
           *-generic:3 UNCLAIMED
                description: System peripheral
                product: xD Host Controller
                vendor: JMicron Technology Corp.
                physical id: 0.4
                bus info: pci@...0:07:00.4
                version: 00
                width: 32 bits
                clock: 33MHz
                capabilities: pm pciexpress msi bus_master cap_list
                configuration: latency=0
                resources: memory:d4600000-d46000ff


>
>> > Another comment below.
>> <snip>
>> >
>> > firewire-ohci's pci_resume() calls request_irq() a little bit before that,
>> > in ohci_enable().  Is the sequence pci_probe/request_irq() ->
>> > pci_suspend/disable_irq() -> pci_resume/request_irq() ->
>> > pci_resume/enable_irq() legal?
>>
>> I missed the call to request_irq(). Perhaps the simplest way to handle
>> the fix would be to use a flag that holds the irq state? I'm open to
>> suggestions.
>
> Not sure what extent of state tracking the PCI core or driver core already
> offer; I'll have to look.
> --
> Stefan Richter
> -=====-===-= ---= ===-=
> http://arcgraph.de/sr/
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@...r.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

Powered by blists - more mailing lists