Trace kernel functions - Qualcomm Dragonwing Documentation

Function tracer (ftrace) provides tracing utilities to perform system-wide profiling and tracing at runtime. To use ftrace, enable the following configuration options:

CONFIG_FTRACE
CONFIG_HAVE_FUNCTION_TRACER
CONFIG_HAVE_FUNCTION_GRAPH_TRACER
CONFIG_HAVE_DYNAMIC_FTRACE
CONFIG_HAVE_FTRACE_MCOUNT_RECORD

The following are some operations that ftrace can perform to debug kernel issues:

Dump ftrace information to the kmsg buffer

To dump the ftrace information into the kmsg buffer anytime from the source code, call the ftrace_dump(DUMP_ALL) function.

To increase the buffer size of the ftrace ring, run the following command:
echo 200 > /sys/kernel/debug/tracing/buffer_size_kb

Enable work queue trace

To enable work queue tracing, run the following commands:

mount -t debugfs none /sys/kernel/debug

echo 1 > /sys/kernel/debug/tracing/events/workqueue/enable

 echo workqueue:workqueue_queue_work > /sys/kernel/debug/tracing/set_event

 cat /sys/kernel/debug/tracing/trace_pipe

cat /sys/kernel/debug/tracing/per_cpu/cpu1/trace

Sample output:

 # tracer: nop

 #

 # entries-in-buffer/entries-written: 8682/8682 #P:1

 #

 # \_-----=\> irqs-off

 # / \_----=\> need-resched

 # | / \_---=\> hardirq/softirq

 # || / \_--=\> preempt-depth

 # ||| / delay

 # TASK-PID CPU# |||| TIMESTAMP FUNCTION

 # | | | |||| | |

 \<...\>-4783 \[001\] d.s4 7524.354249: workqueue\_queue\_work: work struct=f2d91ee4 function=free\_css\_set\_work workqueue=f6427d80 req\_cpu=1 cpu=1

 \<idle\>-0 \[001\] d.h4 7524.424196: workqueue\_queue\_work: work struct=c10c32a8 function=def\_work\_fn workqueue=f55c7880 req\_cpu=1 cpu=4

 e.process.gapps-4758 \[001\] dNs4 7524.454227: workqueue\_queue\_work: work struct=c4727fa4 function=free\_css\_set\_work workqueue=f6427d80 req\_cpu=1 cpu=1

 Binder\_D-1693 \[001\] d.s3 7524.504198: workqueue\_queue\_work: work struct=cec6275c function=do\_dbs\_timer workqueue=f5424680 req\_cpu=1 cpu=1

 \<...\>-4832 \[001\] d.h3 7524.574194: workqueue\_queue\_work: work struct=c10c32a8 function=def\_work\_fn workqueue=f55c7880 req\_cpu=1 cpu=4

Enable Interrupt request (IRQ) trace

To enable interrupt tracing, run the following commands:

mount -t debugfs none /sys/kernel/debug

echo 1 > /sys/kernel/debug/tracing/events/irq/irq_handler_entry/enable

cat /sys/kernel/debug/tracing/trace

cat /sys/kernel/debug/tracing/trace_pipe

Sample output:

 TASK-PID CPU# TIMESTAMP FUNCTION

 | | | | |

 adbd-302 \[000\] 295.075568: irq\_handler\_entry: irq=132 name=msm\_otg

 adbd-302 \[000\] 295.075599: irq\_handler\_entry: irq=132 name=msm\_hsusb

 adbd-302 \[000\] 295.075782: irq\_handler\_entry: irq=132 name=msm\_otg

 adbd-302 \[000\] 295.075782: irq\_handler\_entry: irq=132 name=msm\_hsusb

 \<idle\>-0 \[000\] 295.076270: irq\_handler\_entry: irq=132 name=msm\_otg

 \<idle\>-0 \[000\] 295.076270: irq\_handler\_entry: irq=132 name=msm\_hsusb

 \<idle\>-0 \[000\] 295.077155: irq\_handler\_entry: irq=18 name=gp\_timer

 \<idle\>-0 \[000\] 295.087166: irq\_handler\_entry: irq=18 name=gp\_timer

 \<idle\>-0 \[000\] 295.097146: irq\_handler\_entry: irq=18 name=gp\_timer

Enable scheduler trace

To trace context switches between tasks, run the following commands to enable the sched_switch tracer:

mount -t debugfs none /sys/kernel/debug

