tracing: Provide more parseable hist trigger output

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.

---
 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(-)

index a180abf76d4e..c212c379a172 100644
@@ -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;
 

index 80e96989770e..e5e8ec1cb5d0 100644
@@ -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,

2.17.1

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,

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,

Masami Hiramatsu <[email protected]>

Hi Masami,

That sounds like a good idea, thanks for the suggestion!

Tom

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