* ppc64le kernel panic on 5.2.9-rc1 @ 2019-08-15 12:29 Major Hayden 2019-08-16 11:14 ` Oops in blk_mq_get_request() (was Re: ppc64le kernel panic on 5.2.9-rc1) Michael Ellerman 0 siblings, 1 reply; 4+ messages in thread From: Major Hayden @ 2019-08-15 12:29 UTC (permalink / raw) To: linuxppc-dev Hello there, The CKI Project just found a kernel panic while running the blktests test suite on stable 5.2.9-rc1[0]. Michael Ellerman requested for this list to be copied on these ppc64le failures. We have some logs[1] for these failures and they start with "ppc64le_host_2_Storage_blktests*". We hope this helps! [0] https://lore.kernel.org/stable/255f9af4-6087-7f56-5860-5aa0397a7631@redhat.com/T/#t [1] https://artifacts.cki-project.org/pipelines/100875/logs/ -- Major Hayden ^ permalink raw reply [flat|nested] 4+ messages in thread
* Oops in blk_mq_get_request() (was Re: ppc64le kernel panic on 5.2.9-rc1) 2019-08-15 12:29 ppc64le kernel panic on 5.2.9-rc1 Major Hayden @ 2019-08-16 11:14 ` Michael Ellerman 2019-08-16 12:34 ` Ming Lei 0 siblings, 1 reply; 4+ messages in thread From: Michael Ellerman @ 2019-08-16 11:14 UTC (permalink / raw) To: Major Hayden, linuxppc-dev, Jens Axboe, linux-block Major Hayden <major@redhat.com> writes: > Hello there, > > The CKI Project just found a kernel panic while running the blktests > test suite on stable 5.2.9-rc1[0]. Michael Ellerman requested for this > list to be copied on these ppc64le failures. > > We have some logs[1] for these failures and they start with > "ppc64le_host_2_Storage_blktests*". We hope this helps! > > [0] https://lore.kernel.org/stable/255f9af4-6087-7f56-5860-5aa0397a7631@redhat.com/T/#t > [1] https://artifacts.cki-project.org/pipelines/100875/logs/ Thanks for the report. It looks like you tested the stable queue yesterday, which AFAICS results in the exact same source tree as you tested above, and yet yesterday you didn't see the failure. So it's intermittent, which is annoying. Looking at the oops: [ 7101.930385] NIP: c00000000067b230 LR: c00000000067b1d4 CTR: c000000000029140 [ 7101.930400] REGS: c00020391ccc35c0 TRAP: 0300 Not tainted (5.2.9-rc1-2440e48.cki) [ 7101.930413] MSR: 900000000280b033 <SF,HV,VEC,VSX,EE,FP,ME,IR,DR,RI,LE> CR: 44002228 XER: 20040000 [ 7101.930433] CFAR: c0000000001d9e28 DAR: 800a00066b9e7e28 DSISR: 40000000 IRQMASK: 0 GPR00: c00000000067b1d4 c00020391ccc3850 c0000000016cdb00 0000067578a4ab31 GPR04: 0000000000000000 ffffffffffffffff 0000000001f3fb0e 0000000000000001 GPR08: 800a00066b9e7d80 800a00066b9e7d80 0000000000000001 c00800000cd5db88 r9 GPR12: c000000000029140 c000203fff6b9800 0000000000000008 c00800000d5751e0 GPR16: c000203985a8a6c0 c00800000e013278 c000203985a8a700 0000000000000038 GPR20: 0000000000000030 0000000000000028 0000000000000020 fffffffffffff000 GPR24: 0000000000000001 0000000000000400 0000000000000000 0000000000000023 GPR28: 0000000000000000 0000000000000000 c00020391ccc38c8 c000003ef1b00000 [ 7101.930544] NIP [c00000000067b230] blk_mq_get_request+0x260/0x4b0 [ 7101.930557] LR [c00000000067b1d4] blk_mq_get_request+0x204/0x4b0 [ 7101.930569] Call Trace: [ 7101.930577] [c00020391ccc3850] [c00000000067b1d4] blk_mq_get_request+0x204/0x4b0 (unreliable) [ 7101.930594] [c00020391ccc38a0] [c00000000067b688] blk_mq_alloc_request_hctx+0x108/0x1b0 [ 7101.930617] [c00020391ccc3910] [c00800000cd51aac] nvme_alloc_request+0x54/0xe0 [nvme_core] [ 7101.930633] [c00020391ccc3940] [c00800000cd5641c] __nvme_submit_sync_cmd+0x64/0x290 [nvme_core] [ 7101.930651] [c00020391ccc39c0] [c00800000d571650] nvmf_connect_io_queue+0x148/0x1e0 [nvme_fabrics] [ 7101.930668] [c00020391ccc3ab0] [c00800000e0106b0] nvme_loop_connect_io_queues+0x98/0xf8 [nvme_loop] [ 7101.930684] [c00020391ccc3af0] [c00800000e01116c] nvme_loop_create_ctrl+0x434/0x6a0 [nvme_loop] [ 7101.930700] [c00020391ccc3bd0] [c00800000d5724f0] nvmf_dev_write+0xd38/0x124c [nvme_fabrics] [ 7101.930719] [c00020391ccc3d60] [c000000000421e58] __vfs_write+0x38/0x70 [ 7101.930731] [c00020391ccc3d80] [c000000000426188] vfs_write+0xd8/0x250 [ 7101.930744] [c00020391ccc3dd0] [c000000000426558] ksys_write+0x78/0x130 [ 7101.930758] [c00020391ccc3e20] [c00000000000bde4] system_call+0x5c/0x70 And then the disassembly: x = op_is_sync(op) r27 = op = 0x0000000000000023 c00000000067b1e0: 3e 06 67 57 clrlwi r7,r27,24 # r7 = r27 & REQ_OP_MASK c00000000067b1e4: 00 00 07 2c cmpwi r7,0 # if r7 == REQ_OP_READ, x = 1 then goto label2 x = 1 c00000000067b1e8: 01 00 20 39 li r9,1 ... r30 = data = c00020391ccc38c8 r8 = data->ctx = 800a00066b9e7d80 c00000000067b208: 18 00 1e e9 ld r8,24(r30) c00000000067b20c: 18 00 82 41 beq c00000000067b224 <blk_mq_get_request+0x254> -> label2 (op & (REQ_SYNC | REQ_FUA | REQ_PREFLUSH)) c00000000067b210: 1c 05 6a 57 rlwinm r10,r27,0,20,14 c00000000067b214: 68 03 4a 55 rlwinm r10,r10,0,13,20 c00000000067b218: 34 00 4a 7d cntlzw r10,r10 c00000000067b21c: 7e d9 4a 55 rlwinm r10,r10,27,5,31 c00000000067b220: 01 00 49 69 xori r9,r10,1 c00000000067b224: 24 1f 29 79 rldicr r9,r9,3,60 <- label2 r9 = x * 8 c00000000067b228: 01 00 e0 38 li r7,1 # for refcount_set r9 = data->ctx + x c00000000067b22c: 14 4a 28 7d add r9,r8,r9 data->ctx->rq_dispatched[op_is_sync(op)]++; r10 = data->ctx->rq_dispatched[x] c00000000067b230: a8 00 49 e9 ld r10,168(r9) <- NIP x++ c00000000067b234: 01 00 4a 39 addi r10,r10,1 data->ctx->rq_dispatched[x] = r10 c00000000067b238: a8 00 49 f9 std r10,168(r9) refcount_set(&rq->ref, 1); c00000000067b23c: d4 00 ff 90 stw r7,212(r31) So we're oopsing at data->ctx->rq_dispatched[op_is_sync(op)]++. data->ctx looks completely bogus, ie. 800a00066b9e7d80, that's not anything like a valid kernel address. And also op doesn't look like a valid op value, it's 0x23, which has no flag bits set, but also doesn't match any of the values in req_opf. So I suspect data is pointing somewhere bogus. Or possibly it used to point at a blk_mq_alloc_data but doesn't anymore. Why that's happened I have no idea. I can't see any obvious commits in mainline or stable that mention anything similar, maybe someone on linux-block recognises it? cheers ^ permalink raw reply [flat|nested] 4+ messages in thread
* Re: Oops in blk_mq_get_request() (was Re: ppc64le kernel panic on 5.2.9-rc1) 2019-08-16 11:14 ` Oops in blk_mq_get_request() (was Re: ppc64le kernel panic on 5.2.9-rc1) Michael Ellerman @ 2019-08-16 12:34 ` Ming Lei 0 siblings, 0 replies; 4+ messages in thread From: Ming Lei @ 2019-08-16 12:34 UTC (permalink / raw) To: Michael Ellerman; +Cc: Major Hayden, linuxppc-dev, Jens Axboe, linux-block On Fri, Aug 16, 2019 at 7:15 PM Michael Ellerman <mpe@ellerman.id.au> wrote: > > Major Hayden <major@redhat.com> writes: > > Hello there, > > > > The CKI Project just found a kernel panic while running the blktests > > test suite on stable 5.2.9-rc1[0]. Michael Ellerman requested for this > > list to be copied on these ppc64le failures. > > > > We have some logs[1] for these failures and they start with > > "ppc64le_host_2_Storage_blktests*". We hope this helps! > > > > [0] https://lore.kernel.org/stable/255f9af4-6087-7f56-5860-5aa0397a7631@redhat.com/T/#t > > [1] https://artifacts.cki-project.org/pipelines/100875/logs/ > > Thanks for the report. > > It looks like you tested the stable queue yesterday, which AFAICS > results in the exact same source tree as you tested above, and yet > yesterday you didn't see the failure. So it's intermittent, which is > annoying. > > Looking at the oops: > > [ 7101.930385] NIP: c00000000067b230 LR: c00000000067b1d4 CTR: c000000000029140 > [ 7101.930400] REGS: c00020391ccc35c0 TRAP: 0300 Not tainted (5.2.9-rc1-2440e48.cki) > [ 7101.930413] MSR: 900000000280b033 <SF,HV,VEC,VSX,EE,FP,ME,IR,DR,RI,LE> CR: 44002228 XER: 20040000 > [ 7101.930433] CFAR: c0000000001d9e28 DAR: 800a00066b9e7e28 DSISR: 40000000 IRQMASK: 0 > GPR00: c00000000067b1d4 c00020391ccc3850 c0000000016cdb00 0000067578a4ab31 > GPR04: 0000000000000000 ffffffffffffffff 0000000001f3fb0e 0000000000000001 > GPR08: 800a00066b9e7d80 800a00066b9e7d80 0000000000000001 c00800000cd5db88 > r9 > GPR12: c000000000029140 c000203fff6b9800 0000000000000008 c00800000d5751e0 > GPR16: c000203985a8a6c0 c00800000e013278 c000203985a8a700 0000000000000038 > GPR20: 0000000000000030 0000000000000028 0000000000000020 fffffffffffff000 > GPR24: 0000000000000001 0000000000000400 0000000000000000 0000000000000023 > GPR28: 0000000000000000 0000000000000000 c00020391ccc38c8 c000003ef1b00000 > [ 7101.930544] NIP [c00000000067b230] blk_mq_get_request+0x260/0x4b0 > [ 7101.930557] LR [c00000000067b1d4] blk_mq_get_request+0x204/0x4b0 > [ 7101.930569] Call Trace: > [ 7101.930577] [c00020391ccc3850] [c00000000067b1d4] blk_mq_get_request+0x204/0x4b0 (unreliable) > [ 7101.930594] [c00020391ccc38a0] [c00000000067b688] blk_mq_alloc_request_hctx+0x108/0x1b0 > [ 7101.930617] [c00020391ccc3910] [c00800000cd51aac] nvme_alloc_request+0x54/0xe0 [nvme_core] > [ 7101.930633] [c00020391ccc3940] [c00800000cd5641c] __nvme_submit_sync_cmd+0x64/0x290 [nvme_core] > [ 7101.930651] [c00020391ccc39c0] [c00800000d571650] nvmf_connect_io_queue+0x148/0x1e0 [nvme_fabrics] > [ 7101.930668] [c00020391ccc3ab0] [c00800000e0106b0] nvme_loop_connect_io_queues+0x98/0xf8 [nvme_loop] > [ 7101.930684] [c00020391ccc3af0] [c00800000e01116c] nvme_loop_create_ctrl+0x434/0x6a0 [nvme_loop] > [ 7101.930700] [c00020391ccc3bd0] [c00800000d5724f0] nvmf_dev_write+0xd38/0x124c [nvme_fabrics] > [ 7101.930719] [c00020391ccc3d60] [c000000000421e58] __vfs_write+0x38/0x70 > [ 7101.930731] [c00020391ccc3d80] [c000000000426188] vfs_write+0xd8/0x250 > [ 7101.930744] [c00020391ccc3dd0] [c000000000426558] ksys_write+0x78/0x130 > [ 7101.930758] [c00020391ccc3e20] [c00000000000bde4] system_call+0x5c/0x70 > > And then the disassembly: > > x = op_is_sync(op) > r27 = op = 0x0000000000000023 > c00000000067b1e0: 3e 06 67 57 clrlwi r7,r27,24 # r7 = r27 & REQ_OP_MASK > > c00000000067b1e4: 00 00 07 2c cmpwi r7,0 # if r7 == REQ_OP_READ, x = 1 then goto label2 > x = 1 > c00000000067b1e8: 01 00 20 39 li r9,1 > > ... > > r30 = data = c00020391ccc38c8 > r8 = data->ctx = 800a00066b9e7d80 > c00000000067b208: 18 00 1e e9 ld r8,24(r30) > c00000000067b20c: 18 00 82 41 beq c00000000067b224 <blk_mq_get_request+0x254> -> label2 > > (op & (REQ_SYNC | REQ_FUA | REQ_PREFLUSH)) > c00000000067b210: 1c 05 6a 57 rlwinm r10,r27,0,20,14 > c00000000067b214: 68 03 4a 55 rlwinm r10,r10,0,13,20 > c00000000067b218: 34 00 4a 7d cntlzw r10,r10 > c00000000067b21c: 7e d9 4a 55 rlwinm r10,r10,27,5,31 > c00000000067b220: 01 00 49 69 xori r9,r10,1 > > c00000000067b224: 24 1f 29 79 rldicr r9,r9,3,60 <- label2 > r9 = x * 8 > > c00000000067b228: 01 00 e0 38 li r7,1 # for refcount_set > > r9 = data->ctx + x > c00000000067b22c: 14 4a 28 7d add r9,r8,r9 > > data->ctx->rq_dispatched[op_is_sync(op)]++; > > r10 = data->ctx->rq_dispatched[x] > c00000000067b230: a8 00 49 e9 ld r10,168(r9) <- NIP > > x++ > c00000000067b234: 01 00 4a 39 addi r10,r10,1 > > data->ctx->rq_dispatched[x] = r10 > c00000000067b238: a8 00 49 f9 std r10,168(r9) > > refcount_set(&rq->ref, 1); > c00000000067b23c: d4 00 ff 90 stw r7,212(r31) > > > So we're oopsing at data->ctx->rq_dispatched[op_is_sync(op)]++. > > data->ctx looks completely bogus, ie. 800a00066b9e7d80, that's not > anything like a valid kernel address. > > And also op doesn't look like a valid op value, it's 0x23, which has no > flag bits set, but also doesn't match any of the values in req_opf. > > So I suspect data is pointing somewhere bogus. Or possibly it used to > point at a blk_mq_alloc_data but doesn't anymore. > > Why that's happened I have no idea. I can't see any obvious commits in > mainline or stable that mention anything similar, maybe someone on > linux-block recognises it? > > cheers Please try: https://git.kernel.org/pub/scm/linux/kernel/git/axboe/linux-block.git/commit/?h=for-5.4/block&id=556f36e90dbe7dded81f4fac084d2bc8a2458330 Strictly speaking, it is still a workaround, but it works in case that CPU hotplug isn't involved. Thanks, Ming Lei ^ permalink raw reply [flat|nested] 4+ messages in thread
* Re: Oops in blk_mq_get_request() (was Re: ppc64le kernel panic on 5.2.9-rc1) @ 2019-08-16 12:34 ` Ming Lei 0 siblings, 0 replies; 4+ messages in thread From: Ming Lei @ 2019-08-16 12:34 UTC (permalink / raw) To: Michael Ellerman; +Cc: Major Hayden, Jens Axboe, linuxppc-dev, linux-block On Fri, Aug 16, 2019 at 7:15 PM Michael Ellerman <mpe@ellerman.id.au> wrote: > > Major Hayden <major@redhat.com> writes: > > Hello there, > > > > The CKI Project just found a kernel panic while running the blktests > > test suite on stable 5.2.9-rc1[0]. Michael Ellerman requested for this > > list to be copied on these ppc64le failures. > > > > We have some logs[1] for these failures and they start with > > "ppc64le_host_2_Storage_blktests*". We hope this helps! > > > > [0] https://lore.kernel.org/stable/255f9af4-6087-7f56-5860-5aa0397a7631@redhat.com/T/#t > > [1] https://artifacts.cki-project.org/pipelines/100875/logs/ > > Thanks for the report. > > It looks like you tested the stable queue yesterday, which AFAICS > results in the exact same source tree as you tested above, and yet > yesterday you didn't see the failure. So it's intermittent, which is > annoying. > > Looking at the oops: > > [ 7101.930385] NIP: c00000000067b230 LR: c00000000067b1d4 CTR: c000000000029140 > [ 7101.930400] REGS: c00020391ccc35c0 TRAP: 0300 Not tainted (5.2.9-rc1-2440e48.cki) > [ 7101.930413] MSR: 900000000280b033 <SF,HV,VEC,VSX,EE,FP,ME,IR,DR,RI,LE> CR: 44002228 XER: 20040000 > [ 7101.930433] CFAR: c0000000001d9e28 DAR: 800a00066b9e7e28 DSISR: 40000000 IRQMASK: 0 > GPR00: c00000000067b1d4 c00020391ccc3850 c0000000016cdb00 0000067578a4ab31 > GPR04: 0000000000000000 ffffffffffffffff 0000000001f3fb0e 0000000000000001 > GPR08: 800a00066b9e7d80 800a00066b9e7d80 0000000000000001 c00800000cd5db88 > r9 > GPR12: c000000000029140 c000203fff6b9800 0000000000000008 c00800000d5751e0 > GPR16: c000203985a8a6c0 c00800000e013278 c000203985a8a700 0000000000000038 > GPR20: 0000000000000030 0000000000000028 0000000000000020 fffffffffffff000 > GPR24: 0000000000000001 0000000000000400 0000000000000000 0000000000000023 > GPR28: 0000000000000000 0000000000000000 c00020391ccc38c8 c000003ef1b00000 > [ 7101.930544] NIP [c00000000067b230] blk_mq_get_request+0x260/0x4b0 > [ 7101.930557] LR [c00000000067b1d4] blk_mq_get_request+0x204/0x4b0 > [ 7101.930569] Call Trace: > [ 7101.930577] [c00020391ccc3850] [c00000000067b1d4] blk_mq_get_request+0x204/0x4b0 (unreliable) > [ 7101.930594] [c00020391ccc38a0] [c00000000067b688] blk_mq_alloc_request_hctx+0x108/0x1b0 > [ 7101.930617] [c00020391ccc3910] [c00800000cd51aac] nvme_alloc_request+0x54/0xe0 [nvme_core] > [ 7101.930633] [c00020391ccc3940] [c00800000cd5641c] __nvme_submit_sync_cmd+0x64/0x290 [nvme_core] > [ 7101.930651] [c00020391ccc39c0] [c00800000d571650] nvmf_connect_io_queue+0x148/0x1e0 [nvme_fabrics] > [ 7101.930668] [c00020391ccc3ab0] [c00800000e0106b0] nvme_loop_connect_io_queues+0x98/0xf8 [nvme_loop] > [ 7101.930684] [c00020391ccc3af0] [c00800000e01116c] nvme_loop_create_ctrl+0x434/0x6a0 [nvme_loop] > [ 7101.930700] [c00020391ccc3bd0] [c00800000d5724f0] nvmf_dev_write+0xd38/0x124c [nvme_fabrics] > [ 7101.930719] [c00020391ccc3d60] [c000000000421e58] __vfs_write+0x38/0x70 > [ 7101.930731] [c00020391ccc3d80] [c000000000426188] vfs_write+0xd8/0x250 > [ 7101.930744] [c00020391ccc3dd0] [c000000000426558] ksys_write+0x78/0x130 > [ 7101.930758] [c00020391ccc3e20] [c00000000000bde4] system_call+0x5c/0x70 > > And then the disassembly: > > x = op_is_sync(op) > r27 = op = 0x0000000000000023 > c00000000067b1e0: 3e 06 67 57 clrlwi r7,r27,24 # r7 = r27 & REQ_OP_MASK > > c00000000067b1e4: 00 00 07 2c cmpwi r7,0 # if r7 == REQ_OP_READ, x = 1 then goto label2 > x = 1 > c00000000067b1e8: 01 00 20 39 li r9,1 > > ... > > r30 = data = c00020391ccc38c8 > r8 = data->ctx = 800a00066b9e7d80 > c00000000067b208: 18 00 1e e9 ld r8,24(r30) > c00000000067b20c: 18 00 82 41 beq c00000000067b224 <blk_mq_get_request+0x254> -> label2 > > (op & (REQ_SYNC | REQ_FUA | REQ_PREFLUSH)) > c00000000067b210: 1c 05 6a 57 rlwinm r10,r27,0,20,14 > c00000000067b214: 68 03 4a 55 rlwinm r10,r10,0,13,20 > c00000000067b218: 34 00 4a 7d cntlzw r10,r10 > c00000000067b21c: 7e d9 4a 55 rlwinm r10,r10,27,5,31 > c00000000067b220: 01 00 49 69 xori r9,r10,1 > > c00000000067b224: 24 1f 29 79 rldicr r9,r9,3,60 <- label2 > r9 = x * 8 > > c00000000067b228: 01 00 e0 38 li r7,1 # for refcount_set > > r9 = data->ctx + x > c00000000067b22c: 14 4a 28 7d add r9,r8,r9 > > data->ctx->rq_dispatched[op_is_sync(op)]++; > > r10 = data->ctx->rq_dispatched[x] > c00000000067b230: a8 00 49 e9 ld r10,168(r9) <- NIP > > x++ > c00000000067b234: 01 00 4a 39 addi r10,r10,1 > > data->ctx->rq_dispatched[x] = r10 > c00000000067b238: a8 00 49 f9 std r10,168(r9) > > refcount_set(&rq->ref, 1); > c00000000067b23c: d4 00 ff 90 stw r7,212(r31) > > > So we're oopsing at data->ctx->rq_dispatched[op_is_sync(op)]++. > > data->ctx looks completely bogus, ie. 800a00066b9e7d80, that's not > anything like a valid kernel address. > > And also op doesn't look like a valid op value, it's 0x23, which has no > flag bits set, but also doesn't match any of the values in req_opf. > > So I suspect data is pointing somewhere bogus. Or possibly it used to > point at a blk_mq_alloc_data but doesn't anymore. > > Why that's happened I have no idea. I can't see any obvious commits in > mainline or stable that mention anything similar, maybe someone on > linux-block recognises it? > > cheers Please try: https://git.kernel.org/pub/scm/linux/kernel/git/axboe/linux-block.git/commit/?h=for-5.4/block&id=556f36e90dbe7dded81f4fac084d2bc8a2458330 Strictly speaking, it is still a workaround, but it works in case that CPU hotplug isn't involved. Thanks, Ming Lei ^ permalink raw reply [flat|nested] 4+ messages in thread
end of thread, other threads:[~2019-08-16 12:37 UTC | newest] Thread overview: 4+ messages (download: mbox.gz / follow: Atom feed) -- links below jump to the message on this page -- 2019-08-15 12:29 ppc64le kernel panic on 5.2.9-rc1 Major Hayden 2019-08-16 11:14 ` Oops in blk_mq_get_request() (was Re: ppc64le kernel panic on 5.2.9-rc1) Michael Ellerman 2019-08-16 12:34 ` Ming Lei 2019-08-16 12:34 ` Ming Lei
This is an external index of several public inboxes, see mirroring instructions on how to clone and mirror all data and code used by this external index.