Jonathan Cameron wrote: > On Tue, 06 Feb 2024 14:15:32 -0800 > Ira Weiny <ira.weiny@xxxxxxxxx> wrote: > > > Smatch caught that cxl_cper_post_event() is called with a spinlock held > > or preemption disabled.[1] The callback takes the device lock to > > perform address translation and therefore might sleep. The record data > > is released back to BIOS in ghes_clear_estatus() which requires it to be > > copied for use in the workqueue. > > > > Copy the record to a lockless list and schedule a work item to process > > the record outside of atomic context. > > > > [1] https://lore.kernel.org/all/b963c490-2c13-4b79-bbe7-34c6568423c7@moroto.mountain/ > > > > Reported-by: Dan Carpenter <dan.carpenter@xxxxxxxxxx> > > Signed-off-by: Ira Weiny <ira.weiny@xxxxxxxxx> > > +CC tracing folk for the splat below (the second one as first one is fixed!) > > Lock debugging is slow (on an emulated machine) :( > Testing with my gitlab.com/jic23/qemu cxl-2024-02-05-draft branch > which is only one I've put out with the FW first injection patches so far > > For reference without this patch I got a nice spat identifying the original bug. > So far so good. > > With this patch (and tp_printk in command line and trace points enabled) > [ 193.048229] {1}[Hardware Error]: Hardware error from APEI Generic Hardware Error Source: 1 > [ 193.049636] {1}[Hardware Error]: event severity: recoverable > [ 193.050472] {1}[Hardware Error]: Error 0, type: recoverable > [ 193.051337] {1}[Hardware Error]: section type: unknown, fbcd0a77-c260-417f-85a9-088b1621eba6 > [ 193.052270] {1}[Hardware Error]: section length: 0x90 > [ 193.053402] {1}[Hardware Error]: 00000000: 00000090 00000007 00000000 0d938086 ................ > [ 193.055036] {1}[Hardware Error]: 00000010: 000e0000 00000000 00000005 00000000 ................ > [ 193.058592] {1}[Hardware Error]: 00000020: 00000180 00000000 1626fa24 17b3b158 ........$.&.X... > [ 193.062289] {1}[Hardware Error]: 00000030: 00000000 00000000 00000000 00000000 ................ > [ 193.065959] {1}[Hardware Error]: 00000040: 000007d0 00000000 0fc00307 05210300 ..............!. > [ 193.069782] {1}[Hardware Error]: 00000050: 72690000 6d207361 00326d65 00000000 ..iras mem2..... > [ 193.072760] {1}[Hardware Error]: 00000060: 00000000 00000000 00000000 00000000 ................ > [ 193.074062] {1}[Hardware Error]: 00000070: 00000000 00000000 00000000 00000000 ................ > [ 193.075346] {1}[Hardware Error]: 00000080: 00000000 00000000 00000000 00000000 ................ > > I rebased after this so now we get the smaller print - but that's not really relevant here. > > [ 193.086589] cxl_general_media: memdev=mem1 host=0000:0e:00.0 serial=5 log=Warning : time=1707903675590441508 uuid=fbcd0a77-c260-417f-85a9-088b1621eba6 len=128 flags='0x1' handle=0 related_handle=0 maint_op_class=0 : dpa=7c0 dpa_flags='0x10' descriptor='UNCORRECTABLE_EVENT|THRESHOLD_EVENT|POISON_LIST_OVERFLOW' type='0x3' transaction_type='0xc0' channel=3 rank=33 device=5 comp_id=69 72 61 73 20 6d 65 6d 32 00 00 00 00 00 00 00 validity_flags='CHANNEL|RANK|DEVICE|COMPONENT' > [ 193.087181] > [ 193.087361] ============================= > [ 193.087399] [ BUG: Invalid wait context ] > [ 193.087504] 6.8.0-rc3 #1200 Not tainted > [ 193.087660] ----------------------------- > [ 193.087858] kworker/3:0/31 is trying to lock: > [ 193.087966] ffff0000c0ce1898 (&port_lock_key){-.-.}-{3:3}, at: pl011_console_write+0x148/0x1c8 > [ 193.089754] other info that might help us debug this: > [ 193.089820] context-{5:5}[ 193.089900] 8 locks held by kworker/3:0/31: > [ 193.089990] #0: ffff0000c0018738 ((wq_completion)events){+.+.}-{0:0}, at: process_one_work+0x154/0x500 > [ 193.090439] #1: ffff800083793de0 (cxl_cper_work){+.+.}-{0:0}, at: process_one_work+0x154/0x500 > [ 193.090718] #2: ffff800082883310 (cxl_cper_rw_sem){++++}-{4:4}, at: cxl_cper_work_fn+0x2c/0xb0 > [ 193.091019] #3: ffff0000c0a7b1a8 (&dev->mutex){....}-{4:4}, at: pci_dev_lock+0x28/0x48 > [ 193.091431] #4: ffff800082738f18 (tracepoint_iter_lock){....}-{2:2}, at: trace_event_buffer_commit+0xd8/0x2c8 > [ 193.091772] #5: ffff8000826b3ce8 (console_lock){+.+.}-{0:0}, at: vprintk_emit+0x124/0x398 > [ 193.092031] #6: ffff8000826b3d40 (console_srcu){....}-{0:0}, at: console_flush_all+0x88/0x4b0 > [ 193.092363] #7: ffff8000826b3ef8 (console_owner){....}-{0:0}, at: console_flush_all+0x1bc/0x4b0 > [ 193.092799] stack backtrace: > [ 193.092973] CPU: 3 PID: 31 Comm: kworker/3:0 Not tainted 6.8.0-rc3 #1200 > [ 193.093118] Hardware name: QEMU QEMU Virtual Machine, BIOS unknown unknown > [ 193.093468] Workqueue: events cxl_cper_work_fn > [ 193.093782] Call trace: > [ 193.094004] dump_backtrace+0xa4/0x130 > [ 193.094145] show_stack+0x20/0x38 > [ 193.094231] dump_stack_lvl+0x60/0xb0 > [ 193.094315] dump_stack+0x18/0x28 > [ 193.094395] __lock_acquire+0x9e8/0x1ee8 > [ 193.094477] lock_acquire+0x118/0x2e8 > [ 193.094557] _raw_spin_lock+0x50/0x70 > [ 193.094820] pl011_console_write+0x148/0x1c8 > [ 193.094904] console_flush_all+0x218/0x4b0 > [ 193.094985] console_unlock+0x74/0x140 > [ 193.095066] vprintk_emit+0x230/0x398 > [ 193.095146] vprintk_default+0x40/0x58 > [ 193.095226] vprintk+0x98/0xb0 > [ 193.095306] _printk+0x64/0x98 > [ 193.095385] trace_event_buffer_commit+0x138/0x2c8 > [ 193.095467] trace_event_raw_event_cxl_general_media+0x1a8/0x280 [cxl_core] > [ 193.096191] __traceiter_cxl_general_media+0x50/0x78 [cxl_core] > [ 193.096359] cxl_event_trace_record+0x204/0x2d0 [cxl_core] > [ 193.096520] cxl_cper_event_call+0xb0/0xe0 [cxl_pci] > > The rw_sem is held to protect the callback pointer. > > [ 193.096713] cxl_cper_work_fn+0x7c/0xb0 > [ 193.096808] process_one_work+0x1f4/0x500 > [ 193.096891] worker_thread+0x1f0/0x3f0 > [ 193.096971] kthread+0x110/0x120 > [ 193.097052] ret_from_fork+0x10/0x20 > > So I'm not sure how to fix this or if we even want to. > > We could try and release locks before calling the tracepoint but that looks > very fiddly and would require ghes.c to be able to see more of the > CXL tracepoint infrastructure which isn't great. > > Just because I was feeling cheeky I did a quick test with following. > I have a sneaky suspicion this won't got down well even though it 'fixes' > our issue... My google fu / lore search terms are failing to find > much previous discussion of this. > > diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c > index 9ff8a439d674..7ee45f22f56f 100644 > --- a/kernel/trace/trace.c > +++ b/kernel/trace/trace.c > @@ -2957,7 +2957,7 @@ static void output_printk(struct trace_event_buffer *fbuffer) > iter->ent = fbuffer->entry; > event_call->event.funcs->trace(iter, 0, event); > trace_seq_putc(&iter->seq, 0); > - printk("%s", iter->seq.buffer); > + printk_deferred("%s", iter->seq.buffer); > > raw_spin_unlock_irqrestore(&tracepoint_iter_lock, flags); > } > > My assumption is similar views will apply here to Peter Zijlstra's comment on > not using printk_deferred. > > https://lore.kernel.org/all/20231010141244.GM377@xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx/ > > Note I also tried the hacks Peter links to from there. They trip issues in the initial > CPER print - so I assume not appropriate here. > > So I'm thinking this is a won't fix - wait for the printk rework to land and > assume this will be resolved as well? > Or could we avoid the situation entirely by using a static call? The work queue still needs to be created because of the atomicness of ghes_do_proc() but it avoids cxl_cper_rw_sem. I think the hardest thing may be writing the commit message to explain all this. :-( Ira
