3.12: kernel panic when resuming from suspend to RAM (x86_64)

Today I got a different behaviour, after resuming I got a kernel panic. I could take a picture of the laptop screen:
http://imgur.com/f5uWFTY

Quoted 3 lines · Francis Moreau

Today I got a different behaviour, after resuming I got a kernel panic. I could take a picture of the laptop screen:
http://imgur.com/f5uWFTY

Does archlinux ship the upstream kernel or do they have patches ontop? If "yes" to the last one, try reproducing this panic with the upstream kernel 3.12.

In general, how reliably can you reproduce the kernel panic with the upstream 3.12 kernel?

AFAIK, the kernel has 2 simple patches on top of the vanilla one. They're both are trivial and can't be related to this issue.

You can have look to them here:
https://wiki.archlinux.org/index.php/Kernels#Official_packages

Assuming that I'm running an upstream kernel, it's almost 100% reproductible.

Quoted 5 lines · Francis Moreau

AFAIK, the kernel has 2 simple patches on top of the vanilla one. They're both are trivial and can't be related to this issue.

You can have look to them here:
https://wiki.archlinux.org/index.php/Kernels#Official_packages

Ok.

Quoted 2 lines

Assuming that I'm running an upstream kernel, it's almost 100% reproductible.

Is there any chance you can catch the whole oops, esp. keep the Code:
line complete?

Also, can you do:

$ objdump -d vmlinux | less

then search for 'call_timer_fn' and paste the whole function somewhere.

Also, can you catch a full dmesg and upload that somewhere too?

Sorry I haven't taken the original picture large enough, and getting this kernel panic is pretty hard since the kernel usually displays the black screen.

I can't find any traces of this function in the dump...

Quoted 3 lines · Francis Moreau

Sorry I haven't taken the original picture large enough, and getting this kernel panic is pretty hard since the kernel usually displays the black screen.

Ok, just try to make a readable picture of the whole line, next time you trigger it.

Quoted 1 line

I can't find any traces of this function in the dump...

Hmm, strange. Can you upload the whole vmlinux somewhere? Or is this the official archlinux kernel? If so, where can I get it from?

Quoted 10 lines · Borislav Petkov

Quoted 3 lines · Francis Moreau

Sorry I haven't taken the original picture large enough, and getting this kernel panic is pretty hard since the kernel usually displays the black screen.

Ok, just try to make a readable picture of the whole line, next time you trigger it.

Quoted 1 line

I can't find any traces of this function in the dump...

Quoted 2 lines

Hmm, strange. Can you upload the whole vmlinux somewhere? Or is this the official archlinux kernel? If so, where can I get it from?

Yes, you can download the bin package from :
https://www.archlinux.org/packages/core/x86_64/linux/

The bin package is a tar archive, so it pretty straightforward to unpack the vmlinux file (actual is filename vmlinuz-linux).

Quoted 11 lines · Francis Moreau

Quoted 10 lines · Borislav Petkov

Quoted 3 lines · Francis Moreau

Sorry I haven't taken the original picture large enough, and getting this kernel panic is pretty hard since the kernel usually displays the black screen.

Ok, just try to make a readable picture of the whole line, next time you trigger it.

Quoted 1 line

I can't find any traces of this function in the dump...

Quoted 8 lines

Quoted 2 lines

Hmm, strange. Can you upload the whole vmlinux somewhere? Or is this the official archlinux kernel? If so, where can I get it from?

Yes, you can download the bin package from :
https://www.archlinux.org/packages/core/x86_64/linux/

The bin package is a tar archive, so it pretty straightforward to unpack the vmlinux file (actual is filename vmlinuz-linux).

Ok, here's what I was able to see: rIP points to call_timer_fn+0x33 which is this:

ffffffff8106f590 <call_timer_fn>:

ffffffff8106f590:       e8 2b b2 48 00          callq  ffffffff814fa7c0 <__fentry__>
ffffffff8106f595:       55                      push   %rbp
ffffffff8106f596:       65 48 8b 04 25 70 c7    mov    %gs:0xc770,%rax
ffffffff8106f59d:       00 00 
ffffffff8106f59f:       48 89 e5                mov    %rsp,%rbp
ffffffff8106f5a2:       41 57                   push   %r15
ffffffff8106f5a4:       49 89 d7                mov    %rdx,%r15
ffffffff8106f5a7:       41 56                   push   %r14
ffffffff8106f5a9:       49 89 f6                mov    %rsi,%r14
ffffffff8106f5ac:       41 55                   push   %r13
ffffffff8106f5ae:       41 54                   push   %r12
ffffffff8106f5b0:       49 89 fc                mov    %rdi,%r12
ffffffff8106f5b3:       53                      push   %rbx
ffffffff8106f5b4:       44 8b a8 44 e0 ff ff    mov    -0x1fbc(%rax),%r13d
ffffffff8106f5bb:       0f 1f 44 00 00          nopl   0x0(%rax,%rax,1)
ffffffff8106f5c0:       4c 89 ff                mov    %r15,%rdi
ffffffff8106f5c3:       41 ff d6                callq  *%r14			<--- faulting insn
ffffffff8106f5c6:       0f 1f 44 00 00          nopl   0x0(%rax,%rax,1)
ffffffff8106f5cb:       65 48 8b 04 25 70 c7    mov    %gs:0xc770,%rax
ffffffff8106f5d2:       00 00 
ffffffff8106f5d4:       44 39 a8 44 e0 ff ff    cmp    %r13d,-0x1fbc(%rax)

and the virtual address in rIP is ffffffff8106f5c3, i.e. the same one as in the photo. Thus, the CALL instruction tries to call the timer function 'fn' which we pass as an argument to call_timer_fn.

However, the address we're trying to call in %r14 is garbage:
0x455300323d504544 and not in canonical form, causing the #GP.

So basically what happens is suspend to RAM corrupts something containing one or more timer functions and we end up calling crap after resume.

If you want to debug this further, you could try playing through Documentation/power/basic-pm-debugging.txt and see whether suspend to disk works. There's also a section 2 which talks about testing suspend to RAM which could be of help.

But let me add Rafael and Thomas - they should have much better ideas than me.

Guys, thread starts here:
http://marc.info/?l=linux-kernel&m=138468134321335

This looks like a softirq bug to me (and related to cpuidle).

I'm wondering if that happens with any of the older kernels or just 3.12?

Quoted 1 line · Rafael J. Wysocki

This looks like a softirq bug to me (and related to cpuidle).

Reportedly, it happens right after resume from RAM. Francis, is that correct?

Quoted 66 lines · Borislav Petkov

Quoted 11 lines · Francis Moreau

Quoted 10 lines · Borislav Petkov

Quoted 3 lines · Francis Moreau

Sorry I haven't taken the original picture large enough, and getting this kernel panic is pretty hard since the kernel usually displays the black screen.

Ok, just try to make a readable picture of the whole line, next time you trigger it.

Quoted 1 line

I can't find any traces of this function in the dump...

Quoted 8 lines

Quoted 2 lines

Hmm, strange. Can you upload the whole vmlinux somewhere? Or is this the official archlinux kernel? If so, where can I get it from?

Yes, you can download the bin package from :
https://www.archlinux.org/packages/core/x86_64/linux/

The bin package is a tar archive, so it pretty straightforward to unpack the vmlinux file (actual is filename vmlinuz-linux).

Ok, here's what I was able to see: rIP points to call_timer_fn+0x33 which is this:

ffffffff8106f590 <call_timer_fn>:

ffffffff8106f590:       e8 2b b2 48 00          callq  ffffffff814fa7c0 <__fentry__>
ffffffff8106f595:       55                      push   %rbp
ffffffff8106f596:       65 48 8b 04 25 70 c7    mov    %gs:0xc770,%rax
ffffffff8106f59d:       00 00 
ffffffff8106f59f:       48 89 e5                mov    %rsp,%rbp
ffffffff8106f5a2:       41 57                   push   %r15
ffffffff8106f5a4:       49 89 d7                mov    %rdx,%r15
ffffffff8106f5a7:       41 56                   push   %r14
ffffffff8106f5a9:       49 89 f6                mov    %rsi,%r14
ffffffff8106f5ac:       41 55                   push   %r13
ffffffff8106f5ae:       41 54                   push   %r12
ffffffff8106f5b0:       49 89 fc                mov    %rdi,%r12
ffffffff8106f5b3:       53                      push   %rbx
ffffffff8106f5b4:       44 8b a8 44 e0 ff ff    mov    -0x1fbc(%rax),%r13d
ffffffff8106f5bb:       0f 1f 44 00 00          nopl   0x0(%rax,%rax,1)
ffffffff8106f5c0:       4c 89 ff                mov    %r15,%rdi
ffffffff8106f5c3:       41 ff d6                callq  *%r14			<--- faulting insn
ffffffff8106f5c6:       0f 1f 44 00 00          nopl   0x0(%rax,%rax,1)
ffffffff8106f5cb:       65 48 8b 04 25 70 c7    mov    %gs:0xc770,%rax
ffffffff8106f5d2:       00 00 
ffffffff8106f5d4:       44 39 a8 44 e0 ff ff    cmp    %r13d,-0x1fbc(%rax)

and the virtual address in rIP is ffffffff8106f5c3, i.e. the same one as in the photo. Thus, the CALL instruction tries to call the timer function 'fn' which we pass as an argument to call_timer_fn.

However, the address we're trying to call in %r14 is garbage:
0x455300323d504544 and not in canonical form, causing the #GP.

So basically what happens is suspend to RAM corrupts something containing one or more timer functions and we end up calling crap after resume.

If you want to debug this further, you could try playing through Documentation/power/basic-pm-debugging.txt and see whether suspend to disk works. There's also a section 2 which talks about testing suspend to RAM which could be of help.

But let me add Rafael and Thomas - they should have much better ideas than me.

Quoted 2 lines

Guys, thread starts here:
http://marc.info/?l=linux-kernel&m=138468134321335

This looks like a softirq bug to me (and related to cpuidle).

I'm wondering if that happens with any of the older kernels or just 3.12?

and the virtual address in rIP is ffffffff8106f5c3, i.e. the same one as in the photo. Thus, the CALL instruction tries to call the timer function 'fn' which we pass as an argument to call_timer_fn.

