Improve tracing performance by using isTraceable with appTrc

Written by Kris Hildrum.

To assist in developing and debugging an SPL application, Streams provides the appTrc function to produce trace messages. For example:

>appTrc(Trace.debug,"Tuple is "+(rstring)Data);

It should be no surprise that there’s a cost to output these messages to the log file or the terminal. What may be surprising, though, is that there’s a cost to even having the statement when no output is produced.

That’s because appTrc turns into an ordinary function call in the generated C++ code, and like any function call, the arguments are evaluated before the call is made. Regardless of what the trace level is, in the above example, the code to construct the string described by "Tuple is "+(rstring)Data is executed. If the actual work is small, then this string creation cost can have a significant affect on the the throughput of your application.

Streams 4.0+ introduces the isTraceable function. Similar to Java’s isLoggable function, isTraceable takes a trace level, and returns true if messages at that trace level would be produced. This allows you to avoid expensive string construction when the result won’t be used.

We demonstrate the use of isTraceable in the following examples. First, consider a program without it:

>composite Main {
  param expression<int32> $iterations: (int32)getSubmissionTimeValue("iterations","1000000");
    
  graph
    stream<float32 myFloat, int32 myInt, rstring myString> Data = Beacon() {
        param iterations: $iterations;
        output Data:
            myFloat=3.14159w,
            myInt=24601,
            myString="24601 stole a loaf of bread, not a pi";
    }

    stream<Data> Filtered = Filter(Data) {
        logic onTuple Data: {
            appTrc(Trace.debug,"Tuple is: "+(rstring)Data);
        }
        param filter: false;
    }
}

In this application, the Filter operator does almost nothing, so the time taken by appTrc calls is going to be a relatively large fraction of the total tuple processing time. Without the debug line, run at error level, this application can process 12,800,000 tuples per second. With the appTrc call, the operator processes only 180,000 tuples per second, almost a factor of ten slower. (When outputting the messages, it processed about 4,200 tuples per second.) This is an extreme example because the tuple processing cost is so very low, but we did see a factor of about five slowdown from an appTrc call in a real application.

This left developers with two bad choices: either they had to edit SPL code and recompile to change between a fast version and a version with debug messages, or they had to tolerate a potentially substantial slowdown even when running at error level.

The isTraceable function solves this problem. We’ve taken the example above and guarded the appTrc call with an isTraceable call.

>   stream<Data> Filtered = Filter(Data) {
        logic onTuple Data: {
            if (isTraceable(Trace.debug)) {
                appTrc(Trace.debug,"Tuple is: "+(rstring)Data);
            }
        }
        param filter: false;
    }

The tuple rate at the debug level is the same 4,200 tuples per second as before, but the tuple rate at error is 11.5 million tuples per second, much better than the 180,000 tuples per second we got before we guarded the statement, and almost as much as the 12.8 million tuples per second without any appTrc statement at all. Remember that this example has an unrealistically low work-per-tuple; when the work-per-tuple is higher, the rate difference between no appTrc statement an an guarded appTrc statement would be negligible.

By guarding your appTrc messages with isTraceable, you can keep those messages in your code, even for production environments. You can turn on and off the tracing via the normal mechanisms (even dynamically, at runtime, via Eclipse) without worrying that the appTrc messages will significantly affect your overall application performance.

Using isTraceable as a filter

The previous example shows how to use isTraceable to prevent unnecessary string construction in trace statements, which is a common use case. Here we introduce a different use case.

In some Streams applications, debugging information may take the form of tuples written to files. A common way to do this would be to add in FileSink operators at key points to debug specific issues, and then take them out again the issue is resolved. Developers will often add and remove the same FileSink operator during the debugging process. Using mixed-mode can make this easier, but that still requires recompiling to make changes, and mixed-mode can be cumbersome.

Using isTraceable provides an alternative: it allows you to write tuples to a file only when the debug level is a certain value by using the isTraceable call in a Filter operator in front of the FileSink. An example is below:

>composite FileTest {
  param
    expression<int32> $iterations: (int32)getSubmissionTimeValue("iterations","1000000");
  graph
    stream<float32 myFloat, int32 myInt, rstring myString> Data = Beacon() {
        param iterations: $iterations;
        output Data:
            myFloat=3.14159w,
            myInt=24601,
            myString="24601 stole a loaf of bread, not a pi";
            config placement: partitionColocation("DataSink");
    }
 
    stream<Data> Filtered = Filter(Data) {
        param filter: isTraceable(Trace.debug);
        config placement: partitionColocation("DataSink");
    }

    () as sink = FileSink(Filtered) {
        param file: "tmp.csv";
    }  
}

When run with trace set to error, nothing is written to the file. When the trace level is debug or trace, tuples pass the filter and are written to the file. There is a performance cost to doing this; in this case, the application that includes the Filter and FileSink runs about 25% slower than one without. However, that cost is much less than the cost of actually writing the tuples to the file (about 50 times lower throughput).

Thanks to Mike Bhola who suggested this feature and the FileSink pattern.

Written by Kris Hildrum.