path: root/kernel-devel/kernel-tracing/pres_kernel-tracing_en.tex

\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}

\begin{frame}[fragile]
\frametitle{trace\_printk()}
\begin{itemize}
\item trace\_printk() can be used to write messages to the tracing ring buffer
\item Usage is similar to printk()
\end{itemize}
\end{frame}

\begin{frame}[fragile]
\frametitle{Tracing related kernel parameters}
\begin{verbatim}
ftrace=
\end{verbatim}
Set and start specified tracer as early as possible.
\begin{verbatim}
ftrace_dump_on_oops[=orig_cpu]
\end{verbatim}
Dump the tracing ring buffer if an Oops occurs. Using orig\_cpu it will only
dump the buffer of the CPU which triggered the Oops.
\begin{verbatim}
ftrace_filter=
\end{verbatim}
Only trace specific functions.
\begin{verbatim}
ftrace_notrace=
\end{verbatim}
Don't trace specific functions.
\end{frame}

\begin{frame}[fragile]
\frametitle{Dump trace buffer}
The trace buffer can also be dumped by:\\
\textbf{SysRQ-z}\\
or
\begin{verbatim}
echo z > /proc/sysrq-trigger
\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}