However, the address we're trying to call in %r14 is garbage:
0x455300323d504544 and not in canonical form, causing the #GP.

So basically what happens is suspend to RAM corrupts something containing one or more timer functions and we end up calling crap after resume.

That's part of an ASCII string, "DEP=2\0SE", so if that looks familiar to anyone (part of a kernel command line?) it might give a clue to where the timer callback pointer is being overwritten.

Quoted 3 lines · Kevin Easton

That's part of an ASCII string, "DEP=2\0SE", so if that looks familiar to anyone (part of a kernel command line?) it might give a clue to where the timer callback pointer is being overwritten.

Yeah, it could be anything, maybe even part of dmesg although nothing matches "DEP" in there.

Quoted 11 lines · Francis Moreau

Quoted 10 lines · Borislav Petkov

Quoted 3 lines · Francis Moreau

Sorry I haven't taken the original picture large enough, and getting this kernel panic is pretty hard since the kernel usually displays the black screen.

Ok, just try to make a readable picture of the whole line, next time you trigger it.

Quoted 1 line

I can't find any traces of this function in the dump...

Quoted 8 lines

Quoted 2 lines

Hmm, strange. Can you upload the whole vmlinux somewhere? Or is this the official archlinux kernel? If so, where can I get it from?

Yes, you can download the bin package from :
https://www.archlinux.org/packages/core/x86_64/linux/

The bin package is a tar archive, so it pretty straightforward to unpack the vmlinux file (actual is filename vmlinuz-linux).

Ok, here's what I was able to see: rIP points to call_timer_fn+0x33 which is this:

ffffffff8106f590 <call_timer_fn>:

ffffffff8106f590:       e8 2b b2 48 00          callq  ffffffff814fa7c0 <__fentry__>
ffffffff8106f595:       55                      push   %rbp
ffffffff8106f596:       65 48 8b 04 25 70 c7    mov    %gs:0xc770,%rax
ffffffff8106f59d:       00 00 
ffffffff8106f59f:       48 89 e5                mov    %rsp,%rbp
ffffffff8106f5a2:       41 57                   push   %r15
ffffffff8106f5a4:       49 89 d7                mov    %rdx,%r15
ffffffff8106f5a7:       41 56                   push   %r14
ffffffff8106f5a9:       49 89 f6                mov    %rsi,%r14
ffffffff8106f5ac:       41 55                   push   %r13
ffffffff8106f5ae:       41 54                   push   %r12
ffffffff8106f5b0:       49 89 fc                mov    %rdi,%r12
ffffffff8106f5b3:       53                      push   %rbx
ffffffff8106f5b4:       44 8b a8 44 e0 ff ff    mov    -0x1fbc(%rax),%r13d
ffffffff8106f5bb:       0f 1f 44 00 00          nopl   0x0(%rax,%rax,1)
ffffffff8106f5c0:       4c 89 ff                mov    %r15,%rdi
ffffffff8106f5c3:       41 ff d6                callq  *%r14			<--- faulting insn
ffffffff8106f5c6:       0f 1f 44 00 00          nopl   0x0(%rax,%rax,1)
ffffffff8106f5cb:       65 48 8b 04 25 70 c7    mov    %gs:0xc770,%rax
ffffffff8106f5d2:       00 00 
ffffffff8106f5d4:       44 39 a8 44 e0 ff ff    cmp    %r13d,-0x1fbc(%rax)

and the virtual address in rIP is ffffffff8106f5c3, i.e. the same one as in the photo. Thus, the CALL instruction tries to call the timer function 'fn' which we pass as an argument to call_timer_fn.

However, the address we're trying to call in %r14 is garbage:
0x455300323d504544 and not in canonical form, causing the #GP.

So basically what happens is suspend to RAM corrupts something containing one or more timer functions and we end up calling crap after resume.

If you want to debug this further, you could try playing through Documentation/power/basic-pm-debugging.txt and see whether suspend to disk works. There's also a section 2 which talks about testing suspend to RAM which could be of help.

Just out of curiosity, running "objdump -D" doesn't seem to show the same thing here. How did you get such dump with function names for example ?

The thing is that I'd like to avoid to oops my kernel to avoid to corrupt my filesystem.

Quoted 3 lines · Francis Moreau

Just out of curiosity, running "objdump -D" doesn't seem to show the same thing here. How did you get such dump with function names for example ?

There's another, non-stripped vmlinux in the kernel package:

$ objdump -D usr/src/linux-3.12.0-1-ARCH/vmlinux | less

Quoted 2 lines

The thing is that I'd like to avoid to oops my kernel to avoid to corrupt my filesystem.

Then debugging this thing would be very hard, if not impossible but it is your decision at the end of the day...

I think the easiest way to do it is to install a minimal system on a USB stick and try to reproduce first in order to preserve my system.

Then I'll try to see if this issue exists in a previous kernel version and if so, I'll do a git-bisect session.

I can't find a quicker way to do that although using git-bisect (which implies several kernel builds) is a PITA.

Quoted 2 lines · Francis Moreau

I think the easiest way to do it is to install a minimal system on a USB stick and try to reproduce first in order to preserve my system.

Yep, sounds simple enough.

Quoted 3 lines

Then I'll try to see if this issue exists in a previous kernel version and if so, I'll do a git-bisect session.

Quoted 2 lines

I can't find a quicker way to do that although using git-bisect (which implies several kernel builds) is a PITA.

You can start with a coarse bisect by testing the major kernel versions first, i.e. 3.11, 3.10, 3.9 ... and once you find good and bad, then you can do the git-bisect thing.

Unfortunately the bisect session didn't give any positive results: I couldn't be sure if a specific revision was good or bad because the bug wasn't reproductible every time.

But I got a different kernel oops on my stripped system that may give us a clue: http://imgur.com/zdCknbY

Does this help ?

Quoted 8 lines · Francis Moreau

Unfortunately the bisect session didn't give any positive results: I couldn't be sure if a specific revision was good or bad because the bug wasn't reproductible every time.

But I got a different kernel oops on my stripped system that may give us a clue: http://imgur.com/zdCknbY

Does this help ?

Unfortunately, this is the second oops:

and judging by the instruction, that's addr in %rdi which we try to read and I'd guess %rdi contains garbage after resume.

IOW, this looks like another corruption that happens when you suspend to ram.

I asked you already but you didn't say:

"Also, you can check for BIOS updates for your machine and if there are, check their changelogs whether they fix something suspend-related."

Hmm, I think it's more than that because if I'm removing both rtsx_pci_ms and memstick modules, then suspending and resuming doesn't oops anymore.

Also I took a look at the changes between v3.11 and v3.12 in this area and those changes match the issue I'm facing:

$ git log --oneline v3.11..v3.12 -- drivers/mfd/rtsx_pcr.c
09fd867 mfd: rtsx: Copyright modifications
eb891c6 mfd: rtsx: Configure to enter a deeper power-saving mode in S3
7140812 mfd: rtsx: Move some actions from rtsx_pci_init_hw to individual
extra_init_hw
5947c16 mfd: rtsx: Add shutdown callback in rtsx_pci_driver
773ccdf mfd: rtsx: Read vendor setting from config space

I'll try to bisect one more time those changes tonight to see if I can find out if one of those commits is the culprit.

Sorry for not answering the first time, but yes my bios is uptodate.

Quoted 3 lines · Francis Moreau

Hmm, I think it's more than that because if I'm removing both rtsx_pci_ms and memstick modules, then suspending and resuming doesn't oops anymore.

Interesting - so this is a good datapoint. Sounds like those modules can't stomach suspend-to-ram. So let's add a couple more people for comment.

To the newly-CCed, guys, thread starts here:

http://marc.info/?l=linux-kernel&m=138468134321335

Quoted 10 lines

Also I took a look at the changes between v3.11 and v3.12 in this area and those changes match the issue I'm facing:

$ git log --oneline v3.11..v3.12 -- drivers/mfd/rtsx_pcr.c
09fd867 mfd: rtsx: Copyright modifications
eb891c6 mfd: rtsx: Configure to enter a deeper power-saving mode in S3
7140812 mfd: rtsx: Move some actions from rtsx_pci_init_hw to individual
extra_init_hw
5947c16 mfd: rtsx: Add shutdown callback in rtsx_pci_driver
773ccdf mfd: rtsx: Read vendor setting from config space

Quoted 3 lines

I'll try to bisect one more time those changes tonight to see if I can find out if one of those commits is the culprit.

Good idea.

Quoted 1 line

Sorry for not answering the first time, but yes my bios is uptodate.

Ok, good.

--
Regards/Gruss,
Boris.

Sent from a fat crate under my desk. Formatting is fine. --

In my opinion, rtsx_pci_resume()/rtsx_pci_suspend() in realtek PCIe card reader driver may make the kernel panic.

I think that the commit "mfd: rtsx: Configure to enter a deeper power-saving mode in S3" may be the culprit.

Francis Moreau,
Let us know the exact model name of rts52xx PCIe card reader in your laptop? According to the commit, Wei WANG added S3 mode to rts5227 driver ,and rts5249 driver.

Quoted 11 lines

Quoted 11 lines

Also I took a look at the changes between v3.11 and v3.12 in this area and those changes match the issue I'm facing:

$ git log --oneline v3.11..v3.12 -- drivers/mfd/rtsx_pcr.c
09fd867 mfd: rtsx: Copyright modifications
eb891c6 mfd: rtsx: Configure to enter a deeper power-saving mode in S3
7140812 mfd: rtsx: Move some actions from rtsx_pci_init_hw to individual
extra_init_hw
5947c16 mfd: rtsx: Add shutdown callback in rtsx_pci_driver
773ccdf mfd: rtsx: Read vendor setting from config space

In my opinion, rtsx_pci_resume()/rtsx_pci_suspend() in realtek PCIe card reader driver may make the kernel panic.

I think that the commit "mfd: rtsx: Configure to enter a deeper power-saving mode in S3" may be the culprit.

Le 21/11/2013 12:17, Jingoo Han a écrit :
[...]

Quoted 12 lines

Quoted 11 lines

Quoted 11 lines

Also I took a look at the changes between v3.11 and v3.12 in this area and those changes match the issue I'm facing:

