From c142dc8a6770eedfcbba7100a537a505b128ab98 Mon Sep 17 00:00:00 2001
From: Manuel Traut <manut@mecka.net>
Date: Wed, 10 Jul 2013 22:16:56 +0200
Subject: kernel-tracing: remove sched_switch tracer

Signed-off-by: Manuel Traut <manut@mecka.net>
---
 .../kernel-tracing/pres_kernel-tracing_en.tex      | 48 +++++++++-------------
 1 file changed, 19 insertions(+), 29 deletions(-)

(limited to 'kernel-devel/kernel-tracing/pres_kernel-tracing_en.tex')

diff --git a/kernel-devel/kernel-tracing/pres_kernel-tracing_en.tex b/kernel-devel/kernel-tracing/pres_kernel-tracing_en.tex
index d73a10f..f185e58 100644
--- a/kernel-devel/kernel-tracing/pres_kernel-tracing_en.tex
+++ b/kernel-devel/kernel-tracing/pres_kernel-tracing_en.tex
@@ -7,7 +7,7 @@
 \frametitle{Kerneltracing: Overview}
 \begin{itemize}
 \item DebugFS interface
-\item Different tracers: function, function\_graph, sched\_switch, ...
+\item Different tracers: function, function\_graph, wakeup, wakeup\_rt, \dots
 \item Custom trace events
 \item Graphical frontend (kernelshark)
 \end{itemize}
@@ -62,18 +62,24 @@ wnck-2022  [003]  5766.659918: kfree <-skb
 \frametitle{Tracer: function / latency\_format}
 \begin{verbatim}
 $ echo 1 > options/latency_format
-$ less trace
-#                  _------=> CPU#            
-#                 / _-----=> irqs-off        
-#                | / _----=> need-resched    
-#                || / _---=> hardirq/softirq 
-#                ||| / _--=> preempt-depth   
-#                |||| /_--=> lock-depth       
-#                |||||/     delay             
-#  cmd     pid   |||||| time  |   caller      
-#     \   /      ||||||   \   |   /           
-wnck-app-2022    3..... 1237702us : skb_relea
-wnck-app-2022    3..... 1237703us : sock_wfre
+# tracer: function
+#
+# function latency trace v1.1.5 on 3.9.4-x1-00124-g0bfd8ff
+# --------------------------------------------------------------------
+# latency: 0 us, #204955/25306195, CPU#0 | (M:desktop VP:0, KP:0, SP:0 HP:0 #P:4)
+#    -----------------
+#    | task: -0 (uid:0 nice:0 policy:0 rt_prio:0)
+#    -----------------
+#
+#                  _------=> CPU#
+#                 / _-----=> irqs-off
+#                | / _----=> need-resched
+#                || / _---=> hardirq/softirq
+#                ||| / _--=> preempt-depth
+#                |||| /     delay
+#  cmd     pid   ||||| time  |   caller
+#     \   /      |||||  \    |   /
+terminol-11964   1.... 11639243us : ep_read_events_proc <-ep_scan_ready_list.isra.8
 \end{verbatim}
 \end{frame} 
 
@@ -94,22 +100,6 @@ $ less trace
 \end{verbatim}
 \end{frame}
 
-\begin{frame}[fragile]
-\frametitle{Tracer: sched\_switch}
-\tiny
-\begin{verbatim}
-# tracer: sched_switch
-#
-#  TASK-PID    CPU#    TIMESTAMP  FUNCTION
-#    | |       |          |         |
-  bash-4328  [003]  78.553966: 4328:120:S   + [003]  4328:120:S bash
-  bash-4328  [003]  78.553979: 4328:120:S ==> [003]     0:120:R <idle>
-<idle>-0     [003]  78.553986:    0:120:R   + [003]    13:120:R ksoftirqd/3
-<idle>-0     [003]  78.553988:    0:120:R ==> [003]    13:120:R ksoftirqd/3
-
-\end{verbatim}
-\end{frame}
-
 \begin{frame}[fragile]
 \frametitle{Tracer: wakeup\_rt}
 \tiny
-- 
cgit v1.2.3


From 751dc5e4abec89bddf8260d6756d9db8eb72a0c3 Mon Sep 17 00:00:00 2001
From: Jan Altenberg <jan@linutronix.de>
Date: Mon, 3 Feb 2014 18:16:19 +0100
Subject: Update for the tracing chapter: Overview, Event Tracing, Kprobes,
 Uprobes, Filter

