# Presentation: 417813

## TRACE

-  Stephen Foulkes     Ron Rechenmacher
- sfoulkes@fnal.gov        ron@fnal.gov

## Motivation

- Need a logging facility that:
- Extremely low overhead
- Can gather timing information
- Can log in different ways
- Open source / free ware
- Works well with multithreaded apps
- Works on VxWorks and Linux

- IEEE NPSS RT07 - CM Tools - 04

- May 3, 2007

**Notes:**
Talk about print() cout, etc and the problems with those.

## TRACE Overview

-  Originally developed at FNAL by R. Rechenmacher
-  Support for Linux on x86, x86_64 and PowerPC, VxWorks on PowerPC

- IEEE NPSS RT07 - CM Tools - 04

- May 3, 2007

**Notes:**
TRACE on linux allows logging of messages in kernel space and user space.  Messages go to the circular buffer, the default logging backend.  You can specify your own logging functions.  Give some examples on things you can do with the logging function, log to file, screen, relational database.

## TRACE on Linux

- Based inside the kernel
- Configuration, status information is exported through **/proc/trace**
- Binaries with TRACE run on systems without TRACE
- Only supports C/C++ applications

- IEEE NPSS RT07 - CM Tools - 04

- May 3, 2007

## The TRACE Circular Buffer

- Default logging backend in TRACE
- Contained in kernel space, in memory
- Thread safe, and can log messages from interrupt contexts
- Collects timing information
- One buffer contains all messages

- IEEE NPSS RT07 - CM Tools - 04

- May 3, 2007

**Notes:**
Make sure to explain what atmoic writes mean, and elaborate on how one buffer is shared between all tasks.

## TRACE Circular Buffer Example

** ****21051 uS MIBPMFlashTurnTask.hpp:process() Flash 8 triggered**
**238737 uS MIBPMControl.cpp:changeMode() Done changing to flash...**
**   ****738 uS MIBPMControl.cpp:changeMode() Enabling flash turn mode...**
**     ****9 uS MIBPMControl.cpp:changeMode() Changing mode FLASH...**
**     ****3 uS MIBPMControl.cpp:changeMode() Change mode starting...**
**548319 uS MIBPMFlashTurnTask.hpp:process() Flash 7 triggered**
** ****66702 uS MIBPMFlashTurnTask.hpp:process() Flash 6 triggered**
** ****66693 uS MIBPMFlashTurnTask.hpp:process() Flash 5 triggered**
** ****66711 uS MIBPMFlashTurnTask.hpp:process() Flash 4 triggered**
** ****66675 uS MIBPMFlashTurnTask.hpp:process() Flash 3 triggered**
** ****66708 uS MIBPMFlashTurnTask.hpp:process() Flash 2 triggered**
** ****66675 uS MIBPMFlashTurnTask.hpp:process() Flash 1 triggered**
** ****50799 uS MIBPMControl.cpp:changeMode() Done changing to flash...**
**   ****753 uS MIBPMControl.cpp:changeMode() Enabling flash turn mode...**

- IEEE NPSS RT07 - CM Tools - 04

- May 3, 2007

**Notes:**
Mention that timestamps are relative and that time flows from the bottom to the top.  Talk about how I instrumented the code, that I wanted to take deltas at one point and see the amount of time that elapsed for another.

## Generating TRACE Messages

- Define a TRACE name:
**#define TRACE_NAME “myApplication”**
- Include the TRACE header
- Add TRACE calls where appropriate:
**TRACE(****int**** ****level****, ****char**** *********fmt****, ****int**** ****param1****, ****int**** ****param2****, ****int**** ****param3**** ...);**
- Level is used to group messages
- Can use **%d, %x, %c** as conversion specifiers
- Only supports integer types (int, long, etc)
- Maximum of six parameters

- IEEE NPSS RT07 - CM Tools - 04

- May 3, 2007

**Notes:**
Talk more about the TRACE header, and what it gives me.

## Reading The Circular Buffer

- Contents of the circular buffer are accessed through **/proc/trace/buffer**
- The columns displayed are controllable through **/proc/trace/control**
- Available columns include time stamp, pid, level, cycle, TRACE name, message, count
**echo print=timeStamp,PID,lvl,message \**
**             ****> /proc/trace/control            **

- IEEE NPSS RT07 - CM Tools - 04

- May 3, 2007

**Notes:**
Mention that you can see the available heading by catting /proc/trace/control

## Filtering Messages

- All filtering is controlled through **/proc/trace/level**:
**         ****KERNEL=0x00000000,0x00000000,0x00000000,0x00000000**
**   ****realtimedemo=0xffffffff,0x0000000f,0x00000000,0x00000000**
**      ****NULL_NAME=0xffffffff,0x00000000,0x00000000,0xffffffff   **
**           ****FULL=0xffffffff,0x00000000,0x00000000,0xffffffff**
- Configurable from the command line:
**echo KERNEL=0xf,0xf,0x0,0x0 \ **
**       ****> /proc/trace/level**