$ git log --oneline v3.11..v3.12 -- drivers/mfd/rtsx_pcr.c
09fd867 mfd: rtsx: Copyright modifications
eb891c6 mfd: rtsx: Configure to enter a deeper power-saving mode in S3
7140812 mfd: rtsx: Move some actions from rtsx_pci_init_hw to individual
extra_init_hw
5947c16 mfd: rtsx: Add shutdown callback in rtsx_pci_driver
773ccdf mfd: rtsx: Read vendor setting from config space

Quoted 5 lines

In my opinion, rtsx_pci_resume()/rtsx_pci_suspend() in realtek PCIe card reader driver may make the kernel panic.

I think that the commit "mfd: rtsx: Configure to enter a deeper power-saving mode in S3" may be the culprit.

Unfortunately no, reverting this commit on top of v3.12 doesn't help. I also reverted 7140812, 5947c16 but it didn't improve anything.

The good news is that I managed to have a "light" kernel configuration which is faster to build and more important it seems that the bug is almost 100% reproductible now.

So I'll try to do another git-bisect session later.

Quoted 20 lines · Francis Moreau

Le 21/11/2013 12:17, Jingoo Han a écrit :
[...]

Quoted 12 lines

Quoted 11 lines

Quoted 11 lines

Also I took a look at the changes between v3.11 and v3.12 in this area and those changes match the issue I'm facing:

$ git log --oneline v3.11..v3.12 -- drivers/mfd/rtsx_pcr.c
09fd867 mfd: rtsx: Copyright modifications
eb891c6 mfd: rtsx: Configure to enter a deeper power-saving mode in S3
7140812 mfd: rtsx: Move some actions from rtsx_pci_init_hw to individual
extra_init_hw
5947c16 mfd: rtsx: Add shutdown callback in rtsx_pci_driver
773ccdf mfd: rtsx: Read vendor setting from config space

Quoted 5 lines

In my opinion, rtsx_pci_resume()/rtsx_pci_suspend() in realtek PCIe card reader driver may make the kernel panic.

I think that the commit "mfd: rtsx: Configure to enter a deeper power-saving mode in S3" may be the culprit.

Quoted 8 lines

Unfortunately no, reverting this commit on top of v3.12 doesn't help. I also reverted 7140812, 5947c16 but it didn't improve anything.

The good news is that I managed to have a "light" kernel configuration which is faster to build and more important it seems that the bug is almost 100% reproductible now.

So I'll try to do another git-bisect session later.

So after bisecting between v3.11..v3.12 range, git bisect told me:

the first bad commit is 551f5c74e17ba9257cdc35bf657ee448cad2d5b0

Merge branch 'acpi-processor'

* acpi-processor:
ACPI / processor: Acquire writer lock to update CPU maps ACPI / processor: Remove acpi_processor_get_limit_info()

The two commits brought by the merge are not the culprits because reseting HEAD on "ACPI / processor: Acquire writer lock to update CPU maps" doesn't have the issue anymore.

At that point I'm not sure how to bisect futher.

Quoted 40 lines · Francis Moreau

Quoted 20 lines · Francis Moreau

Le 21/11/2013 12:17, Jingoo Han a écrit :
[...]

Quoted 12 lines

Quoted 11 lines

Quoted 11 lines

Also I took a look at the changes between v3.11 and v3.12 in this area and those changes match the issue I'm facing:

$ git log --oneline v3.11..v3.12 -- drivers/mfd/rtsx_pcr.c
09fd867 mfd: rtsx: Copyright modifications
eb891c6 mfd: rtsx: Configure to enter a deeper power-saving mode in S3
7140812 mfd: rtsx: Move some actions from rtsx_pci_init_hw to individual
extra_init_hw
5947c16 mfd: rtsx: Add shutdown callback in rtsx_pci_driver
773ccdf mfd: rtsx: Read vendor setting from config space

Quoted 5 lines

In my opinion, rtsx_pci_resume()/rtsx_pci_suspend() in realtek PCIe card reader driver may make the kernel panic.

I think that the commit "mfd: rtsx: Configure to enter a deeper power-saving mode in S3" may be the culprit.

Quoted 8 lines

Unfortunately no, reverting this commit on top of v3.12 doesn't help. I also reverted 7140812, 5947c16 but it didn't improve anything.

The good news is that I managed to have a "light" kernel configuration which is faster to build and more important it seems that the bug is almost 100% reproductible now.

So I'll try to do another git-bisect session later.

So after bisecting between v3.11..v3.12 range, git bisect told me:

the first bad commit is 551f5c74e17ba9257cdc35bf657ee448cad2d5b0

Merge branch 'acpi-processor'

* acpi-processor:
ACPI / processor: Acquire writer lock to update CPU maps ACPI / processor: Remove acpi_processor_get_limit_info()

Quoted 5 lines

The two commits brought by the merge are not the culprits because reseting HEAD on "ACPI / processor: Acquire writer lock to update CPU maps" doesn't have the issue anymore.

At that point I'm not sure how to bisect futher.

Does the second parent of this merge (that is, 8462d9df9d50) have the problem?

Quoted 41 lines · Rafael J. Wysocki

Quoted 40 lines · Francis Moreau

Quoted 20 lines · Francis Moreau

Le 21/11/2013 12:17, Jingoo Han a écrit :
[...]

Quoted 12 lines

Quoted 11 lines

Quoted 11 lines

Also I took a look at the changes between v3.11 and v3.12 in this area and those changes match the issue I'm facing:

$ git log --oneline v3.11..v3.12 -- drivers/mfd/rtsx_pcr.c
09fd867 mfd: rtsx: Copyright modifications
eb891c6 mfd: rtsx: Configure to enter a deeper power-saving mode in S3
7140812 mfd: rtsx: Move some actions from rtsx_pci_init_hw to individual
extra_init_hw
5947c16 mfd: rtsx: Add shutdown callback in rtsx_pci_driver
773ccdf mfd: rtsx: Read vendor setting from config space

Quoted 5 lines

In my opinion, rtsx_pci_resume()/rtsx_pci_suspend() in realtek PCIe card reader driver may make the kernel panic.

I think that the commit "mfd: rtsx: Configure to enter a deeper power-saving mode in S3" may be the culprit.

Quoted 8 lines

Unfortunately no, reverting this commit on top of v3.12 doesn't help. I also reverted 7140812, 5947c16 but it didn't improve anything.

The good news is that I managed to have a "light" kernel configuration which is faster to build and more important it seems that the bug is almost 100% reproductible now.

So I'll try to do another git-bisect session later.

So after bisecting between v3.11..v3.12 range, git bisect told me:

the first bad commit is 551f5c74e17ba9257cdc35bf657ee448cad2d5b0

Merge branch 'acpi-processor'

* acpi-processor:
ACPI / processor: Acquire writer lock to update CPU maps ACPI / processor: Remove acpi_processor_get_limit_info()

Quoted 8 lines

Quoted 5 lines

The two commits brought by the merge are not the culprits because reseting HEAD on "ACPI / processor: Acquire writer lock to update CPU maps" doesn't have the issue anymore.

At that point I'm not sure how to bisect futher.

Does the second parent of this merge (that is, 8462d9df9d50) have the problem?

Yes it does.

Ok, I've finally managed to find out the bad commit:
ad07277e82dedabacc52c82746633680a3187d25: ACPI / PM: Hold acpi_scan_lock over system PM transitions

I verified that the parent commit doesn't have the problem.

Rafael, you're the man now ;)

Quoted 5 lines · Francis Moreau

Ok, I've finally managed to find out the bad commit:
ad07277e82dedabacc52c82746633680a3187d25: ACPI / PM: Hold acpi_scan_lock over system PM transitions

I verified that the parent commit doesn't have the problem.

Interesting.

Quoted 1 line

Rafael, you're the man now ;)

I kind of don't see how that commit may result in behavior that you described earlier in the thread.

You get a memory corruption that seems to have started to happen because we're holding an additional lock over suspend resume now. Something's fishy on that machine and we need to figure out what it is.

Quoted 14 lines · Rafael J. Wysocki

Quoted 5 lines · Francis Moreau

Ok, I've finally managed to find out the bad commit:
ad07277e82dedabacc52c82746633680a3187d25: ACPI / PM: Hold acpi_scan_lock over system PM transitions

I verified that the parent commit doesn't have the problem.

Interesting.

Quoted 1 line

Rafael, you're the man now ;)

I kind of don't see how that commit may result in behavior that you described earlier in the thread.

Quoted 3 lines

You get a memory corruption that seems to have started to happen because we're holding an additional lock over suspend resume now. Something's fishy on that machine and we need to figure out what it is.

The hickup happens in the timer softirq.

@Francis: Did you try to enable DEBUG_OBJECTS.*. If not please give it
a try.

This looks like it was a good idea.

The kernel now outputs the following traces after resuming.

[   26.973928] WARNING: CPU: 0 PID: 4 at lib/debugobjects.c:260
debug_print_object+0x83/0xa0()
[   26.973932] ODEBUG: free active (active state 0) object type:

timer_list hint: delayed_work_timer_fn+0x0/0x20

Hello Thomas

Quoted 15 lines · Thomas Gleixner

Quoted 14 lines · Rafael J. Wysocki

Quoted 5 lines · Francis Moreau

Ok, I've finally managed to find out the bad commit:
ad07277e82dedabacc52c82746633680a3187d25: ACPI / PM: Hold acpi_scan_lock over system PM transitions

I verified that the parent commit doesn't have the problem.

Interesting.

Quoted 1 line

Rafael, you're the man now ;)

I kind of don't see how that commit may result in behavior that you described earlier in the thread.

Quoted 8 lines

Quoted 3 lines

You get a memory corruption that seems to have started to happen because we're holding an additional lock over suspend resume now. Something's fishy on that machine and we need to figure out what it is.

The hickup happens in the timer softirq.

@Francis: Did you try to enable DEBUG_OBJECTS.*. If not please give it
a try.

This looks like it was a good idea.

The kernel now outputs the following traces after resuming.

[   26.973928] WARNING: CPU: 0 PID: 4 at lib/debugobjects.c:260
debug_print_object+0x83/0xa0()
[   26.973932] ODEBUG: free active (active state 0) object type:
timer_list hint: delayed_work_timer_fn+0x0/0x20
[   26.973972] Modules linked in: x86_pkg_temp_thermal intel_powerclamp

