From patchwork Fri Aug 13 02:16:55 2021 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Steven Rostedt X-Patchwork-Id: 12434585 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-korg-lkml-1.web.codeaurora.org X-Spam-Level: X-Spam-Status: No, score=-21.7 required=3.0 tests=BAYES_00, HEADER_FROM_DIFFERENT_DOMAINS,INCLUDES_CR_TRAILER,INCLUDES_PATCH, MAILING_LIST_MULTI,MENTIONS_GIT_HOSTING,SPF_HELO_NONE,SPF_PASS,URIBL_BLOCKED, USER_AGENT_GIT autolearn=ham autolearn_force=no version=3.4.0 Received: from mail.kernel.org (mail.kernel.org [198.145.29.99]) by smtp.lore.kernel.org (Postfix) with ESMTP id 7D378C4320E for ; Fri, 13 Aug 2021 02:17:35 +0000 (UTC) Received: from vger.kernel.org (vger.kernel.org [23.128.96.18]) by mail.kernel.org (Postfix) with ESMTP id 66FD361101 for ; Fri, 13 Aug 2021 02:17:35 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S237645AbhHMCR7 (ORCPT ); Thu, 12 Aug 2021 22:17:59 -0400 Received: from mail.kernel.org ([198.145.29.99]:44620 "EHLO mail.kernel.org" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S233036AbhHMCRx (ORCPT ); Thu, 12 Aug 2021 22:17:53 -0400 Received: from gandalf.local.home (cpe-66-24-58-225.stny.res.rr.com [66.24.58.225]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by mail.kernel.org (Postfix) with ESMTPSA id 33389610A7; Fri, 13 Aug 2021 02:17:26 +0000 (UTC) Received: from rostedt by gandalf.local.home with local (Exim 4.94.2) (envelope-from ) id 1mEMlB-003wW4-0B; Thu, 12 Aug 2021 22:17:25 -0400 From: Steven Rostedt To: linux-trace-devel@vger.kernel.org Cc: linux-kernel@vger.kernel.org, Tom Zanussi , Daniel Bristot de Oliveira , Masami Hiramatsu , Namhyung Kim , linux-rt-users , Clark Williams , "Steven Rostedt (VMware)" Subject: [PATCH 7/7] libtracefs: Make a man page for the sqlhist man page example Date: Thu, 12 Aug 2021 22:16:55 -0400 Message-Id: <20210813021655.939819-8-rostedt@goodmis.org> X-Mailer: git-send-email 2.30.2 In-Reply-To: <20210813021655.939819-1-rostedt@goodmis.org> References: <20210813021655.939819-1-rostedt@goodmis.org> MIME-Version: 1.0 Precedence: bulk List-ID: X-Mailing-List: linux-trace-devel@vger.kernel.org From: "Steven Rostedt (VMware)" As the sqlhist example in the tracefs_sql(3) man page is becoming quite the tool to use, give it its own man page! Signed-off-by: Steven Rostedt (VMware) --- Documentation/Makefile | 53 +++- Documentation/libtracefs-sql.txt | 2 +- Documentation/libtracefs-sqlhist.txt.1 | 351 +++++++++++++++++++++++++ 3 files changed, 397 insertions(+), 9 deletions(-) create mode 100644 Documentation/libtracefs-sqlhist.txt.1 diff --git a/Documentation/Makefile b/Documentation/Makefile index efe7b09d4e68..0c00505852b5 100644 --- a/Documentation/Makefile +++ b/Documentation/Makefile @@ -10,6 +10,9 @@ MAN3_TXT= \ $(wildcard libtracefs-*.txt) \ libtracefs.txt +MAN1_TEXT= \ + $(wildcard libtracefs-*.txt.1) + MAN_TXT = $(MAN3_TXT) _MAN_XML=$(patsubst %.txt,%.xml,$(MAN_TXT)) _MAN_HTML=$(patsubst %.txt,%.html,$(MAN_TXT)) @@ -19,6 +22,15 @@ MAN_XML=$(addprefix $(OUTPUT),$(_MAN_XML)) MAN_HTML=$(addprefix $(OUTPUT),$(_MAN_HTML)) DOC_MAN3=$(addprefix $(OUTPUT),$(_DOC_MAN3)) +_MAN1_XML=$(patsubst %.txt.1,%.xml,$(MAN1_TEXT)) +_MAN1_HTML=$(patsubst %.txt.1,%.html,$(MAN1_TEXT)) +_DOC_MAN1=$(patsubst %.txt.1,%.m,$(MAN1_TEXT)) + +MAN1_XML=$(addprefix $(OUTPUT),$(_MAN1_XML)) +MAN1_HTML=$(addprefix $(OUTPUT),$(_MAN1_HTML)) +DOC_MAN1=$(addprefix $(OUTPUT),$(_DOC_MAN1)) + + # Make the path relative to DESTDIR, not prefix ifndef DESTDIR prefix?=$(HOME) @@ -28,6 +40,7 @@ htmldir?=$(prefix)/share/doc/libtracefs-doc pdfdir?=$(prefix)/share/doc/libtracefs-doc mandir?=$(prefix)/share/man man3dir=$(mandir)/man3 +man1dir=$(mandir)/man1 ASCIIDOC=asciidoc ASCIIDOC_EXTRA = --unsafe -f asciidoc.conf @@ -131,12 +144,13 @@ endif all: check-man-tools html man -man: man3 +man: man3 man1 man3: $(DOC_MAN3) +man1: $(DOC_MAN1) -html: $(MAN_HTML) +html: $(MAN_HTML) $(MAN1_HTML) -$(MAN_HTML) $(DOC_MAN3): asciidoc.conf +$(MAN_HTML) $(MAN1_HTML) $(DOC_MAN3) $(DOC_MAN1): asciidoc.conf install: check-man-tools install-man install-html @@ -148,7 +162,10 @@ endif install-%.3: $(OUTPUT)%.3 $(Q)$(call do_install,$<,$(man3dir),644); -do-install-man: man $(addprefix install-,$(wildcard $(OUTPUT)*.3)) +install-%.1: $(OUTPUT)%.1 + $(Q)$(call do_install,$<,$(man1dir),644); + +do-install-man: man $(addprefix install-,$(wildcard $(OUTPUT)*.3)) $(addprefix install-,$(wildcard $(OUTPUT)*.1)) install-man: man $(Q)$(MAKE) -C . do-install-man @@ -156,17 +173,20 @@ install-man: man install-%.txt: $(OUTPUT)%.html $(Q)$(call do_install,$<,$(htmldir),644); -do-install-html: html $(addprefix install-,$(wildcard *.txt)) +install-%.txt.1: $(OUTPUT)%.html + $(Q)$(call do_install,$<,$(htmldir),644); + +do-install-html: html $(addprefix install-,$(wildcard *.txt)) $(addprefix install-,$(wildcard *.txt.1)) install-html: html do-install-html uninstall: uninstall-man uninstall-html uninstall-man: - $(Q)$(RM) $(addprefix $(DESTDIR)$(man3dir)/,$(DOC_MAN3)) + $(Q)$(RM) $(addprefix $(DESTDIR)$(man3dir)/,$(DOC_MAN3)) $(addprefix $(DESTDIR)$(man1dir)/,$(DOC_MAN1)) uninstall-html: - $(Q)$(RM) $(addprefix $(DESTDIR)$(htmldir)/,$(MAN_HTML)) + $(Q)$(RM) $(addprefix $(DESTDIR)$(htmldir)/,$(MAN_HTML)) $(addprefix $(DESTDIR)$(htmldir)/,$(MAN1_HTML)) ifdef missing_tools DO_INSTALL_MAN = $(warning Please install $(missing_tools) to have the man pages installed) @@ -177,7 +197,7 @@ endif CLEAN_FILES = \ $(MAN_XML) $(addsuffix +,$(MAN_XML)) \ $(MAN_HTML) $(addsuffix +,$(MAN_HTML)) \ - $(DOC_MAN3) *.3 *.m + $(DOC_MAN3) *.3 *.1 *.m clean: $(Q) $(RM) $(CLEAN_FILES) @@ -188,6 +208,11 @@ $(OUTPUT)%.3 : $(OUTPUT)%.txt $(ASCIIDOC) -b manpage -d manpage \ $(ASCIIDOC_EXTRA) -alibtracefs_version=$(TRACEFS_VERSION) -o $@+ $< && \ mv $@+ $@ +$(OUTPUT)%.1 : $(OUTPUT)%.txt.1 + $(QUIET_ASCIIDOC)$(RM) $@+ $@ && \ + $(ASCIIDOC) -b manpage -d manpage \ + $(ASCIIDOC_EXTRA) -alibtracefs_version=$(TRACEFS_VERSION) -o $@+ $< && \ + mv $@+ $@ endif $(OUTPUT)%.m : $(OUTPUT)%.xml @@ -201,8 +226,20 @@ $(OUTPUT)%.xml : %.txt $(ASCIIDOC_EXTRA) -alibtracefs_version=$(TRACEFS_VERSION) -o $@+ $< && \ mv $@+ $@ +$(OUTPUT)%.xml : %.txt.1 + $(QUIET_ASCIIDOC)$(RM) $@+ $@ && \ + $(ASCIIDOC) -b docbook -d manpage \ + $(ASCIIDOC_EXTRA) -alibtracefs_version=$(TRACEFS_VERSION) -o $@+ $< && \ + mv $@+ $@ + $(MAN_HTML): $(OUTPUT)%.html : %.txt $(QUIET_ASCIIDOC)$(RM) $@+ $@ && \ $(ASCIIDOC) -b $(ASCIIDOC_HTML) -d manpage \ $(ASCIIDOC_EXTRA) -alibtracefs_version=$(TRACEFS_VERSION) -o $@+ $< && \ mv $@+ $@ + +$(MAN1_HTML): $(OUTPUT)%.html : %.txt.1 + $(QUIET_ASCIIDOC)$(RM) $@+ $@ && \ + $(ASCIIDOC) -b $(ASCIIDOC_HTML) -d manpage \ + $(ASCIIDOC_EXTRA) -alibtracefs_version=$(TRACEFS_VERSION) -o $@+ $< && \ + mv $@+ $@ diff --git a/Documentation/libtracefs-sql.txt b/Documentation/libtracefs-sql.txt index 95625157590e..e762eaea28c2 100644 --- a/Documentation/libtracefs-sql.txt +++ b/Documentation/libtracefs-sql.txt @@ -290,7 +290,6 @@ Then you can run the above examples: JOIN sched_switch as end ON start.pid = end.next_pid WHERE start.prio < 100 || end.prev_prio < 100' -- - EXAMPLE ------- [source,c] @@ -548,6 +547,7 @@ FILES SEE ALSO -------- +_sqlhist(1)_, _libtracefs(3)_, _libtraceevent(3)_, _trace-cmd(1)_, diff --git a/Documentation/libtracefs-sqlhist.txt.1 b/Documentation/libtracefs-sqlhist.txt.1 new file mode 100644 index 000000000000..1e94ea4cd138 --- /dev/null +++ b/Documentation/libtracefs-sqlhist.txt.1 @@ -0,0 +1,351 @@ +SQLHIST(1) +========== + +NAME +---- +sqlhist - Tool that uses SQL language to create / show creation of tracefs histograms and synthetic events. + +SYNOPSIS +-------- +*sqlhist* ['OPTIONS'] ['SQL-select-command'] + +DESCRIPTION +----------- +The sqlhist(1) will take an SQL like statement to create tracefs histograms and +synthetic events that can perform various actions for various handling of the +data. + +The tracefs file system interfaces with the Linux tracing infrastructure that +has various dynamic and static events through out the kernel. Each of these +events can have a "histogram" attached to it, where the fields of the event +will define the buckets of the histogram. + +A synthetic event is a way to attach two separate events and use the fields +and time stamps of those events to create a new dynamic event. This new +dynamic event is call a synthetic event. The fields of each event can have +simple calculations done on them where, for example, the delta between +a field of one event to a field of the other event can be taken. This also +works for the time stamps of the events where the time delta between the +two events can also be extracted and placed into the synthetic event. + +Other actions can be done from the fields of the events. A snapshot can +be taken of the kernel ring buffer a variable used in the synthetic +event creating hits a max, or simply changes. + +The commands to create histograms and synthetic events are complex and +not easy to remember. *sqlhist* is used to convert SQL syntax into the +commands needed to create the histogram or synthetic event. + +The *SQL-select-command* is a SQL string defined by *tracefs_sql*(3). + +Note, this must be run as root (or sudo) as interacting with the tracefs +directory requires root privilege, unless the *-t* option is given with +a copy of the _tracefs_ directory and its events. + +The *sqlhist* is a simple program where its code actual exists in the +*tracefs_sql*(3) man page. + +OPTIONS +------- +*-n* 'name':: + The name of the synthetic event to create. This event can then be + used like any other event, and enabled via *trace-cmd*(1). + +*-t* 'tracefs-dir':: + In order to test this out as non root user, a copy of the tracefs directory + can be used, and passing that directory with this option will allow + the program to work. Obviously, *-e* will not work as non-root because + it will not be able to execute. + + # mkdir /tmp/tracing + # cp -r /sys/kernel/tracing/events /tmp/tracing + # exit + $ ./sqlhist -t /tmp/tracing ... + +*-e*:: + Not only display the commands to create the histogram, but also execute them. + This requires root privilege. + +*-f* 'file':: + Instead of reading the SQL commands from the command line, read them from + _file_. If _file_ is '-' then read from standard input. + +*-m* 'var':: + Do the given action when the variable _var_ hits a new maximum. This can + not be used with *-c*. + +*-c* 'var':: + Do the given action when the variable _var_ changes its value. This can + not be used with *-m*. + +*-s*:: + Perform a snapshot instead of calling the synthetic event. + +*-T*:: + Perform both a snapshot and trace the synthetic event. + +*-S* 'fields[,fields]':: + Save the given fields. The fields must be fields of the "end" event given + in the *SQL-select-command* + + +EXAMPLES +-------- + +Create the sqlhist executable: + +[source, c] +-- + man tracefs_sql | sed -ne '/^EXAMPLE/,/FILES/ { /EXAMPLE/d ; /FILES/d ; p}' > sqlhist.c + gcc -o sqlhist sqlhist.c `pkg-config --cflags --libs libtracefs` +-- + +As described above, for testing purposes, make a copy of the event directory: +[source, c] +-- + $ mkdir /tmp/tracing + $ sudo cp -r /sys/kernel/tracing/events /tmp/tracing/ + $ sudo chmod -R 0644 /tmp/tracing/ +-- + +For an example of simple histogram output using the copy of the tracefs directory. +[source, c] +-- + $ ./sqlhist -t /tmp/tracing/ 'SELECT CAST(call_site as SYM-OFFSET), bytes_req, CAST(bytes_alloc AS _COUNTER_) FROM kmalloc' +-- + +Produces the output: +[source, c] +-- + echo 'hist:keys=call_site.sym-offset,bytes_req:vals=bytes_alloc' > /sys/kernel/tracing/events/kmem/kmalloc/trigger +-- + +Which could be used by root: +[source, c] +-- + # echo 'hist:keys=call_site.sym-offset,bytes_req:vals=bytes_alloc' > /sys/kernel/tracing/events/kmem/kmalloc/trigger + # cat /sys/kernel/tracing/events/kmem/kmalloc/hist +# event histogram +# +# trigger info: hist:keys=call_site.sym-offset,bytes_req:vals=hitcount,bytes_alloc:sort=hitcount:size=2048 [active] +# + +{ call_site: [ffffffff813f8d8a] load_elf_phdrs+0x4a/0xb0 , bytes_req: 728 } hitcount: 1 bytes_alloc: 1024 +{ call_site: [ffffffffc0c69e74] nf_ct_ext_add+0xd4/0x1d0 [nf_conntrack] , bytes_req: 128 } hitcount: 1 bytes_alloc: 128 +{ call_site: [ffffffff818355e6] dma_resv_get_fences+0xf6/0x440 , bytes_req: 8 } hitcount: 1 bytes_alloc: 8 +{ call_site: [ffffffffc06dc73f] intel_gt_get_buffer_pool+0x15f/0x290 [i915] , bytes_req: 424 } hitcount: 1 bytes_alloc: 512 +{ call_site: [ffffffff813f8d8a] load_elf_phdrs+0x4a/0xb0 , bytes_req: 616 } hitcount: 1 bytes_alloc: 1024 +{ call_site: [ffffffff8161a44c] __sg_alloc_table+0x11c/0x180 , bytes_req: 32 } hitcount: 1 bytes_alloc: 32 +{ call_site: [ffffffffc070749d] shmem_get_pages+0xad/0x5d0 [i915] , bytes_req: 16 } hitcount: 1 bytes_alloc: 16 +{ call_site: [ffffffffc07507f5] intel_framebuffer_create+0x25/0x60 [i915] , bytes_req: 408 } hitcount: 1 bytes_alloc: 512 +{ call_site: [ffffffffc06fc20f] eb_parse+0x34f/0x910 [i915] , bytes_req: 408 } hitcount: 1 bytes_alloc: 512 +{ call_site: [ffffffffc0700ebd] i915_gem_object_get_pages_internal+0x5d/0x270 [i915] , bytes_req: 16 } hitcount: 1 bytes_alloc: 16 +{ call_site: [ffffffffc0771188] intel_frontbuffer_get+0x38/0x220 [i915] , bytes_req: 400 } hitcount: 1 bytes_alloc: 512 +{ call_site: [ffffffff8161a44c] __sg_alloc_table+0x11c/0x180 , bytes_req: 128 } hitcount: 1 bytes_alloc: 128 +{ call_site: [ffffffff813f8f45] load_elf_binary+0x155/0x1680 , bytes_req: 28 } hitcount: 1 bytes_alloc: 32 +{ call_site: [ffffffffc07038c8] __assign_mmap_offset+0x208/0x3d0 [i915] , bytes_req: 288 } hitcount: 1 bytes_alloc: 512 +{ call_site: [ffffffff813737b2] alloc_bprm+0x32/0x2f0 , bytes_req: 416 } hitcount: 1 bytes_alloc: 512 +{ call_site: [ffffffff813f9027] load_elf_binary+0x237/0x1680 , bytes_req: 64 } hitcount: 1 bytes_alloc: 64 +{ call_site: [ffffffff8161a44c] __sg_alloc_table+0x11c/0x180 , bytes_req: 64 } hitcount: 1 bytes_alloc: 64 +{ call_site: [ffffffffc040ffe7] drm_vma_node_allow+0x27/0xe0 [drm] , bytes_req: 40 } hitcount: 2 bytes_alloc: 128 +{ call_site: [ffffffff813cda98] __do_sys_timerfd_create+0x58/0x1c0 , bytes_req: 336 } hitcount: 2 bytes_alloc: 1024 +{ call_site: [ffffffff818355e6] dma_resv_get_fences+0xf6/0x440 , bytes_req: 40 } hitcount: 2 bytes_alloc: 128 +{ call_site: [ffffffff8139b75a] single_open+0x2a/0xa0 , bytes_req: 32 } hitcount: 2 bytes_alloc: 64 +{ call_site: [ffffffff815df715] bio_kmalloc+0x25/0x80 , bytes_req: 136 } hitcount: 2 bytes_alloc: 384 +{ call_site: [ffffffffc071e5cd] i915_vma_work+0x1d/0x50 [i915] , bytes_req: 416 } hitcount: 3 bytes_alloc: 1536 +{ call_site: [ffffffff81390d0d] alloc_fdtable+0x4d/0x100 , bytes_req: 56 } hitcount: 3 bytes_alloc: 192 +{ call_site: [ffffffffc06ff65f] i915_gem_do_execbuffer+0x158f/0x2440 [i915] , bytes_req: 16 } hitcount: 4 bytes_alloc: 64 +{ call_site: [ffffffff8137713c] alloc_pipe_info+0x5c/0x230 , bytes_req: 384 } hitcount: 5 bytes_alloc: 2560 +{ call_site: [ffffffff813771b4] alloc_pipe_info+0xd4/0x230 , bytes_req: 640 } hitcount: 5 bytes_alloc: 5120 +{ call_site: [ffffffff81834cdb] dma_resv_list_alloc+0x1b/0x40 , bytes_req: 40 } hitcount: 6 bytes_alloc: 384 +{ call_site: [ffffffff81834cdb] dma_resv_list_alloc+0x1b/0x40 , bytes_req: 56 } hitcount: 9 bytes_alloc: 576 +{ call_site: [ffffffff8120086e] tracing_map_sort_entries+0x9e/0x3e0 , bytes_req: 24 } hitcount: 60 bytes_alloc: 1920 + +Totals: + Hits: 122 + Entries: 30 + Dropped: 0 +-- + +Note, although the examples use uppercase for the SQL keywords, they do not have +to be. 'SELECT' could also be 'select' or even 'sElEcT'. + +By using the full SQL language, synthetic events can be made and processed. +For example, using *sqlhist* along with *trace-cmd*(1), wake up latency can +be recorded by creating a synthetic event by attaching the _sched_waking_ +and the _sched_switch_ events. + +[source, c] +-- + # sqlhist -n wakeup_lat -e -T -m lat 'SELECT end.next_comm AS comm, (end.TIMESTAMP_USECS - start.TIMESTAMP_USECS) AS lat FROM ' \ + 'sched_waking AS start JOIN sched_switch AS end ON start.pid = end.next_pid WHERE end.next_prio < 100 && end.next_comm == "cyclictest"' + # trace-cmd start -e all -e wakeup_lat -R stacktrace + # cyclictest -l 1000 -p80 -i250 -a -t -q -m -d 0 -b 1000 --tracemark + # trace-cmd show -s | tail -30 + -0 [002] dNh4 23454.902246: sched_wakeup: comm=cyclictest pid=12272 prio=120 target_cpu=002 + -0 [005] ...1 23454.902246: cpu_idle: state=4294967295 cpu_id=5 + -0 [007] d..1 23454.902246: cpu_idle: state=0 cpu_id=7 + -0 [002] dNh1 23454.902247: hrtimer_expire_exit: hrtimer=0000000037956dc2 + -0 [005] d..1 23454.902248: cpu_idle: state=0 cpu_id=5 + -0 [002] dNh1 23454.902248: write_msr: 6e0, value 4866ce957272 + -0 [006] ...1 23454.902248: cpu_idle: state=4294967295 cpu_id=6 + -0 [002] dNh1 23454.902249: local_timer_exit: vector=236 + -0 [006] d..1 23454.902250: cpu_idle: state=0 cpu_id=6 + -0 [002] .N.1 23454.902250: cpu_idle: state=4294967295 cpu_id=2 + -0 [002] dN.1 23454.902251: rcu_utilization: Start context switch + -0 [002] dN.1 23454.902252: rcu_utilization: End context switch + -0 [001] ...1 23454.902252: cpu_idle: state=4294967295 cpu_id=1 + -0 [002] dN.3 23454.902253: prandom_u32: ret=3692516021 + -0 [001] d..1 23454.902254: cpu_idle: state=0 cpu_id=1 + -0 [002] d..2 23454.902254: sched_switch: prev_comm=swapper/2 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=cyclictest next_pid=12275 next_prio=19 + -0 [002] d..4 23454.902256: wakeup_lat: next_comm=cyclictest lat=17 + -0 [002] d..5 23454.902258: + => trace_event_raw_event_synth + => action_trace + => event_hist_trigger + => event_triggers_call + => trace_event_buffer_commit + => trace_event_raw_event_sched_switch + => __traceiter_sched_switch + => __schedule + => schedule_idle + => do_idle + => cpu_startup_entry + => secondary_startup_64_no_verify +-- + +Here's the options for *sqlhist* explained: + + *-n wakeup_lat* :: + Name the synthetic event to use *wakeup_lat*. + + *-e*:: + Execute the commands that are printed. + + *-T*:: + Perform both a trace action and then a snapshot action (swap the buffer into the static 'snapshot' buffer). + + *-m lat*:: + Trigger the actions whenever 'lat' hits a new maximum value. + +Now a breakdown of the SQL statement: +[source, c] +-- + 'SELECT end.next_comm AS comm, (end.TIMESTAMP_USECS - start.TIMESTAMP_USECS) AS lat FROM ' \ + 'sched_waking AS start JOIN sched_switch AS end ON start.pid = end.next_pid WHERE end.next_prio < 100 && end.next_comm == "cyclictest"' +-- + *end.next_comm AS comm*:: + Save the 'sched_switch' field *next_comm* and place it into the *comm* field of the 'wakeup_lat' synthetic event. + + *(end.TIMESTAMP_USECS - start.TIMESTAMP_USECS) AS lat*:: + Take the delta of the time stamps from the 'sched_switch' event and the 'sched_waking' event. + As time stamps are usually recorded in nanoseconds, *TIMESTAMP* would give the full nanosecond time stamp, + but here, the *TIMESTAMP_USECS* will truncate it into microseconds. The value is saved in the + variable *lat*, which will also be recorded in the synthetic event. + + *FROM 'sched_waking' AS start JOIN sched_switch AS end ON start.pid = end.next_pid*:: + Create the synthetic event by joining _sched_waking_ to _sched_switch_, matching + the _sched_waking_ 'pid' field with the _sched_switch_ 'next_pid' field. + Also make *start* an alias for _sched_waking_ and *end* an alias for _sched_switch_ + which then an use *start* and *end* as a subsitute for _sched_waking_ and _sched_switch_ + respectively through out the rest of the SQL statement. + + *WHERE end.next_prio < 100 && end.next_comm == "cyclictest"*:: + Filter the logic where it executes only if _sched_waking_ 'next_prio' field + is less than 100. (Note, in the Kernel, priorities are inverse, and the real-time + priorities are represented from 0-100 where 0 is the highest priority). + Also only trace when the 'next_comm' (the task scheduling in) of the _sched_switch_ + event has the name "cyclictest". + +For the *trace-cmd*(3) command: +[source, c] +-- + trace-cmd start -e all -e wakeup_lat -R stacktrace +-- + + *trace-cmd start*:: + Enables tracing (does not record to a file). + + *-e all*:: + Enable all events + + *-e wakeup_lat -R stacktrace*:: + have the "wakeup_lat" event (our synthetic event) enable the *stacktrace* trigger, were + for every instance of the "wakeup_lat" event, a kernel stack trace will be recorded + in the ring buffer. + +After calling *cyclictest* (a real-time tool to measure wakeup latency), read the snapshot +buffer. + + *trace-cmd show -s*:: + *trace-cmd show* reads the kernel ring buffer, and the *-s* option will read the *snapshot* + buffer instead of the normal one. + +[source, c] +-- + -0 [002] d..4 23454.902256: wakeup_lat: next_comm=cyclictest lat=17 +-- + We see on the "wakeup_lat" event happened on CPU 2, with a wake up latency 17 microseconds. + +This can be extracted into a *trace.dat* file that *trace-cmd*(3) can read and do further +analysis, as well as *kernelshark*. + +[source, c] +-- + # trace-cmd extract -s + # trace-cmd report --cpu 2 | tail -30 + -0 [002] 23454.902238: prandom_u32: ret=1633425088 + -0 [002] 23454.902239: sched_wakeup: cyclictest:12275 [19] CPU:002 + -0 [002] 23454.902241: hrtimer_expire_exit: hrtimer=0xffffbbd68286fe60 + -0 [002] 23454.902241: hrtimer_cancel: hrtimer=0xffffbbd6826efe70 + -0 [002] 23454.902242: hrtimer_expire_entry: hrtimer=0xffffbbd6826efe70 now=23455294430750 function=hrtimer_wakeup/0x0 + -0 [002] 23454.902243: sched_waking: comm=cyclictest pid=12272 prio=120 target_cpu=002 + -0 [002] 23454.902244: prandom_u32: ret=1102749734 + -0 [002] 23454.902246: sched_wakeup: cyclictest:12272 [120] CPU:002 + -0 [002] 23454.902247: hrtimer_expire_exit: hrtimer=0xffffbbd6826efe70 + -0 [002] 23454.902248: write_msr: 6e0, value 4866ce957272 + -0 [002] 23454.902249: local_timer_exit: vector=236 + -0 [002] 23454.902250: cpu_idle: state=4294967295 cpu_id=2 + -0 [002] 23454.902251: rcu_utilization: Start context switch + -0 [002] 23454.902252: rcu_utilization: End context switch + -0 [002] 23454.902253: prandom_u32: ret=3692516021 + -0 [002] 23454.902254: sched_switch: swapper/2:0 [120] R ==> cyclictest:12275 [19] + -0 [002] 23454.902256: wakeup_lat: next_comm=cyclictest lat=17 + -0 [002] 23454.902258: kernel_stack: +=> trace_event_raw_event_synth (ffffffff8121a0db) +=> action_trace (ffffffff8121e9fb) +=> event_hist_trigger (ffffffff8121ca8d) +=> event_triggers_call (ffffffff81216c72) +=> trace_event_buffer_commit (ffffffff811f7618) +=> trace_event_raw_event_sched_switch (ffffffff8110fda4) +=> __traceiter_sched_switch (ffffffff8110d449) +=> __schedule (ffffffff81c02002) +=> schedule_idle (ffffffff81c02c86) +=> do_idle (ffffffff8111e898) +=> cpu_startup_entry (ffffffff8111eba9) +=> secondary_startup_64_no_verify (ffffffff81000107) +-- + +BUGS +---- + +As *sqlhist* is just example code from a man page, it is guaranteed to contain +lots of bugs. For one thing, not all error paths are covered properly. + +SEE ALSO +-------- +trace-cmd(1), tracefs_sql(3) + +AUTHOR +------ +Written by Steven Rostedt, + +RESOURCES +--------- +https://git.kernel.org/pub/scm/utils/trace-cmd/trace-cmd.git/ + +COPYING +------- +Copyright \(C) 2021 , Inc. Free use of this software is granted under +the terms of the GNU Public License (GPL). +