Hi Steve and Daniel,
Following our discussion last week about more parseable hist trigger
output, I started trying to implement the 'csv' output you had
mentioned, but realized that since it was more than just table output
that was needed, JSON would be a better fit, so implemented that in
this patch instead.
I designed it so that more files/formats could be easily added as
desired, so if you still want the csv output, let me know. If so,
though, please give me some more detailed idea as to what you think
that should look like.
Here are some examples of the JSON output for various histograms:
A simple straighforward histogram:
# echo 'hist:key=id.syscall,common_pid.execname:val=hitcount:sort=id,hitcount' >> /sys/kernel/debug/tracing/events/raw_syscalls/sys_enter/trigger
# cat /sys/kernel/debug/tracing/events/raw_syscalls/sys_enter/hist_json
[
"hist":{
"info":{
"trigger":"hist:keys=id.syscall,common_pid.execname:vals=hitcount:sort=id.syscall,hitcount:size=2048 [active]
"
},
"map":{
"entry":{
"keys":[
{
"id":"sys_read [ 0]",
},
{
"common_pid":"Xwayland [ 2867]",
},
],
"vals":[
{
"hitcount":"1",
},
],
},
"entry":{
"keys":[
{
"id":"sys_read [ 0]",
},
{
"common_pid":"sh [ 3428]",
},
],
"vals":[
{
"hitcount":"1",
},
],
},
"entry":{
...
"entry":{
"keys":[
{
"id":"sys_getrandom [318]",
},
{
"common_pid":"update-notifier [ 3408]",
},
],
"vals":[
{
"hitcount":"95",
},
],
},
"entry":{
"keys":[
{
"id":"sys_getrandom [318]",
},
{
"common_pid":"apt-check [ 3416]",
},
],
"vals":[
{
"hitcount":"815",
},
],
},
},
"totals":{
"hits":"112930",
"entries":"1390",
"dropped":"0",
},
},
]
A histogram with save() variables and snapshot() info:
# echo 'hist:keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_waking/trigger
#echo 'hist:keys=next_pid:wakeup_lat=common_timestamp.usecs-$ts0:onmax($wakeup_lat).save(next_prio,next_comm,prev_pid,prev_prio,prev_comm):onmax($wakeup_lat).snapshot() if next_comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_switch/trigger
# cat /sys/kernel/debug/tracing/events/sched/sched_switch/hist_json
[
"hist":{
"info":{
"trigger":"hist:keys=next_pid:vals=hitcount:wakeup_lat=common_timestamp.usecs-$ts0:sort=hitcount:size=2048:clock=global:onmax($wakeup_lat).save(next_prio,next_comm,prev_pid,prev_prio,prev_comm):onmax($wakeup_lat).snapshot() if next_comm=="cyclictest" [active]
"
},
"map":{
"entry":{
"keys":[
{
"next_pid":"3419",
},
],
"vals":[
{
"hitcount":"156",
},
],
"action":{
"max":"439",
"next_prio":"120",
"next_comm":"cyclictest",
"prev_pid":"0",
"prev_prio":"120",
"prev_comm":"swapper/1",
},
},
"entry":{
"keys":[
{
"next_pid":"3420",
},
],
"vals":[
{
"hitcount":"1563",
},
],
"action":{
"max":"1667",
"next_prio":"120",
"next_comm":"cyclictest",
"prev_pid":"1991",
"prev_prio":"120",
"prev_comm":"FAHClient",
},
},
},
"snapshot":{
"handler":"onmax",
"$wakeup_lat":"1667",
"keys":[
{
"next_pid":"3420",
},
],
},
"totals":{
"hits":"1719",
"entries":"2",
"dropped":"0",
},
},
]
And finally, just to show that even stacktraces in JSON works ;-)
# echo 'hist:keys=stacktrace:values=bytes_req,bytes_alloc:sort=bytes_alloc' >> /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger
# cat /sys/kernel/debug/tracing/events/kmem/kmalloc/hist_json
"info":{
"trigger":"hist:keys=stacktrace:vals=hitcount,bytes_req,bytes_alloc:sort=b
ytes_alloc:size=2048 [active]
"
},
"map":{
"entry":{
"keys":[
{
"stacktrace":"
acpi_ns_internalize_name+0x4a/0xa3
acpi_ns_get_node_unlocked+0x70/0xd8
acpi_ns_get_node+0x40/0x55
acpi_ns_evaluate+0x4c/0x24e
acpi_evaluate_object+0x137/0x240
acpi_battery_get_state+0x95/0x230
acpi_battery_get_property+0x4c/0x3f0
power_supply_show_property+0xd2/0x260
dev_attr_show+0x18/0x50
sysfs_kf_seq_show+0xa3/0x110
seq_read_iter+0xdd/0x460
new_sync_read+0x11b/0x1a0
vfs_read+0x198/0x1c0
ksys_read+0xa7/0xe0
do_syscall_64+0x3a/0xb0
entry_SYSCALL_64_after_hwframe+0x44/0xae
"
},
],
"vals":[
{
"hitcount":"1",
},
{
"bytes_req":"8",
},
{
"bytes_alloc":"8",
},
},
],
},
"entry":{
"keys":[
{
"stacktrace":"
ecryptfs_write_inode_size_to_metadata+0x38/0x190
truncate_upper.isra.16+0x14e/0x250
ecryptfs_setattr+0x276/0x2c0
notify_change+0x392/0x4d0
do_truncate+0x7c/0xd0
path_openat+0x8e2/0xa60
do_filp_open+0xc5/0x140
do_sys_openat2+0x23e/0x300
do_sys_open+0x57/0x80
do_syscall_64+0x3a/0xb0
entry_SYSCALL_64_after_hwframe+0x44/0xae
"
},
],
"vals":[
{
"hitcount":"1",
},
{
"bytes_req":"8",
},
{
"bytes_alloc":"8",
},
],
},
...
"entry":{
"keys":[
{
"stacktrace":"
ath10k_wmi_tlv_parse_alloc.constprop.30+0x35/0x80 [ath10k_core]
ath10k_wmi_tlv_op_pull_fw_stats+0x38/0x420 [ath10k_core]
ath10k_debug_fw_stats_process+0x9c/0x410 [ath10k_core]
ath10k_wmi_tlv_op_rx+0x1a6/0xf20 [ath10k_core]
ath10k_htc_rx_completion_handler+0x13c/0x180 [ath10k_core]
ath10k_pci_process_rx_cb+0x122/0x190 [ath10k_pci]
ath10k_ce_per_engine_service+0x5d/0x80 [ath10k_core]
ath10k_ce_per_engine_service_any+0x6a/0xa0 [ath10k_core]
ath10k_pci_napi_poll+0x44/0x110 [ath10k_pci]
__napi_poll+0x2d/0x200
net_rx_action+0xe6/0x210
__do_softirq+0xce/0x43c
irq_exit_rcu+0xa4/0xb0
common_interrupt+0x5c/0xa0
asm_common_interrupt+0x1e/0x40
cpuidle_enter_state+0x113/0x4a0
"
},
],
"vals":[
{
"hitcount":"569",
},
{
"bytes_req":"3149984",
},
{
"bytes_alloc":"4661248",
},
],
},
},
"totals":{
"hits":"62147",
"entries":"453",
"dropped":"0",
},
},
]
Tom
The following changes since commit 3dc65994e3c1c999be3d991cdc96705e167cb3b1:
tools/bootconfig: Use per-group/all enable option in ftrace2bconf script (2021-08-08 19:41:50 -0400)
are available in the Git repository at:
git://git.kernel.org/pub/scm/linux/kernel/git/zanussi/linux-trace.git ftrace/hist-json-v1
Tom Zanussi (1):
tracing: Add hist_json event file
kernel/trace/trace.h | 1 +
kernel/trace/trace_events.c | 2 +
kernel/trace/trace_events_hist.c | 532 ++++++++++++++++++++++++++-----
3 files changed, 463 insertions(+), 72 deletions(-)
--
2.17.1
Add a file named hist_json for each trace event. Reading it will dump
the contents of all current histogram(s) defined on the event in json
format.
The file contents include not only the histogram bucket contents but
also related data associated with the histogram such as histogram
info, totals, and the values of any action variables that may be
associated with it.
If there are multiple histograms associated with an event, each
histogram is dumped in its entirety before the next starts.
The same functions that print the histogram to the 'hist' file are
used to print the 'hist_json' contents. Other formats can easily be
added by adding a new show_format in addition to the TEXT and JSON
formats implemented here.
Signed-off-by: Tom Zanussi <[email protected]>
---
kernel/trace/trace.h | 1 +
kernel/trace/trace_events.c | 2 +
kernel/trace/trace_events_hist.c | 532 ++++++++++++++++++++++++++-----
3 files changed, 463 insertions(+), 72 deletions(-)
diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
index a180abf76d4e..c212c379a172 100644
--- a/kernel/trace/trace.h
+++ b/kernel/trace/trace.h
@@ -1526,6 +1526,7 @@ extern struct list_head ftrace_events;
extern const struct file_operations event_trigger_fops;
extern const struct file_operations event_hist_fops;
+extern const struct file_operations event_hist_json_fops;
extern const struct file_operations event_hist_debug_fops;
extern const struct file_operations event_inject_fops;
diff --git a/kernel/trace/trace_events.c b/kernel/trace/trace_events.c
index 80e96989770e..e5e8ec1cb5d0 100644
--- a/kernel/trace/trace_events.c
+++ b/kernel/trace/trace_events.c
@@ -2432,6 +2432,8 @@ event_create_dir(struct dentry *parent, struct trace_event_file *file)
#ifdef CONFIG_HIST_TRIGGERS
trace_create_file("hist", 0444, file->dir, file,
&event_hist_fops);
+ trace_create_file("hist_json", 0444, file->dir, file,
+ &event_hist_json_fops);
#endif
#ifdef CONFIG_HIST_TRIGGERS_DEBUG
trace_create_file("hist_debug", 0444, file->dir, file,
diff --git a/kernel/trace/trace_events_hist.c b/kernel/trace/trace_events_hist.c
index 9d91b1c06957..5221522d9a3d 100644
--- a/kernel/trace/trace_events_hist.c
+++ b/kernel/trace/trace_events_hist.c
@@ -2903,6 +2903,176 @@ static bool check_track_val(struct tracing_map_elt *elt,
return data->track_data.check_val(track_val, var_val);
}
+enum show_format {
+ TEXT,
+ JSON,
+};
+
+static void indent(struct seq_file *m, int *level)
+{
+#define JSON_INDENT 2
+
+ int indent_spaces = *level * JSON_INDENT;
+
+ seq_printf(m, "%*c", indent_spaces, ' ');
+}
+
+static void __print_obj_name(struct seq_file *m, const char *name,
+ enum show_format format)
+{
+ if (!name)
+ return;
+
+ if (format == JSON)
+ seq_printf(m, "\"%s\":", name);
+ else if (format == TEXT)
+ seq_printf(m, "%s:", name);
+}
+
+static void __start_json_obj(struct seq_file *m, const char *name, int *level,
+ const char *bracket)
+{
+ indent(m, level);
+ __print_obj_name(m, name, JSON);
+ seq_puts(m, bracket);
+ (*level)++;
+}
+
+static void __end_json_obj(struct seq_file *m, int *level, const char *bracket)
+{
+ (*level)--;
+ indent(m, level);
+ seq_puts(m, bracket);
+}
+
+static void print_json_obj_start(struct seq_file *m,
+ const char *name, int *level)
+{
+ __start_json_obj(m, name, level, "{\n");
+}
+
+static void print_json_obj_end(struct seq_file *m, int *level)
+{
+ __end_json_obj(m, level, "},\n");
+}
+
+static void __start_obj(struct seq_file *m, const char *name,
+ enum show_format format, int *level)
+{
+ if (format == JSON)
+ print_json_obj_start(m, name, level);
+}
+
+static void __end_obj(struct seq_file *m, enum show_format format, int *level)
+{
+ if (format == JSON)
+ print_json_obj_end(m, level);
+}
+
+static void __start_json_array(struct seq_file *m, const char *name,
+ int *level)
+{
+ __start_json_obj(m, name, level, "[\n");
+}
+
+static void __end_json_array(struct seq_file *m, int *level)
+{
+ __end_json_obj(m, level, "],\n");
+}
+
+static void print_hist_start(struct seq_file *m, int nth_hist,
+ enum show_format format, int *level)
+{
+ if (nth_hist > 0 && format == TEXT)
+ seq_puts(m, "\n\n");
+
+ __start_obj(m, "hist", format, level);
+}
+
+#define print_hist_end(m, format, level) \
+ __end_obj(m, format, level)
+#define print_map_start(m, format, level) \
+ __start_obj(m, "map", format, level)
+#define print_map_end(m, format, level) \
+ __end_obj(m, format, level)
+#define print_entry_start(m, format, level) \
+ __start_obj(m, "entry", format, level)
+#define print_entry_end(m, format, level) \
+ __end_obj(m, format, level)
+#define print_action_start(m, format, level) \
+ __start_obj(m, "action", format, level)
+#define print_action_end(m, format, level) \
+ __end_obj(m, format, level)
+#define print_snapshot_action_start(m, format, level) \
+ __start_obj(m, "snapshot", format, level)
+#define print_snapshot_action_end(m, format, level) \
+ __end_obj(m, format, level)
+#define print_key_start(m, format, level) \
+ __start_obj(m, NULL, format, level)
+#define print_key_end(m, format, level) \
+ __end_obj(m, format, level)
+#define print_val_end(m, format, level) \
+ __end_obj(m, format, level)
+
+static void print_val_start(struct seq_file *m,
+ enum show_format format, int *level)
+{
+ if (format == JSON)
+ print_json_obj_start(m, NULL, level);
+ else if (format == TEXT)
+ seq_putc(m, ' ');
+}
+
+static void print_keys_start(struct seq_file *m,
+ enum show_format format, int *level)
+{
+ if (format == JSON)
+ __start_json_array(m, "keys", level);
+ else if (format == TEXT)
+ seq_puts(m, "{ ");
+}
+
+static void print_keys_end(struct seq_file *m,
+ enum show_format format, int *level)
+{
+ if (format == JSON)
+ __end_json_array(m, level);
+ else if (format == TEXT)
+ seq_puts(m, "}");
+}
+
+static void print_vals_start(struct seq_file *m,
+ enum show_format format, int *level)
+{
+ if (format == JSON)
+ __start_json_array(m, "vals", level);
+}
+
+static void print_vals_end(struct seq_file *m,
+ enum show_format format, int *level)
+{
+ if (format == JSON)
+ __end_json_array(m, level);
+}
+
+static void print_pair_start(struct seq_file *m, const char *name,
+ enum show_format format, int *level)
+{
+ if (format == JSON)
+ indent(m, level);
+
+ __print_obj_name(m, name, format);
+}
+
+static void print_pair_end(struct seq_file *m, const char *val,
+ enum show_format format)
+{
+ if (format == JSON)
+ seq_printf(m, "\"%s\",\n", val);
+ else if (format == TEXT)
+ seq_puts(m, val);
+}
+
#ifdef CONFIG_TRACER_SNAPSHOT
static bool cond_snapshot_update(struct trace_array *tr, void *cond_data)
{
@@ -2956,7 +3126,8 @@ static void save_track_data_snapshot(struct hist_trigger_data *hist_data,
static void hist_trigger_print_key(struct seq_file *m,
struct hist_trigger_data *hist_data,
void *key,
- struct tracing_map_elt *elt);
+ struct tracing_map_elt *elt,
+ enum show_format format, int *level);
static struct action_data *snapshot_action(struct hist_trigger_data *hist_data)
{
@@ -2976,11 +3147,13 @@ static struct action_data *snapshot_action(struct hist_trigger_data *hist_data)
}
static void track_data_snapshot_print(struct seq_file *m,
- struct hist_trigger_data *hist_data)
+ struct hist_trigger_data *hist_data,
+ enum show_format format, int *level)
{
struct trace_event_file *file = hist_data->event_file;
struct track_data *track_data;
struct action_data *action;
+ char str[MAX_FILTER_STR_VAL];
track_data = tracing_cond_snapshot_data(file->tr);
if (!track_data)
@@ -2993,14 +3166,32 @@ static void track_data_snapshot_print(struct seq_file *m,
if (!action)
return;
- seq_puts(m, "\nSnapshot taken (see tracing/snapshot). Details:\n");
- seq_printf(m, "\ttriggering value { %s(%s) }: %10llu",
- action->handler == HANDLER_ONMAX ? "onmax" : "onchange",
- action->track_data.var_str, track_data->track_val);
+ if (format == JSON) {
+ print_snapshot_action_start(m, format, level);
+ print_pair_start(m, "handler", format, level);
+ if (action->handler == HANDLER_ONMAX)
+ print_pair_end(m, "onmax", format);
+ else
+ print_pair_end(m, "onchange", format);
- seq_puts(m, "\ttriggered by event with key: ");
- hist_trigger_print_key(m, hist_data, track_data->key, &track_data->elt);
- seq_putc(m, '\n');
+ print_pair_start(m, action->track_data.var_str, format, level);
+ snprintf(str, sizeof(str), "%10llu", track_data->track_val);
+ print_pair_end(m, strim(str), format);
+ } else if (format == TEXT) {
+ seq_puts(m, "\nSnapshot taken (see tracing/snapshot). Details:\n");
+ seq_printf(m, "\ttriggering value { %s(%s) }: %10llu",
+ action->handler == HANDLER_ONMAX ? "onmax" : "onchange",
+ action->track_data.var_str, track_data->track_val);
+
+ seq_puts(m, "\ttriggered by event with key: ");
+ }
+
+ hist_trigger_print_key(m, hist_data, track_data->key, &track_data->elt,
+ format, level);
+ if (format == JSON)
+ print_snapshot_action_end(m, format, level);
+ else
+ seq_putc(m, '\n');
}
#else
static bool cond_snapshot_update(struct trace_array *tr, void *cond_data)
@@ -3014,24 +3205,71 @@ static void save_track_data_snapshot(struct hist_trigger_data *hist_data,
struct action_data *data,
u64 *var_ref_vals) {}
static void track_data_snapshot_print(struct seq_file *m,
- struct hist_trigger_data *hist_data) {}
+ struct hist_trigger_data *hist_data,
+ enum show_format format, int *level) {}
#endif /* CONFIG_TRACER_SNAPSHOT */
+static void print_track_val(struct seq_file *m, const char *handler,
+ u64 track_val, enum show_format format, int *level)
+{
+ char str[MAX_FILTER_STR_VAL];
+
+ if (format == JSON) {
+ print_pair_start(m, handler, format, level);
+ snprintf(str, sizeof(str), "%10llu", track_val);
+ print_pair_end(m, strim(str), format);
+ } else if (format == TEXT) {
+ seq_printf(m, "\n\t%s: %10llu", handler, track_val);
+ }
+}
+
+static void print_variable(struct seq_file *m, const char *var_name, u64 val,
+ bool is_string, enum show_format format, int *level)
+{
+ char str[MAX_FILTER_STR_VAL];
+
+ if (is_string) {
+ if (format == JSON) {
+ snprintf(str, sizeof(str), "%s", var_name);
+ print_pair_start(m, str, format, level);
+ snprintf(str, sizeof(str), "%-32s", (char *)(uintptr_t)(val));
+ print_pair_end(m, strim(str), format);
+ } else if (format == TEXT) {
+ seq_printf(m, " %s: %-32s", var_name,
+ (char *)(uintptr_t)(val));
+ }
+ } else {
+ if (format == JSON) {
+ snprintf(str, sizeof(str), "%s", var_name);
+ print_pair_start(m, str, format, level);
+ snprintf(str, sizeof(str), "%10llu", val);
+ print_pair_end(m, strim(str), format);
+ } else {
+ seq_printf(m, " %s: %10llu", var_name, val);
+ }
+ }
+}
+
static void track_data_print(struct seq_file *m,
struct hist_trigger_data *hist_data,
struct tracing_map_elt *elt,
- struct action_data *data)
+ struct action_data *data,
+ enum show_format format, int *level)
{
u64 track_val = get_track_val(hist_data, elt, data);
unsigned int i, save_var_idx;
+ print_action_start(m, format, level);
+
if (data->handler == HANDLER_ONMAX)
- seq_printf(m, "\n\tmax: %10llu", track_val);
+ print_track_val(m, "max", track_val, format, level);
else if (data->handler == HANDLER_ONCHANGE)
- seq_printf(m, "\n\tchanged: %10llu", track_val);
+ print_track_val(m, "changed", track_val, format, level);
- if (data->action == ACTION_SNAPSHOT)
+ if (data->action == ACTION_SNAPSHOT) {
+ print_action_end(m, format, level);
return;
+ }
for (i = 0; i < hist_data->n_save_vars; i++) {
struct hist_field *save_val = hist_data->save_vars[i]->val;
@@ -3042,12 +3280,12 @@ static void track_data_print(struct seq_file *m,
val = tracing_map_read_var(elt, save_var_idx);
- if (save_val->flags & HIST_FIELD_FL_STRING) {
- seq_printf(m, " %s: %-32s", save_var->var.name,
- (char *)(uintptr_t)(val));
- } else
- seq_printf(m, " %s: %10llu", save_var->var.name, val);
+ print_variable(m, save_var->var.name, val,
+ save_val->flags & HIST_FIELD_FL_STRING,
+ format, level);
}
+
+ print_action_end(m, format, level);
}
static void ontrack_action(struct hist_trigger_data *hist_data,
@@ -4276,7 +4514,8 @@ static int create_actions(struct hist_trigger_data *hist_data)
static void print_actions(struct seq_file *m,
struct hist_trigger_data *hist_data,
- struct tracing_map_elt *elt)
+ struct tracing_map_elt *elt,
+ enum show_format format, int *level)
{
unsigned int i;
@@ -4288,7 +4527,7 @@ static void print_actions(struct seq_file *m,
if (data->handler == HANDLER_ONMAX ||
data->handler == HANDLER_ONCHANGE)
- track_data_print(m, hist_data, elt, data);
+ track_data_print(m, hist_data, elt, data, format, level);
}
}
@@ -4694,7 +4933,8 @@ static void event_hist_trigger(struct event_trigger_data *data,
static void hist_trigger_stacktrace_print(struct seq_file *m,
unsigned long *stacktrace_entries,
- unsigned int max_entries)
+ unsigned int max_entries,
+ enum show_format format, int *level)
{
char str[KSYM_SYMBOL_LEN];
unsigned int spaces = 8;
@@ -4704,7 +4944,10 @@ static void hist_trigger_stacktrace_print(struct seq_file *m,
if (!stacktrace_entries[i])
return;
- seq_printf(m, "%*c", 1 + spaces, ' ');
+ if (format == JSON)
+ indent(m, level);
+ else if (format == TEXT)
+ seq_printf(m, "%*c", 1 + spaces, ' ');
sprint_symbol(str, stacktrace_entries[i]);
seq_printf(m, "%s\n", str);
}
@@ -4713,8 +4956,10 @@ static void hist_trigger_stacktrace_print(struct seq_file *m,
static void hist_trigger_print_key(struct seq_file *m,
struct hist_trigger_data *hist_data,
void *key,
- struct tracing_map_elt *elt)
+ struct tracing_map_elt *elt,
+ enum show_format format, int *level)
{
+ char key_str[MAX_FILTER_STR_VAL];
struct hist_field *key_field;
char str[KSYM_SYMBOL_LEN];
bool multiline = false;
@@ -4722,29 +4967,36 @@ static void hist_trigger_print_key(struct seq_file *m,
unsigned int i;
u64 uval;
- seq_puts(m, "{ ");
+ print_keys_start(m, format, level);
for_each_hist_key_field(i, hist_data) {
key_field = hist_data->fields[i];
- if (i > hist_data->n_vals)
+ if (i > hist_data->n_vals && format == TEXT)
seq_puts(m, ", ");
- field_name = hist_field_name(key_field, 0);
+ print_key_start(m, format, level);
+
+ if (key_field->flags & HIST_FIELD_FL_STACKTRACE)
+ field_name = "stacktrace";
+ else
+ field_name = hist_field_name(key_field, 0);
+
+ print_pair_start(m, field_name, format, level);
if (key_field->flags & HIST_FIELD_FL_HEX) {
uval = *(u64 *)(key + key_field->offset);
- seq_printf(m, "%s: %llx", field_name, uval);
+ snprintf(key_str, sizeof(key_str), "%llx", uval);
} else if (key_field->flags & HIST_FIELD_FL_SYM) {
uval = *(u64 *)(key + key_field->offset);
sprint_symbol_no_offset(str, uval);
- seq_printf(m, "%s: [%llx] %-45s", field_name,
- uval, str);
+ snprintf(key_str, sizeof(key_str), "[%llx] %-45s",
+ uval, str);
} else if (key_field->flags & HIST_FIELD_FL_SYM_OFFSET) {
uval = *(u64 *)(key + key_field->offset);
sprint_symbol(str, uval);
- seq_printf(m, "%s: [%llx] %-55s", field_name,
- uval, str);
+ snprintf(key_str, sizeof(key_str), "[%llx] %-55s",
+ uval, str);
} else if (key_field->flags & HIST_FIELD_FL_EXECNAME) {
struct hist_elt_data *elt_data = elt->private_data;
char *comm;
@@ -4755,8 +5007,8 @@ static void hist_trigger_print_key(struct seq_file *m,
comm = elt_data->comm;
uval = *(u64 *)(key + key_field->offset);
- seq_printf(m, "%s: %-16s[%10llu]", field_name,
- comm, uval);
+ snprintf(key_str, sizeof(key_str), "%-16s[%10llu]",
+ comm, uval);
} else if (key_field->flags & HIST_FIELD_FL_SYSCALL) {
const char *syscall_name;
@@ -4765,49 +5017,72 @@ static void hist_trigger_print_key(struct seq_file *m,
if (!syscall_name)
syscall_name = "unknown_syscall";
- seq_printf(m, "%s: %-30s[%3llu]", field_name,
- syscall_name, uval);
+ snprintf(key_str, sizeof(key_str), "%-30s[%3llu]",
+ syscall_name, uval);
} else if (key_field->flags & HIST_FIELD_FL_STACKTRACE) {
- seq_puts(m, "stacktrace:\n");
+ if (format == JSON)
+ seq_puts(m, "\"\n");
+ else if (format == TEXT)
+ seq_puts(m, "\n");
hist_trigger_stacktrace_print(m,
key + key_field->offset,
- HIST_STACKTRACE_DEPTH);
+ HIST_STACKTRACE_DEPTH,
+ format, level);
multiline = true;
} else if (key_field->flags & HIST_FIELD_FL_LOG2) {
- seq_printf(m, "%s: ~ 2^%-2llu", field_name,
- *(u64 *)(key + key_field->offset));
+ snprintf(key_str, sizeof(key_str), "~ 2^%-2llu",
+ *(u64 *)(key + key_field->offset));
} else if (key_field->flags & HIST_FIELD_FL_BUCKET) {
unsigned long buckets = key_field->buckets;
uval = *(u64 *)(key + key_field->offset);
- seq_printf(m, "%s: ~ %llu-%llu", field_name,
- uval, uval + buckets -1);
+ snprintf(key_str, sizeof(key_str), "~ %llu-%llu",
+ uval, uval + buckets - 1);
} else if (key_field->flags & HIST_FIELD_FL_STRING) {
- seq_printf(m, "%s: %-50s", field_name,
- (char *)(key + key_field->offset));
+ snprintf(key_str, sizeof(key_str), "%-50s",
+ (char *)(key + key_field->offset));
} else {
uval = *(u64 *)(key + key_field->offset);
- seq_printf(m, "%s: %10llu", field_name, uval);
+ snprintf(key_str, sizeof(key_str), "%10llu", uval);
}
+ if (key_field->flags & HIST_FIELD_FL_STACKTRACE) {
+ if (format == JSON) {
+ indent(m, level);
+ seq_puts(m, "\"\n");
+ }
+ } else {
+ print_pair_end(m, strim(key_str), format);
+ }
+ print_key_end(m, format, level);
}
- if (!multiline)
+ if (!multiline && format == TEXT)
seq_puts(m, " ");
- seq_puts(m, "}");
+ print_keys_end(m, format, level);
}
static void hist_trigger_entry_print(struct seq_file *m,
struct hist_trigger_data *hist_data,
void *key,
- struct tracing_map_elt *elt)
+ struct tracing_map_elt *elt,
+ enum show_format format, int *level)
{
+ char val_str[MAX_FILTER_STR_VAL];
const char *field_name;
unsigned int i;
- hist_trigger_print_key(m, hist_data, key, elt);
+ print_entry_start(m, format, level);
+
+ hist_trigger_print_key(m, hist_data, key, elt, format, level);
- seq_printf(m, " hitcount: %10llu",
- tracing_map_read_sum(elt, HITCOUNT_IDX));
+ print_vals_start(m, format, level);
+
+ print_val_start(m, format, level);
+ print_pair_start(m, "hitcount", format, level);
+ snprintf(val_str, sizeof(val_str), "%10llu",
+ tracing_map_read_sum(elt, HITCOUNT_IDX));
+ print_pair_end(m, strim(val_str), format);
+ print_val_end(m, format, level);
for (i = 1; i < hist_data->n_vals; i++) {
field_name = hist_field_name(hist_data->fields[i], 0);
@@ -4816,22 +5091,34 @@ static void hist_trigger_entry_print(struct seq_file *m,
hist_data->fields[i]->flags & HIST_FIELD_FL_EXPR)
continue;
+ print_val_start(m, format, level);
+ print_pair_start(m, field_name, format, level);
+
if (hist_data->fields[i]->flags & HIST_FIELD_FL_HEX) {
- seq_printf(m, " %s: %10llx", field_name,
- tracing_map_read_sum(elt, i));
+ snprintf(val_str, sizeof(val_str), "%10llx",
+ tracing_map_read_sum(elt, i));
} else {
- seq_printf(m, " %s: %10llu", field_name,
- tracing_map_read_sum(elt, i));
+ snprintf(val_str, sizeof(val_str), "%10llu",
+ tracing_map_read_sum(elt, i));
}
+
+ print_pair_end(m, strim(val_str), format);
+ print_val_end(m, format, level);
}
- print_actions(m, hist_data, elt);
+ print_vals_end(m, format, level);
+
+ print_actions(m, hist_data, elt, format, level);
+
+ print_entry_end(m, format, level);
- seq_puts(m, "\n");
+ if (format != JSON)
+ seq_puts(m, "\n");
}
static int print_entries(struct seq_file *m,
- struct hist_trigger_data *hist_data)
+ struct hist_trigger_data *hist_data,
+ enum show_format format, int *level)
{
struct tracing_map_sort_entry **sort_entries = NULL;
struct tracing_map *map = hist_data->map;
@@ -4846,43 +5133,97 @@ static int print_entries(struct seq_file *m,
for (i = 0; i < n_entries; i++)
hist_trigger_entry_print(m, hist_data,
sort_entries[i]->key,
- sort_entries[i]->elt);
+ sort_entries[i]->elt, format, level);
tracing_map_destroy_sort_entries(sort_entries, n_entries);
return n_entries;
}
+static void show_hist_info(struct seq_file *m, struct event_trigger_data *data,
+ enum show_format format, int *level)
+{
+ if (format == JSON) {
+ print_json_obj_start(m, "info", level);
+ print_pair_start(m, "trigger", format, level);
+ seq_puts(m, "\"");
+ } else if (format == TEXT) {
+ seq_puts(m, "# event histogram\n#\n# trigger info: ");
+ }
+
+ data->ops->print(m, data->ops, data);
+
+ if (format == JSON) {
+ seq_puts(m, "\"\n");
+ print_json_obj_end(m, level);
+ } else {
+ seq_puts(m, "#\n\n");
+ }
+}
+
+static void print_hist_totals(struct seq_file *m,
+ struct hist_trigger_data *hist_data, int n_entries,
+ enum show_format format, int *level)
+{
+ char str[MAX_FILTER_STR_VAL];
+
+ if (format == JSON) {
+ print_json_obj_start(m, "totals", level);
+
+ print_pair_start(m, "hits", format, level);
+ snprintf(str, sizeof(str), "%llu",
+ (u64)atomic64_read(&hist_data->map->hits));
+ print_pair_end(m, strim(str), format);
+
+ print_pair_start(m, "entries", format, level);
+ snprintf(str, sizeof(str), "%u", n_entries);
+ print_pair_end(m, strim(str), format);
+
+ print_pair_start(m, "dropped", format, level);
+ snprintf(str, sizeof(str), "%llu",
+ (u64)atomic64_read(&hist_data->map->drops));
+ print_pair_end(m, strim(str), format);
+
+ print_json_obj_end(m, level);
+ } else if (format == TEXT) {
+ seq_printf(m, "\nTotals:\n Hits: %llu\n Entries: %u\n Dropped: %llu\n",
+ (u64)atomic64_read(&hist_data->map->hits),
+ n_entries, (u64)atomic64_read(&hist_data->map->drops));
+ }
+}
+
static void hist_trigger_show(struct seq_file *m,
- struct event_trigger_data *data, int n)
+ struct event_trigger_data *data, int n,
+ enum show_format format, int *level)
{
struct hist_trigger_data *hist_data;
int n_entries;
- if (n > 0)
- seq_puts(m, "\n\n");
+ print_hist_start(m, n, format, level);
- seq_puts(m, "# event histogram\n#\n# trigger info: ");
- data->ops->print(m, data->ops, data);
- seq_puts(m, "#\n\n");
+ show_hist_info(m, data, format, level);
+
+ print_map_start(m, format, level);
hist_data = data->private_data;
- n_entries = print_entries(m, hist_data);
+ n_entries = print_entries(m, hist_data, format, level);
if (n_entries < 0)
n_entries = 0;
- track_data_snapshot_print(m, hist_data);
+ print_map_end(m, format, level);
- seq_printf(m, "\nTotals:\n Hits: %llu\n Entries: %u\n Dropped: %llu\n",
- (u64)atomic64_read(&hist_data->map->hits),
- n_entries, (u64)atomic64_read(&hist_data->map->drops));
+ track_data_snapshot_print(m, hist_data, format, level);
+
+ print_hist_totals(m, hist_data, n_entries, format, level);
+
+ print_hist_end(m, format, level);
}
static int hist_show(struct seq_file *m, void *v)
{
struct event_trigger_data *data;
struct trace_event_file *event_file;
- int n = 0, ret = 0;
+ int n = 0, ret = 0, level = 1;
mutex_lock(&event_mutex);
@@ -4894,7 +5235,7 @@ static int hist_show(struct seq_file *m, void *v)
list_for_each_entry(data, &event_file->triggers, list) {
if (data->cmd_ops->trigger_type == ETT_EVENT_HIST)
- hist_trigger_show(m, data, n++);
+ hist_trigger_show(m, data, n++, TEXT, &level);
}
out_unlock:
@@ -4921,6 +5262,53 @@ const struct file_operations event_hist_fops = {
.release = single_release,
};
+static int hist_json_show(struct seq_file *m, void *v)
+{
+ struct event_trigger_data *data;
+ struct trace_event_file *event_file;
+ int n = 0, ret = 0, level = 1;
+
+ mutex_lock(&event_mutex);
+
+ event_file = event_file_data(m->private);
+ if (unlikely(!event_file)) {
+ ret = -ENODEV;
+ goto out_unlock;
+ }
+
+ seq_puts(m, "[\n");
+
+ list_for_each_entry(data, &event_file->triggers, list) {
+ if (data->cmd_ops->trigger_type == ETT_EVENT_HIST)
+ hist_trigger_show(m, data, n++, JSON, &level);
+ }
+
+ seq_puts(m, "]\n");
+
+out_unlock:
+ mutex_unlock(&event_mutex);
+
+ return ret;
+}
+
+static int event_hist_json_open(struct inode *inode, struct file *file)
+{
+ int ret;
+
+ ret = security_locked_down(LOCKDOWN_TRACEFS);
+ if (ret)
+ return ret;
+
+ return single_open(file, hist_json_show, file);
+}
+
+const struct file_operations event_hist_json_fops = {
+ .open = event_hist_json_open,
+ .read = seq_read,
+ .llseek = seq_lseek,
+ .release = single_release,
+};
+
#ifdef CONFIG_HIST_TRIGGERS_DEBUG
static void hist_field_debug_show_flags(struct seq_file *m,
unsigned long flags)
--
2.17.1
On Thu, 12 Aug 2021 17:43:23 -0500
Tom Zanussi <[email protected]> wrote:
> I designed it so that more files/formats could be easily added as
> desired, so if you still want the csv output, let me know. If so,
> though, please give me some more detailed idea as to what you think
> that should look like.
Thanks Tom!
BTW, I have off tomorrow, so I wont be looking at this until next week.
Although, tomorrow I'll probably spend my "free" time finishing up
slides that were due two weeks ago :-/
-- Steve
Hi Tom,
On Thu, 12 Aug 2021 17:43:23 -0500
Tom Zanussi <[email protected]> wrote:
> Hi Steve and Daniel,
>
> Following our discussion last week about more parseable hist trigger
> output, I started trying to implement the 'csv' output you had
> mentioned, but realized that since it was more than just table output
> that was needed, JSON would be a better fit, so implemented that in
> this patch instead.
This seems really good feature! BTW, what about adding an tracing
option to switch the hist output format?
e.g.
$ echo 1 > /sys/kernel/tracing/options/hist-json
This will no need to add additional pseudo file but just add an option to
the ftrace.
Thank you,
>
> I designed it so that more files/formats could be easily added as
> desired, so if you still want the csv output, let me know. If so,
> though, please give me some more detailed idea as to what you think
> that should look like.
>
> Here are some examples of the JSON output for various histograms:
>
> A simple straighforward histogram:
>
> # echo 'hist:key=id.syscall,common_pid.execname:val=hitcount:sort=id,hitcount' >> /sys/kernel/debug/tracing/events/raw_syscalls/sys_enter/trigger
>
> # cat /sys/kernel/debug/tracing/events/raw_syscalls/sys_enter/hist_json
>
> [
> "hist":{
> "info":{
> "trigger":"hist:keys=id.syscall,common_pid.execname:vals=hitcount:sort=id.syscall,hitcount:size=2048 [active]
> "
> },
> "map":{
> "entry":{
> "keys":[
> {
> "id":"sys_read [ 0]",
> },
> {
> "common_pid":"Xwayland [ 2867]",
> },
> ],
> "vals":[
> {
> "hitcount":"1",
> },
> ],
> },
> "entry":{
> "keys":[
> {
> "id":"sys_read [ 0]",
> },
> {
> "common_pid":"sh [ 3428]",
> },
> ],
> "vals":[
> {
> "hitcount":"1",
> },
> ],
> },
> "entry":{
> ...
> "entry":{
> "keys":[
> {
> "id":"sys_getrandom [318]",
> },
> {
> "common_pid":"update-notifier [ 3408]",
> },
> ],
> "vals":[
> {
> "hitcount":"95",
> },
> ],
> },
> "entry":{
> "keys":[
> {
> "id":"sys_getrandom [318]",
> },
> {
> "common_pid":"apt-check [ 3416]",
> },
> ],
> "vals":[
> {
> "hitcount":"815",
> },
> ],
> },
> },
> "totals":{
> "hits":"112930",
> "entries":"1390",
> "dropped":"0",
> },
> },
> ]
>
>
> A histogram with save() variables and snapshot() info:
>
> # echo 'hist:keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_waking/trigger
>
> #echo 'hist:keys=next_pid:wakeup_lat=common_timestamp.usecs-$ts0:onmax($wakeup_lat).save(next_prio,next_comm,prev_pid,prev_prio,prev_comm):onmax($wakeup_lat).snapshot() if next_comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_switch/trigger
>
> # cat /sys/kernel/debug/tracing/events/sched/sched_switch/hist_json
>
> [
> "hist":{
> "info":{
> "trigger":"hist:keys=next_pid:vals=hitcount:wakeup_lat=common_timestamp.usecs-$ts0:sort=hitcount:size=2048:clock=global:onmax($wakeup_lat).save(next_prio,next_comm,prev_pid,prev_prio,prev_comm):onmax($wakeup_lat).snapshot() if next_comm=="cyclictest" [active]
> "
> },
> "map":{
> "entry":{
> "keys":[
> {
> "next_pid":"3419",
> },
> ],
> "vals":[
> {
> "hitcount":"156",
> },
> ],
> "action":{
> "max":"439",
> "next_prio":"120",
> "next_comm":"cyclictest",
> "prev_pid":"0",
> "prev_prio":"120",
> "prev_comm":"swapper/1",
> },
> },
> "entry":{
> "keys":[
> {
> "next_pid":"3420",
> },
> ],
> "vals":[
> {
> "hitcount":"1563",
> },
> ],
> "action":{
> "max":"1667",
> "next_prio":"120",
> "next_comm":"cyclictest",
> "prev_pid":"1991",
> "prev_prio":"120",
> "prev_comm":"FAHClient",
> },
> },
> },
> "snapshot":{
> "handler":"onmax",
> "$wakeup_lat":"1667",
> "keys":[
> {
> "next_pid":"3420",
> },
> ],
> },
> "totals":{
> "hits":"1719",
> "entries":"2",
> "dropped":"0",
> },
> },
> ]
>
> And finally, just to show that even stacktraces in JSON works ;-)
>
> # echo 'hist:keys=stacktrace:values=bytes_req,bytes_alloc:sort=bytes_alloc' >> /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger
>
> # cat /sys/kernel/debug/tracing/events/kmem/kmalloc/hist_json
>
> "info":{
> "trigger":"hist:keys=stacktrace:vals=hitcount,bytes_req,bytes_alloc:sort=b
> ytes_alloc:size=2048 [active]
> "
> },
> "map":{
> "entry":{
> "keys":[
> {
> "stacktrace":"
> acpi_ns_internalize_name+0x4a/0xa3
> acpi_ns_get_node_unlocked+0x70/0xd8
> acpi_ns_get_node+0x40/0x55
> acpi_ns_evaluate+0x4c/0x24e
> acpi_evaluate_object+0x137/0x240
> acpi_battery_get_state+0x95/0x230
> acpi_battery_get_property+0x4c/0x3f0
> power_supply_show_property+0xd2/0x260
> dev_attr_show+0x18/0x50
> sysfs_kf_seq_show+0xa3/0x110
> seq_read_iter+0xdd/0x460
> new_sync_read+0x11b/0x1a0
> vfs_read+0x198/0x1c0
> ksys_read+0xa7/0xe0
> do_syscall_64+0x3a/0xb0
> entry_SYSCALL_64_after_hwframe+0x44/0xae
> "
> },
> ],
> "vals":[
> {
> "hitcount":"1",
> },
> {
> "bytes_req":"8",
> },
> {
> "bytes_alloc":"8",
> },
> },
> ],
> },
> "entry":{
> "keys":[
> {
> "stacktrace":"
> ecryptfs_write_inode_size_to_metadata+0x38/0x190
> truncate_upper.isra.16+0x14e/0x250
> ecryptfs_setattr+0x276/0x2c0
> notify_change+0x392/0x4d0
> do_truncate+0x7c/0xd0
> path_openat+0x8e2/0xa60
> do_filp_open+0xc5/0x140
> do_sys_openat2+0x23e/0x300
> do_sys_open+0x57/0x80
> do_syscall_64+0x3a/0xb0
> entry_SYSCALL_64_after_hwframe+0x44/0xae
> "
> },
> ],
> "vals":[
> {
> "hitcount":"1",
> },
> {
> "bytes_req":"8",
> },
> {
> "bytes_alloc":"8",
> },
> ],
> },
> ...
> "entry":{
> "keys":[
> {
> "stacktrace":"
> ath10k_wmi_tlv_parse_alloc.constprop.30+0x35/0x80 [ath10k_core]
> ath10k_wmi_tlv_op_pull_fw_stats+0x38/0x420 [ath10k_core]
> ath10k_debug_fw_stats_process+0x9c/0x410 [ath10k_core]
> ath10k_wmi_tlv_op_rx+0x1a6/0xf20 [ath10k_core]
> ath10k_htc_rx_completion_handler+0x13c/0x180 [ath10k_core]
> ath10k_pci_process_rx_cb+0x122/0x190 [ath10k_pci]
> ath10k_ce_per_engine_service+0x5d/0x80 [ath10k_core]
> ath10k_ce_per_engine_service_any+0x6a/0xa0 [ath10k_core]
> ath10k_pci_napi_poll+0x44/0x110 [ath10k_pci]
> __napi_poll+0x2d/0x200
> net_rx_action+0xe6/0x210
> __do_softirq+0xce/0x43c
> irq_exit_rcu+0xa4/0xb0
> common_interrupt+0x5c/0xa0
> asm_common_interrupt+0x1e/0x40
> cpuidle_enter_state+0x113/0x4a0
> "
> },
> ],
> "vals":[
> {
> "hitcount":"569",
> },
> {
> "bytes_req":"3149984",
> },
> {
> "bytes_alloc":"4661248",
> },
> ],
> },
> },
> "totals":{
> "hits":"62147",
> "entries":"453",
> "dropped":"0",
> },
> },
> ]
>
> Tom
>
> The following changes since commit 3dc65994e3c1c999be3d991cdc96705e167cb3b1:
>
> tools/bootconfig: Use per-group/all enable option in ftrace2bconf script (2021-08-08 19:41:50 -0400)
>
> are available in the Git repository at:
>
> git://git.kernel.org/pub/scm/linux/kernel/git/zanussi/linux-trace.git ftrace/hist-json-v1
>
> Tom Zanussi (1):
> tracing: Add hist_json event file
>
> kernel/trace/trace.h | 1 +
> kernel/trace/trace_events.c | 2 +
> kernel/trace/trace_events_hist.c | 532 ++++++++++++++++++++++++++-----
> 3 files changed, 463 insertions(+), 72 deletions(-)
>
> --
> 2.17.1
>
--
Masami Hiramatsu <[email protected]>
Hi Masami,
On Fri, 2021-08-13 at 18:24 +0900, Masami Hiramatsu wrote:
> Hi Tom,
>
> On Thu, 12 Aug 2021 17:43:23 -0500
> Tom Zanussi <[email protected]> wrote:
>
> > Hi Steve and Daniel,
> >
> > Following our discussion last week about more parseable hist
> > trigger
> > output, I started trying to implement the 'csv' output you had
> > mentioned, but realized that since it was more than just table
> > output
> > that was needed, JSON would be a better fit, so implemented that in
> > this patch instead.
>
> This seems really good feature! BTW, what about adding an tracing
> option to switch the hist output format?
> e.g.
>
> $ echo 1 > /sys/kernel/tracing/options/hist-json
>
> This will no need to add additional pseudo file but just add an
> option to
> the ftrace.
>
That sounds like a good idea, thanks for the suggestion!
Tom
On Fri, 13 Aug 2021 10:31:03 -0500
Tom Zanussi <[email protected]> wrote:
> > $ echo 1 > /sys/kernel/tracing/options/hist-json
> >
> > This will no need to add additional pseudo file but just add an
> > option to
> > the ftrace.
> >
>
> That sounds like a good idea, thanks for the suggestion!
My only worry about this approach is that it affects all events in the
instance (please make this an instance option).
But I think I still rather have it affecting all events in an instance
than to bloat the directories with yet-another-file.
Yeah, make it an option.
Thanks!
-- Steve