rtsx_pci_ms coretemp memstick kvm_intel i2c_i801 iTCO_wdt iTCO_vendor_support i915 i2c_algo_bit intel_agp intel_gtt drm_kms_helper r8169 drm kvm mii agpgart i2c_core lpc_ich ac shpchp crc32c_intel battery thermal wmi evdev mei_me video mei button mperf processor serio_raw microcode ext4 crc16 mbcache jbd2 sr_mod cdrom sd_mod usb_storage rtsx_pci_sdmmc mmc_core ahci libahci libata ehci_pci ehci_hcd xhci_hcd scsi_mod rtsx_pci usbcore usb_common

[   26.974013] CPU: 0 PID: 4 Comm: kworker/0:0 Not tainted
3.11.0-rc2-ARCH #64
[   26.974014] Hardware name: CLEVO CO.                        W55xEU
                       /W55xEU                          , BIOS 4.6.5
03/05/2013
[   26.974019] Workqueue: kacpi_hotplug hotplug_event_work
[   26.974020]  0000000000000009 ffff880407d0da18 ffffffff81459fe9
ffff880407d0da60
[   26.974023]  ffff880407d0da50 ffffffff8104dc7d ffff880407fad488
ffffffff81836fc0
[   26.974025]  ffffffff81701358 ffffffff81afef70 0000000000000003
ffff880407d0dab0
[   26.974027] Call Trace:
[   26.974031]  [<ffffffff81459fe9>] dump_stack+0x54/0x8d
[   26.974043]  [<ffffffff8104dc7d>] warn_slowpath_common+0x7d/0xa0
[   26.974044]  [<ffffffff8104dcec>] warn_slowpath_fmt+0x4c/0x50
[   26.974047]  [<ffffffff81261433>] debug_print_object+0x83/0xa0
[   26.974050]  [<ffffffff8106b820>] ? queue_work_on+0x50/0x50
[   26.974053]  [<ffffffff81261c2b>] __debug_check_no_obj_freed+0x1fb/0x240
[   26.974059]  [<ffffffffa008e959>] ? rtsx_pci_remove+0x119/0x1d0

[rtsx_pci]

Quoted 63 lines · Francis Moreau

Hello Thomas

Quoted 15 lines · Thomas Gleixner

Quoted 14 lines · Rafael J. Wysocki

Quoted 5 lines · Francis Moreau

Ok, I've finally managed to find out the bad commit:
ad07277e82dedabacc52c82746633680a3187d25: ACPI / PM: Hold acpi_scan_lock over system PM transitions

I verified that the parent commit doesn't have the problem.

Interesting.

Quoted 1 line

Rafael, you're the man now ;)

I kind of don't see how that commit may result in behavior that you described earlier in the thread.

Quoted 8 lines

Quoted 3 lines

You get a memory corruption that seems to have started to happen because we're holding an additional lock over suspend resume now. Something's fishy on that machine and we need to figure out what it is.

The hickup happens in the timer softirq.

@Francis: Did you try to enable DEBUG_OBJECTS.*. If not please give it
a try.

This looks like it was a good idea.

The kernel now outputs the following traces after resuming.

[   26.973928] WARNING: CPU: 0 PID: 4 at lib/debugobjects.c:260
debug_print_object+0x83/0xa0()
[   26.973932] ODEBUG: free active (active state 0) object type:
timer_list hint: delayed_work_timer_fn+0x0/0x20
[   26.973972] Modules linked in: x86_pkg_temp_thermal intel_powerclamp

rtsx_pci_ms coretemp memstick kvm_intel i2c_i801 iTCO_wdt iTCO_vendor_support i915 i2c_algo_bit intel_agp intel_gtt drm_kms_helper r8169 drm kvm mii agpgart i2c_core lpc_ich ac shpchp crc32c_intel battery thermal wmi evdev mei_me video mei button mperf processor serio_raw microcode ext4 crc16 mbcache jbd2 sr_mod cdrom sd_mod usb_storage rtsx_pci_sdmmc mmc_core ahci libahci libata ehci_pci ehci_hcd xhci_hcd scsi_mod rtsx_pci usbcore usb_common

[   26.974013] CPU: 0 PID: 4 Comm: kworker/0:0 Not tainted
3.11.0-rc2-ARCH #64
[   26.974014] Hardware name: CLEVO CO.                        W55xEU
                       /W55xEU                          , BIOS 4.6.5
03/05/2013
[   26.974019] Workqueue: kacpi_hotplug hotplug_event_work
[   26.974020]  0000000000000009 ffff880407d0da18 ffffffff81459fe9
ffff880407d0da60
[   26.974023]  ffff880407d0da50 ffffffff8104dc7d ffff880407fad488
ffffffff81836fc0
[   26.974025]  ffffffff81701358 ffffffff81afef70 0000000000000003
ffff880407d0dab0
[   26.974027] Call Trace:
[   26.974031]  [<ffffffff81459fe9>] dump_stack+0x54/0x8d
[   26.974043]  [<ffffffff8104dc7d>] warn_slowpath_common+0x7d/0xa0
[   26.974044]  [<ffffffff8104dcec>] warn_slowpath_fmt+0x4c/0x50
[   26.974047]  [<ffffffff81261433>] debug_print_object+0x83/0xa0
[   26.974050]  [<ffffffff8106b820>] ? queue_work_on+0x50/0x50
[   26.974053]  [<ffffffff81261c2b>] __debug_check_no_obj_freed+0x1fb/0x240
[   26.974059]  [<ffffffffa008e959>] ? rtsx_pci_remove+0x119/0x1d0

Quoted 1 line

[rtsx_pci]

So a device driven by rtsx_pcr.c is removed after resume. Without the commit you've bisected it is removed as well, but that happens during resume, so rtsx_pci_resume() is likely not called in that case.

I bet that there's a bug either in rtsx_pci_remove() or in rtsx_pci_resume(). The latter definitely should check if the device is actually still present before scheduling the delayed work, but then the Boris' patch should take care of that anyway.

Quoted 66 lines · Rafael J. Wysocki

Quoted 64 lines · Francis Moreau

Hello Thomas

Quoted 15 lines · Thomas Gleixner

Quoted 14 lines · Rafael J. Wysocki

Quoted 5 lines · Francis Moreau

Ok, I've finally managed to find out the bad commit:
ad07277e82dedabacc52c82746633680a3187d25: ACPI / PM: Hold acpi_scan_lock over system PM transitions

I verified that the parent commit doesn't have the problem.

Interesting.

Quoted 1 line

Rafael, you're the man now ;)

I kind of don't see how that commit may result in behavior that you described earlier in the thread.

Quoted 8 lines

Quoted 3 lines

You get a memory corruption that seems to have started to happen because we're holding an additional lock over suspend resume now. Something's fishy on that machine and we need to figure out what it is.

The hickup happens in the timer softirq.

@Francis: Did you try to enable DEBUG_OBJECTS.*. If not please give it
a try.

This looks like it was a good idea.

The kernel now outputs the following traces after resuming.

[   26.973928] WARNING: CPU: 0 PID: 4 at lib/debugobjects.c:260
debug_print_object+0x83/0xa0()
[   26.973932] ODEBUG: free active (active state 0) object type:
timer_list hint: delayed_work_timer_fn+0x0/0x20
[   26.973972] Modules linked in: x86_pkg_temp_thermal intel_powerclamp

rtsx_pci_ms coretemp memstick kvm_intel i2c_i801 iTCO_wdt iTCO_vendor_support i915 i2c_algo_bit intel_agp intel_gtt drm_kms_helper r8169 drm kvm mii agpgart i2c_core lpc_ich ac shpchp crc32c_intel battery thermal wmi evdev mei_me video mei button mperf processor serio_raw microcode ext4 crc16 mbcache jbd2 sr_mod cdrom sd_mod usb_storage rtsx_pci_sdmmc mmc_core ahci libahci libata ehci_pci ehci_hcd xhci_hcd scsi_mod rtsx_pci usbcore usb_common

[   26.974013] CPU: 0 PID: 4 Comm: kworker/0:0 Not tainted
3.11.0-rc2-ARCH #64
[   26.974014] Hardware name: CLEVO CO.                        W55xEU
                       /W55xEU                          , BIOS 4.6.5
03/05/2013
[   26.974019] Workqueue: kacpi_hotplug hotplug_event_work
[   26.974020]  0000000000000009 ffff880407d0da18 ffffffff81459fe9
ffff880407d0da60
[   26.974023]  ffff880407d0da50 ffffffff8104dc7d ffff880407fad488
ffffffff81836fc0
[   26.974025]  ffffffff81701358 ffffffff81afef70 0000000000000003
ffff880407d0dab0
[   26.974027] Call Trace:
[   26.974031]  [<ffffffff81459fe9>] dump_stack+0x54/0x8d
[   26.974043]  [<ffffffff8104dc7d>] warn_slowpath_common+0x7d/0xa0
[   26.974044]  [<ffffffff8104dcec>] warn_slowpath_fmt+0x4c/0x50
[   26.974047]  [<ffffffff81261433>] debug_print_object+0x83/0xa0
[   26.974050]  [<ffffffff8106b820>] ? queue_work_on+0x50/0x50
[   26.974053]  [<ffffffff81261c2b>] __debug_check_no_obj_freed+0x1fb/0x240
[   26.974059]  [<ffffffffa008e959>] ? rtsx_pci_remove+0x119/0x1d0

[rtsx_pci]

Quoted 3 lines

So a device driven by rtsx_pcr.c is removed after resume. Without the commit you've bisected it is removed as well, but that happens during resume, so rtsx_pci_resume() is likely not called in that case.

I'm not sure to understand your point.

Quoted 67 lines · Francis Moreau

Quoted 66 lines · Rafael J. Wysocki

Quoted 64 lines · Francis Moreau

Hello Thomas

Quoted 15 lines · Thomas Gleixner

Quoted 14 lines · Rafael J. Wysocki

Quoted 5 lines · Francis Moreau

Ok, I've finally managed to find out the bad commit:
ad07277e82dedabacc52c82746633680a3187d25: ACPI / PM: Hold acpi_scan_lock over system PM transitions

