Update for the tracing chapter: Overview, Event Tracing, Kprobes, Uprobes, Filter

4 files changed, 383 insertions, 32 deletions

diff --git a/images/pthread_kernelshark.png b/images/pthread_kernelshark.png
new file mode 100644
index 0000000..d73f913
--- /dev/null
+++ b/images/pthread_kernelshark.png
diff --git a/images/trace_overview.dia b/images/trace_overview.dia
new file mode 100644
index 0000000..6b705cf
--- /dev/null
+++ b/images/trace_overview.dia
diff --git a/images/trace_overview.png b/images/trace_overview.png
new file mode 100644
index 0000000..7156705
--- /dev/null
+++ b/images/trace_overview.png
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}
@@ -14,6 +20,14 @@
 \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}
 $ mount -t debugfs debugfs /sys/kernel/debug
@@ -23,27 +37,103 @@ 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}
 # tracer: function
@@ -59,7 +149,38 @@ wnck-2022  [003]  5766.659918: kfree <-skb
 \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
@@ -84,23 +205,6 @@ terminol-11964   1.... 11639243us : ep_read_events_proc <-ep_scan_ready_list.isr
 \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
 \begin{verbatim}
@@ -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/