This article aims at equipping users with the knowledge required to write effective trace format entries. We will look at elements of the trace format entry, covering each of them with examples and situations where they can be handy. There is an example at the end of the article to give you a sense of how these pieces of a puzzle fit together.

Share:

Prateek Goel (pragoel1@in.ibm.com), Staff Software Engineer, IBM

photo of Prateek GoelPrateek has been working with the IBM AIX® reliability, availability, and serviceability (RAS) features development team. He has written articles on ProbeVue in IBM developerWorks® and IBM Systems Magazine forums.



03 October 2013

Also available in Chinese

Introduction

Tracing is one of the most commonly used technologies for debugging issues. It equips users with the information of the activities happened before reaching the problem state. To achieve this, developers might need to place trace hooks into the code. It is these hooks that log the required data whenever you run the code path containing these hooks. The data logged with these trace hooks is in the binary format, and this is then formatted using user-defined specifications and presented for analysis. This type of tracing is known as static tracing as the trace points and trace data is fixed. There are two classifications of static tracing namely, system tracing and component tracing. In system tracing, we use a common global kernel buffer to save the traces. However, in component tracing, it is the components buffer where we save traces coming from that specific component. Component tracing provides granular flexibility to control the trace behavior of components individually as required. There is a trace report generation utility which transforms the raw data received from trace points into a human readable format using entries specified in the trace format file.

The focus of this article revolves around trace format entry, covering points such as syntax, various constructs, and so on. We conclude with an example covering frequently used constructs.

Hook identifier

To uniquely identify every trace point and its data, an identifier is associated with it. With the help of these identifiers, the trace report generation utility looks up for the trace format entry in the trace format file. To overcome the challenge of managing high number of unique identifiers, the concept of subhook identifiers was brought it. Each component can be assigned a parent hook identifier, which is unique across all components. This hook identifier can be appended with a few bits of subhook identifiers, which are internal to the component and can be used freely at the component level.

Application programming interfaces (APIs) for tracing

There are various APIs defined for developers to consume for writing trace data for their code. Non-generic type tracing APIs have fixed-length data to be written, ranging from 0 to 5 data words, where each data word is of 8 or 16 bytes in a 32- or 64-bit environment. Generic type tracing APIs enable users to trace variable-length data. Refer to the Resources section for more information about system tracing APIs.

Structure of a trace entry

The structure of a trace entry includes the following parts.

  • Starting part: Hookword (consists of hook ID, flags, subhook ID)
  • Trailing part: Thread ID, timestamp (optional processor ID as well in case of 64 bit only)
  • Middle part: 0 to 5 words of data called data words and these data words are symbolically represented as D1, D2 D3, D4 and D5

Example of a non-generic tracing structure:

Hookword | [ D1|D2|D3|D4|D5 ] | Thread ID|Timestamp

Example of a generic tracing structure:

Hookword| D1 | Variable_length_data | Thread ID | Timestamp

A sample C program:

#include <sys/types.h>
#include <sys/trchkid.h>
#include <stdio.h>

#define HKWD_CUSTOM 0x01000000
main()
{
int *i;
i=malloc(sizeof(int)*10);
/* logs a trace entry with 3 datawords passed as argument after HKWD_CUSTOM */
TRCHKL3(HKWD_CUSTOM,sizeof(int),i,10);
}

Compiling the above program:

/usr/vac/bin/cc -q64 -g myc.c -l rts

Running the above program:

trace -aj 010 ; ./a.out ; trcstop

trcrpt output:

ID	ELAPSED_SEC	DELTA_MSEC	APPL    SYSCALL KERNEL  INTERRUPT
010	0.005312869	5.312869	UNDEFINED TRACE ID idx 0x1fc28
					traceid 0100 hookword  8000002801000000 type 8000
					hookdata 0000 0000000000000004 
					00000001100008D0 000000000000000A

Traced data is printed in a hexadecimal format and apart from hookword , type, and hookdata, it is difficult to recognize which hexadecimal word represents what. This form of data is difficult to analyze as you need to know what these data words correspond to and remember that for every trace entry in consideration. To ease this, trace infrastructure provides a facility for users to define their own trace format entries. For example, if the above output is presented in the following format, it would be easily consumable.

ID	ELAPSED_SEC	DELTA_MSEC	APPL    SYSCALL KERNEL  INTERRUPT
010	0.005312869	5.312869	Single Unit:0004 Address:1100008D0 Count:000A