I verified that the parent commit doesn't have the problem.

Interesting.

Quoted 1 line

Rafael, you're the man now ;)

I kind of don't see how that commit may result in behavior that you described earlier in the thread.

Quoted 8 lines

Quoted 3 lines

You get a memory corruption that seems to have started to happen because we're holding an additional lock over suspend resume now. Something's fishy on that machine and we need to figure out what it is.

The hickup happens in the timer softirq.

@Francis: Did you try to enable DEBUG_OBJECTS.*. If not please give it
a try.

This looks like it was a good idea.

The kernel now outputs the following traces after resuming.

[   26.973928] WARNING: CPU: 0 PID: 4 at lib/debugobjects.c:260
debug_print_object+0x83/0xa0()
[   26.973932] ODEBUG: free active (active state 0) object type:
timer_list hint: delayed_work_timer_fn+0x0/0x20
[   26.973972] Modules linked in: x86_pkg_temp_thermal intel_powerclamp

rtsx_pci_ms coretemp memstick kvm_intel i2c_i801 iTCO_wdt iTCO_vendor_support i915 i2c_algo_bit intel_agp intel_gtt drm_kms_helper r8169 drm kvm mii agpgart i2c_core lpc_ich ac shpchp crc32c_intel battery thermal wmi evdev mei_me video mei button mperf processor serio_raw microcode ext4 crc16 mbcache jbd2 sr_mod cdrom sd_mod usb_storage rtsx_pci_sdmmc mmc_core ahci libahci libata ehci_pci ehci_hcd xhci_hcd scsi_mod rtsx_pci usbcore usb_common

[   26.974013] CPU: 0 PID: 4 Comm: kworker/0:0 Not tainted
3.11.0-rc2-ARCH #64
[   26.974014] Hardware name: CLEVO CO.                        W55xEU
                       /W55xEU                          , BIOS 4.6.5
03/05/2013
[   26.974019] Workqueue: kacpi_hotplug hotplug_event_work
[   26.974020]  0000000000000009 ffff880407d0da18 ffffffff81459fe9
ffff880407d0da60
[   26.974023]  ffff880407d0da50 ffffffff8104dc7d ffff880407fad488
ffffffff81836fc0
[   26.974025]  ffffffff81701358 ffffffff81afef70 0000000000000003
ffff880407d0dab0
[   26.974027] Call Trace:
[   26.974031]  [<ffffffff81459fe9>] dump_stack+0x54/0x8d
[   26.974043]  [<ffffffff8104dc7d>] warn_slowpath_common+0x7d/0xa0
[   26.974044]  [<ffffffff8104dcec>] warn_slowpath_fmt+0x4c/0x50
[   26.974047]  [<ffffffff81261433>] debug_print_object+0x83/0xa0
[   26.974050]  [<ffffffff8106b820>] ? queue_work_on+0x50/0x50
[   26.974053]  [<ffffffff81261c2b>] __debug_check_no_obj_freed+0x1fb/0x240
[   26.974059]  [<ffffffffa008e959>] ? rtsx_pci_remove+0x119/0x1d0

[rtsx_pci]

Quoted 5 lines

Quoted 3 lines

So a device driven by rtsx_pcr.c is removed after resume. Without the commit you've bisected it is removed as well, but that happens during resume, so rtsx_pci_resume() is likely not called in that case.

I'm not sure to understand your point.

The problem is that with the commit you've bisected, the whole removal of rtsx_pcr is likely done *before* the PM core calls resume callbacks of device drivers (although only incidentally, because it very well may be done in parallel with that). However, after that commit the removal is only done after the resume callbacks have been called, which means that the device is not physically present when rtsx_pci_resume() is called. Of course, it may not be physically present at that point anyway, so rtsx_pci_resume() should have taken that into consideration already, but it doesn't from what I can say.

Since it seems to be related to rtsx driver or its upper layer, could the folks involved in this area have a look to this issue please ?

Quoted 2 lines · Francis Moreau

Since it seems to be related to rtsx driver or its upper layer, could the folks involved in this area have a look to this issue please ?

I'm not involved, but looking at the debug objects backtrace it's related to the delayed work in rtsx.

Does the untested patch below cure the issue?

Hello Thomas,

Sorry for the delay.

Quoted 4 lines · Thomas Gleixner

Quoted 2 lines · Francis Moreau

Since it seems to be related to rtsx driver or its upper layer, could the folks involved in this area have a look to this issue please ?

Quoted 5 lines

I'm not involved, but looking at the debug objects backtrace it's related to the delayed work in rtsx.

Does the untested patch below cure the issue?

It seems it does since I can't see the debug object trace anymore however Ican see this now:

[   64.498270] irq 16: nobody cared (try booting with the "irqpoll" option)
[   64.498314] CPU: 0 PID: 0 Comm: swapper/0 Not tainted 3.11.0-rc2-ARCH #65
[   64.498316] Hardware name: CLEVO CO.                        W55xEU
                       /W55xEU                          , BIOS 4.6.5
03/05/2013
[   64.498317]  ffff8804078bd38c ffff88041e203e48 ffffffff81459fe9
ffff8804078bd300
[   64.498320]  ffff88041e203e70 ffffffff810d8632 ffff8804078bd300
0000000000000010
[   64.498322]  0000000000000000 ffff88041e203eb0 ffffffff810d8a58
ffffffff8136a882
[   64.498324] Call Trace:
[   64.498325]  <IRQ>  [<ffffffff81459fe9>] dump_stack+0x54/0x8d
[   64.498334]  [<ffffffff810d8632>] __report_bad_irq+0x32/0xd0
[   64.498337]  [<ffffffff810d8a58>] note_interrupt+0x138/0x1f0
[   64.498340]  [<ffffffff8136a882>] ? cpuidle_enter_state+0x52/0xc0
[   64.498343]  [<ffffffff810d6439>] handle_irq_event_percpu+0xf9/0x250
[   64.498345]  [<ffffffff810d65cd>] handle_irq_event+0x3d/0x60
[   64.498347]  [<ffffffff810d95ca>] handle_fasteoi_irq+0x5a/0x100
[   64.498350]  [<ffffffff81004a6e>] handle_irq+0x1e/0x30
[   64.498353]  [<ffffffff8146aafd>] do_IRQ+0x4d/0xc0
[   64.498355]  [<ffffffff8146116d>] common_interrupt+0x6d/0x6d
[   64.498356]  <EOI>  [<ffffffff8136a882>] ? cpuidle_enter_state+0x52/0xc0
[   64.498360]  [<ffffffff8136a878>] ? cpuidle_enter_state+0x48/0xc0
[   64.498362]  [<ffffffff8136a9b9>] cpuidle_idle_call+0xc9/0x280
[   64.498365]  [<ffffffff8100bf6e>] arch_cpu_idle+0xe/0x30
[   64.498368]  [<ffffffff810a1287>] cpu_startup_entry+0x257/0x2d0
[   64.498370]  [<ffffffff8144d404>] rest_init+0x84/0x90
[   64.498373]  [<ffffffff818d9ee1>] start_kernel+0x414/0x420
[   64.498375]  [<ffffffff818d98d6>] ? repair_env_string+0x5c/0x5c
[   64.498377]  [<ffffffff818d9120>] ? early_idt_handlers+0x120/0x120
[   64.498379]  [<ffffffff818d95be>] x86_64_start_reservations+0x2a/0x2c
[   64.498381]  [<ffffffff818d96c8>] x86_64_start_kernel+0x108/0x117
[   64.498382] handlers:
[   64.498402] [<ffffffffa00168f0>] usb_hcd_irq [usbcore]
[   64.498422] Disabling IRQ #16

So I don't think it completely solve the problem but it's a good start.

Quoted 9 lines · Francis Moreau

Hello Thomas,

Sorry for the delay.

Quoted 4 lines · Thomas Gleixner

Quoted 2 lines · Francis Moreau

Since it seems to be related to rtsx driver or its upper layer, could the folks involved in this area have a look to this issue please ?

Quoted 8 lines

Quoted 5 lines

I'm not involved, but looking at the debug objects backtrace it's related to the delayed work in rtsx.

Does the untested patch below cure the issue?

It seems it does since I can't see the debug object trace anymore however Ican see this now:

So Thomas' patch should be applied to the rtsx driver.

Quoted 37 lines

[   64.498270] irq 16: nobody cared (try booting with the "irqpoll" option)
[   64.498314] CPU: 0 PID: 0 Comm: swapper/0 Not tainted 3.11.0-rc2-ARCH #65
[   64.498316] Hardware name: CLEVO CO.                        W55xEU
                       /W55xEU                          , BIOS 4.6.5
03/05/2013
[   64.498317]  ffff8804078bd38c ffff88041e203e48 ffffffff81459fe9
ffff8804078bd300
[   64.498320]  ffff88041e203e70 ffffffff810d8632 ffff8804078bd300
0000000000000010
[   64.498322]  0000000000000000 ffff88041e203eb0 ffffffff810d8a58
ffffffff8136a882
[   64.498324] Call Trace:
[   64.498325]  <IRQ>  [<ffffffff81459fe9>] dump_stack+0x54/0x8d
[   64.498334]  [<ffffffff810d8632>] __report_bad_irq+0x32/0xd0
[   64.498337]  [<ffffffff810d8a58>] note_interrupt+0x138/0x1f0
[   64.498340]  [<ffffffff8136a882>] ? cpuidle_enter_state+0x52/0xc0
[   64.498343]  [<ffffffff810d6439>] handle_irq_event_percpu+0xf9/0x250
[   64.498345]  [<ffffffff810d65cd>] handle_irq_event+0x3d/0x60
[   64.498347]  [<ffffffff810d95ca>] handle_fasteoi_irq+0x5a/0x100
[   64.498350]  [<ffffffff81004a6e>] handle_irq+0x1e/0x30
[   64.498353]  [<ffffffff8146aafd>] do_IRQ+0x4d/0xc0
[   64.498355]  [<ffffffff8146116d>] common_interrupt+0x6d/0x6d
[   64.498356]  <EOI>  [<ffffffff8136a882>] ? cpuidle_enter_state+0x52/0xc0
[   64.498360]  [<ffffffff8136a878>] ? cpuidle_enter_state+0x48/0xc0
[   64.498362]  [<ffffffff8136a9b9>] cpuidle_idle_call+0xc9/0x280
[   64.498365]  [<ffffffff8100bf6e>] arch_cpu_idle+0xe/0x30
[   64.498368]  [<ffffffff810a1287>] cpu_startup_entry+0x257/0x2d0
[   64.498370]  [<ffffffff8144d404>] rest_init+0x84/0x90
[   64.498373]  [<ffffffff818d9ee1>] start_kernel+0x414/0x420
[   64.498375]  [<ffffffff818d98d6>] ? repair_env_string+0x5c/0x5c
[   64.498377]  [<ffffffff818d9120>] ? early_idt_handlers+0x120/0x120
[   64.498379]  [<ffffffff818d95be>] x86_64_start_reservations+0x2a/0x2c
[   64.498381]  [<ffffffff818d96c8>] x86_64_start_kernel+0x108/0x117
[   64.498382] handlers:
[   64.498402] [<ffffffffa00168f0>] usb_hcd_irq [usbcore]
[   64.498422] Disabling IRQ #16

