Received-SPF: pass (google.com: domain of linux-kernel+bounces-65566-linux.lists.archive=gmail.com@vger.kernel.org designates 147.75.199.223 as permitted sender) client-ip=147.75.199.223;
Date: Wed, 14 Feb 2024 08:40:55 -0800
From: Ira Weiny <ira.weiny@intel.com>
To: Jonathan Cameron <Jonathan.Cameron@huawei.com>, Ira Weiny
	<ira.weiny@intel.com>
CC: "Rafael J. Wysocki" <rafael@kernel.org>, Dan Williams
	<dan.j.williams@intel.com>, Smita Koralahalli
	<Smita.KoralahalliChannabasappa@amd.com>, <linux-acpi@vger.kernel.org>,
	<linux-cxl@vger.kernel.org>, <linux-kernel@vger.kernel.org>, Dan Carpenter
	<dan.carpenter@linaro.org>, Steven Rostedt <rostedt@goodmis.org>, "Masami
 Hiramatsu" <mhiramat@kernel.org>, Mathieu Desnoyers
	<mathieu.desnoyers@efficios.com>, <linux-trace-kernel@vger.kernel.org>
Subject: Re: [PATCH v2] acpi/ghes: Prevent sleeping with spinlock held
Message-ID: <65cced1753256_cbc9b29490@iweiny-mobl.notmuch>
References: <20240206-cxl-cper-smatch-v2-1-84ed07563c31@intel.com>
 <20240214121153.00005c97@huawei.com>
Content-Type: text/plain; charset="us-ascii"
Content-Disposition: inline
In-Reply-To: <20240214121153.00005c97@huawei.com>
Precedence: bulk
MIME-Version: 1.0
X-MS-Exchange-AntiSpam-MessageData-ChunkCount: 1
X-MS-Exchange-AntiSpam-MessageData-0: =?us-ascii?Q?Olkt0EwxFcYP+DR+gzAgY5KGP6WLomfuTl7W2z3j7y53POMGCF7Ovbp9KbDk?=
 =?us-ascii?Q?g7q0hg72sTfzZ/fzxoHGJfqLQ3HYwXg5pyhFYc7MElDdkG7jDyv1Dp6sovg3?=
 =?us-ascii?Q?0fg2QtYV9F3Xlz6qkezX68mtWVIWUkdfwzGmfa9saSgpABkZrDp/hhTY946e?=
 =?us-ascii?Q?9grS0PsdGUS7o0/twbnsO0/6kW4592RYL4lgJDvTRrNutTlp/Eves4Gwis2v?=
 =?us-ascii?Q?myXcE8xmLN5I93H786BdRpX4blKoh7+k1mHN8rx5dM3fZsFA7fF6TEY6MOTu?=
 =?us-ascii?Q?EltCZ+oDWgjtPqkZxrMcGYwDeekgYgLFL4E8NGZaDhvpnd6ZS40KOPIiI5i3?=
 =?us-ascii?Q?UanCIZxQVazAGBNuezdTF7hy8spucHVJuV5Z15gTFmwwTJjr3ZST+QZg72Ac?=
 =?us-ascii?Q?sxn7rD7r9/xf4c+mgxk1XzJQN3nMdHMpDKrwJ8tN4OEj7e3VwgQwpmLDpEtr?=
 =?us-ascii?Q?hb8LdGw2/VqGaa5a7jF6T+76U6djx+YSBiyyelxQE6wDYO1eA8upZi05p+Dn?=
 =?us-ascii?Q?W1mt2qCpCdgwLAgKWuAFTeMpmaBYXJ5WOljSsZ6fXw4yJQZMp6j8Kxk/MHLf?=
 =?us-ascii?Q?Z1cU5SXzx7iQgFR7jBw3wwc5FAcGBYpyZftz7i/5NROcnifJb3weWKtAVE/h?=
 =?us-ascii?Q?NdhDDArkUSE2mIqpfk5IN7pmjU/GUxZtPo0qEg33hcpmaHi924ljL/O6CSuD?=
 =?us-ascii?Q?iUoS0s8t3kvesspTSql9Hv0LZvTQG10gYxuGW1jRoiLk2kD+jG3w7dQoHQ11?=
 =?us-ascii?Q?XPpNYmLY7UFUOz03mu1FEq6tioDlenD+kve3zcXH4Vgt0lSYv8EdqvuMEdis?=
 =?us-ascii?Q?/o74bTKLSmfzW5igwLPPxMq8j5TlkQ/xVRz+n/FVeA3ne48incZwsI5nOOfR?=
 =?us-ascii?Q?qJY+GRkrE4VqH/ZAEqxTIrzzvbLEwOu/r074SwOkSV2UFR7YbLo1/wm1hkCf?=
 =?us-ascii?Q?TXkwaRwh7VUj/hv5oH5ZKCtdX3QbMgJzeTixrob2TogsAprlY9ELY2Hr0tbb?=
 =?us-ascii?Q?TR2sz4SJdCQglo88VFCQqDKFx33/pRxvzjX+i515cfSixq0UsVmzhReIdGc2?=
 =?us-ascii?Q?3zdNqmsZlwf85J4WBg0oi3vofKy9p9MDvsSMmfs8leO4FrhWuhk8luax66xA?=
 =?us-ascii?Q?UVuHJ7NMgkQPjxH/AsFwa6JotrJekJ7bL2ZWcK7m4U3RNg3b3Bp/q6sqxivM?=
 =?us-ascii?Q?Zf0nkN7LQVJ8UZ6jX2TtQiZ3vZLpQTXHOjlNYquDKpKt7rWEoQ31NUrYujjP?=
 =?us-ascii?Q?uXErKiDuzw1P46AFMkh375qMvmrV7DNxDEXY+AJ3g/4LmATd+Lc43iTo3yCx?=
 =?us-ascii?Q?k77g0GgGC1LOloL00lL0h99uVmvuUja16mF7fvFa3CMtPFLd73Q4YSExnrXS?=
 =?us-ascii?Q?XqXuXpeE6oVRZIUPet619rm0Szzvqe727kDDOG/isHDpQIPyHFEZC89MGNex?=
 =?us-ascii?Q?fzFRMJVxC5fsujKHDMmmSgGeVRU/2QvqejpSCx/PWXIj1OeXXzU8pfKyAH1R?=
 =?us-ascii?Q?sNYkhUQevWfADkvyXKyy1bbYhmXcKjqe5mv+6MxrFyw2HpEPkyYnrMPvwlUL?=
 =?us-ascii?Q?C5K2h+G4kBZJEtUZvRicdGKXB1OPorLS3G11lgye?=