- IEEE NPSS RT07 - CM Tools - 04

- May 3, 2007

**Notes:**
Talk about how you would filter messages only from your applications, and that the filters work on messages going into the buffer.  They do not work pulling messages out of the buffer.  Refer to the beginning where I introduce the multiple backends.

## Miscellaneous Tasks

- Clearing the circular buffer:
**echo reset > /proc/trace/control**
- Enabling/Disabling Logging Backends
- Mode is a bitmask that enables/disables the backends
**echo mode=0x3 > /proc/trace/control**
**Turn TRACE completely off:**
**echo mode=0x0 > /proc/trace/control**

- IEEE NPSS RT07 - CM Tools - 04

- May 3, 2007

## Installing TRACE

- If your architecture is already supported, this is easy:
- Download and unpack the TRACE tarball
- ftp://ftp.fnal.gov/pub/trace/current
- make install
- The installer will try to guess the location of your kernel sources and version, and will apply the correct set of patches
- Rebuild your kernel and reboot

- IEEE NPSS RT07 - CM Tools - 04

- May 3, 2007

## A successful TRACE installation

- CPU 0 irqstacks, hard=c03f5000 soft=c03d5000
- PID hash table entries: 4096 (order: 12, 65536 bytes)
- Detected 1600.001 MHz processor.
- Using pmtmr for high-res timesource
**trace_init****: allocated 4096(0x1000) bytes for ...**
**trace_init****: allocated 4096(0x1000) bytes for sp ...**
**trace_init****: traceLevel_ip=c191e010**
**trace_init****: attempting to allocate 8392704(0x801000)**
**trace****: cpu0 just set AMD PMC0 to 0x400003**
**trace****: cpu0 just set AMD PMC1 to 0x400004**
- Console: colour VGA+ 80x25
- Dentry cache hash table entries: 131072 (order: 7, 524288 bytes)
- Memory: 1024868k/1048064k available (1897k kernel code, 22316k reserved, 767k data, 184k init, 130496k highmem)

- IEEE NPSS RT07 - CM Tools - 04

- May 3, 2007

**Notes:**
This is what you would see on the console as the system boots.

## Configuring The Circular Buffer

- Configuration is done at compile time
- Can change:
- The max number of applications that can log to TRACE
- The max number of logging backends
- The max message size
- The max number of parameters to a message
- All contained in **src/init/trace.c**

- IEEE NPSS RT07 - CM Tools - 04

- May 3, 2007

**Notes:**
Reference that there are other things that can be changed...

## TRACE Example

- Define a function to log to the console with **printf()**
- Generate two TRACE messages, one with parameters and one without
- Should see both messages on the console, and in the circular buffer

- IEEE NPSS RT07 - CM Tools - 04

- May 3, 2007

## TRACE Example

**#****include**** <****stdio.h****>**
**#****include**** <****sys/time.h****>**
**#****include**** <****stdarg.h****>**
**// Define my logging function, log to the console**
**void**** ****steves_logger****(****struct**** ****timeval**** *****time****, ****int**** ****lvl****, ****int**** ****id****, ****char**** *****fmt****, ...) {**
**	****va_list ****ap****;**
**	****va_start( ****ap****, ****msg**** );**
**	****vprintf( ****msg****, ****ap**** );**
**	****va_end( ****ap**** );**
**}**

- IEEE NPSS RT07 - CM Tools - 04

- May 3, 2007

**Notes:**
Say that TRACE passes in the time, level and id.  I chose not to use these, and just print out all messages to the console.

## TRACE Example

**#****define**** ****TRACE_NAME**** “****realtimedemo****”**
**#****define**** ****TRACE_FUNCTIONS**** {****steves_logger****}**
**#****include**** <****linux/trace.h****>**
**int**** ****main****() {**
**	****int**** ****one**** = 1; ****int**** ****eleven**** = 11;**
**	****TRACE(0, “****Hello World!****”);**
**	****TRACE(5, “****With parameters: %d %x****”, ****one****, ****eleven****);**
**	****return 0;**
**}**

- IEEE NPSS RT07 - CM Tools - 04

- May 3, 2007

## TRACE Example

**[~]$ gcc -I/usr/src/linux/include -Wall test.c**
**[~]$ ./a.out**
**Hello World!**
**With parameters: 1 b**
**[~]$ cat /proc/trace/buffer**
**timeStamp    PID    lvl Name         Message**
**--------------------------------------------------**
**117757564    8259   5   realtimedemo With Parameters: 1 b**
**117751573    8259   0   realtimedemo Hello World!**
**[~]$**

- IEEE NPSS RT07 - CM Tools - 04

- May 3, 2007

**Notes:**
Be more explicit about what looking in the TRACE buffer means.

## Summary

- Open source logging facility that runs on VxWorks and Linux
- Low overhead
- Multiple backends
- Easy filtering of messages
- TRACE Website:
- http://fermitools.fnal.gov/abstracts/trace/abstract.html

- IEEE NPSS RT07 - CM Tools - 04

- May 3, 2007