Quoted 1 line

So I don't think it completely solve the problem but it's a good start.

That issue may or may not be related.

If your system survives resume (I guess it does?),

can you please send
/proc/interrupts before and after the first suspend/resume cycle?

If your system survives resume (I guess it does?), can you please send /proc/interrupts before and after the first suspend/resume cycle?

Hello Thomas,

Sorry for the delay.

Quoted 9 lines · Thomas Gleixner

Quoted 2 lines · Francis Moreau

Since it seems to be related to rtsx driver or its upper layer, could the folks involved in this area have a look to this issue please ?

I'm not involved, but looking at the debug objects backtrace it's related to the delayed work in rtsx.

Does the untested patch below cure the issue?

It seems it does since I can't see the debug object trace anymore however Ican see this now:

So I don't think it completely solve the problem but it's a good start.

Quoted 17 lines · Francis Moreau

Hello Thomas,

Sorry for the delay.

Quoted 9 lines · Thomas Gleixner

Quoted 2 lines · Francis Moreau

Since it seems to be related to rtsx driver or its upper layer, could the folks involved in this area have a look to this issue please ?

I'm not involved, but looking at the debug objects backtrace it's related to the delayed work in rtsx.

Does the untested patch below cure the issue?

It seems it does since I can't see the debug object trace anymore however Ican see this now:

<SNIP>

Quoted 1 line

So I don't think it completely solve the problem but it's a good start.

I kinda expected that, but I wanted to confirm my suspicion, that the interrupt hits after the delayed work is canceled and just requeues it again, which then leads to an armed timer being freed further down.

I'm not familiar with that driver and I leave the final fixup to the driver maintainers. It's enough data for them to figure out the real solution.

Quoted 27 lines · Thomas Gleixner

Quoted 17 lines · Francis Moreau

Hello Thomas,

Sorry for the delay.

Quoted 9 lines · Thomas Gleixner

Quoted 2 lines · Francis Moreau

Since it seems to be related to rtsx driver or its upper layer, could the folks involved in this area have a look to this issue please ?

I'm not involved, but looking at the debug objects backtrace it's related to the delayed work in rtsx.

Does the untested patch below cure the issue?

It seems it does since I can't see the debug object trace anymore however Ican see this now:

<SNIP>

Quoted 1 line

So I don't think it completely solve the problem but it's a good start.

I kinda expected that, but I wanted to confirm my suspicion, that the interrupt hits after the delayed work is canceled and just requeues it again, which then leads to an armed timer being freed further down.

Quoted 3 lines

I'm not familiar with that driver and I leave the final fixup to the driver maintainers. It's enough data for them to figure out the real solution.

Just had a quick look and the obvious solution is to disable the interrupts at the device level _BEFORE_ doing anything else in the teardown path. Updated patch below. That should avoid the nobody cared splat on the other irq line.

Hello Thomas,

Quoted 28 lines · Thomas Gleixner

Quoted 27 lines · Thomas Gleixner

Quoted 17 lines · Francis Moreau

Hello Thomas,

Sorry for the delay.

Quoted 9 lines · Thomas Gleixner

Quoted 2 lines · Francis Moreau

Since it seems to be related to rtsx driver or its upper layer, could the folks involved in this area have a look to this issue please ?

I'm not involved, but looking at the debug objects backtrace it's related to the delayed work in rtsx.

Does the untested patch below cure the issue?

It seems it does since I can't see the debug object trace anymore however Ican see this now:

<SNIP>

Quoted 1 line

So I don't think it completely solve the problem but it's a good start.

I kinda expected that, but I wanted to confirm my suspicion, that the interrupt hits after the delayed work is canceled and just requeues it again, which then leads to an armed timer being freed further down.

Quoted 9 lines

Quoted 3 lines

I'm not familiar with that driver and I leave the final fixup to the driver maintainers. It's enough data for them to figure out the real solution.

Just had a quick look and the obvious solution is to disable the interrupts at the device level _BEFORE_ doing anything else in the teardown path. Updated patch below. That should avoid the nobody cared splat on the other irq line.

Yes it does.

Now that you did the hard work, I hope driver's maintainer/developper will care about this issue.

Quoted 41 lines · Francis Moreau

Hello Thomas,

Quoted 28 lines · Thomas Gleixner

Quoted 27 lines · Thomas Gleixner

Quoted 17 lines · Francis Moreau

Hello Thomas,

Sorry for the delay.

Quoted 9 lines · Thomas Gleixner

Quoted 2 lines · Francis Moreau

Since it seems to be related to rtsx driver or its upper layer, could the folks involved in this area have a look to this issue please ?

I'm not involved, but looking at the debug objects backtrace it's related to the delayed work in rtsx.

Does the untested patch below cure the issue?

It seems it does since I can't see the debug object trace anymore however Ican see this now:

<SNIP>

Quoted 1 line

So I don't think it completely solve the problem but it's a good start.

I kinda expected that, but I wanted to confirm my suspicion, that the interrupt hits after the delayed work is canceled and just requeues it again, which then leads to an armed timer being freed further down.

Quoted 9 lines

Quoted 3 lines

I'm not familiar with that driver and I leave the final fixup to the driver maintainers. It's enough data for them to figure out the real solution.

Just had a quick look and the obvious solution is to disable the interrupts at the device level _BEFORE_ doing anything else in the teardown path. Updated patch below. That should avoid the nobody cared splat on the other irq line.

Quoted 5 lines

Yes it does.

Now that you did the hard work, I hope driver's maintainer/developper will care about this issue.

Unfortunately he/she doesn't seem to care.

Moreover I've been by this now:

[  241.003324] INFO: task kworker/u16:4:108 blocked for more than 120
seconds.
[  241.003331]       Not tainted 3.12.2-1-ARCH #1
[  241.003332] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
disables this message.
[  241.003335] kworker/u16:4   D ffff880405bc8000     0   108      2
0x00000000
[  241.003355] Workqueue: kmemstick memstick_check [memstick]
[  241.003358]  ffff880405bc3c90 0000000000000046 00000000000144c0
ffff880405bc3fd8
[  241.003362]  ffff880405bc3fd8 00000000000144c0 ffff880405bc8000
ffff880405bc3c68
[  241.003366]  ffffffff814ef57c ffff880405bc3fd8 0000000000000286
0000000000000000
[  241.003370] Call Trace:
[  241.003380]  [<ffffffff814ef57c>] ? schedule_timeout+0x13c/0x290
[  241.003385]  [<ffffffff8106f590>] ? detach_if_pending+0x120/0x120
[  241.003388]  [<ffffffff8106f590>] ? detach_if_pending+0x120/0x120
[  241.003392]  [<ffffffff814f2e79>] schedule+0x29/0x70
[  241.003396]  [<ffffffff814ef659>] schedule_timeout+0x219/0x290
[  241.003401]  [<ffffffff8129a4d1>] ? vsnprintf+0x1e1/0x680
[  241.003405]  [<ffffffff814f2213>] wait_for_common+0xd3/0x180
[  241.003411]  [<ffffffff81095100>] ? wake_up_process+0x40/0x40
[  241.003414]  [<ffffffff814f22dd>] wait_for_completion+0x1d/0x20
[  241.003419]  [<ffffffffa061334a>] memstick_set_rw_addr+0x4a/0x50
[memstick]
[  241.003424]  [<ffffffffa061388e>] memstick_check+0x10e/0x370 [memstick]
[  241.003429]  [<ffffffff8107daf7>] process_one_work+0x167/0x450
[  241.003432]  [<ffffffff8107e501>] worker_thread+0x121/0x3a0
[  241.003436]  [<ffffffff8107e3e0>] ? manage_workers.isra.23+0x2b0/0x2b0
[  241.003441]  [<ffffffff81084e90>] kthread+0xc0/0xd0
[  241.003446]  [<ffffffff81084dd0>] ? kthread_create_on_node+0x120/0x120
[  241.003450]  [<ffffffff814fc33c>] ret_from_fork+0x7c/0xb0
[  241.003454]  [<ffffffff81084dd0>] ? kthread_create_on_node+0x120/0x120

looks like a different issue.

Now that you did the hard work, I hope driver's maintainer/developper will care about this issue.

Hi Francis,

Adding Lee to the Cc list.

Quoted 2 lines · Francis Moreau

Now that you did the hard work, I hope driver's maintainer/developper will care about this issue.

I applied Thomas' patch to mfd-fixes.
Thanks a lot to you and Thomas for that.

Cheers,
Samuel.

which is based on Thomas' patch.

Hi Francis:

Quoted 1 line · wwang

which is based on Thomas' patch.

Can you help us test this patch, we disable irq while suspend here.

Hi Micky,

Quoted 2 lines · micky

Hi Francis:
On 12/10/2013 09:39 AM, wwang wrote:

Quoted 3 lines

Quoted 1 line

which is based on Thomas' patch.

Can you help us test this patch, we disable irq while suspend here.

I already pushed a patch from Thomas to mfd-fixes that seems to fix the resume breakage:

https://git.kernel.org/cgit/linux/kernel/git/sameo/mfd-fixes.git/commit/?id=19e49e445e198197c5e243f92d333d076e23d032