To provide the subhook ID, users can append the subhook ID to the hook ID using the logical OR ("|") operation as show in the following example:

#define FIRST_SUBHOOK 0x01
TRCHKL3(HKWD_CUSTOM | FIRST_SUBHOOK,sizeof(int),i,10);

Building blocks of a trace format entry

Macros

Macros are similar to #define statements in a C program, where a task is defined to these macros and are called where ever required. The trace format infrastructure provides certain predefined macros to perform some basic task with trace entries. Some of the commonly used ones are discussed in this section.

  • $DATAPOINTER: Contains the offset from the start of the trace entry to the current position. Value can range between 0 to the length of the trace entry.
  • $BASEPOINTER: Points to the start of the trace entry, usually 0.
  • $HOOKENV: Denotes if it is coming from a 32- or 64-bit environment. Value: 32 or 64.
  • $D1-$D5: Provides value of the data words of trace entry from 1 to 5.
  • $GENERIC: Denotes if the trace entry is logged using generic type trace API.
Table 1. Interpretation of the value of the $GENERIC macro
ValueMeaning
0Non-generic type trace API
1Generic type trace API
  • $HD: Gives the subhook ID information. The exception in case of 32-bit generic tracing is that HD points to length of the generic data traced.
  • $HL: Points to the length in bytes of hook data. In generic tracing it points to the length of the generic data traced.
Table 2. Non-generic trace entries
32 bit64 bit
DATAPOINTER (initial value)26
First data word ( D1 ) starts at an offset of48
Table 3. Generic trace entries
32 bit64 bit
DATAPOINTER (initial value)46
First data word (D1) starts at an offset of48
Variable data starts at an offset of816

Note: Macros are useful in accessing the well-defined aspects of trace entry logged. To manipulate the data within the data logged as part of trace entry, we use format codes, which are discussed in the following section.

Format Codes

Format codes are used to fetch a part of the data word pointed by DATAPOINTER or data returned by any of the Macros seen above. Following table lists some of the commonly used formatting codes.

Table 4. Indentation formats
FormatExplanation
L=APPLMoves the left margin to the first column
L=SVCMoves the left margin to the second column
L=KERNMoves the left margin to the third column
L=INTMoves the left margin to the fourth column

Example:

With the help of these alignments, users can easily identify if the trace entry has come from an application, system call, kernel service routines, or interrupt. In the following code, tags such as APPL, SYSCALL, and so on are accompanied with the column number to which they belong.

ID    ELAPSED_SEC    DELTA_MSEC   APPL(1st)    SYSCALL(2nd) KERNEL(3rd)  INTERRUPT(4rth)
Table 5. Codes that manipulate DATAPOINTER
FormatExplanation
Gm.nSets the DATAPOINTER macro to “m” bytes and after that “n” bit location in trace entry.
Om.nAdvances the DATAPOINTER macro by “m” bytes and after that “.n” bits amount in trace entry.
RmDecrements the DATAPOINTER macro by “m” bytes in the trace entry.
WmPositions the DATAPOINTER at word m. The word size is either 4 or 8 bytes, depending on whether this is a 32- or 64-bit format trace.

Example:

G8: This is equivalent to {{ DATAPOINTER = 8 }} (which means go to the 8th byte in the trace entry.)

The following table contains some of the commonly used format codes. For a complete list, refer to the Resources section.

Table 6. Codes that result in data output
FormatExplanation
Am.nLeft justified ASCII, where m = length in bytes and n = width of the displayed field
Bm.nOutput in binary format, where m = length in bytes and n is bits after m bytes to be displayed
XmHexadecimal format output of “m” bytes where “m” can take a value between 0 and 16
DmSigned decimal format output, “m” is the number of bytes to be displayed
UmUnsigned decimal format output, “m” is the number of bytes to be displayed
OmOctal format output, “m” is the number of bytes to be displayed.
F4Floating point format output (similar to %0.4E, data length = 4)
F8Floating point format output (similar to %0.8E, data length = 8)
HBNumber of bytes in the trcgen() variable length buffer.
HT32-bit hooks:
The hooktype (0 - E)
trcgen = 0, trchk = 1, trchl = 2, trchkg = 6 trcgent = 8, trchkt = 9, trchlt = A, trchkgt = E
HT & 0x07 masks off the timestamp bit
64-bit hooks
0x8000 - Hook is time stamped.
0x4000 - This is a generic trace.