---
 images/pthread_kernelshark.png                     | Bin 0 -> 8857 bytes
 images/trace_overview.dia                          | Bin 0 -> 2201 bytes
 images/trace_overview.png                          | Bin 0 -> 21041 bytes
 .../kernel-tracing/pres_kernel-tracing_en.tex      | 415 +++++++++++++++++++--
 4 files changed, 383 insertions(+), 32 deletions(-)
 create mode 100644 images/pthread_kernelshark.png
 create mode 100644 images/trace_overview.dia
 create mode 100644 images/trace_overview.png

(limited to 'kernel-devel/kernel-tracing/pres_kernel-tracing_en.tex')

diff --git a/images/pthread_kernelshark.png b/images/pthread_kernelshark.png
new file mode 100644
index 0000000..d73f913
Binary files /dev/null and b/images/pthread_kernelshark.png differ
diff --git a/images/trace_overview.dia b/images/trace_overview.dia
new file mode 100644
index 0000000..6b705cf
Binary files /dev/null and b/images/trace_overview.dia differ
diff --git a/images/trace_overview.png b/images/trace_overview.png
new file mode 100644
index 0000000..7156705
Binary files /dev/null and b/images/trace_overview.png differ
diff --git a/kernel-devel/kernel-tracing/pres_kernel-tracing_en.tex b/kernel-devel/kernel-tracing/pres_kernel-tracing_en.tex
index f185e58..d5a9686 100644
--- a/kernel-devel/kernel-tracing/pres_kernel-tracing_en.tex
+++ b/kernel-devel/kernel-tracing/pres_kernel-tracing_en.tex
@@ -1,8 +1,14 @@
 \input{configpres}
 
 \title{Kernel-Tracing}
-\section{FTRACE}
+\section{Overview}
 \maketitle
+
+\begin{frame}
+\frametitle{Overview}
+\tableofcontents
+\end{frame}
+
 \begin{frame}[fragile]
 \frametitle{Kerneltracing: Overview}
 \begin{itemize}
@@ -13,6 +19,14 @@
 \end{itemize}
 \end{frame}
 
+\begin{frame}[fragile]
+\frametitle{Kerneltracing: Overview}
+\begin{figure}[h]
+\centering
+\includegraphics[width=10cm]{images/trace_overview.png}
+\end{figure}
+\end{frame}
+
 \begin{frame}[fragile]
 \frametitle{Kernel-Tracing: DebugFS}
 \begin{verbatim}
@@ -23,26 +37,102 @@ blk function_graph mmiotrace wakeup_rt wakeup
 \end{verbatim}
 \end{frame}
 
+\section{Event tracing}
+\begin{frame}[fragile]
+\frametitle{Event tracing}
+current\_tracer can be set to NOP
+\begin{verbatim}
+$ cd /sys/kernel/debug/tracing
+$ ls events/
+[...]
+irq
+sched
+scsi
+signal
+skb
+[...]
+\end{verbatim}
+\end{frame}
 
 \begin{frame}[fragile]
-\frametitle{Kerneltracing: Trivial example}
+\frametitle{Event tracing}
 \begin{verbatim}
-$ echo function_graph > current_tracer
-$ echo 1 > tracing_enabled
-$ sleep 1
-$ echo 0 > tracing_enabled
-$ less trace
-# tracer: function_graph
-# CPU  DURATION           FUNCTION CALLS
-# |     |   |              |   |   |   |
- 1)               |         enqueue_entity() {
- 1)               |           update_curr() {
- 1)   0.336 us    |             task_of();
- 1)   1.524 us    |           }
- 1)   0.420 us    |           place_entity();
+$ cd /sys/kernel/debug/tracing
+$ ls -1 events/sched/
+enable
+filter
+sched_kthread_stop
+sched_kthread_stop_ret
+sched_migrate_task
+sched_pi_setprio
+[...]
+\end{verbatim}
+\end{frame}
+
+\begin{frame}[fragile]
+\frametitle{Event tracing: Enable events}
+\begin{verbatim}
+$ cd /sys/kernel/debug/tracing
+# Enable ALL events of the group ''sched''
+$ echo 1 > events/sched/enable
 \end{verbatim}
 \end{frame}
 
