From a905aa78240da26c2b03c1781a975399398ab2b5 Mon Sep 17 00:00:00 2001 From: Bjoern Brandenburg Date: Tue, 9 Dec 2008 23:06:27 +0100 Subject: provide documentation for tracing with LITMUS^RT --- doc/tracing.html | 149 ++++++++++++++++++++++++++++++++++++++++++++++--------- doc/tracing.text | 146 +++++++++++++++++++++++++++++++++++++++++++---------- 2 files changed, 246 insertions(+), 49 deletions(-) (limited to 'doc') diff --git a/doc/tracing.html b/doc/tracing.html index ba5b4e3..5d40ab7 100644 --- a/doc/tracing.html +++ b/doc/tracing.html @@ -8,14 +8,13 @@ Tracing with LITMUS^RT - + Note: PLEASE UPDATE THE CHANGE HISTORY AT THE END OF THE FILE WHEN YOU + UPDATE THIS FILE. -

Tracing with LITMUSRT

-This document is part of the documentation of the LITMUSRT project.
-Written by Bjoern B. Brandenburg (bbb at cs.unc.edu) on 12/09/2008. +This document is part of the documentation of the LITMUSRT project.

As of version 2008.2, there are three tracing mechanisms available in LITMUSRT:

@@ -44,13 +43,13 @@ Written by Bjoern B. Brandenburg (bbb at cs.unc.edu) on 12/09/2008.

  • litmus_log: This trace contains text messages (created with the TRACE() macro, see litmus.h) that convey information useful for debugging. There is one global litmus_log buffer for the whole system. Debug tracing must be enabled at compile time. Note that debug tracing creates significant overhead because string formatting takes place.

    • -

  • ft_trace: This trace contains binary-encoded time stamps. It is used for overhead tracing. There is one ft_trace buffer per processor. The "ft" stands for Feather-Trace. Feather-Trace is designed to create only negligible overhead when event sources are disabled, and to incur only low overhead when recording time stamps.

    • +

  • ft_trace: This trace contains binary-encoded time stamps. It is used for overhead tracing. There is one global ft_trace buffer for the whole system. The "ft" stands for Feather-Trace. Feather-Trace is designed to create only negligible overhead when event sources are disabled, and to incur only low overhead when recording time stamps.

  • sched_trace: This trace contains binary-encoded scheduling event information, e.g., an event can be recorded whenever a task got scheduled, a job was released, a job completed, etc. There is one sched_trace buffer per processor. sched_trace is also based on Feather-Trace and hence incurs only neglible overhead when event sources are disabled.

    • Accessing Trace Buffers

    -

    Currently, all three traces are exported to user space through character device drivers. You can discover the major numbers allocated by the drivers by looking at /proc/devices. Usually, the major numbers are 251, 252, and 253 respectively.

    +

    Currently, all three traces are exported to user space through character device drivers. The major numbers allocated by the drivers can be discovered by looking at /proc/devices. Usually, the major numbers are 251, 252, and 253 respectively.

    The per-processor buffers are accessible via the minor numbers of the drivers. Hence, proper device files can be created with the following script.

    @@ -60,17 +59,18 @@ LITMUS_LOG_MAJOR=`grep litmus_log /proc/devices | awk '{print $1}'` FT_TRACE_MAJOR=`grep ft_trace /proc/devices | awk '{print $1}'` SCHED_TRACE_MAJOR=`grep sched_trace /proc/devices | awk '{print $1}'` +mknod litmus_log c $LITMUS_LOG_MAJOR 0 +mknod ft_trace c $FT_TRACE_MAJOR 0 + NUM_PROCS=$((`grep 'processor' /proc/cpuinfo | wc -l` - 1)) -mknod litmus_log c $LITMUS_LOG_MAJOR 0 for P in `seq 0 $NUM_PROCS` do - mknod "ft_trace$P" c $FT_TRACE_MAJOR $P mknod "sched_trace$P" c $SCHED_TRACE_MAJOR $P done -

    Alternatively, you can setup udev rules to create the devices on demand. This, however, is beyond the scope of this document.

    +

    Alternatively, one can setup udev rules to create the devices on demand. This, however, is beyond the scope of this document.

    Recording Debug Traces

    @@ -79,25 +79,128 @@ done 
    cat litmus_log > my_debug_log
    -

    Kill the cat process to stop recording debug messages. No post-processing is required since the debug messages are plain text.

    +

    Kill the cat process to stop recording debug messages.

    + +

    No post-processing is required since the debug messages are plain text. However, note that messages may appear in a different order than how they occured at runtime. If order is important (for example when debugging race conditions), then recorded messages can be sorted offline with the help of the sequence number at the start of each recorded message.
    +Example:

    + +
    sort -n my_debug_log > my_sorted_debug_log
