From nobody Sun Sep 14 08:58:39 2025 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-korg-lkml-1.web.codeaurora.org Received: from vger.kernel.org (vger.kernel.org [23.128.96.18]) by smtp.lore.kernel.org (Postfix) with ESMTP id ED798C54E94 for ; Wed, 25 Jan 2023 17:14:34 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S236228AbjAYROd (ORCPT ); Wed, 25 Jan 2023 12:14:33 -0500 Received: from lindbergh.monkeyblade.net ([23.128.96.19]:38926 "EHLO lindbergh.monkeyblade.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S236103AbjAYROD (ORCPT ); Wed, 25 Jan 2023 12:14:03 -0500 Received: from ams.source.kernel.org (ams.source.kernel.org [145.40.68.75]) by lindbergh.monkeyblade.net (Postfix) with ESMTPS id F169C7289 for ; Wed, 25 Jan 2023 09:13:54 -0800 (PST) Received: from smtp.kernel.org (relay.kernel.org [52.25.139.140]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by ams.source.kernel.org (Postfix) with ESMTPS id 84863B81B5B for ; Wed, 25 Jan 2023 17:13:42 +0000 (UTC) Received: by smtp.kernel.org (Postfix) with ESMTPSA id 2442BC4339B; Wed, 25 Jan 2023 17:13:41 +0000 (UTC) Received: from rostedt by gandalf.local.home with local (Exim 4.96) (envelope-from ) id 1pKjL9-004Nt1-2q; Wed, 25 Jan 2023 12:13:39 -0500 Message-ID: <20230125171339.695687314@goodmis.org> User-Agent: quilt/0.66 Date: Wed, 25 Jan 2023 12:12:59 -0500 From: Steven Rostedt To: linux-kernel@vger.kernel.org Cc: Masami Hiramatsu , Andrew Morton , Tom Zanussi , Ross Zwisler , Ching-lin Yu Subject: [for-next][PATCH 07/12] tracing: Allow synthetic events to pass around stacktraces References: <20230125171252.431857411@goodmis.org> MIME-Version: 1.0 Precedence: bulk List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Content-Transfer-Encoding: quoted-printable Content-Type: text/plain; charset="utf-8" From: "Steven Rostedt (Google)" Allow a stacktrace from one event to be displayed by the end event of a synthetic event. This is very useful when looking for the longest latency of a sleep or something blocked on I/O. # cd /sys/kernel/tracing/ # echo 's:block_lat pid_t pid; u64 delta; unsigned long[] stack;' > dynami= c_events # echo 'hist:keys=3Dnext_pid:ts=3Dcommon_timestamp.usecs,st=3Dstacktrace = if prev_state =3D=3D 1||prev_state =3D=3D 2' > events/sched/sched_switch/tr= igger # echo 'hist:keys=3Dprev_pid:delta=3Dcommon_timestamp.usecs-$ts,s=3D$st:on= max($delta).trace(block_lat,prev_pid,$delta,$s)' >> events/sched/sched_swit= ch/trigger The above creates a "block_lat" synthetic event that take the stacktrace of when a task schedules out in either the interruptible or uninterruptible states, and on a new per process max $delta (the time it was scheduled out), will print the process id and the stacktrace. # echo 1 > events/synthetic/block_lat/enable # cat trace # TASK-PID CPU# ||||| TIMESTAMP FUNCTION # | | | ||||| | | kworker/u16:0-767 [006] d..4. 560.645045: block_lat: pid=3D767 de= lta=3D66 stack=3DSTACK: =3D> __schedule =3D> schedule =3D> pipe_read =3D> vfs_read =3D> ksys_read =3D> do_syscall_64 =3D> 0x966000aa -0 [003] d..4. 561.132117: block_lat: pid=3D0 delt= a=3D413787 stack=3DSTACK: =3D> __schedule =3D> schedule =3D> schedule_hrtimeout_range_clock =3D> do_sys_poll =3D> __x64_sys_poll =3D> do_syscall_64 =3D> 0x966000aa <...>-153 [006] d..4. 562.068407: block_lat: pid=3D153 de= lta=3D54 stack=3DSTACK: =3D> __schedule =3D> schedule =3D> io_schedule =3D> rq_qos_wait =3D> wbt_wait =3D> __rq_qos_throttle =3D> blk_mq_submit_bio =3D> submit_bio_noacct_nocheck =3D> ext4_bio_write_page =3D> mpage_submit_page =3D> mpage_process_page_bufs =3D> mpage_prepare_extent_to_map =3D> ext4_do_writepages =3D> ext4_writepages =3D> do_writepages =3D> __writeback_single_inode Link: https://lkml.kernel.org/r/20230117152236.010941267@goodmis.org Cc: Masami Hiramatsu Cc: Andrew Morton Cc: Tom Zanussi Cc: Ross Zwisler Cc: Ching-lin Yu Signed-off-by: Steven Rostedt (Google) --- kernel/trace/trace.h | 4 ++ kernel/trace/trace_events_hist.c | 7 ++- kernel/trace/trace_events_synth.c | 80 ++++++++++++++++++++++++++++++- kernel/trace/trace_synth.h | 1 + 4 files changed, 87 insertions(+), 5 deletions(-) diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h index 4eb6d6b97a9f..d16929dd0f08 100644 --- a/kernel/trace/trace.h +++ b/kernel/trace/trace.h @@ -113,6 +113,10 @@ enum trace_type { #define MEM_FAIL(condition, fmt, ...) \ DO_ONCE_LITE_IF(condition, pr_err, "ERROR: " fmt, ##__VA_ARGS__) =20 +#define HIST_STACKTRACE_DEPTH 16 +#define HIST_STACKTRACE_SIZE (HIST_STACKTRACE_DEPTH * sizeof(unsigned long= )) +#define HIST_STACKTRACE_SKIP 5 + /* * syscalls are special, and need special handling, this is why * they are not included in trace_entries.h diff --git a/kernel/trace/trace_events_hist.c b/kernel/trace/trace_events_h= ist.c index f8f67e17898a..2c0837ff2299 100644 --- a/kernel/trace/trace_events_hist.c +++ b/kernel/trace/trace_events_hist.c @@ -480,10 +480,6 @@ DEFINE_HIST_FIELD_FN(u8); #define for_each_hist_key_field(i, hist_data) \ for ((i) =3D (hist_data)->n_vals; (i) < (hist_data)->n_fields; (i)++) =20 -#define HIST_STACKTRACE_DEPTH 16 -#define HIST_STACKTRACE_SIZE (HIST_STACKTRACE_DEPTH * sizeof(unsigned long= )) -#define HIST_STACKTRACE_SKIP 5 - #define HITCOUNT_IDX 0 #define HIST_KEY_SIZE_MAX (MAX_FILTER_STR_VAL + HIST_STACKTRACE_SIZE) =20 @@ -3869,6 +3865,9 @@ static int check_synth_field(struct synth_event *even= t, && field->is_dynamic) return 0; =20 + if (strstr(hist_field->type, "long[") && field->is_stack) + return 0; + if (strcmp(field->type, hist_field->type) !=3D 0) { if (field->size !=3D hist_field->size || (!field->is_string && field->is_signed !=3D hist_field->is_signed)) diff --git a/kernel/trace/trace_events_synth.c b/kernel/trace/trace_events_= synth.c index 9f79cd689b79..adb630633f31 100644 --- a/kernel/trace/trace_events_synth.c +++ b/kernel/trace/trace_events_synth.c @@ -173,6 +173,14 @@ static int synth_field_is_string(char *type) return false; } =20 +static int synth_field_is_stack(char *type) +{ + if (strstr(type, "long[") !=3D NULL) + return true; + + return false; +} + static int synth_field_string_size(char *type) { char buf[4], *end, *start; @@ -248,6 +256,8 @@ static int synth_field_size(char *type) size =3D sizeof(gfp_t); else if (synth_field_is_string(type)) size =3D synth_field_string_size(type); + else if (synth_field_is_stack(type)) + size =3D 0; =20 return size; } @@ -292,6 +302,8 @@ static const char *synth_field_fmt(char *type) fmt =3D "%x"; else if (synth_field_is_string(type)) fmt =3D "%.*s"; + else if (synth_field_is_stack(type)) + fmt =3D "%s"; =20 return fmt; } @@ -371,6 +383,23 @@ static enum print_line_t print_synth_event(struct trac= e_iterator *iter, i =3D=3D se->n_fields - 1 ? "" : " "); n_u64 +=3D STR_VAR_LEN_MAX / sizeof(u64); } + } else if (se->fields[i]->is_stack) { + u32 offset, data_offset, len; + unsigned long *p, *end; + + offset =3D (u32)entry->fields[n_u64]; + data_offset =3D offset & 0xffff; + len =3D offset >> 16; + + p =3D (void *)entry + data_offset; + end =3D (void *)p + len - (sizeof(long) - 1); + + trace_seq_printf(s, "%s=3DSTACK:\n", se->fields[i]->name); + + for (; *p && p < end; p++) + trace_seq_printf(s, "=3D> %pS\n", (void *)*p); + n_u64++; + } else { struct trace_print_flags __flags[] =3D { __def_gfpflag_names, {-1, NULL} }; @@ -446,6 +475,43 @@ static unsigned int trace_string(struct synth_trace_ev= ent *entry, return len; } =20 +static unsigned int trace_stack(struct synth_trace_event *entry, + struct synth_event *event, + long *stack, + unsigned int data_size, + unsigned int *n_u64) +{ + unsigned int len; + u32 data_offset; + void *data_loc; + + data_offset =3D struct_size(entry, fields, event->n_u64); + data_offset +=3D data_size; + + for (len =3D 0; len < HIST_STACKTRACE_DEPTH; len++) { + if (!stack[len]) + break; + } + + /* Include the zero'd element if it fits */ + if (len < HIST_STACKTRACE_DEPTH) + len++; + + len *=3D sizeof(long); + + /* Find the dynamic section to copy the stack into. */ + data_loc =3D (void *)entry + data_offset; + memcpy(data_loc, stack, len); + + /* Fill in the field that holds the offset/len combo */ + data_offset |=3D len << 16; + *(u32 *)&entry->fields[*n_u64] =3D data_offset; + + (*n_u64)++; + + return len; +} + static notrace void trace_event_raw_event_synth(void *__data, u64 *var_ref_vals, unsigned int *var_ref_idx) @@ -498,6 +564,12 @@ static notrace void trace_event_raw_event_synth(void *= __data, event->fields[i]->is_dynamic, data_size, &n_u64); data_size +=3D len; /* only dynamic string increments */ + } if (event->fields[i]->is_stack) { + long *stack =3D (long *)(long)var_ref_vals[val_idx]; + + len =3D trace_stack(entry, event, stack, + data_size, &n_u64); + data_size +=3D len; } else { struct synth_field *field =3D event->fields[i]; u64 val =3D var_ref_vals[val_idx]; @@ -560,6 +632,9 @@ static int __set_synth_event_print_fmt(struct synth_eve= nt *event, event->fields[i]->is_dynamic) pos +=3D snprintf(buf + pos, LEN_OR_ZERO, ", __get_str(%s)", event->fields[i]->name); + else if (event->fields[i]->is_stack) + pos +=3D snprintf(buf + pos, LEN_OR_ZERO, + ", __get_stacktrace(%s)", event->fields[i]->name); else pos +=3D snprintf(buf + pos, LEN_OR_ZERO, ", REC->%s", event->fields[i]->name); @@ -696,7 +771,8 @@ static struct synth_field *parse_synth_field(int argc, = char **argv, ret =3D -EINVAL; goto free; } else if (size =3D=3D 0) { - if (synth_field_is_string(field->type)) { + if (synth_field_is_string(field->type) || + synth_field_is_stack(field->type)) { char *type; =20 len =3D sizeof("__data_loc ") + strlen(field->type) + 1; @@ -727,6 +803,8 @@ static struct synth_field *parse_synth_field(int argc, = char **argv, =20 if (synth_field_is_string(field->type)) field->is_string =3D true; + else if (synth_field_is_stack(field->type)) + field->is_stack =3D true; =20 field->is_signed =3D synth_field_signed(field->type); out: diff --git a/kernel/trace/trace_synth.h b/kernel/trace/trace_synth.h index b29595fe3ac5..43f6fb6078db 100644 --- a/kernel/trace/trace_synth.h +++ b/kernel/trace/trace_synth.h @@ -18,6 +18,7 @@ struct synth_field { bool is_signed; bool is_string; bool is_dynamic; + bool is_stack; }; =20 struct synth_event { --=20 2.39.0