+\begin{frame}[fragile]
+\frametitle{Record a trace}
+After enabling the events you want to see, do:
+\begin{verbatim}
+$ cd /sys/kernel/debug/tracing
+# Start recording to the ringbuffer
+$ echo 1 > tracing_on
+# Stop recording to the ringbuffer
+$ echo 0 > tracing_on
+\end{verbatim}
+\end{frame}
+
+\begin{frame}[fragile]
+\frametitle{Analyze a trace}
+You can even do this while recording!
+\begin{verbatim}
+$ cd /sys/kernel/debug/tracing
+# Just print the current content of the ring buffer
+$ cat trace
+# or: do a consuming read on the ring buffer
+$ cat trace_pipe
+\end{verbatim}
+\end{frame}
+
+\begin{frame}[fragile]
+\frametitle{Trace event format and filters}
+Each trace event has a specific format and parameters.
+You can put a filter on those parameters for recording a trace:
+\begin{verbatim}
+$ cat events/sched/sched_switch/format
+[...]
+field:__u8 prev_comm[15];
+field:pid_t prev_pid;
+field:int prev_prio;
+field:long prev_state;
+[...]
+$ echo 'next_comm == bash' \
+    > events/sched/sched_switch/filter
+$ echo 1 > events/sched/sched_switch/enable
+$ echo 1 > tracing_on
+$ cat trace
+\end{verbatim}
+\end{frame}
+
+\begin{frame}[fragile]
+\frametitle{Tracing on multicore}
+\begin{itemize}
+\item One ringbuffer per cpu
+\item trace contains ALL events
+\item the per\_cpu directory contains a trace for each cpu
+\item tracing\_cpumask can limit tracing to specific cores
+\end{itemize}
+\end{frame}
+
+\section{Tracers}
 \begin{frame}[fragile]
 \frametitle{Tracer: function}
 \begin{verbatim}
@@ -58,8 +148,39 @@ wnck-2022  [003]  5766.659918: kfree <-skb
 \end{verbatim}
 \end{frame} 
 
+\begin{frame}[fragile]
+\frametitle{Tracer: function\_graph}
+\begin{verbatim}
+$ echo function_graph > current_tracer
+$ echo 1 > tracing_on
+$ sleep 1
+$ echo 0 > tracing_on
+$ less trace
+# tracer: function_graph
+# CPU  DURATION           FUNCTION CALLS
+# |     |   |              |   |   |   |
+ 1)               |         enqueue_entity() {
+ 1)               |           update_curr() {
+ 1)   0.336 us    |             task_of();
+ 1)   1.524 us    |           }
+ 1)   0.420 us    |           place_entity();
+\end{verbatim}
+\end{frame}
+
+\begin{frame}[fragile]
+\frametitle{function\_graph: Set a trigger function}
+You can set a trigger function for the function\_graph tracer
+if you just want to record specific functions and their childs:
+\begin{verbatim}
+echo do_IRQ > set_graph_function
+# Additionals triggers can be set with
+echo another_function >> set_graph_function
+\end{verbatim}
+\end{frame}
+
 \begin{frame}[fragile]
 \frametitle{Tracer: function / latency\_format}
+\tiny
 \begin{verbatim}
 $ echo 1 > options/latency_format
 # tracer: function
@@ -83,23 +204,6 @@ terminol-11964   1.... 11639243us : ep_read_events_proc <-ep_scan_ready_list.isr
 \end{verbatim}
 \end{frame} 
 
-\begin{frame}[fragile]
-\frametitle{Tracer: function (custom tracepoint)}
-\begin{verbatim}
-$ echo 1 > tracing_enabled
-$ echo "MARK" > trace_marker
-$ echo 0 > tracing_enabled
-$ less trace
-...
- bash-4328  [003]  5603.687935: get_slab
- bash-4328  [003]  5603.687935: _cond_re
- bash-4328  [003]  5603.687936: _cond_re
- bash-4328  [003]  5603.687939: 0: MARK
- bash-4328  [003]  5603.687939: kfree <-
-...
-\end{verbatim}
-\end{frame}
-
 \begin{frame}[fragile]
 \frametitle{Tracer: wakeup\_rt}
 \tiny
@@ -121,6 +225,44 @@ ls-4579    3dN...    5us : _raw_spin_unlock_irqrestore <-try_to_wake_up
 \end{verbatim}
 \end{frame}
 