+
    + +

    Hint: One can use netcat(1) to send the debug messages to another machine via UDP to avoid filesystem activity.

    + +

    Recording Overhead Traces

    -

    Hint: You can use netcat to send the debug messages to another machine via UDP to avoid filesystem activity.

    +

    Feather-Trace allows for much more fine-grained tracing than the simple debug stream realized by litmus_log and hence requires special-purpose tools to be used. These tools are available as part of the ft_tools package, which is available on the LITMUSRT download page.

    -

    Recording Overhead Traces

    +

    Feather-Trace events can be enabled on a per-event basis. Each event is identified by a unique 32-bit ID. Intially, when the device buffer is not being accessed by any user space programs (i.e., when the device driver is unused), all events are disabled. Events can be enabled (and subsequently disabled again) by writing binary commands to the buffer device file. Once events are enabled they can generate trace records, which are stored in the trace buffer. Userspace programs can obtain these records by reading from the device file. Reading a trace record removes it from the buffer, i.e., each record can be read exactly once. Since buffer capacity is limited records should be consumed shortly after they were created.

    -

    to be written

    +

    The tool ftcat, which is part of the ft_tools package (see above), automates the process of enabling events and retrieving trace records. It takes the name of the ft_trace device file and the events of interest as arguments:

    + +
    ftcat <ft device> <event 1> <event 2> <event 3> ...
+
    + +

    The tool enables the specified events and copies all recorded events to stdout.

    + +

    Events can be specified either by their ID (see include/litmus/trace.h in the kernel directory for a list of timestamp-generating events) or by their symbolic name. The following symbolic names are recognized:

    + + + +

    For example, the following command can be used to store the length of context switches and scheduling decisions in the file my_trace.

    + +
    $ ftcat ft_trace CXS_START CXS_END SCHED_START SCHED_END SCHED2_START SCHED2_END > my_trace
+
    + +

    The tracing can be stopped by interrupting ftcat with ^C or by sending SIGTERM with kill(1).

    + +

    Note that the recorded trace is stored in the byte order of the host.

    Post-Processing Overhead Traces

    -

    to be written

    +

    The binary event stream recorded by ftcat is of course of limited direct use—the data has yet to be exported for analysis. This can be achieved with the tool ft2csv, which is also part of the ft_tools package.

    + +

    As the name suggests, ft2csv extracts intervals defined by pairs of timestamps in a recorded trace and displayse them as comma-separated values (CSV). It takes the name of an overhead trace and one start event as arguments:

    + +
    ft2csv <start event> <overhead trace>
+
    + +

    Events are specified in the same way as with ftcat. For example, the following command can be used to print the context-switch lengths that were recorded in the example above to stdout.

    + +
    $ ft2csv CXS_START my_trace
+2397634444579592, 2397634444583328, 3736
+2397634477323130, 2397634477326686, 3556
+2397634477346366, 2397634477348986, 2620
+2397634611910924, 2397634611914348, 3424
+...
+
    + +

    For each event, the start time (in clock cycles) is given in the first column, the end time is given in the second column, and the length is given in the third column (again, in cycles).

    + +

    ft2csv accepts a few options that affect how events are filtered. By default, events that do not involve real-time tasks are ignored. This can be changed by specifiying the -b option. If one happens to be processing output on a little-endian host that was produced on a big-endian host then the -e option can come in handy.

    -

    Recording Scheduling Traces

    +

    Once the recorded overheads have been exported to CSV files they can be easily analyzed with tools such as Python, Octave, or Matlab.

    -

    to be written

    +

    Recording and Post-Processing Scheduling Traces

    + +

    Scheduling traces are also recorded using Feather-Trace. However, a different binary format is being used. The definition and an explanation of the format can be found in the file include/litmus/sched_trace.h (in the kernel directory).

    + +

    Since sched_trace uses per-processor buffers several ftcat instances have to be launched. The ft_tools package includes a wrapper script called st_trace that automates this setup procedure. Note that one may have to modify st_trace to change the default location of the sched_trace device files. st_trace accepts a tag as the only argument. The tag is used to assign a unique name to the trace files.

    + +

    The following example illustrates how a st_trace is used with the tag global-exp.

    + +
    $ st_trace global-exp
+CPU 0: 8204 > st-global-exp-0.bin [0]
+CPU 1: 8205 > st-global-exp-1.bin [0]
+CPU 2: 8206 > st-global-exp-2.bin [0]
+CPU 3: 8207 > st-global-exp-3.bin [0]
+Press Enter to end tracing... # enter pressed
+
+Disabling 9 events.
+Disabling 9 events.
+Disabling 9 events.
+Disabling 9 events.
+/home/litmus/log0: 1234 bytes read.
+/home/litmus/log1: 1234 bytes read.
+/home/litmus/log2: 1234 bytes read.
+/home/litmus/log3: 1234 bytes read.
+
    + +

    Note that st_trace may have to modified to change the default sched_trace device locations.

    + +

    Hint: To study/test the behavior of a scheduler plugin the dummy real-time task rtspin (distributed as part of the liblitmus package) may be useful.

    Post-Processing Overhead Traces

    -

    to be written

    +

    The user space library and tools package liblitmus contains the necessary headers to write sched_trace post-processing and analysis tools (see include/sched_trace.h and src/sched_trace.c).

    + +

    The tool showst (distributed as part of liblitmus) can be used to inspect the binary traces recorded with st_trace and may provide a good starting point for the development of custom analysis tools.

    + +

    Concluding Remarks

    + +

    At this point we only offer data acquisition tools since we have not yet had the time to develop release-quality analysis tools. Patches to improve the acquisition tools and contributions of analysis and visualization tools are very much welcome!

    + +

    For any questions please contact the current LITMUSRT maintainer (as indicated on the LITMUSRT homepage).

    + +

    Change History

    + +