X-MS-Exchange-CrossTenant-Network-Message-Id: a694e886-8e9d-481d-3ddd-08dc2d7bb90c
X-MS-Exchange-CrossTenant-AuthSource: SA1PR11MB6733.namprd11.prod.outlook.com
X-MS-Exchange-CrossTenant-AuthAs: Internal
X-MS-Exchange-CrossTenant-OriginalArrivalTime: 14 Feb 2024 16:40:59.0438
 (UTC)
X-MS-Exchange-CrossTenant-FromEntityHeader: Hosted
X-MS-Exchange-CrossTenant-Id: 46c98d88-e344-4ed4-8496-4ed7712e255d
X-MS-Exchange-CrossTenant-MailboxType: HOSTED
X-MS-Exchange-CrossTenant-UserPrincipalName: Bu+7TOm7WHfBq6bbeDtx/G4TJOXZhfcKezFyEeQfzIqTsabZnJjiLxWjYrxCYYsaJ9q2b0KWCvw/Tpmz+VPptQ==
X-MS-Exchange-Transport-CrossTenantHeadersStamped: DM4PR11MB5568
X-OriginatorOrg: intel.com

Jonathan Cameron wrote:
> On Tue, 06 Feb 2024 14:15:32 -0800
> Ira Weiny <ira.weiny@intel.com> 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@linaro.org>
> > Signed-off-by: Ira Weiny <ira.weiny@intel.com>
> 
> +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@noisy.programming.kicks-ass.net/
> 
> 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