+\section{Kernel function profiler}
+
+\begin{frame}[fragile]
+\frametitle{Kernel function profiler}
+\begin{verbatim}
+$ echo 1 > function_profile_enabled
+$ echo 1 > tracing_on
+# then do something...
+$ echo 0 > tracing_on
+$ less trace_stat/function0
+Function      Hit  Time          Avg        
+--------      ---  ----          ---        
+__schedule   7064  1958976725 us 277318.3 us 
+schedule     6961  1958965845 us 281420.1 us 
+[...]
+\end{verbatim}
+\end{frame}
+
+\section{trace\_marker}
+\begin{frame}[fragile]
+\frametitle{Custom application tracepoints: ''simple method''}
+\begin{verbatim}
+$ echo 1 > tracing_on
+$ echo "MARK" > trace_marker
+$ echo 0 > tracing_on
+$ less trace
+...
+ bash-4328  [003]  5603.687935: get_slab
+ bash-4328  [003]  5603.687935: _cond_re
+ bash-4328  [003]  5603.687936: _cond_re
+ bash-4328  [003]  5603.687939: 0: MARK
+ bash-4328  [003]  5603.687939: kfree <-
+...
+\end{verbatim}
+\end{frame}
+
+\section{trace\_printk}
+
 \begin{frame}[fragile]
 \frametitle{trace\_printk()}
 \begin{itemize}
@@ -148,6 +290,10 @@ Only trace specific functions.
 ftrace_notrace=
 \end{verbatim}
 Don't trace specific functions.
+\begin{verbatim}
+trace_event=
+\end{verbatim}
+Just enable trace events (comma separated list)
 \end{frame}
 
 \begin{frame}[fragile]
@@ -160,6 +306,20 @@ echo z > /proc/sysrq-trigger
 \end{verbatim}
 \end{frame}
 
+\begin{frame}[fragile]
+\frametitle{Trace instances}
+You can have separate trace instances with their own
+buffers and events:
+\begin{verbatim}
+$ cd /sys/kernel/debug/tracing
+$ mkdir instances/my_inst1
+$ cd instances/my_inst1
+$ echo 1 > events/sched/enable
+$ cat trace
+[...]
+\end{verbatim}
+\end{frame}
+
 \section{trace-cmd}
 
 \begin{frame}
@@ -316,9 +476,200 @@ $ kernelshark -i mytrace.dat
 \includegraphics[width=10cm]{images/kernelshark_zoom.png}
 \end{figure}
 \end{frame}
