Tracing functionality can serve as a powerful problem-determination technique for wireless software developers. A robust and efficient trace infrastructure proves vital for a modern software product -- particularly in the wireless field, which, by its nature, can be more volatile than traditional computing environments. Unfortunately, wireless devices' small memory and storage sizes cause many wireless developers to ignore tracing, but properly constructed tracing facilities let you diagnose problems without affecting performance.

This three-part series introduces topics to consider while designing and implementing tracing in your wireless applications. Part 1 explored tracing issues relevant to wireless environments (a small footprint requirement, for example) and introduced the binary-trace implementation. Part 2, for its part, further refined the implementation by detailing four file-size reduction algorithms. By the end of part 2, the binary-trace implementation had become fairly functional. To complete the process, this third and final article will:

• Detail the fifth and final maximum file-size algorithm: In-Place Wrapping
• Add parameter tracing to trace entry/exit calls
• Add timing information to each trace record
• Measure the completed implementation to check our success

Additionally, the included reference implementation demonstrates a working binary-trace architecture you can use today.

Algorithm 5: In-Place Wrapping

Part 2 detailed four algorithms that limited the trace's usable disk space. Beginning with the basic Stop algorithm, which simply stopped tracing when the file size reached its maximum limit, each successive algorithm from part 2 let you collect increasingly more information at the expense of code complexity and lower performance.

As you might expect, the fifth and final algorithm, In-Place Wrapping, continues the trend by letting you catch the most information of any algorithm, but also requiring the most complex code.

The In-Place Wrapping algorithm, rather than maintaining multiple files, sports a single trace file. As in previous algorithms, with In-Place Wrapping's record-based trace file every trace statement writes a separate record to the file. Moreover, each record written to the file contains a length field that reveals the record's length.

In-Place Wrapping simply writes records to the end of the file as normal. Once the file reaches the maximum size, however, the algorithm returns to the file's beginning. Now, each time you write a record, In-Place Wrapping overwrites one or more existing records in the file (followed by a wrap record that indicates the file's logical end). This way, you maintain a circular buffer efficient at capturing data.

In general, for a given maximum file size, M, In-Place Wrapping captures close to M bytes of information. The exact amount captured will vary according to where the file wrapped, but in general the amount will approximate M-R, where R represents the average record size (because on average you will waste one record for the wrap record).

For all its benefits, In-Place Wrapping exhibits three major disadvantages:

• Complexity: The complex logic makes correct implementations difficult.
• Performance: Because In-Place Wrapping treats the file as a circular buffer, it searches back and forth to find space to write the record. Once the algorithm has wrapped, each record-writing operation comprises at least one file read, two file seeks, and two file writes -- with more seeks and reads possible if the record doesn't fit in the first free record. Later in this article you'll see measurements showing those effects on real world performance.
• Record size: As the record length now appears in each trace record, the trace file's size increases. This might outweigh the advantages when compared to Multiple Flip (algorithm 4), depending on such factors as average record length and the length field's size (governed by the maximum allowable record length).

To choose the best algorithm, first understand the architecture's design and implementation, then decide if it applies to your situation. For example, if the In-Place Wrapping algorithm seems like overkill, select one of the simpler algorithms.

Back to top

Parameter tracing

Up to this point in the series, the tracing mechanism has traced only the following information types:

• Which functions the program has entered
• Which functions the program has exited and the associated return codes
• Specific items of arbitrary data in which the programmer thought we might show interest

The information types listed help you grasp the execution path and, when combined with the source code, let you infer the program's general state at any given point during the execution. Sometimes, however, knowing the value of any parameters passed into or out of functions can also help. You can find such data with the dwTraceData call, but then the programmer must call that function with any information that interests us (not to mention the increased code size).

With that in mind, what if you could incorporate parameter information into the existing dwTraceEntry and dwTraceExit calls, thus leaving the dwTraceData call for more extraordinary items of information?

Due to the limited scope of this series, the sample architecture features only a simple implementation of that complex topic, but it features enough built-in extensibility for you to add complexity as required.