echo 1 > /sys/kernel/debug/tracing/events/sched/sched_switch/enable

cat /sys/kernel/debug/tracing/trace

cat /sys/kernel/debug/tracing/trace_pipe

Sample output:

 TASK-PID CPU# TIMESTAMP FUNCTION

 | | | | |

 WindowManagerPo-484 \[000\] 994.583135: sched\_switch: prev\_comm=WindowManagerPo

 SurfaceFlinger-334 \[000\] 994.583652: sched\_switch: prev\_comm=SurfaceFlinger

 WindowManagerPo-484 \[000\] 994.584320: sched\_switch: prev\_comm=WindowManagerPo

 GL updater-675 \[000\] 994.584370: sched\_switch: prev\_comm=GL updater

 WindowManagerPo-484 \[000\] 994.584424: sched\_switch: prev\_comm=WindowManagerPo

Find IRQ latency

To find the maximum IRQ latency and pre-emption latency in the system, enable ftrace configurations for IRQOFF and PREEMPTIONOFF as follows:
CONFIG_IRQSOFF_TRACER =Y CONFIG_PREEMPT_TRACER =Y
For this configuration to take effect, recompile the kernel. This configuration detects latency in milliseconds effectively.

To enable tracing, run the following commands:

echo 0 > /sys/kernel/debug/tracing/tracing_enabled

echo 0 > /sys/kernel/debug/tracing/tracing_max_latency

echo irqsoff > /sys/kernel/debug/tracing/current_tracer

echo 1 > /sys/kernel/debug/tracing/tracing_enabled

cat /sys/kernel/debug/tracing/trace

To find the maximum latency observed in the system, configure tracing_max_latency = 0. To detect any latency higher than the specified limit, set the threshold level in microseconds. For example,
echo 2000 > /sys/kernel/debug/tracing/tracing_thresh

The following example shows the traces for IRQ latency of 16 ms:

cat /sys/kernel/debug/tracing/trace

# tracer: irqsoff

#

# WARNING: FUNCTION TRACING IS CORRUPTED

# MAY BE MISSING FUNCTION EVENTS

# irqsoff latency trace v1.1.5 on 3.4.0-perf-g7736d93-dirty

# --------------------------------------------------------------------

# latency: 16757 us, #4/4, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:1)

# -----------------

# | task: EventThread-534 (uid:1000 nice:-9 policy:0 rt\_prio:0)

# -----------------

# =\> started at: _raw_spin\_lock\_irqsave

# =\> ended at: _raw_spin\_unlock\_irqrestore

#

#

# \_------=\> CPU#

# / \_-----=\> irqs-off

# | / \_----=\> need-resched

# || / \_---=\> hardirq/softirq

# ||| / \_--=\> preempt-depth

# |||| / delay

# cmd pid ||||| time | caller

# / ||||| | /

\<...\>-534 0d... 0us!: _raw_spin\_lock\_irqsave

\<...\>-534 0d..1 16756us\+: _raw_spin\_unlock\_irqrestore

\<...\>-534 0d..1 16758us\+: trace\_hardirqs\_on \<-\_raw\_spin\_unlock\_irqrestore

\<...\>-534 0d..1 16780us : \<stack trace\>

=\> trace\_hardirqs\_on

=\> _raw_spin\_unlock\_irqrestore

=\> clk\_enable

=\> mdss\_dsi\_clk\_enable

=\> mdss\_dsi\_clk\_ctrl

=\> mdss\_dsi\_clk\_req

=\> mdss\_dsi\_event\_handler

=\> mdss\_mdp\_ctl\_intf\_event

=\> mdss\_mdp\_cmd\_add\_vsync\_handler

=\> mdss\_mdp\_overlay\_vsync\_ctrl

=\> mdss\_mdp\_overlay\_ioctl\_handler

=\> mdss\_fb\_ioctl

=\> do\_fb\_ioctl

=\> fb\_ioctl

=\> do\_vfs\_ioctl

=\> sys\_ioctl

=\> ret\_fast\_syscall

/sys/kernel/debug/tracing #

For more information, see the Documentation/trace/ftrace.txt file available in the kernel documentation.

​Dump ftrace information to the kmsg buffer

​Enable work queue trace

​Enable Interrupt request (IRQ) trace

​Enable scheduler trace

​Find IRQ latency

Dump ftrace information to the kmsg buffer

Enable work queue trace

Enable Interrupt request (IRQ) trace

Enable scheduler trace

Find IRQ latency