+
+\section{Useful things}
+
+\begin{frame}[fragile]
+\frametitle{Control a trace from your kernel code}
+\begin{verbatim}
+void my_kernel_function(void)
+{
+     tracing_on();
+     do_some_stuff_i_wanna_trace();
+     tracing_off();
+}
+\end{verbatim}
+\end{frame}
+
+\begin{frame}[fragile]
+\frametitle{Matching PIDs and process names of your trace(s)}
+\begin{verbatim}
+$ cat saved_cmdlines
+[...]
+5112 bash
+5223 ARTHUR_DENT
+5546 kworker/0:2
+8465 kworker/0:0
+[...]
+\end{verbatim}
+\end{frame}
+
+\begin{frame}[fragile]
+\frametitle{Where's my thread in the trace?!}
+To ''find'' a specific thread in your trace, you can use the
+following function to set the thread's name:
+\begin{verbatim}
+#define _GNU_SOURCE
+#include <pthread.h>
+
+pthread_setname_np(pthread_t thread,
+                     const char *name);
+\end{verbatim}
+Available since glibc version 2.12
+\end{frame}
+
+\begin{frame}[fragile]
+\frametitle{Thread names: Example}
+\begin{verbatim}
+/* pthread_example */
+pthread_t test_thread;
+[...]
+pthread_create(&test_thread, NULL,
+                 my_test_thread, NULL);
+[...]
+pthread_setname_np(test_thread, "ARTHUR_DENT");
+\end{verbatim}
+Check with the ps command:
+\begin{verbatim}
+$ ps H -C pthread_example -o 'pid tid cmd comm'
+ PID   TID CMD               COMMAND
+4515  4515 ./pthread_example pthread_example
+4515  4516 ./pthread_example ARTHUR_DENT
+\end{verbatim}
+\end{frame}
+
 \begin{frame}
+\frametitle{Thread name in kernelshark}
+\begin{figure}[h]
+\centering
+\includegraphics[width=10cm]{images/pthread_kernelshark.png}
+\end{figure}
+\end{frame}
+
+\section{kprobes}
+\begin{frame}[fragile]
+\frametitle{Dynamic kernel tracepoints: KPROBES}
+\begin{itemize}
+\item Similar to Tracepoints
+\item Can be added / removed dynamically
+\end{itemize}
+\end{frame}
+
+\begin{frame}[fragile]
+\frametitle{Dynamic kernel tracepoints: KPROBES}
+\begin{verbatim}
+$ echo 'p:my_k_event do_IRQ' > kprobe_events
+$ echo 1 events/kprobes/my_k_event/enabled
+$ echo 1 > tracing_on
+$ cat trace
+<idle>-0 [000] d... 545.173709: my_k_event: (do_IRQ+0x0/0xc0)
+<idle>-0 [000] d... 545.331051: my_k_event: (do_IRQ+0x0/0xc0)
+<idle>-0 [000] d... 545.331490: my_k_event: (do_IRQ+0x0/0xc0)
+<idle>-0 [000] d... 545.490730: my_k_event: (do_IRQ+0x0/0xc0)
+\end{verbatim}
+\end{frame}
+
+\begin{frame}[fragile]
+\frametitle{Dynamic kernel tracepoints: KPROBES for custom modules}
+Let's assume we want to have a tracepoint for the function
+hello\_init in the module hello.ko
+\begin{verbatim}
+# Note: >> will append a new event
+$ echo 'p:my_mod_event hello:hello_init' \
+           >> kprobe_events
+$ echo 1 > events/kprobes/my_mod_event/enable
+$ insmod hello.ko
+$ cat trace
+insmod-9586  [000] d... 13278.003468: my_mod_event: (0xf878d080)
+\end{verbatim}
+\end{frame}
+
+\begin{frame}[fragile]
+\frametitle{Dynamic kernel tracepoints: Question / Exercise}
+What happens, if we add the following event. What's different?
+\begin{verbatim}
+# Note >> will append a new event
+$ echo 'r:my_exercise_event hello:hello_init' \
+           >> kprobe_events
+\end{verbatim}
+\end{frame}
+
+\begin{frame}[fragile]
+\frametitle{KPROBES statistics}
+\begin{verbatim}
+$ cat kprobe_profile 
+my_mod_event_ret           2               0
+my_mod_event               2               0
+\end{verbatim}
+\end{frame}
+
+\section{uprobes}
+\begin{frame}[fragile]
+\frametitle{Dynamic Userspace Tracepoints: uprobes}
+\begin{itemize}
+\item Similar to kprobes
+\item For userspace applications
+\item A uprobe event is set on a specific offset in a userland process
+\item Powerful method to correlate your kernel and userland events!
+\end{itemize}
+\end{frame}
+
+\begin{frame}[fragile]
+\frametitle{Dynamic Userspace Tracepoints: uprobes}
+\begin{verbatim}
+$ gcc -Wall -g -o pthread_example \
+      pthread_example.c -lpthread
+$ objdump -F -D -S pthread_example | less
+\end{verbatim}
+\begin{verbatim}
+08048594 <my_test_thread> (File Offset: 0x594):
+[...]
+void *my_test_thread(void *x_void_ptr)
+[...]
+        for (i = 0; i < 10; i++) {
+80485a1:  c7 45 f4 00 00 00 00    movl   $0x0,-0xc(%ebp)
+80485a8:  eb 1c                   jmp    80485c6 <my_test_thread+0x32> (File Offset: 0x5c6)
+          printf("The answer is 42!\n");
+80485aa:  c7 04 24 50 87 04 08    movl   $0x8048750,(%esp)
+\end{verbatim}
+So, the file offset for the printf call is 0x5aa !
+\end{frame}
+
+\begin{frame}[fragile]
+\frametitle{Dynamic Userspace Tracepoints: uprobes II}
+\begin{verbatim}
+echo \
+'p:my_ev /home/devel/pthread/pthread_example:0x5aa' \
+       >  /sys/kernel/debug/tracing/uprobe_events
+\end{verbatim}
+\end{frame}
+
+\begin{frame}[fragile]
+\frametitle{Dynamic Userspace Tracepoints: uprobes III}
+\begin{verbatim}
+$ cd /sys/kernel/debug/tracing/
+$ echo 1 > events/uprobes/my_ev/enable
+$ echo 1 > tracing on
+$ /home/devel/pthread_example/pthread_example
+$ echo 0 > tracing_on
+$ less trace
+#      TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
+#         | |       |   ||||       |         |
+ARTHUR_DENT-5223  [000] d...  5653.154822: my_ev: (0x80485aa)
+ARTHUR_DENT-5223  [000] d...  5654.155723: my_ev: (0x80485aa)
+\end{verbatim}
+\end{frame}
+
+\begin{frame}[fragile]
+\frametitle{uprobes: statistics}
+\begin{verbatim}
+$  cat uprobe_profile 
+/home/devel/pthread/pthread_example my_ev    10
+\end{verbatim}
+\end{frame}
 
 \section{sources}
+\begin{frame}
 \frametitle{sources}
 \begin{thebibliography}{1}
 \bibitem{trace1} http://lwn.net/Articles/365835/
-- 
cgit v1.2.3

