Why Not Profile Everything?

General code profilers collect lots of timing and usage data. Often you don't want all that data and have a tough time sifting through it all. What you want instead is to be able to time a few selected blocks and/or parts of your code to understand where the time is being spent.

Libraries/extensions were developed in Java, C, and Python for this purpose. The basic timing "object" (C struct, C++ class) is the stop watch. You can create "stop watches" that can be started at the beginning of the code section and stopped at the end. Stop watches can be independent or nested. Stop watches can accumulate cumulative time, average time, standard deviation, and min/max time. You can get the statistics programmatically or invoke a simple method to print all the statistics for all the stopwatches in a simple format.

The original goal was to provide a similar API in each of the languages to support multi-language benchmark development without having to delve into all the different languages and platform timing service details. The most mature of these is the Java version and the least mature of these is the Python version.

Each subdirectory has an AboutXXX.txt with additional documentation. The Java docs for JPoorMansTimingAndProfiling are included in the download and can be browsed above. The C docs for CPoorMansTimingAndProfiling are included in the download and can be browsed above. There is no documentation for PyPoorMansTiming (yet).

The three subdirectories are:

  • /CPoorMansTimingAndProfiling
  • /JPoorMansTimingAndProfiling
  • /PyPoorMansTiming

Measuring Server Clock Differences

When testing multi-node services, agents, or actors there can be complex interactions that may require fine grained analysis of the sequence of events across multiple server logs. One strategy is to have a single server that does all the logging, but, the server can get bogged down with I/O. Another strategy is to create all the logs locally using local clock time stamps. If exchanges happen rapidly server clock time differences can make multilog analysis frustrating if the clocks are out of alignment. Even when synchronized using NTP clocks can drift over the course of minutes -- enough to be confusing when interactions are at the sub-millisecond level. Finally, there can be configuration errors that can cause clocks to be out of sync without anyone realizing it.

A Java utility was written to measure the timing differences between two nodes using a UDP-based dialog. Clock differences are usually resolved to less than one microsecond. The utility can be used from the command line or it can be activated from developer code repeatedly as needed to monitor clock differences over time.

The following subdirectory contains the clock skew measurement tool:

  • /JNodeToNodeClockSkew

CPU Loading and Application Event Logging

The /JPoorMansPerformanceAndEventLogging directory contains a Java helper class that uses HYPERIC's System Information Gatherer And Reporter, (SIGAR) to repeatedly log CPU loading to a log file. This allows a Java application under test to take control of monitoring its own loading without requiring the developer to separately start logging tools.

There is also an event logging mechanism that creates a time stamped activity log file with time stamps that can be correlated with the CPU loading log file for subsequent analysis.

Note that the helper classes just create log files. Analysis and the choice of analysis tools are left to the developer :)

Nazario Irizarry, Jr.
n_irizarry (at) users (dot) sourceforge (dot) net
© 2012 The MITRE Corporation. All Rights Reserved.
Approved for Public Release: 12-2651. Distribution Unlimited.