In my simple implementation, the dwTraceEntry and dwTraceExit calls take a variable number of parameters. The parameters are passed as pairs of DWTYPE (which specifies the parameter's type), followed by a pointer to the parameter itself. An additional parameter to these calls specifies how many pairs are present (necessary because, as in C, no built-in method exists to determine how many arguments pass to a var-args function).

During execution, if parameter tracing is enabled, the type is written to the trace file. The parameter pointer is dereferenced and its value (interpreted as an 8-, 16-, or 32-bit unsigned value) is written to the trace file -- meaning that the values of basic types such as ints, shorts, and bools are correctly written to the trace file. For more complex structures, however, dereferencing the pointer would not make sense as only the structure's first 32 bits would be written to the file, which is unlikely to prove useful.

For that reason, for nonbasic types, you simply output the pointer's value rather than the contents, meaning that the structure's address appears in the trace, which you can then match between different functions. That represents a limitation of the simple implementation. A fuller implementation could correctly interpret more complex structures and write their values correctly to the trace file, requiring the trace implementation to know in detail the structures involved and also requiring some control from the user to determine how deep to go for nested structures, linked-lists, and so on. Finally, a fuller implementation would also require that the formatter understands the format in which the decoded parameters are written and can cope with the different decoding levels.

Considering that, when writing parameters to the trace file, be sure to also write an additional field, dwTraceFormatControl for each parameter specifying how much formatting has been applied to the parameter so that the formatter can cope with it correctly. This article's implementation supports only three possible values:

• DWTRACEFORMATCONTROL_UNFORMATTED: The usual value with no formatting.
• DWTRACEFORMATCONTROL_NULLPTR: A special value indicating that the pointer passed to the trace parameter call was null.
• DWTRACEFORMATCONTROL_NOTALIGNED: A special value indicating that the pointer passed to the trace parameter call was incorrectly aligned and, therefore, could not be dereferenced.

Back to top

Timing information

As mentioned in part 1, the trace system would benefit from a way to measure the time when each trace statement was made. Because tracing drastically changes the time each method takes (and additional calls to determine and include the timing information changes the time yet further), the timing facility cannot replace a full set of profiling tools. Nevertheless, if you account for its limitations and inherent inaccuracy, timing information can show (albeit at a high level) approximately where time is taken within your code.

While the actual numbers prove relatively meaningless, the ratios should stay approximately the same -- that is, if function A takes 100 times longer than function B, it's unlikely the cause stems from the trace calls alone, assuming the times are not small. Your implementation will depend on the accuracy required. While the sample implementation uses a 32-bit number retrieved via a QueryPerformanceCounter system call, you could instead use a 64-bit number. Also note that the value does not necessarily have the full granularity of 32-bits. Moreover, because the value represents a measure of time in an arbitrary unit on this specific device (the value likely measures the number of processor ticks since the last system restart or something similar), it does not measure an actual time. Therefore, you cannot directly compare two devices with either the absolute value or duration.

If you require a value related to a specific real world time or one comparable between devices, you'll need more expensive operating system calls. Note: To reduce file sizes when you don't require timestamps, a flag in the trace file header indicates whether you are using timestamps and lets you remove the timestamp field from each record -- saving four bytes per record.

Back to top

Performance metrics

Throughout this series I've strived to make a binary-trace infrastructure with both small file sizes and high performance (especially when not actually tracing). With those two goals in mind, we'll measure our success in this section.

The supplied test application performs simple math routines (doubling, squaring, and so on). The test application in many ways measures the worst performance case because the actual time spent between trace calls is small. In a real-world application the performance percentages will look much better, as large time periods will be spent in computations, waiting for I/O (input/output), and so on.

As usual with benchmarks, the reported results represent a general performance indication and the validity of these figures will vary greatly depending upon the application.

Test parameters

All measurements werer taken against the PocketPC 2002, Arm build.

• Binary file size vs. formatted file:
  • Binary size: 15,052,469 bytes.
  • Formatted size: 38,721,251 bytes.
  As you can see, because the binary file measures less than half the size of the formatted file, you can capture twice as much information than if you output the trace in a readable format.
• Trace code size (dwTrace.dll): 10,752 bytes.
• Runtime performance: Time measured in ms (milliseconds), average of three runs:
  • Trace turned off
  • Nonwrapping trace
  • Wrapping trace (wrapping at 1,000,000 bytes)

Execution time

The table below shows the execution times.

As the results indicate, the application's execution time takes approximately 10 times longer with normal tracing turned on than with no trace. Furthermore, by enabling wrapping trace the application takes two times longer still. I consider those performance scores reasonable for such a simple, short-lived application in which tracing will have a noticeable affect. For typical real-world applications, my experience indicates that normal tracing and wrapping tracing slows performance by one-third and two-thirds, respectively.

Again, the performance depends on the application concerned. CPU-bound applications, for example, might experience a noticeable impact from tracing, whereas the affect on I/O-bound applications that wait for input might be unimportant. To test performance on your own, it's best to write a benchmark that closely models your application's functions.

Back to top

Future improvements

This series describes an efficient binary-trace architecture that's easily incorporated into your wireless applications. While the finished implementation proves complete and useful as is, every application can use some improvement:

• Vertical filtering: To trace a layered application, the current filtering model lets you filter functions horizontally. While horizontal filtering proves useful, you might also want to filter vertically -- for example, to trace function F and any functions F calls.
• Trace exits: User-written exits called by the trace can add powerful additional features. With such exit points you can alter an application's trace behavior when it's in the field. Possibilities include:
  • Exits called on entry, exit, and data calls (for example to let users suppress certain trace points)
  • Exits called before writing the trace to a disk (for example to let users send the trace data over a network/serial cable instead of (or as well as) writing it to a disk
  • Exits called when formatting parameters (so you can expand complex data types in the trace, for example)
  • Exits called during formatting (for example, to display complex data types correctly)
• Further ways to reduce file size: Possible optimizations include:
  • A compression algorithm.
  • Profiling the application to find the most common functions, then giving them a smaller function ID.
  • Separate types for parameters with small-enumerated values. For example, rather than storing a bool and the values true or false, employ two types, TRUE_BOOL and FALSE_BOOL, with no value stored.

Back to top

Download

Information about download methods

Resources

• You'll find the binary-trace reference implementation working as is.
  
  
• Read or reread Parts 1 and 2 of this series:
  • "A significant trace, Part 1: Binary trace" (developerWorks, January 2003).
  • "A significant trace, Part 2" (developerWorks, May 2003).
  
  
  
• For more background check out, "Preprocessor commands".
  
  
• Previous developerWorks articles by Martyn Honeyford:
  • "Weighing in on Java native compilation" (developerWorks, January 2002).
  • "Port DLLs to Palm OS with ease" (developerWorks, October 2002).
  
  
  

About the author

Rate this article

Comments

Back to top

Table of contents

• Algorithm 5: In-Place Wrapping
• Parameter tracing
• Timing information
• Performance metrics
• Future improvements
• Download
• Resources
• About the author
• Comments

Local resources

• IBM Innovation Center - Austin, TX
• IBM Innovation Center - Chicago, IL
• IBM Innovation Center - Dallas, TX
• IBM Innovation Center - San Mateo, CA
• IBM Innovation Center - Waltham, MA
• Technical Briefings in North America

Special offers