Example:

  • $HD%D1: Fetch 1 byte of data returned by the $HD macro and present in the decimal format. DATAPOINTER remains unchanged as the data comes from the macro.
  • D1: Fetch 1 byte of data returned from location pointed by DATAPOINTER in the decimal format. DATAPOINTER is incremented by 1 byte.

SWITCH statement

Syntax:

Format_code ,
Matchvalue1 { descriptor },
Matchvalue2 { descriptor2 },
\* { default_descriptor }

A format code followed by a comma is a SWITCH statement. Each CASE entry of the SWITCH statement consists of:

  • A 'matchvalue' with a type (usually numeric) corresponding to the format code
  • A simple 'string' or a new 'descriptor' bounded by braces. A descriptor is a sequence of format codes, strings, switches, and loops
  • A comma delimiter

The switch is terminated by a CASE entry without a comma delimiter. The CASE entry selected is the first entry whose matchvalue is equal to the expansion of the format code. The special matchvalue '\*' is a wildcard character and matches anything. The DATAPOINTER is advanced by the format code.

Note: Used in taking an appropriate action based on factors such as subhook ID, if data is logged from the generic type trace API, and so on.

LOOP statement

Syntax:

 LOOP format_code { descriptor }

The descriptor is run N times, where N is the numeric value of the format code. The DATAPOINTER is advanced by the format code plus whatever the descriptor does. Loops are used to output binary buffers of data, so descriptor is usually X1 or X0. Note that X0 is similar to X1 but does not supply a space separator ' ' between each byte. Similar is the case with A0 and A1. If, format codes are used with macros, then change in DATAPOINTER is dictated by the descriptor only. Refer to the example in the Macros section for more details.

Note: Loops are useful when the length of the variable data is not static and is written as a part of data from trace entry.

Custom macros

Macros are temporary (for the duration of that event) variables that work similar to shell variables.

Syntax:

   {{ $xxx = EXPR }}
EXPR is a combination of format codes, macros, and constants.
   Allowed operators are + - / *
   For example:
{{ $dog = 7 + 6 }} {{ $cat = $dog * 2 }} $dog $cat
   will output:
000D 001A

Note: Macros are also useful in loops where the loop count is not always just before the data.

G1.5 {{ $count = B0.5 }} G11 LOOP $count {X0}

Here, we fetch count from the 5th bit onwards after the 1st byte, and the real data starts from the 11th byte. In such cases, using macros eases the writing of the trace format entry.

Template subroutines

If a macro name consists of 3 or 4 hex digits, it is a template subroutine. The template whose trace ID equals the macro name is inserted in place of the macro. The data pointer is where it was when the template substitution was encountered. Any change made to the data pointer by the template subroutine remains in effect when the template ends. Macros used within the template subroutine correspond to those in the calling template. The first definition of a macro in the called template is the same variable as the first in the called template. The names are not related.

Note: Nesting of template subroutines is supported up to 10 levels. There is a slight difference between a macro and template subroutines. Both are meant to serve the same purpose of avoiding rewriting the same format. However, they differ in the area where template subroutines might be a trace entry formatter for a defined hook identifier but macros are not.

BITFLAGS

Syntax:

BITFLAGS [format_code|register],
flag_value string {optional string if false},   

--- or  ----

'&' mask field_value string

This statement simplifies expanding state flag as it looks a lot similar to a series of #define statements. The '&' mask is used for interpreting bit fields. The result of the '&' operation between the register and mask value is compared to field_value. If the field_value matches one of the options provided, the corresponding string is printed. The base is 16 for flag_value and masks, and the DATAPOINTER is advanced if a format code is used.

Now, consider an example where you need to print the permissions of a file. To do so you need to check its permissions. If the file has read permissions alone, the output would be r--.

In the following sample code, if the value of $omode%o4 is 00400 then r is printed, else - is printed. A similar action is taken for 0020

BITFLAGS $omode%o4, \
00400 "r" "-" \
00200 "w" "-" \

Cases where we have to either display or not display anything:

BITFLAGS $omode%o4, \
& 012 040   "I"
& 012 020   "B"
& 012 080   "M"

Here, after masking 012 with the $omode%o4 value, if the value is 040, I is printed. If the value is 020, B is printed. If the value is 080, M is printed.

