right after the return of call to _raw_write_lock_irqsave, which should be fixed up by the instruction that recover the toc, IIUC. How that end up being a call to _cond_resched() is still unknown.
Besides, Pooja, I cannot reproduce this in a PowerKVM guest with 16 VCPUs. What's your setup for the machine that hit the problem? And how many times you need to run the testcase in order to hit one?
------- Comment From <email address hidden> 2017-02-06 03:07 EDT------- to+0x2e0/ 0x4c0 0x300/0x990 0x78/0xa0 rwlock_ write_lock_ irq+0x30/ 0x60 [locktorture]
(In reply to comment #71)
> Hi,
>
> Ran runltp on 17.04, and ended up with continuous call traces on console.
>
> ---uname output---
> Linux ltc-garri1 4.9.0-15-generic #16-Ubuntu SMP Fri Jan 20 15:28:49 UTC
> 2017 ppc64le ppc64le ppc64le GNU/Linux
>
> ---Call Trace---
> [332850.158228] Call Trace:
> [332850.158253] [c000001fcec4fb50] [c00000000001c3a0] __switch_
> [332850.159375] [c000001fcec4fbb0] [c000000000b193a0] __schedule+
> [332850.159872] [c000001fcec4fc90] [c000000000b19e88] _cond_resched+
> [332850.160475] [c000001fcec4fcc0] [d00000001c810278]
> torture_
This one is weird, because torture_ rwlock_ write_lock_ irq will acquire a lock with irq disabled, so it will not get any change to reschedule..
And the asm code for /lib/modules/ 4.9.0-15- generic/ kernel/ kernel/ locking/ locktorture. ko:
0000000000000248 <torture_ rwlock_ write_lock_ irq>: rwlock_ write_lock_ irq+0xc> rwlock_ write_lock_ irq+0x2c> lock_irqsave
248: f8 ff 4c e8 ld r2,-8(r12)
248: R_PPC64_ENTRY *ABS*
24c: 14 62 42 7c add r2,r2,r12
250: a6 02 08 7c mflr r0
254: 01 00 00 48 bl 254 <torture_
254: R_PPC64_REL24 _mcount
258: a6 02 08 7c mflr r0
25c: f8 ff e1 fb std r31,-8(r1)
260: 10 00 01 f8 std r0,16(r1)
264: d1 ff 21 f8 stdu r1,-48(r1)
268: 00 00 22 3d addis r9,r2,0
268: R_PPC64_TOC16_HA .toc
26c: 00 00 e9 eb ld r31,0(r9)
26c: R_PPC64_TOC16_LO_DS .toc
270: 30 00 7f 38 addi r3,r31,48
274: 01 00 00 48 bl 274 <torture_
274: R_PPC64_REL24 _raw_write_
278: 00 00 00 60 nop
27c: 18 00 3f e9 ld r9,24(r31)
280: 40 00 69 f8 std r3,64(r9)
284: 00 00 60 38 li r3,0
288: 30 00 21 38 addi r1,r1,48
so torture_ rwlock_ write_lock_ irq+0x30/ 0x60 is
278: 00 00 00 60 nop
right after the return of call to _raw_write_ lock_irqsave, which should be fixed up by the instruction that recover the toc, IIUC. How that end up being a call to _cond_resched() is still unknown.
Besides, Pooja, I cannot reproduce this in a PowerKVM guest with 16 VCPUs. What's your setup for the machine that hit the problem? And how many times you need to run the testcase in order to hit one?
Regards,
Boqun
> [332850.161157] [c000001fcec4fcf0] [d00000001c810988] writer+ 0xc0/0x270 [locktorture] kernel_ thread+ 0x5c/0x74 +0xa0/0xe0 task_switch+ 0xb0/0x340 wait+0x8c/ 0x130 [torture] common+ 0x114/0x180 (unreliable) shutdown_ init+0x2a4/ 0x770 wait+0x8c/ 0x130 [torture] rwlock_ write_lock_ irq+0x30/ 0x60 [locktorture] (unreliable) writer+ 0xc0/0x270 [locktorture] kernel_ thread+ 0x5c/0x74 interrupt+ 0x11c/0x2a0 (unreliable) to+0x2e0/ 0x4c0 0x300/0x990 base+0xa8/ 0x100 del_timer_ sync+0x68/ 0xa0 sync+0x70/ 0x90 timeout+ 0x234/0x470 rwlock_ write_lock_ irq+0x30/ 0x60 [locktorture] writer+ 0xc0/0x270 [locktorture] kernel_ thread+ 0x5c/0x74
> lock_torture_
> [332850.170046] [c000001fcec4fd80] [c0000000000f53c0] kthread+0x110/0x130
> [332850.173108] [c000001fcec4fe30] [c00000000000c0e8]
> ret_from_
> [332850.174169] Task dump for CPU 10:
> [332850.174202] lock_torture_wr R running task 0 37019 2
> 0x00000804
> [332850.174734] Call Trace:
> [332850.175218] [c000001fcf3ab980] [c0000000000d0008] irq_exit+0xe8/0x120
> (unreliable)
> [332850.175813] [c000001fcf3ab9a0] [c000000000024e10]
> timer_interrupt
> [332850.176438] --- interrupt: d00000001c6008c0 at
> finish_
> [332850.176438] LR = stutter_
> [332850.177950] [c000001fcf3ab9d0] [c000000000009514]
> decrementer_
> [332850.178517] --- interrupt: 901 at torture_
> [torture]
> [332850.178517] LR = stutter_
> [332850.179557] [c000001fcf3abcc0] [d00000001c810278]
> torture_
> [332850.180675] [c000001fcf3abcf0] [d00000001c810988]
> lock_torture_
> [332850.181646] [c000001fcf3abd80] [c0000000000f53c0] kthread+0x110/0x130
> [332850.194048] [c000001fcf3abe30] [c00000000000c0e8]
> ret_from_
> [332850.196658] Task dump for CPU 12:
> [332850.198840] lock_torture_wr R running task 0 36921 2
> 0x00000804
> [332850.201377] Call Trace:
> [332850.201402] [c000001fc3747890] [c00000000016127c]
> hrtimer_
> [332850.206296] [c000001fc3747a60] [c00000000001c3a0] __switch_
> [332850.208647] [c000001fc3747ac0] [c000000000b193a0] __schedule+
> [332850.211007] [c000001fc3747b00] [c00000000015bc78]
> lock_timer_
> [332850.214641] [c000001fc3747b60] [c00000000015bde8]
> try_to_
> [332850.215236] [c000001fc3747ba0] [c00000000015be90]
> del_timer_
> [332850.215817] [c000001fc3747bd0] [c000000000b1de14]
> schedule_
> [332850.216369] [c000001fc3747cc0] [d00000001c810278]
> torture_
> [332850.217397] [c000001fc3747cf0] [d00000001c810988]
> lock_torture_
> [332850.218433] [c000001fc3747d80] [c0000000000f53c0] kthread+0x110/0x130
> [332850.219013] [c000001fc3747e30] [c00000000000c0e8]
> ret_from_
>
>
> Thanks,
> Pooja