I still can see any traces of this fix in Linus' tree.

Shouldn't this get merged before 3.13 is out ?

Thanks

Hi.

Quoted 11 lines · Samuel Ortiz

Hi Micky,

Quoted 5 lines · micky

Hi Francis:

Quoted 1 line · wwang

which is based on Thomas' patch.

Can you help us test this patch, we disable irq while suspend here.

I already pushed a patch from Thomas to mfd-fixes that seems to fix the resume breakage:

Quoted 2 lines

https://git.kernel.org/cgit/linux/kernel/git/sameo/mfd-fixes.git/commit/?id=19e49e445e198197c5e243f92d333d076e23d032

I still can see any traces of this fix in Linus' tree.

Shouldn't this get merged before 3.13 is out ?

Hi Francis,

Quoted 14 lines · Francis Moreau

Hi.

Quoted 11 lines · Samuel Ortiz

Hi Micky,

Quoted 5 lines · micky

Hi Francis:

Quoted 1 line · wwang

which is based on Thomas' patch.

Can you help us test this patch, we disable irq while suspend here.

I already pushed a patch from Thomas to mfd-fixes that seems to fix the resume breakage:

Quoted 6 lines

Quoted 2 lines

https://git.kernel.org/cgit/linux/kernel/git/sameo/mfd-fixes.git/commit/?id=19e49e445e198197c5e243f92d333d076e23d032

I still can see any traces of this fix in Linus' tree.

Shouldn't this get merged before 3.13 is out ?

Yes, it should. I just sent a pull request to Linus for that.

Hi Francis:

Quoted 1 line · wwang

which is based on Thomas' patch.

Can you help us test this patch, we disable irq while suspend here.

Hi Francis:

Quoted 1 line · wwang

which is based on Thomas' patch.

Can you help us test this patch, we disable irq while suspend here.

Hi,

Quoted 4 lines · micky

Hi Francis:

Quoted 1 line · wwang

which is based on Thomas' patch.

Can you help us test this patch, we disable irq while suspend here.

This patch doesn't seem to help, it still oops:

[   29.843910] ------------[ cut here ]------------
[   29.843917] WARNING: CPU: 0 PID: 53 at lib/debugobjects.c:260
debug_print_object+0x83/0xa0()
[   29.843921] ODEBUG: free active (active state 0) object type:
timer_list hint: delayed_work_timer_fn+0x0/0x20
[   29.843972] Modules linked in: x86_pkg_temp_thermal intel_powerclamp

coretemp kvm_intel kvm rtsx_pci_ms i915 i2c_algo_bit intel_agp intel_gtt memstick iTCO_wdt drm_kms_helper crc32c_intel video drm r8169 mei_me mii thermal agpgart mei wmi iTCO_vendor_support ac i2c_i801 i2c_core battery evdev button shpchp lpc_ich mperf processor serio_raw microcode ext4 crc16 mbcache jbd2 sr_mod cdrom sd_mod usb_storage rtsx_pci_sdmmc mmc_core ahci libahci libata scsi_mod ehci_pci xhci_hcd ehci_hcd rtsx_pci usbcore usb_common

[   29.844004] CPU: 0 PID: 53 Comm: kworker/0:1 Not tainted
3.11.0-rc2-ARCH #66
[   29.844006] Hardware name: CLEVO CO.                        W55xEU
                        /W55xEU                          , BIOS 4.6.5
03/05/2013
[   29.844010] Workqueue: kacpi_hotplug hotplug_event_work
[   29.844012]  0000000000000009 ffff880407a95a18 ffffffff81459fe9
ffff880407a95a60
[   29.844014]  ffff880407a95a50 ffffffff8104dc7d ffff880406b896b8
ffffffff81836fc0
[   29.844017]  ffffffff81701358 ffffffff81b2f9b0 0000000000000003
ffff880407a95ab0
[   29.844019] Call Trace:
[   29.844024]  [<ffffffff81459fe9>] dump_stack+0x54/0x8d
[   29.844027]  [<ffffffff8104dc7d>] warn_slowpath_common+0x7d/0xa0
[   29.844029]  [<ffffffff8104dcec>] warn_slowpath_fmt+0x4c/0x50
[   29.844032]  [<ffffffff81261433>] debug_print_object+0x83/0xa0
[   29.844034]  [<ffffffff8106b820>] ? queue_work_on+0x50/0x50
[   29.844037]  [<ffffffff81261c2b>] __debug_check_no_obj_freed+0x1fb/0x240
[   29.844044]  [<ffffffffa00d8989>] ? rtsx_pci_remove+0x119/0x1d0
[rtsx_pci]
[   29.844046]  [<ffffffff81262619>] debug_check_no_obj_freed+0x19/0x20
[   29.844049]  [<ffffffff8116f861>] kfree+0x191/0x210
[   29.844054]  [<ffffffff813819e0>] ? pcibios_disable_device+0x20/0x30
[   29.844066]  [<ffffffffa00d8989>] ? rtsx_pci_remove+0x119/0x1d0
[rtsx_pci]
[   29.844071]  [<ffffffffa00d8989>] rtsx_pci_remove+0x119/0x1d0 [rtsx_pci]
[   29.844075]  [<ffffffff8128004b>] pci_device_remove+0x3b/0xb0
[   29.844079]  [<ffffffff8132c92f>] __device_release_driver+0x7f/0xf0
[   29.844082]  [<ffffffff8132c9c3>] device_release_driver+0x23/0x30
[   29.844084]  [<ffffffff8132c194>] bus_remove_device+0xf4/0x170
[   29.844087]  [<ffffffff81328c55>] device_del+0x135/0x1d0
[   29.844089]  [<ffffffff8127ae24>] pci_stop_bus_device+0x94/0xa0
[   29.844091]  [<ffffffff8127af32>]
pci_stop_and_remove_bus_device+0x12/0x20
[   29.844094]  [<ffffffff81297466>] disable_slot+0x76/0xd0
[   29.844096]  [<ffffffff81297568>] acpiphp_check_bridge+0xa8/0xd0
[   29.844099]  [<ffffffff81297c8a>] hotplug_event+0xfa/0x210
[   29.844101]  [<ffffffff81297dc7>] hotplug_event_work+0x27/0x60
[   29.844104]  [<ffffffff8106c178>] process_one_work+0x178/0x470
[   29.844106]  [<ffffffff8106cb91>] worker_thread+0x121/0x3a0
[   29.844109]  [<ffffffff8106ca70>] ? manage_workers.isra.21+0x2b0/0x2b0
[   29.844111]  [<ffffffff81073a50>] kthread+0xc0/0xd0
[   29.844114]  [<ffffffff81073990>] ? kthread_create_on_node+0x120/0x120
[   29.844117]  [<ffffffff814688ec>] ret_from_fork+0x7c/0xb0
[   29.844119]  [<ffffffff81073990>] ? kthread_create_on_node+0x120/0x120
[   29.844120] ---[ end trace ed9751fe6c0cd9e3 ]---
[   29.844137] kobject: '0000:03:00.0' (ffff880407a010a8):
kobject_uevent_env
[   29.844150] kobject: '0000:03:00.0' (ffff880407a010a8):
fill_kobj_path: path = '/devices/pci0000:00/0000:00:1c.3/0000:03:00.0'
[   29.844162] kobject: '0000:03:00.0' (ffff880407a010a8): kobject_cleanup
[   29.844164] kobject: '0000:03:00.0' (ffff880407a010a8): calling ktype
release
[   29.844166] kobject: '0000:03:00.0': free name
[   29.844367] kobject: 'rx-0' (ffff8804067ae010): kobject_cleanup
[   29.844370] kobject: 'rx-0' (ffff8804067ae010): auto cleanup 'remove'
event
[   29.844371] kobject: 'rx-0' (ffff8804067ae010): kobject_uevent_env
[   29.844374] kobject: 'rx-0' (ffff8804067ae010): fill_kobj_path: path
= '/devices/pci0000:00/0000:00:1c.3/0000:03:00.2/net/enp3s0f2/queues/rx-0'
[   29.844379] kobject: 'rx-0' (ffff8804067ae010): auto cleanup kobject_del
[   29.844383] kobject: 'rx-0' (ffff8804067ae010): calling ktype release
[   29.844384] kobject: 'rx-0': free name
[   29.844389] kobject: 'tx-0' (ffff880407205e18): kobject_cleanup
[   29.844390] kobject: 'tx-0' (ffff880407205e18): auto cleanup 'remove'
event
[   29.844391] kobject: 'tx-0' (ffff880407205e18): kobject_uevent_env
[   29.844393] kobject: 'tx-0' (ffff880407205e18): fill_kobj_path: path
= '/devices/pci0000:00/0000:00:1c.3/0000:03:00.2/net/enp3s0f2/queues/tx-0'
[   29.844396] kobject: 'tx-0' (ffff880407205e18): auto cleanup kobject_del
[   29.844398] kobject: 'tx-0' (ffff880407205e18): calling ktype release
[   29.844399] kobject: 'tx-0': free name
[   29.844400] kobject: 'queues' (ffff880406216c78): kobject_cleanup
[   29.844401] kobject: 'queues' (ffff880406216c78): auto cleanup
kobject_del
[   29.844403] kobject: 'queues' (ffff880406216c78): calling ktype release
[   29.844404] kobject: 'queues' (ffff880406216c78): kset_release
[   29.844405] kobject: 'queues': free name
[   29.844438] kobject: 'enp3s0f2' (ffff880406be2410): kobject_uevent_env
[   29.844440] kobject: 'enp3s0f2' (ffff880406be2410): fill_kobj_path:
path = '/devices/pci0000:00/0000:00:1c.3/0000:03:00.2/net/enp3s0f2'
[   29.844445] kobject: 'net' (ffff880406216cc0): kobject_cleanup
[   29.844446] kobject: 'net' (ffff880406216cc0): auto cleanup kobject_del
[   29.844447] kobject: 'net' (ffff880406216cc0): calling ktype release
[   29.844448] kobject: 'net': free name
[   29.890009] kobject: '44' (ffff880407327408): kobject_cleanup
[   29.890014] kobject: '44' (ffff880407327408): calling ktype release
[   29.890015] kobject: '44': free name
[   29.890018] kobject: 'msi_irqs' (ffff880406216d38): kobject_cleanup
[   29.890019] kobject: 'msi_irqs' (ffff880406216d38): auto cleanup
kobject_del
[   29.890022] kobject: 'msi_irqs' (ffff880406216d38): calling ktype release
[   29.890024] kobject: 'msi_irqs' (ffff880406216d38): kset_release
[   29.890026] kobject: 'msi_irqs': free name
[   29.890121] kobject: 'enp3s0f2' (ffff880406be2410): kobject_cleanup
[   29.890123] kobject: 'enp3s0f2' (ffff880406be2410): calling ktype release
[   29.890127] kobject: 'enp3s0f2': free name
[   29.899887] kobject: '0000:03:00.2' (ffff880407a020a8):
kobject_uevent_env
[   29.899892] kobject: '0000:03:00.2' (ffff880407a020a8):
fill_kobj_path: path = '/devices/pci0000:00/0000:00:1c.3/0000:03:00.2'
[   29.899914] kobject: '0000:03:00.2' (ffff880407a020a8): kobject_cleanup
[   29.899915] kobject: '0000:03:00.2' (ffff880407a020a8): calling ktype
release
[   29.899918] kobject: '0000:03:00.2': free name
[   29.899966] kobject: 'device:10' (ffff8804079731f0): kobject_uevent_env
[   29.899969] kobject: 'device:10' (ffff8804079731f0): fill_kobj_path:
path = '/devices/LNXSYSTM:00/device:00/PNP0A08:00/device:0f/device:10'
[   29.899976] ACPI: Device does not support D3cold
[   29.899978] kobject: 'device:10' (ffff8804079731f0): kobject_cleanup
[   29.899979] kobject: 'device:10' (ffff8804079731f0): calling ktype
release
[   29.899982] kobject: 'device:10': free name
[   29.900025] kobject: 'device:11' (ffff8804079739f0): kobject_uevent_env
[   29.900028] kobject: 'device:11' (ffff8804079739f0): fill_kobj_path:
path = '/devices/LNXSYSTM:00/device:00/PNP0A08:00/device:0f/device:11'
[   29.900033] ACPI: Device does not support D3cold
[   29.900035] kobject: 'device:11' (ffff8804079739f0): kobject_cleanup
[   29.900036] kobject: 'device:11' (ffff8804079739f0): calling ktype
release
[   29.900038] kobject: 'device:11': free name
[   29.900105] kobject: 'device:12' (ffff8804079741f0): kobject_uevent_env
[   29.900106] kobject: 'device:12' (ffff8804079741f0): fill_kobj_path:
path = '/devices/LNXSYSTM:00/device:00/PNP0A08:00/device:0f/device:12'
[   29.900112] ACPI: Device does not support D3cold
[   29.900114] kobject: 'device:12' (ffff8804079741f0): kobject_cleanup
[   29.900114] kobject: 'device:12' (ffff8804079741f0): calling ktype
release
[   29.900117] kobject: 'device:12': free name
[   29.900163] kobject: 'device:14' (ffff8804079751f0): kobject_uevent_env
[   29.900164] kobject: 'device:14' (ffff8804079751f0): fill_kobj_path:
path = '/devices/LNXSYSTM:00/device:00/PNP0A08:00/device:13/device:14'
[   29.900171] ACPI: Device does not support D3cold
[   29.900174] kobject: 'device:14' (ffff8804079751f0): kobject_cleanup
[   29.900175] kobject: 'device:14' (ffff8804079751f0): calling ktype
release
[   29.900178] kobject: 'device:14': free name
[   30.404233] irq 16: nobody cared (try booting with the "irqpoll" option)
[   30.404272] CPU: 0 PID: 0 Comm: swapper/0 Tainted: G        W
3.11.0-rc2-ARCH #66
[   30.404274] Hardware name: CLEVO CO.                        W55xEU
                        /W55xEU                          , BIOS 4.6.5
