| lists.openwall.net | lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC | |
|
Open Source and information security mailing list archives
| ||
|
Message-Id: <20210813182436.0ca56fe333a80fb7188f0b14@kernel.org>
Date: Fri, 13 Aug 2021 18:24:36 +0900
From: Masami Hiramatsu <mhiramat@...nel.org>
To: Tom Zanussi <zanussi@...nel.org>
Cc: rostedt@...dmis.org, bristot@...nel.org, mhiramat@...nel.org,
linux-kernel@...r.kernel.org, linux-rt-users@...r.kernel.org
Subject: Re: [PATCH 0/1] tracing: Provide more parseable hist trigger output
Hi Tom,
On Thu, 12 Aug 2021 17:43:23 -0500
Tom Zanussi <zanussi@...nel.org> 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 <mhiramat@...nel.org>
Powered by blists - more mailing lists