ELC2009 – Measuring Function Call Duration with Ftrace

Speaker

  Tim Bird

Links

  http://www.celinuxforum.org/CelfPubWiki/ELCEurope2009Presentations
  http://lwn.net/Articles/291091/

Introduction

Tim’s talk was presented on Thursday 15th October 2009 to a crowd of about 80 attendees. In it he talked about Ftrace, the first generic function call tracing system to be included in the mainline kernel tree. This talk contributed to the general theme of improving boot times and generally improving system performance.

Main points

• Ftrace is a ‘mainlined’ method of measuring function call duration.
• Tracing can add huge amount of overhead (500% or more) so timing measurements are not accurate, only relative ones.
• Much work is to be done to support some architectures peculiarities.

Background

Ftrace is the first generic function call tracing system to be added to the main Linux kernel. It was added to 2.6.27 and was derived from the real-time pre-empt latency tracer.

Tracing with Ftrace

There are two way to trace, explicitly or implicitly. Tracing explicitly requires the programmer to add calls to the trace handler in the source code at points they are interested in. This is fine if one is trying to trace only a small subset of functions, but to do this on a large scale is impractical. That’s where the implicit method works well.

gcc can automatically insert calls the the trace handler at the start of each function. The trace handler is called mcount.

mcount is called by the kernel every function (except for inlines and some other special functions) and has to be very low overhead as to interrupt the running system as little as possible. Although there are a few incompatibility problems with architecture specific peculiarities it works well as a relative time measuring tool.

Working with Ftrace

Ftrace can be interacted with through ‘pseudo’ files in a debugfs mounted usually on /debug. You can select which tracer to use (function_graph, function_duration, function, sched_switch, nop) by echoing a the tracer name to current_tracer within the debugfs. Similary tracing parameters can be set such as tracing_threshold and trace_options.

Ftrace uses a ring buffer to collect its trace data. This is a special buffer arranged as a list of pages. The buffer is lockless for writing, has automatic time stamp management and avoids multi-cpu issues. Tim was a little hesitant to answer a question from the audience about how Ftrace copes with recurrence and timings although he vowed to go away and check it.

What Ftrace produces is a human readable text output that can be read with common text manipulation tools.

Duration testing with Ftrace

Ftrace extends the normal gcc -pg tracing mechanism by tracking not just function entry, but function exit too. This can be used to measure the time in any given function. To do this Ftrace uses a ‘trampoline’ which saves the real return address of a function and replaces this with the address of the trampoline. The trampoline can then record the necessary information before using the real saved return address to continue.

Ftrace also allows filtering of its data. This is necessary due to the huge amounts of data being recorded but also provides a mechanism to look at on the data resolution your interested in.

A design decision was made to off load any time consuming, resource heavy of
potentially blocking task to a separate component so as to not block the UI.

Tim then went on to show examples timings using Ftrace with various options to demonstrate its versatility. He also demonstrated how Ftrace could be used to look at the boot sequence to potential optimise the kernel for faster boots.

Tim did point out that the trace itself does come with a overhead itself, from 12% to 500% depending on the options used.

The Future for Ftrace

Ftrace is already mainlined and used by many individuals but it Tim is looking to improve it. He plans to add ARM function graph assembly support, a function_duration tracer and boot time support extensions. He has already used Ftrace to highlight problems with the functions call_usermode_helper and ip_auto_config which slow down boot time.