From patchwork Fri Aug 23 01:39:03 2024 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Steven Rostedt X-Patchwork-Id: 13774487 Received: from smtp.kernel.org (aws-us-west-2-korg-mail-1.web.codeaurora.org [10.30.226.201]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by smtp.subspace.kernel.org (Postfix) with ESMTPS id D13FD171A7; Fri, 23 Aug 2024 01:39:46 +0000 (UTC) Authentication-Results: smtp.subspace.kernel.org; arc=none smtp.client-ip=10.30.226.201 ARC-Seal: i=1; a=rsa-sha256; d=subspace.kernel.org; s=arc-20240116; t=1724377186; cv=none; b=nJ0xmHBTxUWgMK9wQyLVDK/kPpP1jmALs9wKl9TCbuPLoMVUgyB/A1fpwj7lKPDbDCu2zzBaN1VE9mc6Y9EX5iIanWDs5YG4hnGyAT+GuyRSiDXgMq+dqQNOfmTe9j5BgrihmY1YwnDvPDQcal50akcIKNc2Zni/YWS0MmNTS58= ARC-Message-Signature: i=1; a=rsa-sha256; d=subspace.kernel.org; s=arc-20240116; t=1724377186; c=relaxed/simple; bh=v7JSQko84R2XGVryVlMWWTln1DMXjC7h878O2Z+H3Cs=; h=Message-ID:Date:From:To:Cc:Subject:References:MIME-Version: Content-Type; b=MovM3rDOxRefsIDTYrUaf6MGIJJAApSn4JWQqUxZallz5t+SsOEd30i5Nrk1qgA3FumyzCW+vvh8NrAGOnbk3aXSu8/czq6LTopmx4Z0APFIbB9XLz7GbcQrpLns5oyxKtm4yjcDDdjQ78ubfZ+Vn94oyuFOQncgqFkOwgkRELo= ARC-Authentication-Results: i=1; smtp.subspace.kernel.org; arc=none smtp.client-ip=10.30.226.201 Received: by smtp.kernel.org (Postfix) with ESMTPSA id 6FC5BC4AF0B; Fri, 23 Aug 2024 01:39:46 +0000 (UTC) Received: from rostedt by gandalf with local (Exim 4.98) (envelope-from ) id 1shJHn-00000003Zh7-0qQ7; Thu, 22 Aug 2024 21:40:19 -0400 Message-ID: <20240823014019.053229958@goodmis.org> User-Agent: quilt/0.68 Date: Thu, 22 Aug 2024 21:39:03 -0400 From: Steven Rostedt To: linux-kernel@vger.kernel.org, linux-trace-kernel@vger.kernel.org, linux-doc@vger.kernel.org Cc: Masami Hiramatsu , Mark Rutland , Mathieu Desnoyers , Andrew Morton , Vincent Donnefort , Joel Fernandes , Ingo Molnar , Peter Zijlstra , suleiman@google.com, Thomas Gleixner , Vineeth Pillai , Beau Belgrave , Alexander Graf , Baoquan He , Borislav Petkov , "Paul E. McKenney" , David Howells , Mike Rapoport , Dave Hansen , Tony Luck , Guenter Roeck , Ross Zwisler , Kees Cook , Alexander Aring , "Luis Claudio R. Goncalves" , Tomas Glozar , John Kacur , Clark Williams , Linus Torvalds , "Jonathan Corbet" Subject: [PATCH 1/5] tracing: Add "traceoff" flag to boot time tracing instances References: <20240823013902.135036960@goodmis.org> Precedence: bulk X-Mailing-List: linux-trace-kernel@vger.kernel.org List-Id: List-Subscribe: List-Unsubscribe: MIME-Version: 1.0 From: Steven Rostedt Add a "flags" delimiter (^) to the "trace_instance" kernel command line parameter, and add the "traceoff" flag. The format is: trace_instance=[^[^]][@][,] The code allows for more than one flag to be added, but currently only "traceoff" is done so. The motivation for this change came from debugging with the persistent ring buffer and having trace_printk() writing to it. The trace_printk calls are always enabled, and the boot after the crash was having the unwanted trace_printks from the current boot inject into the ring buffer with the trace_printks of the crash kernel, making the output very confusing. Signed-off-by: Steven Rostedt (Google) --- .../admin-guide/kernel-parameters.txt | 17 ++++++++++ kernel/trace/trace.c | 31 ++++++++++++++++++- 2 files changed, 47 insertions(+), 1 deletion(-) diff --git a/Documentation/admin-guide/kernel-parameters.txt b/Documentation/admin-guide/kernel-parameters.txt index 388653448e72..3803f2b7f065 100644 --- a/Documentation/admin-guide/kernel-parameters.txt +++ b/Documentation/admin-guide/kernel-parameters.txt @@ -6743,6 +6743,15 @@ the same thing would happen if it was left off). The irq_handler_entry event, and all events under the "initcall" system. + Flags can be added to the instance to modify its behavior when it is + created. The flags are separated by '^'. Currently there's only one flag + defined, and that's "traceoff", to have the tracing instance tracing + disabled after it is created. + + trace_instance=foo^traceoff,sched,irq + + The flags must come before the defined events. + If memory has been reserved (see memmap for x86), the instance can use that memory: @@ -6765,6 +6774,14 @@ kernel versions where the validator will fail and reset the ring buffer if the layout is not the same as the previous kernel. + If the ring buffer is used for persistent bootups and has events enabled, + it is recommend to disable tracing so that events from a previous boot do not + mix with events of the current boot (unless you are debugging a random crash + at boot up). + + reserve_mem=12M:4096:trace trace_instance=boot_map^traceoff@trace,sched,irq + + trace_options=[option-list] [FTRACE] Enable or disable tracer options at boot. The option-list is a comma delimited list of options diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c index 9bcef199ae90..a79eefe84d6b 100644 --- a/kernel/trace/trace.c +++ b/kernel/trace/trace.c @@ -10468,10 +10468,36 @@ __init static void enable_instances(void) phys_addr_t start = 0; phys_addr_t size = 0; unsigned long addr = 0; + bool traceoff = false; + char *flag_delim; + char *addr_delim; tok = strsep(&curr_str, ","); - name = strsep(&tok, "@"); + flag_delim = strchr(tok, '^'); + addr_delim = strchr(tok, '@'); + + if (addr_delim) + *addr_delim++ = '\0'; + + if (flag_delim) + *flag_delim++ = '\0'; + + name = tok; + + if (flag_delim) { + char *flag; + + while ((flag = strsep(&flag_delim, "^"))) { + if (strcmp(flag, "traceoff") == 0) + traceoff = true; + else + pr_info("Tracing: Invalid instance flag '%s' for %s\n", + flag, name); + } + } + + tok = addr_delim; if (tok && isdigit(*tok)) { start = memparse(tok, &tok); if (!start) { @@ -10519,6 +10545,9 @@ __init static void enable_instances(void) continue; } + if (traceoff) + tracer_tracing_off(tr); + /* Only allow non mapped buffers to be deleted */ if (!start) trace_array_put(tr); From patchwork Fri Aug 23 01:39:04 2024 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Steven Rostedt X-Patchwork-Id: 13774486 Received: from smtp.kernel.org (aws-us-west-2-korg-mail-1.web.codeaurora.org [10.30.226.201]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by smtp.subspace.kernel.org (Postfix) with ESMTPS id BCB77B66F; Fri, 23 Aug 2024 01:39:46 +0000 (UTC) Authentication-Results: smtp.subspace.kernel.org; arc=none smtp.client-ip=10.30.226.201 ARC-Seal: i=1; a=rsa-sha256; d=subspace.kernel.org; s=arc-20240116; t=1724377186; cv=none; b=Xz/omyouHprCrO6XuCSfrf7geAU5Q2BLteN2ILvmAdWUu7/hOeN2FklOhBQHLkVDo4axPHwkHSJhN60AOGj2KzAXtfDcSjKPFhX/BoxojHRtfi/XgGff708WSY6go10MoG8DCDvG/nk3UAbW0Yj70uT25mrSfL7relPE8aTh1D4= ARC-Message-Signature: i=1; a=rsa-sha256; d=subspace.kernel.org; s=arc-20240116; t=1724377186; c=relaxed/simple; bh=/d1bvxifrbkSDTMaZcbI1ILGIbF1ysjIACrWH57QwDI=; h=Message-ID:Date:From:To:Cc:Subject:References:MIME-Version: Content-Type; b=IxSacUb2JRlDZdNIRw1Af9iIeGdkRwVn4TSuw01CC5FUyXkzIoB5wgrC2YjXp8yMTjSjSLiCSG6bJ59vRk9mwoWdgyploSN3b0rJfaAgBf0aQw40dg2rH0rDWoHBnEhCsKu4dKGX+4aFTOIfy4kq9PbuMVFeXztTHUFe9QuWROs= ARC-Authentication-Results: i=1; smtp.subspace.kernel.org; arc=none smtp.client-ip=10.30.226.201 Received: by smtp.kernel.org (Postfix) with ESMTPSA id 8058DC4AF10; Fri, 23 Aug 2024 01:39:46 +0000 (UTC) Received: from rostedt by gandalf with local (Exim 4.98) (envelope-from ) id 1shJHn-00000003Zhb-1Xf5; Thu, 22 Aug 2024 21:40:19 -0400 Message-ID: <20240823014019.226694946@goodmis.org> User-Agent: quilt/0.68 Date: Thu, 22 Aug 2024 21:39:04 -0400 From: Steven Rostedt To: linux-kernel@vger.kernel.org, linux-trace-kernel@vger.kernel.org, linux-doc@vger.kernel.org Cc: Masami Hiramatsu , Mark Rutland , Mathieu Desnoyers , Andrew Morton , Vincent Donnefort , Joel Fernandes , Ingo Molnar , Peter Zijlstra , suleiman@google.com, Thomas Gleixner , Vineeth Pillai , Beau Belgrave , Alexander Graf , Baoquan He , Borislav Petkov , "Paul E. McKenney" , David Howells , Mike Rapoport , Dave Hansen , Tony Luck , Guenter Roeck , Ross Zwisler , Kees Cook , Alexander Aring , "Luis Claudio R. Goncalves" , Tomas Glozar , John Kacur , Clark Williams , Linus Torvalds , "Jonathan Corbet" Subject: [PATCH 2/5] tracing: Allow trace_printk() to go to other instance buffers References: <20240823013902.135036960@goodmis.org> Precedence: bulk X-Mailing-List: linux-trace-kernel@vger.kernel.org List-Id: List-Subscribe: List-Unsubscribe: MIME-Version: 1.0 From: Steven Rostedt Currently, trace_printk() just goes to the top level ring buffer. But there may be times that it should go to one of the instances created by the kernel command line. Add a new trace_instance flag: traceprintk (also can use "printk" or "trace_printk" as people tend to forget the actual flag name). trace_instance=foo^traceprintk Will assign the trace_printk to this buffer at boot up. Signed-off-by: Steven Rostedt (Google) --- .../admin-guide/kernel-parameters.txt | 14 ++++-- kernel/trace/trace.c | 46 ++++++++++++++----- 2 files changed, 45 insertions(+), 15 deletions(-) diff --git a/Documentation/admin-guide/kernel-parameters.txt b/Documentation/admin-guide/kernel-parameters.txt index 3803f2b7f065..a8803c0c0a89 100644 --- a/Documentation/admin-guide/kernel-parameters.txt +++ b/Documentation/admin-guide/kernel-parameters.txt @@ -6744,11 +6744,17 @@ event, and all events under the "initcall" system. Flags can be added to the instance to modify its behavior when it is - created. The flags are separated by '^'. Currently there's only one flag - defined, and that's "traceoff", to have the tracing instance tracing - disabled after it is created. + created. The flags are separated by '^'. - trace_instance=foo^traceoff,sched,irq + The available flags are: + + traceoff - Have the tracing instance tracing disabled after it is created. + traceprintk - Have trace_printk() write into this trace instance + (note, "printk" and "trace_printk" can also be used) + Currently, traceprintk flag cannot be used for memory + mapped ring buffers as described below. + + trace_instance=foo^traceoff^traceprintk,sched,irq The flags must come before the defined events. diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c index a79eefe84d6b..8e28f19f5316 100644 --- a/kernel/trace/trace.c +++ b/kernel/trace/trace.c @@ -500,6 +500,8 @@ static struct trace_array global_trace = { .trace_flags = TRACE_DEFAULT_FLAGS, }; +static struct trace_array *printk_trace = &global_trace; + void trace_set_ring_buffer_expanded(struct trace_array *tr) { if (!tr) @@ -1117,7 +1119,7 @@ EXPORT_SYMBOL_GPL(__trace_array_puts); */ int __trace_puts(unsigned long ip, const char *str, int size) { - return __trace_array_puts(&global_trace, ip, str, size); + return __trace_array_puts(printk_trace, ip, str, size); } EXPORT_SYMBOL_GPL(__trace_puts); @@ -1128,6 +1130,7 @@ EXPORT_SYMBOL_GPL(__trace_puts); */ int __trace_bputs(unsigned long ip, const char *str) { + struct trace_array *tr = printk_trace; struct ring_buffer_event *event; struct trace_buffer *buffer; struct bputs_entry *entry; @@ -1135,14 +1138,14 @@ int __trace_bputs(unsigned long ip, const char *str) int size = sizeof(struct bputs_entry); int ret = 0; - if (!(global_trace.trace_flags & TRACE_ITER_PRINTK)) + if (!(tr->trace_flags & TRACE_ITER_PRINTK)) return 0; if (unlikely(tracing_selftest_running || tracing_disabled)) return 0; trace_ctx = tracing_gen_ctx(); - buffer = global_trace.array_buffer.buffer; + buffer = tr->array_buffer.buffer; ring_buffer_nest_start(buffer); event = __trace_buffer_lock_reserve(buffer, TRACE_BPUTS, size, @@ -1155,7 +1158,7 @@ int __trace_bputs(unsigned long ip, const char *str) entry->str = str; __buffer_unlock_commit(buffer, event); - ftrace_trace_stack(&global_trace, buffer, trace_ctx, 4, NULL); + ftrace_trace_stack(tr, buffer, trace_ctx, 4, NULL); ret = 1; out: @@ -3025,7 +3028,7 @@ void trace_dump_stack(int skip) /* Skip 1 to skip this function. */ skip++; #endif - __ftrace_trace_stack(global_trace.array_buffer.buffer, + __ftrace_trace_stack(printk_trace->array_buffer.buffer, tracing_gen_ctx(), skip, NULL); } EXPORT_SYMBOL_GPL(trace_dump_stack); @@ -3244,7 +3247,7 @@ int trace_vbprintk(unsigned long ip, const char *fmt, va_list args) struct trace_event_call *call = &event_bprint; struct ring_buffer_event *event; struct trace_buffer *buffer; - struct trace_array *tr = &global_trace; + struct trace_array *tr = printk_trace; struct bprint_entry *entry; unsigned int trace_ctx; char *tbuffer; @@ -3342,7 +3345,7 @@ __trace_array_vprintk(struct trace_buffer *buffer, memcpy(&entry->buf, tbuffer, len + 1); if (!call_filter_check_discard(call, entry, buffer, event)) { __buffer_unlock_commit(buffer, event); - ftrace_trace_stack(&global_trace, buffer, trace_ctx, 6, NULL); + ftrace_trace_stack(printk_trace, buffer, trace_ctx, 6, NULL); } out: @@ -3438,7 +3441,7 @@ int trace_array_printk_buf(struct trace_buffer *buffer, int ret; va_list ap; - if (!(global_trace.trace_flags & TRACE_ITER_PRINTK)) + if (!(printk_trace->trace_flags & TRACE_ITER_PRINTK)) return 0; va_start(ap, fmt); @@ -3450,7 +3453,7 @@ int trace_array_printk_buf(struct trace_buffer *buffer, __printf(2, 0) int trace_vprintk(unsigned long ip, const char *fmt, va_list args) { - return trace_array_vprintk(&global_trace, ip, fmt, args); + return trace_array_vprintk(printk_trace, ip, fmt, args); } EXPORT_SYMBOL_GPL(trace_vprintk); @@ -9666,6 +9669,9 @@ static int __remove_instance(struct trace_array *tr) set_tracer_flag(tr, 1 << i, 0); } + if (printk_trace == tr) + printk_trace = &global_trace; + tracing_set_nop(tr); clear_ftrace_function_probes(tr); event_trace_del_tracer(tr); @@ -10468,6 +10474,7 @@ __init static void enable_instances(void) phys_addr_t start = 0; phys_addr_t size = 0; unsigned long addr = 0; + bool traceprintk = false; bool traceoff = false; char *flag_delim; char *addr_delim; @@ -10489,11 +10496,16 @@ __init static void enable_instances(void) char *flag; while ((flag = strsep(&flag_delim, "^"))) { - if (strcmp(flag, "traceoff") == 0) + if (strcmp(flag, "traceoff") == 0) { traceoff = true; - else + } else if ((strcmp(flag, "printk") == 0) || + (strcmp(flag, "traceprintk") == 0) || + (strcmp(flag, "trace_printk") == 0)) { + traceprintk = true; + } else { pr_info("Tracing: Invalid instance flag '%s' for %s\n", flag, name); + } } } @@ -10548,6 +10560,18 @@ __init static void enable_instances(void) if (traceoff) tracer_tracing_off(tr); + if (traceprintk) { + /* + * The binary format of traceprintk can cause a crash if used + * by a buffer from another boot. Do not allow it for the + * memory mapped ring buffers. + */ + if (start) + pr_warn("Tracing: WARNING: memory mapped ring buffers cannot be used for trace_printk\n"); + else + printk_trace = tr; + } + /* Only allow non mapped buffers to be deleted */ if (!start) trace_array_put(tr); From patchwork Fri Aug 23 01:39:05 2024 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Steven Rostedt X-Patchwork-Id: 13774490 Received: from smtp.kernel.org (aws-us-west-2-korg-mail-1.web.codeaurora.org [10.30.226.201]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by smtp.subspace.kernel.org (Postfix) with ESMTPS id 19F8E1C680; Fri, 23 Aug 2024 01:39:46 +0000 (UTC) Authentication-Results: smtp.subspace.kernel.org; arc=none smtp.client-ip=10.30.226.201 ARC-Seal: i=1; a=rsa-sha256; d=subspace.kernel.org; s=arc-20240116; t=1724377187; cv=none; b=fbcpGabH86Ms+yZtk0zcSLAWZ8DJ4GtVIa8V+mkD+29RnROPTmOgvcX3GteQ/E/xgRHIO2Ca0Qb5QUU+mYKLdrt8Yz1vgSe5BKpGgHn4Vij8uu6KQsWUFyR+Xpt45SEwO0L8E1xfgx4vsrFj82IAGkbONIPRwWSGhFiJz6CtDGo= ARC-Message-Signature: i=1; a=rsa-sha256; d=subspace.kernel.org; s=arc-20240116; t=1724377187; c=relaxed/simple; bh=LTa5Q0p6734zkmNcZEFYat5XOLYbgOkYhY4a5oLezn0=; h=Message-ID:Date:From:To:Cc:Subject:References:MIME-Version: Content-Type; b=NsAiY+aoKGkEoOX6N1I71LXczD9YAwjdcPUT6x+2cigakvMMeV+Tr0FFIFxm4XiEESniyuiBo6DmX4EbfOd1LV7cNNUwN4CGcrLKLcYFQR1zdSwgXEDG5tbDNXCyd60TdbwDwVW+FoKACN78jGtjrhi2i9+cN5V0+qs+aoi0NUI= ARC-Authentication-Results: i=1; smtp.subspace.kernel.org; arc=none smtp.client-ip=10.30.226.201 Received: by smtp.kernel.org (Postfix) with ESMTPSA id A50BAC4AF13; Fri, 23 Aug 2024 01:39:46 +0000 (UTC) Received: from rostedt by gandalf with local (Exim 4.98) (envelope-from ) id 1shJHn-00000003Zi5-2CYW; Thu, 22 Aug 2024 21:40:19 -0400 Message-ID: <20240823014019.386925800@goodmis.org> User-Agent: quilt/0.68 Date: Thu, 22 Aug 2024 21:39:05 -0400 From: Steven Rostedt To: linux-kernel@vger.kernel.org, linux-trace-kernel@vger.kernel.org, linux-doc@vger.kernel.org Cc: Masami Hiramatsu , Mark Rutland , Mathieu Desnoyers , Andrew Morton , Vincent Donnefort , Joel Fernandes , Ingo Molnar , Peter Zijlstra , suleiman@google.com, Thomas Gleixner , Vineeth Pillai , Beau Belgrave , Alexander Graf , Baoquan He , Borislav Petkov , "Paul E. McKenney" , David Howells , Mike Rapoport , Dave Hansen , Tony Luck , Guenter Roeck , Ross Zwisler , Kees Cook , Alexander Aring , "Luis Claudio R. Goncalves" , Tomas Glozar , John Kacur , Clark Williams , Linus Torvalds , "Jonathan Corbet" Subject: [PATCH 3/5] tracing: Have trace_printk not use binary prints if boot buffer References: <20240823013902.135036960@goodmis.org> Precedence: bulk X-Mailing-List: linux-trace-kernel@vger.kernel.org List-Id: List-Subscribe: List-Unsubscribe: MIME-Version: 1.0 From: Steven Rostedt If the persistent boot mapped ring buffer is used for trace_printk(), force it to not use the binary versions. trace_printk() by default uses bin_printf() that only saves the pointer to the format and not the format itself inside the ring buffer. But for a persistent buffer that is read after reboot, the pointers to the format strings may not be the same, or worse, not even exist! Instead, just force the more robust, but slower, version that does the formatting before saving into the ring buffer. The boot mapped buffer can now be used for trace_printk and friends! Using the trace_printk() and the persistent buffer was used to debug the issue with the osnoise tracer: Link: https://lore.kernel.org/all/20240822103443.6a6ae051@gandalf.local.home/ Signed-off-by: Steven Rostedt (Google) --- .../admin-guide/kernel-parameters.txt | 4 +- kernel/trace/trace.c | 44 ++++++++++++------- kernel/trace/trace.h | 3 +- kernel/trace/trace_output.c | 5 ++- 4 files changed, 36 insertions(+), 20 deletions(-) diff --git a/Documentation/admin-guide/kernel-parameters.txt b/Documentation/admin-guide/kernel-parameters.txt index a8803c0c0a89..9e507e6cb4c8 100644 --- a/Documentation/admin-guide/kernel-parameters.txt +++ b/Documentation/admin-guide/kernel-parameters.txt @@ -6751,8 +6751,6 @@ traceoff - Have the tracing instance tracing disabled after it is created. traceprintk - Have trace_printk() write into this trace instance (note, "printk" and "trace_printk" can also be used) - Currently, traceprintk flag cannot be used for memory - mapped ring buffers as described below. trace_instance=foo^traceoff^traceprintk,sched,irq @@ -6785,7 +6783,7 @@ mix with events of the current boot (unless you are debugging a random crash at boot up). - reserve_mem=12M:4096:trace trace_instance=boot_map^traceoff@trace,sched,irq + reserve_mem=12M:4096:trace trace_instance=boot_map^traceoff^traceprintk@trace,sched,irq trace_options=[option-list] diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c index 8e28f19f5316..35b37c9aa26c 100644 --- a/kernel/trace/trace.c +++ b/kernel/trace/trace.c @@ -502,6 +502,17 @@ static struct trace_array global_trace = { static struct trace_array *printk_trace = &global_trace; +static __always_inline bool printk_binsafe(struct trace_array *tr) +{ + /* + * The binary format of traceprintk can cause a crash if used + * by a buffer from another boot. Force the use of the + * non binary version of trace_printk if the trace_printk + * buffer is a boot mapped ring buffer. + */ + return !(tr->flags & TRACE_ARRAY_FL_BOOT); +} + void trace_set_ring_buffer_expanded(struct trace_array *tr) { if (!tr) @@ -1130,7 +1141,7 @@ EXPORT_SYMBOL_GPL(__trace_puts); */ int __trace_bputs(unsigned long ip, const char *str) { - struct trace_array *tr = printk_trace; + struct trace_array *tr = READ_ONCE(printk_trace); struct ring_buffer_event *event; struct trace_buffer *buffer; struct bputs_entry *entry; @@ -1138,6 +1149,9 @@ int __trace_bputs(unsigned long ip, const char *str) int size = sizeof(struct bputs_entry); int ret = 0; + if (!printk_binsafe(tr)) + return __trace_puts(ip, str, strlen(str)); + if (!(tr->trace_flags & TRACE_ITER_PRINTK)) return 0; @@ -3247,12 +3261,15 @@ int trace_vbprintk(unsigned long ip, const char *fmt, va_list args) struct trace_event_call *call = &event_bprint; struct ring_buffer_event *event; struct trace_buffer *buffer; - struct trace_array *tr = printk_trace; + struct trace_array *tr = READ_ONCE(printk_trace); struct bprint_entry *entry; unsigned int trace_ctx; char *tbuffer; int len = 0, size; + if (!printk_binsafe(tr)) + return trace_vprintk(ip, fmt, args); + if (unlikely(tracing_selftest_running || tracing_disabled)) return 0; @@ -10560,20 +10577,17 @@ __init static void enable_instances(void) if (traceoff) tracer_tracing_off(tr); - if (traceprintk) { - /* - * The binary format of traceprintk can cause a crash if used - * by a buffer from another boot. Do not allow it for the - * memory mapped ring buffers. - */ - if (start) - pr_warn("Tracing: WARNING: memory mapped ring buffers cannot be used for trace_printk\n"); - else - printk_trace = tr; - } + if (traceprintk) + printk_trace = tr; - /* Only allow non mapped buffers to be deleted */ - if (!start) + /* + * If start is set, then this is a mapped buffer, and + * cannot be deleted by user space, so keep the reference + * to it. + */ + if (start) + tr->flags |= TRACE_ARRAY_FL_BOOT; + else trace_array_put(tr); while ((tok = strsep(&curr_str, ","))) { diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h index 4f448ab2d1e7..07b2d2af9b33 100644 --- a/kernel/trace/trace.h +++ b/kernel/trace/trace.h @@ -429,7 +429,8 @@ struct trace_array { }; enum { - TRACE_ARRAY_FL_GLOBAL = (1 << 0) + TRACE_ARRAY_FL_GLOBAL = BIT(0), + TRACE_ARRAY_FL_BOOT = BIT(1), }; extern struct list_head ftrace_trace_arrays; diff --git a/kernel/trace/trace_output.c b/kernel/trace/trace_output.c index 48de93598897..868f2f912f28 100644 --- a/kernel/trace/trace_output.c +++ b/kernel/trace/trace_output.c @@ -1591,10 +1591,13 @@ static enum print_line_t trace_print_print(struct trace_iterator *iter, { struct print_entry *field; struct trace_seq *s = &iter->seq; + unsigned long ip; trace_assign_type(field, iter->ent); - seq_print_ip_sym(s, field->ip, flags); + ip = field->ip + iter->tr->text_delta; + + seq_print_ip_sym(s, ip, flags); trace_seq_printf(s, ": %s", field->buf); return trace_handle_return(s); From patchwork Fri Aug 23 01:39:06 2024 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Steven Rostedt X-Patchwork-Id: 13774489 Received: from smtp.kernel.org (aws-us-west-2-korg-mail-1.web.codeaurora.org [10.30.226.201]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by smtp.subspace.kernel.org (Postfix) with ESMTPS id 19FCD1C694; Fri, 23 Aug 2024 01:39:46 +0000 (UTC) Authentication-Results: smtp.subspace.kernel.org; arc=none smtp.client-ip=10.30.226.201 ARC-Seal: i=1; a=rsa-sha256; d=subspace.kernel.org; s=arc-20240116; t=1724377187; cv=none; b=spJmb2/JVycWGgluhqmyv7nJWEVZbj9YCFS4MdIEVDziZOBZdfhB5tYcS+KubTZ2CSt/iJQKvLlOw1sqHp1E5+kLCFCOYrYBsKuifmUBG5y0OK9YxdySrn/ESK1AcXWCP0TjC42CLdqMKGIuJQTISyWP24hNHFgpdlEoqNnWn2c= ARC-Message-Signature: i=1; a=rsa-sha256; d=subspace.kernel.org; s=arc-20240116; t=1724377187; c=relaxed/simple; bh=R883UB1lQPveP+GSFXVrQFNV+2afojxMSJTjv9FnDKc=; h=Message-ID:Date:From:To:Cc:Subject:References:MIME-Version: Content-Type; b=H2iy/4wrn45iBCySg4b1KWivwppt3KBxa53vEjSuLb83M2Ydd/DJv0ckGrtBBd6dO4MCJKgVDn5+mVZPqPvFgU0mXRF6zI5fOC8jUIn0ZQssLp3romAv3l0gi2bfSPKbIz1hOAh1/5qPq+2mbjNzOQzO7Hz1XAtjLfH7UsMm2Eo= ARC-Authentication-Results: i=1; smtp.subspace.kernel.org; arc=none smtp.client-ip=10.30.226.201 Received: by smtp.kernel.org (Postfix) with ESMTPSA id C001EC4AF50; Fri, 23 Aug 2024 01:39:46 +0000 (UTC) Received: from rostedt by gandalf with local (Exim 4.98) (envelope-from ) id 1shJHn-00000003ZiZ-2rLe; Thu, 22 Aug 2024 21:40:19 -0400 Message-ID: <20240823014019.545459018@goodmis.org> User-Agent: quilt/0.68 Date: Thu, 22 Aug 2024 21:39:06 -0400 From: Steven Rostedt To: linux-kernel@vger.kernel.org, linux-trace-kernel@vger.kernel.org, linux-doc@vger.kernel.org Cc: Masami Hiramatsu , Mark Rutland , Mathieu Desnoyers , Andrew Morton , Vincent Donnefort , Joel Fernandes , Ingo Molnar , Peter Zijlstra , suleiman@google.com, Thomas Gleixner , Vineeth Pillai , Beau Belgrave , Alexander Graf , Baoquan He , Borislav Petkov , "Paul E. McKenney" , David Howells , Mike Rapoport , Dave Hansen , Tony Luck , Guenter Roeck , Ross Zwisler , Kees Cook , Alexander Aring , "Luis Claudio R. Goncalves" , Tomas Glozar , John Kacur , Clark Williams , Linus Torvalds , "Jonathan Corbet" Subject: [PATCH 4/5] tracing: Add option to set an instance to be the trace_printk destination References: <20240823013902.135036960@goodmis.org> Precedence: bulk X-Mailing-List: linux-trace-kernel@vger.kernel.org List-Id: List-Subscribe: List-Unsubscribe: MIME-Version: 1.0 From: Steven Rostedt Add a option "trace_printk_dest" that will make the tracing instance the location that trace_printk() will go to. This is useful if the trace_printk or one of the top level tracers is too noisy and there's a need to separate the two. Then an instance can be created, the trace_printk can be set to go there instead, where it will not be lost in the noise of the top level tracer. Note, only one instance can be the destination of trace_printk at a time. If an instance sets this flag, the instance that had it set will have it cleared. There is always one instance that has this set. By default, that is the top instance. This flag cannot be cleared from the top instance. Doing so will result in an -EINVAL. The only way this flag can be cleared from the top instance is by another instance setting it. Signed-off-by: Steven Rostedt (Google) --- Documentation/trace/ftrace.rst | 12 ++++++++++ kernel/trace/trace.c | 40 +++++++++++++++++++++++++++++----- kernel/trace/trace.h | 1 + 3 files changed, 48 insertions(+), 5 deletions(-) diff --git a/Documentation/trace/ftrace.rst b/Documentation/trace/ftrace.rst index 5aba74872ba7..4073ca48af4a 100644 --- a/Documentation/trace/ftrace.rst +++ b/Documentation/trace/ftrace.rst @@ -1186,6 +1186,18 @@ Here are the available options: trace_printk Can disable trace_printk() from writing into the buffer. + trace_printk_dest + Set to have trace_printk() and similar internal tracing functions + write into this instance. Note, only one trace instance can have + this set. By setting this flag, it clears the trace_printk_dest flag + of the instance that had it set previously. By default, the top + level trace has this set, and will get it set again if another + instance has it set then clears it. + + This flag cannot be cleared by the top level instance, as it is the + default instance. The only way the top level instance has this flag + cleared, is by it being set in another instance. + annotate It is sometimes confusing when the CPU buffers are full and one CPU buffer had a lot of events recently, thus diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c index 35b37c9aa26c..658b40b483a3 100644 --- a/kernel/trace/trace.c +++ b/kernel/trace/trace.c @@ -482,7 +482,7 @@ EXPORT_SYMBOL_GPL(unregister_ftrace_export); TRACE_ITER_ANNOTATE | TRACE_ITER_CONTEXT_INFO | \ TRACE_ITER_RECORD_CMD | TRACE_ITER_OVERWRITE | \ TRACE_ITER_IRQ_INFO | TRACE_ITER_MARKERS | \ - TRACE_ITER_HASH_PTR) + TRACE_ITER_HASH_PTR | TRACE_ITER_TRACE_PRINTK) /* trace_options that are only supported by global_trace */ #define TOP_LEVEL_TRACE_FLAGS (TRACE_ITER_PRINTK | \ @@ -490,7 +490,7 @@ EXPORT_SYMBOL_GPL(unregister_ftrace_export); /* trace_flags that are default zero for instances */ #define ZEROED_TRACE_FLAGS \ - (TRACE_ITER_EVENT_FORK | TRACE_ITER_FUNC_FORK) + (TRACE_ITER_EVENT_FORK | TRACE_ITER_FUNC_FORK | TRACE_ITER_TRACE_PRINTK) /* * The global_trace is the descriptor that holds the top-level tracing @@ -513,6 +513,16 @@ static __always_inline bool printk_binsafe(struct trace_array *tr) return !(tr->flags & TRACE_ARRAY_FL_BOOT); } +static void update_printk_trace(struct trace_array *tr) +{ + if (printk_trace == tr) + return; + + printk_trace->trace_flags &= ~TRACE_ITER_TRACE_PRINTK; + printk_trace = tr; + tr->trace_flags |= TRACE_ITER_TRACE_PRINTK; +} + void trace_set_ring_buffer_expanded(struct trace_array *tr) { if (!tr) @@ -5300,7 +5310,8 @@ int trace_keep_overwrite(struct tracer *tracer, u32 mask, int set) int set_tracer_flag(struct trace_array *tr, unsigned int mask, int enabled) { if ((mask == TRACE_ITER_RECORD_TGID) || - (mask == TRACE_ITER_RECORD_CMD)) + (mask == TRACE_ITER_RECORD_CMD) || + (mask == TRACE_ITER_TRACE_PRINTK)) lockdep_assert_held(&event_mutex); /* do nothing if flag is already set */ @@ -5312,6 +5323,25 @@ int set_tracer_flag(struct trace_array *tr, unsigned int mask, int enabled) if (tr->current_trace->flag_changed(tr, mask, !!enabled)) return -EINVAL; + if (mask == TRACE_ITER_TRACE_PRINTK) { + if (enabled) { + update_printk_trace(tr); + } else { + /* + * The global_trace cannot clear this. + * It's flag only gets cleared if another instance sets it. + */ + if (printk_trace == &global_trace) + return -EINVAL; + /* + * An instance must always have it set. + * by default, that's the global_trace instane. + */ + if (printk_trace == tr) + update_printk_trace(&global_trace); + } + } + if (enabled) tr->trace_flags |= mask; else @@ -9687,7 +9717,7 @@ static int __remove_instance(struct trace_array *tr) } if (printk_trace == tr) - printk_trace = &global_trace; + update_printk_trace(&global_trace); tracing_set_nop(tr); clear_ftrace_function_probes(tr); @@ -10578,7 +10608,7 @@ __init static void enable_instances(void) tracer_tracing_off(tr); if (traceprintk) - printk_trace = tr; + update_printk_trace(tr); /* * If start is set, then this is a mapped buffer, and diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h index 07b2d2af9b33..c866991b9c78 100644 --- a/kernel/trace/trace.h +++ b/kernel/trace/trace.h @@ -1321,6 +1321,7 @@ extern int trace_get_user(struct trace_parser *parser, const char __user *ubuf, C(IRQ_INFO, "irq-info"), \ C(MARKERS, "markers"), \ C(EVENT_FORK, "event-fork"), \ + C(TRACE_PRINTK, "trace_printk_dest"), \ C(PAUSE_ON_TRACE, "pause-on-trace"), \ C(HASH_PTR, "hash-ptr"), /* Print hashed pointer */ \ FUNCTION_FLAGS \ From patchwork Fri Aug 23 01:39:07 2024 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Steven Rostedt X-Patchwork-Id: 13774491 Received: from smtp.kernel.org (aws-us-west-2-korg-mail-1.web.codeaurora.org [10.30.226.201]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by smtp.subspace.kernel.org (Postfix) with ESMTPS id 244B61CAB1; Fri, 23 Aug 2024 01:39:47 +0000 (UTC) Authentication-Results: smtp.subspace.kernel.org; arc=none smtp.client-ip=10.30.226.201 ARC-Seal: i=1; a=rsa-sha256; d=subspace.kernel.org; s=arc-20240116; t=1724377187; cv=none; b=XoFD4vJv7jyohS4xkpcRuia4cCVH44SyEk5IwKHSWdtydcNUNIQ7NaRWKjQQAfx4XmoZDMYqMn1VWiF9K7tTnJPKcxpUXLR91A7JVgkgIDg0j6I88pyzFI74XR5YTSOjP5IGDTpPWLUnzzhe+xqEN3HXdNFxaR14eO4pF7fZxGA= ARC-Message-Signature: i=1; a=rsa-sha256; d=subspace.kernel.org; s=arc-20240116; t=1724377187; c=relaxed/simple; bh=YU0QIbXtgoAbgVwROAdDdrWELtxzSNwB9GOOMj6ww5s=; h=Message-ID:Date:From:To:Cc:Subject:References:MIME-Version: Content-Type; b=awmYuMfV4h05jbOzAe/4jedt4ezOeoTBIDX0is8WvbY09hDngoiGczxppONwyXLhOAEx06TNNL5DhcVegJtEpOlmymDBF6o0YJ4ZNGuPQEcUNHCdzRF0pR4n2cP1YsX3By9vT6MZxsGDuWVk/UY64VqMzCiKaIWIDEdiLosBV7w= ARC-Authentication-Results: i=1; smtp.subspace.kernel.org; arc=none smtp.client-ip=10.30.226.201 Received: by smtp.kernel.org (Postfix) with ESMTPSA id E96F1C4AF51; Fri, 23 Aug 2024 01:39:46 +0000 (UTC) Received: from rostedt by gandalf with local (Exim 4.98) (envelope-from ) id 1shJHn-00000003Zj3-3XjD; Thu, 22 Aug 2024 21:40:19 -0400 Message-ID: <20240823014019.702433486@goodmis.org> User-Agent: quilt/0.68 Date: Thu, 22 Aug 2024 21:39:07 -0400 From: Steven Rostedt To: linux-kernel@vger.kernel.org, linux-trace-kernel@vger.kernel.org, linux-doc@vger.kernel.org Cc: Masami Hiramatsu , Mark Rutland , Mathieu Desnoyers , Andrew Morton , Vincent Donnefort , Joel Fernandes , Ingo Molnar , Peter Zijlstra , suleiman@google.com, Thomas Gleixner , Vineeth Pillai , Beau Belgrave , Alexander Graf , Baoquan He , Borislav Petkov , "Paul E. McKenney" , David Howells , Mike Rapoport , Dave Hansen , Tony Luck , Guenter Roeck , Ross Zwisler , Kees Cook , Alexander Aring , "Luis Claudio R. Goncalves" , Tomas Glozar , John Kacur , Clark Williams , Linus Torvalds , "Jonathan Corbet" Subject: [PATCH 5/5] tracing/Documentation: Start a document on how to debug with tracing References: <20240823013902.135036960@goodmis.org> Precedence: bulk X-Mailing-List: linux-trace-kernel@vger.kernel.org List-Id: List-Subscribe: List-Unsubscribe: MIME-Version: 1.0 From: Steven Rostedt Add a new document Documentation/trace/debugging.rst that will hold various ways to debug tracing. This initial version mentions trace_printk and how to create persistent buffers that can last across bootups. Signed-off-by: Steven Rostedt (Google) --- .../admin-guide/kernel-parameters.txt | 2 + Documentation/trace/debugging.rst | 159 ++++++++++++++++++ 2 files changed, 161 insertions(+) create mode 100644 Documentation/trace/debugging.rst diff --git a/Documentation/admin-guide/kernel-parameters.txt b/Documentation/admin-guide/kernel-parameters.txt index 9e507e6cb4c8..9bb50dc78338 100644 --- a/Documentation/admin-guide/kernel-parameters.txt +++ b/Documentation/admin-guide/kernel-parameters.txt @@ -6785,6 +6785,8 @@ reserve_mem=12M:4096:trace trace_instance=boot_map^traceoff^traceprintk@trace,sched,irq + See also Documentation/trace/debugging.rst + trace_options=[option-list] [FTRACE] Enable or disable tracer options at boot. diff --git a/Documentation/trace/debugging.rst b/Documentation/trace/debugging.rst new file mode 100644 index 000000000000..54fb16239d70 --- /dev/null +++ b/Documentation/trace/debugging.rst @@ -0,0 +1,159 @@ +============================== +Using the tracer for debugging +============================== + +Copyright 2024 Google LLC. + +:Author: Steven Rostedt +:License: The GNU Free Documentation License, Version 1.2 + (dual licensed under the GPL v2) + +- Written for: 6.12 + +Introduction +------------ +The tracing infrastructure can be very useful for debugging the Linux +kernel. This document is a place to add various methods of using the tracer +for debugging. + +First, make sure that the tracefs file system is mounted:: + + $ sudo mount -t tracefs tracefs /sys/kernel/tracing + + +Using trace_printk() +-------------------- + +trace_printk() is a very lightweight utility that can be used in any context +inside the kernel, with the exception of "noinstr" sections. It can be used +in normal, softirq, interrupt and even NMI context. The trace data is +written to the tracing ring buffer in a lockless way. To make it even +lighter weight, when possible, it will only record the pointer to the format +string, and save the raw arguments into the buffer. The format and the +arguments will be post processed when the ring buffer is read. This way the +trace_printk() format conversions are not done during the hot path, where +the trace is being recorded. + +trace_printk() is meant only for debugging, and should never be added into +a subsystem of the kernel. If you need debugging traces, add trace events +instead. If a trace_printk() is found in the kernel, the following will +appear in the dmesg:: + + ********************************************************** + ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** + ** ** + ** trace_printk() being used. Allocating extra memory. ** + ** ** + ** This means that this is a DEBUG kernel and it is ** + ** unsafe for production use. ** + ** ** + ** If you see this message and you are not debugging ** + ** the kernel, report this immediately to your vendor! ** + ** ** + ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** + ********************************************************** + +Debugging kernel crashes +------------------------ +There is various methods of acquiring the state of the system when a kernel +crash occurs. This could be from the oops message in printk, or one could +use kexec/kdump. But these just show what happened at the time of the crash. +It can be very useful in knowing what happened up to the point of the crash. +The tracing ring buffer, by default, is a circular buffer than will +overwrite older events with newer ones. When a crash happens, the content of +the ring buffer will be all the events that lead up to the crash. + +There are several kernel command line parameters that can be used to help in +this. The first is "ftrace_dump_on_oops". This will dump the tracing ring +buffer when a oops occurs to the console. This can be useful if the console +is being logged somewhere. If a serial console is used, it may be prudent to +make sure the ring buffer is relatively small, otherwise the dumping of the +ring buffer may take several minutes to hours to finish. Here's an example +of the kernel command line:: + + ftrace_dump_on_oops trace_buf_size=50K + +Note, the tracing buffer is made up of per CPU buffers where each of these +buffers is broken up into sub-buffers that are by default PAGE_SIZE. The +above trace_buf_size option above sets each of the per CPU buffers to 50K, +so, on a machine with 8 CPUs, that's actually 400K total. + +Persistent buffers across boots +------------------------------- +If the system memory allows it, the tracing ring buffer can be specified at +a specific location in memory. If the location is the same across boots and +the memory is not modified, the tracing buffer can be retrieved from the +following boot. There's two ways to reserve memory for the use of the ring +buffer. + +The more reliable way (on x86) is to reserve memory with the "memmap" kernel +command line option and then use that memory for the trace_instance. This +requires a bit of knowledge of the physical memory layout of the system. The +advantage of using this method, is that the memory for the ring buffer will +always be the same:: + + memmap==12M$0x284500000 trace_instance=boot_map@0x284500000:12M + +The memmap above reserves 12 megabytes of memory at the physical memory +location 0x284500000. Then the trace_instance option will create a trace +instance "boot_map" at that same location with the same amount of memory +reserved. As the ring buffer is broke up into per CPU buffers, the 12 +megabytes will be broken up evenly between those CPUs. If you have 8 CPUs, +each per CPU ring buffer will be 1.5 megabytes in size. Note, that also +includes meta data, so the amount of memory actually used by the ring buffer +will be slightly smaller. + +Another more generic but less robust way to allocate a ring buffer mapping +at boot is with the "reserve_mem" option:: + + reserve_mem=12M:4096:trace trace_instance=boot_map@trace + +The reserve_mem option above will find 12 megabytes that are available at +boot up, and align it by 4096 bytes. It will label this memory as "trace" +that can be used by later command line options. + +The trace_instance option creates a "boot_map" instance and will use the +memory reserved by reserve_mem that was labeled as "trace". This method is +more generic but may not be as reliable. Due to KASLR, the memory reserved +by reserve_mem may not be located at the same location. If this happens, +then the ring buffer will not be from the previous boot and will be reset. + +Sometimes, by using a larger alignment, it can keep KASLR from moving things +around in such a way that it will move the location of the reserve_mem. By +using a larger alignment, you may find better that the buffer is more +consistent to where it is placed:: + + reserve_mem=12M:0x2000000:trace trace_instance=boot_map@trace + +On boot up, the memory reserved for the ring buffer is validated. It will go +through a series of tests to make sure that the ring buffer contains valid +data. If it is, it will then set it up to be available to read from the +instance. If it fails any of the tests, it will clear the entire ring buffer +and initialize it as new. + +The layout of this mapped memory may not be consistent from kernel to +kernel, so only the same kernel is guaranteed to work if the mapping is +preserved. Switching to a different kernel version may find a different +layout and mark the buffer as invalid. + +Using trace_printk() in the boot instance +----------------------------------------- +By default, the content of trace_printk() goes into the top level tracing +instance. But this instance is never preserved across boots. To have the +trace_printk() content, and some other internal tracing go to the preserved +buffer (like dump stacks), either set the instance to be the trace_printk() +destination from the kernel command line, or set it after boot up via the +trace_printk_dest option. + +After boot up:: + + echo 1 > /sys/kernel/tracing/instances/boot_map/options/trace_printk_dest + +From the kernel command line:: + + reserve_mem=12M:4096:trace trace_instance=boot_map^traceprintk^traceoff@trace + +If setting it from the kernel command line, it is recommended to also +disable tracing with the "traceoff" flag, and enable tracing after boot up. +Otherwise the trace from the most recent boot will be mixed with the trace +from the previous boot, and may make it confusing to read.