| <html devsite> |
| <head> |
| <title>Using ftrace</title> |
| <meta name="project_path" value="/_project.yaml" /> |
| <meta name="book_path" value="/_book.yaml" /> |
| </head> |
| <body> |
| <!-- |
| Copyright 2017 The Android Open Source Project |
| |
| Licensed under the Apache License, Version 2.0 (the "License"); |
| you may not use this file except in compliance with the License. |
| You may obtain a copy of the License at |
| |
| http://www.apache.org/licenses/LICENSE-2.0 |
| |
| Unless required by applicable law or agreed to in writing, software |
| distributed under the License is distributed on an "AS IS" BASIS, |
| WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. |
| See the License for the specific language governing permissions and |
| limitations under the License. |
| --> |
| |
| |
| <p>ftrace is a debugging tool for understanding what is going on inside the |
| Linux kernel. The following sections detail basic ftrace functionality, ftrace |
| usage with atrace (which captures kernel events), and dynamic ftrace.</p> |
| |
| <p>For details on advanced ftrace functionality that is not available from |
| systrace, refer to the ftrace documentation at |
| <a href="https://www.kernel.org/doc/Documentation/trace/ftrace.txt"><code><kernel |
| tree>/Documentation/trace/ftrace.txt</code></a>.</p> |
| |
| <h2 id="atrace">Capturing kernel events with atrace</h2> |
| <p>atrace (<code>frameworks/native/cmds/atrace</code>) uses ftrace to capture |
| kernel events. In turn, systrace.py (or run_systrace.py in later versions of |
| <a href="https://github.com/catapult-project/catapult">Catapult</a>) uses adb |
| to run atrace on the device. atrace does the following:</p> |
| <ul> |
| <li>Sets up user-mode tracing by setting a property |
| (<code>debug.atrace.tags.enableflags</code>).</li> |
| <li>Enables the desired ftrace functionality by writing to the appropriate |
| ftrace sysfs nodes. However, as ftrace supports more features, you might set |
| some sysfs nodes yourself then use atrace. </li> |
| </ul> |
| |
| <p>With the exception of boot-time tracing, rely on using atrace to set the |
| property to the appropriate value. The property is a bitmask and there's no good |
| way to determine the correct values other than looking at the appropriate header |
| (which could change between Android releases).</p> |
| |
| <h2 id="enabling_events">Enabling ftrace events</h2> |
| |
| <p>The ftrace sysfs nodes are in <code>/d/tracing</code> and trace events are |
| divided into categories in <code>/d/tracing/events</code>. |
| |
| <p>To enable events on a per-category basis, use: |
| <pre class="devsite-terminal devsite-click-to-copy"> |
| echo 1 > /d/tracing/events/irq/enable |
| </pre> |
| |
| <p>To enable events on per-event basis, use: |
| <pre class="devsite-terminal devsite-click-to-copy"> |
| echo 1 > /d/tracing/events/sched/sched_wakeup/enable |
| </pre> |
| |
| <p>If extra events have been enabled by writing to sysfs nodes, they will |
| <strong>not</strong> be reset by atrace. A common pattern |
| for Qualcomm device bringup is to enable <code>kgsl</code> (GPU) and |
| <code>mdss</code> (display pipeline) tracepoints and then use atrace or |
| <a href="/devices/tech/debug/systrace.html">systrace</a>:</p> |
| |
| <pre class="devsite-click-to-copy"> |
| <code class="devsite-terminal">adb shell "echo 1 > /d/tracing/events/mdss/enable"</code> |
| <code class="devsite-terminal">adb shell "echo 1 > /d/tracing/events/kgsl/enable"</code> |
| <code class="devsite-terminal">./systrace.py sched freq idle am wm gfx view binder_driver irq workq ss sync -t 10 -b 96000 -o full_trace.html</code> |
| </pre> |
| |
| <p>You can also use ftrace without atrace or systrace, which is |
| useful when you want kernel-only traces (or if you've taken the time to write |
| the user-mode tracing property by hand). To run just ftrace:</p> |
| |
| <ol> |
| <li>Set the buffer size to a value large enough for your trace: |
| <pre class="devsite-terminal devsite-click-to-copy"> |
| echo 96000 > /d/tracing/buffer_size_kb |
| </pre> |
| </li> |
| <li>Enable tracing: |
| <pre class="devsite-terminal devsite-click-to-copy"> |
| echo 1 > /d/tracing/tracing_on |
| </pre> |
| </li> |
| <li>Run your test, then disable tracing: |
| <pre class="devsite-terminal devsite-click-to-copy"> |
| echo 0 > /d/tracing/tracing_on |
| </pre> |
| </li> |
| <li>Dump the trace: |
| <pre class="devsite-terminal devsite-click-to-copy"> |
| cat /d/tracing/trace > /data/local/tmp/trace_output |
| </pre> |
| </li> |
| </ol> |
| |
| <p>The trace_output gives the trace in text form. To visualize it using |
| Catapult, get the |
| <a href="https://github.com/catapult-project/catapult/tree/master/">Catapult |
| repository</a> from Github and run trace2html:</p> |
| |
| <pre class="devsite-terminal devsite-click-to-copy"> |
| catapult/tracing/bin/trace2html ~/path/to/trace_file |
| </pre> |
| |
| <p>By default, this writes <code>trace_file.html</code> in the same |
| directory.</p> |
| |
| <h2 id="correlate">Correlating events</h2> |
| <p>It is often useful to look at the Catapult visualization and the ftrace |
| log simultaneously; for example, some ftrace events (especially vendor-specific |
| ones) are not visualized by Catapult. However, Catapult's timestamps are |
| relative either to the first event in the trace or to a specific timestamp |
| dumped by atrace, while the raw ftrace timestamps are based on a particular |
| absolute clock source in the Linux kernel.</p> |
| |
| <p>To find a given ftrace event from a Catapult event:</p> |
| |
| <ol> |
| <li>Open the raw ftrace log. Traces in recent versions of systrace are |
| compressed by default: |
| <ul> |
| <li>If you captured your systrace with <code>--no-compress</code>, this is in |
| the html file in the section beginning with BEGIN TRACE.</li> |
| <li>If not, run html2trace from the |
| <a href="https://github.com/catapult-project/catapult/tree/master/">Catapult |
| tree</a> (<code>tracing/bin/html2trace</code>) to uncompress the trace.</li> |
| </ul> |
| </li> |
| <li>Find the relative timestamp in the Catapult visualization.</li> |
| |
| <li>Find a line at the beginning of the trace containing |
| <code>tracing_mark_sync</code>. It should look something like this: |
| <pre class="devsite-click-to-copy"> |
| <5134>-5134 (-----) [003] ...1 68.104349: tracing_mark_write: trace_event_clock_sync: parent_ts=68.104286 |
| </pre> |
| |
| <br>If this line does not exist (or if you used ftrace without atrace), then |
| timings will be relative from the first event in the ftrace log. |
| <ol style="list-style-type: lower-alpha"> |
| <li>Add the relative timestamp (in milliseconds) to the value in |
| <code>parent_ts</code> (in seconds).</li> |
| <li>Search for the new timestamp.</li> |
| </ol> |
| </li> |
| </ol> |
| <p>These steps should put you at (or at least very close to) the event.</p> |
| |
| <h2 id="dftrace">Using dynamic ftrace</h2> |
| <p>When systrace and standard ftrace are insufficient, there is one last |
| recourse available: <em>dynamic ftrace</em>. Dynamic ftrace involves rewriting |
| of kernel code after boot, and as a result it is not available in production |
| kernels for security reasons. However, every single difficult performance bug in |
| 2015 and 2016 was ultimately root-caused using dynamic ftrace. It is especially |
| powerful for debugging uninterruptible sleeps because you can get a stack trace |
| in the kernel every time you hit the function triggering uninterruptible sleep. |
| You can also debug sections with interrupts and preemptions disabled, which can |
| be very useful for proving issues.</p> |
| |
| <p>To turn on dynamic ftrace, edit your kernel's defconfig:</p> |
| |
| <ol> |
| <li>Remove CONFIG_STRICT_MEMORY_RWX (if it's present). If you're on 3.18 or |
| newer and arm64, it's not there.</li> |
| <li>Add the following: CONFIG_DYNAMIC_FTRACE=y, CONFIG_FUNCTION_TRACER=y, |
| CONFIG_IRQSOFF_TRACER=y, CONFIG_FUNCTION_PROFILER=y, and CONFIG_PREEMPT_TRACER=y |
| </li> |
| <li>Rebuild and boot the new kernel.</li> |
| <li>Run the following to check for available tracers: |
| <pre class="devsite-terminal devsite-click-to-copy"> |
| cat /d/tracing/available_tracers |
| </pre> |
| </li> |
| <li>Confirm the command returns <code>function</code>, <code>irqsoff</code>, |
| <code>preemptoff</code>, and <code>preemptirqsoff</code>.</li> |
| <li>Run the following to ensure dynamic ftrace is working: |
| <pre class="devsite-terminal devsite-click-to-copy"> |
| cat /d/tracing/available_filter_functions | grep <a function you care about> |
| </pre> |
| </li> |
| </ol> |
| |
| <p>After completing these steps, you have dynamic ftrace, the function profiler, |
| the irqsoff profiler, and the preemptoff profiler available. We <strong>strongly |
| recommend</strong> reading ftrace documentation on these topics before using |
| them as they are powerful but complex. irqsoff and preemptoff are primarily |
| useful for confirming that drivers may be leaving interrupts or preemption |
| turned off for too long.</p> |
| <p>The function profiler is the best option for performance issues and is often |
| used to find out where a function is being called.</p> |
| |
| <section class="expandable"> |
| <h4 class="showalways">Show Issue: HDR photo + rotating viewfinder</h4> |
| |
| <p>In this issue, using a Pixel XL to take an HDR+ photo then immediately |
| rotating the viewfinder caused jank every time. We used the function profiler to |
| debug the issue in less than one hour. To follow along with the example, |
| <a href="perf_traces.zip">download the zip file</a> of traces (which also |
| includes other traces referred to in this section), unzip the file, and open the |
| trace_30898724.html file in your browser.</p> |
| |
| <p>The trace shows several threads in the cameraserver process blocked in |
| uninterruptible sleep on <code>ion_client_destroy</code>. That's an expensive |
| function, but it should be called very infrequently because ion clients should |
| encompass many allocations. Initially, the blame fell on the Hexagon code in |
| Halide, which was indeed one of the culprits (it created a new client for every |
| ion allocation and destroyed that client when the allocation was freed, which |
| was way too expensive). Moving to a single ion client for all Hexagon |
| allocations improved the situation, but the jank wasn't fixed.</p> |
| <p>At this point we need to know who is calling <code>ion_client_destroy</code>, |
| so it's time to use the function profiler:</p> |
| <p></p> |
| <ol> |
| <li>As functions are sometimes renamed by the compiler, confirm |
| <code>ion_client_destroy</code> is there by using: |
| <pre class="devsite-terminal devsite-click-to-copy"> |
| cat /d/tracing/available_filter_functions | grep ion_client_destroy |
| </pre> |
| </li> |
| <li>After confirming it is there, use it as the ftrace filter: |
| <pre class="devsite-terminal devsite-click-to-copy"> |
| echo ion_client_destroy > /d/tracing/set_ftrace_filter |
| </pre> |
| </li> |
| <li>Turn on the function profiler: |
| <pre class="devsite-terminal devsite-click-to-copy"> |
| echo function > /d/tracing/current_tracer |
| </pre> |
| </li> |
| <li>Turn on stack traces whenever a filter function is called: |
| <pre class="devsite-terminal devsite-click-to-copy"> |
| echo func_stack_trace > /d/tracing/trace_options |
| </pre> |
| </li> |
| <li>Increase the buffer size: |
| <pre class="devsite-terminal devsite-click-to-copy"> |
| echo 64000 > /d/tracing/buffer_size_kb |
| </pre> |
| </li> |
| <li>Turn on tracing: |
| <pre class="devsite-terminal devsite-click-to-copy"> |
| echo 1 > /d/tracing/trace_on |
| </pre> |
| </li> |
| <li>Run the test and get the trace: |
| <pre class="devsite-terminal devsite-click-to-copy"> |
| cat /d/tracing/trace > /data/local/tmp/trace |
| </pre> |
| </li> |
| <li>View the trace to see lots and lots of stack traces: |
| <pre class="devsite-click-to-copy"> |
| cameraserver-643 [003] ...1 94.192991: ion_client_destroy <-ion_release |
| cameraserver-643 [003] ...1 94.192997: <stack trace> |
| => ftrace_ops_no_ops |
| => ftrace_graph_call |
| => ion_client_destroy |
| => ion_release |
| => __fput |
| => ____fput |
| => task_work_run |
| => do_notify_resume |
| => work_pending |
| </pre> |
| </li> |
| </ol> |
| |
| <p>Based on inspection of the ion driver, we can see that |
| <code>ion_client_destroy</code> is being spammed by a userspace function closing |
| an fd to <code>/dev/ion</code>, not a random kernel driver. By searching the |
| Android codebase for <code>\"/dev/ion\"</code>, we find several vendor drivers |
| doing the same thing as the Hexagon driver and opening/closing |
| <code>/dev/ion</code> (creating and destroying a new ion client) every time they |
| need a new ion allocation. Changing those to |
| <a href="https://android.googlesource.com/platform/hardware/qcom/camera/+/8f7984018b6643f430c229725a58d3c6bb04acab">use |
| a single ion client</a> for the lifetime of the process fixed the bug.</p> |
| </section> |
| <hr> |
| |
| <p>If the data from function profiler isn't specific enough, you can combine |
| ftrace tracepoints with the function profiler. ftrace events can be enabled in |
| exactly the same way as usual, and they will be interleaved with your trace. |
| This is great if there's an occasional long uninterruptible sleep in a specific |
| function you want to debug: set the ftrace filter to the function you want, |
| enable tracepoints, take a trace. You can parse the resulting trace with |
| <code>trace2html</code>, find the event you want, then get nearby stack traces |
| in the raw trace.</p> |
| |
| <h2 id="lock_stat">Using lockstat</h2> |
| <p>Sometimes, ftrace isn't enough and you really need to debug what appears to |
| be kernel lock contention. There is one more kernel option worth trying: |
| <code>CONFIG_LOCK_STAT</code>. This is a last resort as it is extremely |
| difficult to get working on Android devices because it inflates the size of the |
| kernel beyond what most devices can handle.</p> |
| <p>However, lockstat uses the debug |
| locking infrastructure, which is useful for many other applications. Everyone |
| working on device bringup should figure out some way to get that option working |
| on every device because there <strong>will</strong> be a time when you think |
| "If only I could turn on <code>LOCK_STAT</code>, I could confirm or refute this |
| as the problem in five minutes instead of five days."</p> |
| |
| <section class="expandable"> |
| <h4 class="showalways">Show Issue: Stall in SCHED_FIFO when cores at max load |
| with non-SCHED_FIFO</h4> |
| |
| <p>In this issue, the SCHED_FIFO thread stalled when all cores were at maximum |
| load with non-SCHED_FIFO threads. We had traces showing significant lock |
| contention on an fd in VR apps, but we couldn't easily identify the fd in use. |
| To follow along with the example, <a href="perf_traces.zip">download the zip |
| file</a> of traces (which also includes other traces referred to in this |
| section), unzip the file, and open the trace_30905547.html file in your browser. |
| </p> |
| |
| <p>We hypothesized that ftrace itself was the source of lock contention, when a |
| low priority thread would start writing to the ftrace pipe and then get |
| preempted before it could release the lock. This is a worst-case scenario that |
| was exacerbated by a mixture of extremely low-priority threads writing to the |
| ftrace marker along with some higher priority threads spinning on CPUs to |
| simulate a completely loaded device.</p> |
| <p>As we couldn't use ftrace to debug, we got <code>LOCK_STAT</code> working |
| then turned off all other tracing from the app. The results showed the lock |
| contention was actually from ftrace because none of the contention showed up in |
| the lock trace when ftrace was not running.</p> |
| </section> |
| <hr> |
| |
| <p>If you can boot a kernel with the config option, lock tracing is similar to |
| ftrace:</p> |
| <ol> |
| <li>Enable tracing: |
| <pre class="devsite-terminal devsite-click-to-copy"> |
| echo 1 > /proc/sys/kernel/lock_stat |
| </pre> |
| </li> |
| <li>Run your test.</li> |
| <li>Disable tracing: |
| <pre class="devsite-terminal devsite-click-to-copy"> |
| echo 0 > /proc/sys/kernel/lock_stat |
| </pre> |
| </li> |
| <li>Dump your trace: |
| <pre class="devsite-terminal devsite-click-to-copy"> |
| cat /proc/lock_stat > /data/local/tmp/lock_stat |
| </pre> |
| </li> |
| </ol> |
| |
| <p>For help interpreting the resulting output, refer to lockstat documentation |
| at <a href="https://www.kernel.org/doc/Documentation/locking/lockstat.txt"><code><kernel>/Documentation/locking/lockstat.txt</code></a>.</p> |
| |
| </body> |
| </html> |