Syntax of the trace format entry

Having looked at the building blocks of the trace format entry, now let us put all the small pieces together and attempt to write a complete trace format entry.

HOOK_ID version L=APPL/SYS/KERN "name" \
Macro%Format code,\
Matchvalue1 {,\
	Format code,\
	Matchvalue1a { Action },\
	Matchvalue1b { Action }\
      },\
Matchvalue2 {,\
	Macro%Format code,\
	Matchvalue2a { Action },\
	Matchvalue2b { Action }\
       }
Action could be any combination of building blocks that we have looked at.

Example

The following C program logs trace entry with TRCHKL4 and TRCGEN defined macros:

#include <sys/types.h>
#include <sys/trchkid.h>
#include <stdio.h>

#define HKWD_CUSTOM 0x01000000
main()
{
char s[]="malloc";
char s1[]="successful malloc";
int *i;
int j=5;
int k=20;
i=malloc(sizeof(int)*10);
/* 
  * please note the way string is 
  * passed as one of the datawords in non-generic trace API  
  */
TRCHKL4(HKWD_CUSTOM,*(unsigned long *)s,i,sizeof(int),10);
TRCGEN(0,HKWD_CUSTOM|0x20,strlen(s1),strlen(s1),(char *)s1);
i[5]=20;
TRCHKL3(HKWD_CUSTOM+0x1,i+j,j,k);
}

Compiling the above C program:

cc -q64 -g myc.c -l rts

Running (to capture entries coming from hook ID 010 only):

trace -aj 010 ; ./a.out ; trcstop

Trace entry format for "MyCustomHook":

#cat mytrace
##########################
# Check if, the entry is GENERIC
# If, not then check for subhook ID using $HD%D1
#	 if, Subhookid is 0 datawords using Macros
# 	if, subhookid is 1 print simple datawords
# 	if, none matched print Undefined Hook and subhook id
#if, the entry is GENERIC print ASCII string using LOOP construct
#	where the length of the String is in Dataword1 
#           HL macro can also be used to access the length as shown below
###########################

010 1.0 L=APPL "MyCustomHook" \
$GENERIC,\
0 {\
    $HD%D1,\
        0 { "Activity="G8 A10 \ 
		"Address=0x"$D2 {{ $total_size = $D3 * $D4 }} \
		"Size="$total_size%D4 },\
        1 { "Address=0x"$D1 "Array Index="$D2%D4 "Value="$D3%D4 },\
        \* {"Undefined Hook with subhook id = "$HD%D1 }\
    },\
1 { "String Length=" $D1%D4 {{ $loopcnt = $HL }} G16 LOOP $loopcnt {A0} }

Viewing the trace entry with our custom trace entry format:

#trcrpt -t mytrace
ID    ELAPSED_SEC    DELTA_MSEC   APPL    SYSCALL KERNEL  INTERRUPT

010   0.003872577    3.872577   MyCustomHook Activity=malloc Address=0x110000970 Size=40
010   0.003874101    0.001524   MyCustomHook String Length=17 successful malloc
010   0.003874956    0.000855   MyCustomHook Address=0x110000984 Array Index=5 Value=20

Resources

Learn

Get products and technologies

Discuss

Comments

developerWorks: Sign in

Required fields are indicated with an asterisk (*).


Need an IBM ID?
Forgot your IBM ID?


Forgot your password?
Change your password

By clicking Submit, you agree to the developerWorks terms of use.

 


The first time you sign into developerWorks, a profile is created for you. Information in your profile (your name, country/region, and company name) is displayed to the public and will accompany any content you post, unless you opt to hide your company name. You may update your IBM account at any time.

All information submitted is secure.

Choose your display name



The first time you sign in to developerWorks, a profile is created for you, so you need to choose a display name. Your display name accompanies the content you post on developerWorks.

Please choose a display name between 3-31 characters. Your display name must be unique in the developerWorks community and should not be your email address for privacy reasons.

Required fields are indicated with an asterisk (*).

(Must be between 3 – 31 characters.)

By clicking Submit, you agree to the developerWorks terms of use.

 


All information submitted is secure.

Dig deeper into AIX and Unix on developerWorks


static.content.url=http://www.ibm.com/developerworks/js/artrating/
SITE_ID=1
Zone=AIX and UNIX
ArticleID=946856
ArticleTitle=How to write trace format entries
publish-date=10032013