From 5c90abcf73cccc9247e935c83807f2293ebb8fb7 Mon Sep 17 00:00:00 2001
From: Jan Altenberg <jan@linutronix.de>
Date: Wed, 9 Feb 2011 15:09:25 +0100
Subject: Some slides about ftrace / trace-cmd and kernelshark.

---
 .../kernel-tracing/pres_kernel-tracing_en.tex      | 300 +++++++++++++++++++++
 1 file changed, 300 insertions(+)
 create mode 100644 kernel-devel/kernel-tracing/pres_kernel-tracing_en.tex

(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
new file mode 100644
index 0000000..11c2f5f
--- /dev/null
+++ b/kernel-devel/kernel-tracing/pres_kernel-tracing_en.tex
@@ -0,0 +1,300 @@
+\input{configpres}
+
+\title{Kernel-Tracing}
+\section{FTRACE}
+\maketitle
+\begin{frame}[fragile]
+\frametitle{Kerneltracing: Overview}
+\begin{itemize}
+\item DebugFS interface
+\item Different tracers: function, function\_graph, sched\_switch, ...
+\item Custom trace events
+\item Graphical frontend (kernelshark)
+\end{itemize}
+\end{frame}
+
+\begin{frame}[fragile]
+\frametitle{Kernel-Tracing: DebugFS}
+\begin{verbatim}
+$ mount -t debugfs debugfs /sys/kernel/debug
+$ cd /sys/kernel/debug/tracing
+$ cat available_tracers
+blk function_graph mmiotrace wakeup_rt wakeup
+\end{verbatim}
+\end{frame}
+
+
+\begin{frame}[fragile]
+\frametitle{Kerneltracing: Trivial example}
+\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();
+\end{verbatim}
+\end{frame}
+
+\begin{frame}[fragile]
+\frametitle{Tracer: function}
+\begin{verbatim}
+# tracer: function
+#
+# TASK-PID  CPU#    TIMESTAMP  FUNCTION
+#  | |       |          |         |
+wnck-2022  [003]  5766.659915: skb_release
+wnck-2022  [003]  5766.659916: sock_wfree
+wnck-2022  [003]  5766.659917: unix_write_free
+wnck-2022  [003]  5766.659917: skb_releasee_skb
+wnck-2022  [003]  5766.659918: kfree <-skb
+\end{verbatim}
+\end{frame} 
+
+\begin{frame}[fragile]
+\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
+\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: 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
+\begin{verbatim}
+# tracer: wakeup_rt
+#
+# wakeup_rt latency trace v1.1.5 on 2.6.35-22-generic
+# --------------------------------------------------------------------
+# latency: 11 us, #20/20, CPU#3 | (M:desktop VP:0, KP:0, SP:0 HP:0 #P:4)
+...
+#  cmd     pid          time  |   caller      
+#     \   /               \   |   /           
+ls-4579    3d....    1us+:   4579:120:R   + [003]    12:  0:R migration/3
+ls-4579    3d....    4us : wake_up_process <-cpu_stop_queue_work
+ls-4579    3d....    4us : check_preempt_wakeup <-try_to_wake_up
+ls-4579    3d....    4us : resched_task <-check_preempt_wakeup
+ls-4579    3dN...    5us : task_woken_rt <-try_to_wake_up
+ls-4579    3dN...    5us : _raw_spin_unlock_irqrestore <-try_to_wake_up
+\end{verbatim}
+\end{frame}
+
+\section{trace-cmd}
+
+\begin{frame}
+\frametitle{trace-cmd}
+\begin{alertblock}{What is trace-cmd?}
+trace-cmd is a commandline utility for controlling and analysing kernel traces.
+\end{alertblock}
+\end{frame}
+
+\begin{frame}[fragile]
+\frametitle{trace-cmd: Installation}
+\begin{verbatim}
+$ git clone git://git.kernel.org/pub/scm/linux/\
+                  kernel/git/rostedt/trace-cmd.git
+$ cd trace-cmd
+# On Debian system
+$ apt-get install libgtk2.0-dev libxml2-dev
+$ make && make gui
+$ make install && make install_gui
+\end{verbatim}
+\end{frame}
+
+\begin{frame}[fragile]
+\small
+\frametitle{trace-cmd: Usage}
+\begin{verbatim}
+$ trace-cmd 
+[...]
+record - record a trace into a trace.dat file
+start - start tracing without recording into a file
+extract - extract a trace from the kernel
+stop - stop the kernel from recording trace data
+reset - disable all kernel tracing / clear trace buffers
+report - read out the trace stored in a trace.dat file
+split - parse a trace.dat file into smaller file(s)
+listen - listen on a network socket for trace clients
+list - list the available events, plugins or options
+restore - restore a crashed record
+stack - output, enable or disable kernel stack tracing
+\end{verbatim}
+\end{frame}
+
+\begin{frame}[fragile]
+\frametitle{trace-cmd: Usage}
+\begin{verbatim}
+# Recording a sched_switch trace
+$ trace-cmd -p sched_switch
+  plugin sched_switch
+Hit Ctrl^C to stop recording
+Hit Ctrl^C to stop recording
+offset=ae000
+[...]
+
+CPU: 0
+entries: 0
+overrun: 0
+commit overrun: 0
+\end{verbatim}
+\end{frame}
+
+\begin{frame}[fragile]
+\frametitle{trace-cmd: Usage}
+\begin{verbatim}
+# Analysing a trace
+$ trace-cmd report
+version = 6
+cpus=1
+trace-cmd-29057 [000]  6901.652365: wakeup:
+29057:120:1 ==+ 29057:120:1 [000]
+trace-cmd-29057 [000]  6901.652388: wakeup:
+29057:120:0 ==+ 323:120:0 [000]
+trace-cmd-29057 [000]  6901.652393: context_switch:
+29057:120:0 ==> 323:120:0 [000]
+kworker/0:1-323   [000]  6901.652397: wakeup:
+323:120:0 ==+ 28355:120:0 [000]
+\end{verbatim}
+\end{frame}
+
+\begin{frame}
+\frametitle{trace-cmd: Usage}
+\begin{itemize}
+\item trace-cmd record generates a file called trace.dat. This can be overridden by
+the -o option
+\item trace-cmd report uses the -i option for specifying an input file 
+\end{itemize}
+\end{frame}
+
+\begin{frame}[fragile]
+\frametitle{trace-cmd: Record specific events}
+\begin{verbatim}
+trace-cmd record -e sched
+# or a specific scheduler event
+trace-cmd record -e sched_wait_task
+# List availabe events and options
+trace-cmd report --events
+\end{verbatim}
+\begin{verbatim}
+
+\end{verbatim}
+\end{frame}
+
+\begin{frame}[fragile]
+\frametitle{trace-cmd: Filters}
+Based on the options from ''trace-cmd report --events'':
+\begin{verbatim}
+trace-cmd record -e context_switch \
+                   -f 'next_pid == 323'
+\end{verbatim}
+\end{frame}
+
+\begin{frame}[fragile]
+\frametitle{trace-cmd: Tracing a specific command}
+Enable tracing while a specific command is being executed:
+\begin{verbatim}
+$ trace-cmd record -p function ls
+\end{verbatim}
+\end{frame}
+
+\begin{frame}[fragile]
+\frametitle{trace-cmd: Recording traces via network}
+On the host:
+\begin{verbatim}
+trace-cmd listen -p 1234 -o trace_remote
+\end{verbatim}
+On the target:
+\begin{verbatim}
+trace-cmd record -p sched_switch \
+       -N 192.168.0.182:1234 /bin/ls
+\end{verbatim}
+\end{frame}
+
+\section{Kernelshark}
+\begin{frame}[fragile]
+\frametitle{Kernelshark: A graphical front-end}
+\begin{verbatim}
+$ kernelshark
+# or
+$ kernelshark -i mytrace.dat
+\end{verbatim}
+\end{frame}
+
+\begin{frame}
+\frametitle{Kernelshark}
+\begin{figure}[h]
+\centering
+\includegraphics[width=10cm]{images/kernelshark.png}
+\end{figure}
+\end{frame}
+
+\begin{frame}
+\frametitle{Kernelshark}
+\begin{figure}[h]
+\centering
+\includegraphics[width=10cm]{images/kernelshark_zoom.png}
+\end{figure}
+\end{frame}
+\begin{frame}
+
+\section{sources}
+\frametitle{sources}
+\begin{thebibliography}{1}
+\bibitem{trace1} http://lwn.net/Articles/365835/
+\bibitem{trace2} http://lwn.net/Articles/366796/
+\end{thebibliography} 
+\end{frame}
+
+\input{tailpres}
-- 
cgit v1.2.3