03/05/2013
[   30.404275]  ffff8804078bd38c ffff88041e203e48 ffffffff81459fe9
ffff8804078bd300
[   30.404278]  ffff88041e203e70 ffffffff810d8632 ffff8804078bd300
0000000000000010
[   30.404280]  0000000000000000 ffff88041e203eb0 ffffffff810d8a58
ffffffff8136a882
[   30.404282] Call Trace:
[   30.404284]  <IRQ>  [<ffffffff81459fe9>] dump_stack+0x54/0x8d
[   30.404293]  [<ffffffff810d8632>] __report_bad_irq+0x32/0xd0
[   30.404296]  [<ffffffff810d8a58>] note_interrupt+0x138/0x1f0
[   30.404299]  [<ffffffff8136a882>] ? cpuidle_enter_state+0x52/0xc0
[   30.404302]  [<ffffffff810d6439>] handle_irq_event_percpu+0xf9/0x250
[   30.404304]  [<ffffffff810d65cd>] handle_irq_event+0x3d/0x60
[   30.404306]  [<ffffffff810d95ca>] handle_fasteoi_irq+0x5a/0x100
[   30.404309]  [<ffffffff81004a6e>] handle_irq+0x1e/0x30
[   30.404312]  [<ffffffff8146aafd>] do_IRQ+0x4d/0xc0
[   30.404314]  [<ffffffff8146116d>] common_interrupt+0x6d/0x6d
[   30.404315]  <EOI>  [<ffffffff8136a882>] ? cpuidle_enter_state+0x52/0xc0
[   30.404319]  [<ffffffff8136a878>] ? cpuidle_enter_state+0x48/0xc0
[   30.404321]  [<ffffffff8136a9b9>] cpuidle_idle_call+0xc9/0x280
[   30.404325]  [<ffffffff8100bf6e>] arch_cpu_idle+0xe/0x30
[   30.404328]  [<ffffffff810a1287>] cpu_startup_entry+0x257/0x2d0
[   30.404330]  [<ffffffff8144d404>] rest_init+0x84/0x90
[   30.404333]  [<ffffffff818d9ee1>] start_kernel+0x414/0x420
[   30.404335]  [<ffffffff818d98d6>] ? repair_env_string+0x5c/0x5c
[   30.404337]  [<ffffffff818d9120>] ? early_idt_handlers+0x120/0x120
[   30.404339]  [<ffffffff818d95be>] x86_64_start_reservations+0x2a/0x2c
[   30.404342]  [<ffffffff818d96c8>] x86_64_start_kernel+0x108/0x117
[   30.404343] handlers:
[   30.404363] [<ffffffffa00168f0>] usb_hcd_irq [usbcore]
[   30.404383] Disabling IRQ #16

.

Hi:

It seems that the card-reader was removed during suspend or resume, is that right? or did you removed by hand?

I want to know with Thomas' patch, after resume, is the card-reader and card-reader driver still exist?

if not exist, I also want to know which function called first, rtsx_pci_resume or rtsx_pci_remove, can you determine it? And IRQ16 seems not handled by rtsx_pci driver, so with Thomas' patch, is there still some go wrong?

Hi Francis,

We are trying to get the environment same with yours, so it may take some to solve this problem.
maybe next month.

Hi Francis,

Adding Lee to the Cc list.

Quoted 2 lines · Francis Moreau

Now that you did the hard work, I hope driver's maintainer/developper will care about this issue.

I applied Thomas' patch to mfd-fixes.
Thanks a lot to you and Thomas for that.

Quoted 51 lines · Francis Moreau

Quoted 41 lines · Rafael J. Wysocki

Quoted 40 lines · Francis Moreau

Quoted 20 lines · Francis Moreau

Le 21/11/2013 12:17, Jingoo Han a écrit :
[...]

Quoted 12 lines

Quoted 11 lines

Quoted 11 lines

Also I took a look at the changes between v3.11 and v3.12 in this area and those changes match the issue I'm facing:

$ git log --oneline v3.11..v3.12 -- drivers/mfd/rtsx_pcr.c
09fd867 mfd: rtsx: Copyright modifications
eb891c6 mfd: rtsx: Configure to enter a deeper power-saving mode in S3
7140812 mfd: rtsx: Move some actions from rtsx_pci_init_hw to individual
extra_init_hw
5947c16 mfd: rtsx: Add shutdown callback in rtsx_pci_driver
773ccdf mfd: rtsx: Read vendor setting from config space

Quoted 5 lines

In my opinion, rtsx_pci_resume()/rtsx_pci_suspend() in realtek PCIe card reader driver may make the kernel panic.

I think that the commit "mfd: rtsx: Configure to enter a deeper power-saving mode in S3" may be the culprit.

Quoted 8 lines

Unfortunately no, reverting this commit on top of v3.12 doesn't help. I also reverted 7140812, 5947c16 but it didn't improve anything.

The good news is that I managed to have a "light" kernel configuration which is faster to build and more important it seems that the bug is almost 100% reproductible now.

So I'll try to do another git-bisect session later.

So after bisecting between v3.11..v3.12 range, git bisect told me:

the first bad commit is 551f5c74e17ba9257cdc35bf657ee448cad2d5b0

Merge branch 'acpi-processor'

* acpi-processor:
ACPI / processor: Acquire writer lock to update CPU maps ACPI / processor: Remove acpi_processor_get_limit_info()

Quoted 8 lines

Quoted 5 lines

The two commits brought by the merge are not the culprits because reseting HEAD on "ACPI / processor: Acquire writer lock to update CPU maps" doesn't have the issue anymore.

At that point I'm not sure how to bisect futher.

Does the second parent of this merge (that is, 8462d9df9d50) have the problem?

Quoted 7 lines

Yes it does.

Ok, I've finally managed to find out the bad commit:
ad07277e82dedabacc52c82746633680a3187d25: ACPI / PM: Hold acpi_scan_lock over system PM transitions

I verified that the parent commit doesn't have the problem.

Interesting.

Quoted 1 line

Rafael, you're the man now ;)

I kind of don't see how that commit may result in behavior that you described earlier in the thread.

You get a memory corruption that seems to have started to happen because we're holding an additional lock over suspend resume now. Something's fishy on that machine and we need to figure out what it is.

Please file a bug at bugzilla.kernel.org against ACPI and assign it to me. Please put all of the relevant info in there and attach the output of dmesg after a fresh boot and the output of acpidump from the affected machine to the bug entry.