Simple DSUI Example

Before going through this example, please make sure you have checked out and installed the appropriate KUSP kernel and KUSP application source trees. Instructions for this can be found at:

  • Building the Kernel

    This is not strictly necessary for a purely DSUI example, but it is still better to make sure this has worked properly for you. Also the KUSP kernel is required for most other examples.

  • Building and Installing KUSP

    This ensures that all of the header files and libraries required for this and other examples are available in the correct locations.

Introduction

This is a basic example covering the use of various DSUI instrumentation points and a brief introduction to Data Streams Post-Processing using some of the existing event filters.

Warning

Make sure you have the RPM built and installed before you run this example. If you do not have the RPM built the example will not make properly.

If you have not built the KUSP examples before, go to Building KUSP Examples

It can be found in the experiments tree at this location:

bash$ cd $KUSPROOT/examples/simple_dsui/

The compiled code for simple_dsui can br found at the:

bash$ cd $KUSPROOT/examples/build/simple_dsui/

To run the example:

bash$ ./simple

To run the example using DSUI configuration file specification, look at Execution section below

Note

The binary file produced in this example is stored in the directory /tmp/ – Make sure you look at this directory to see if the binary file is there. It should be called simple.dsui.bin

The source for the simple application is found in simple.c. Note in the makefile output that the dsui-header command is used to generate the simple_dsui.c and simple_dsui.h instrumentation support files.

DSUI Support Files

The first thing to notice upon making the project is the creation of the simple_dsui.c and simple_dsui.h files. These are the DSUI header and source files. All programs that use DSUI must generate these files. The file simple_dsui.h defines a set of macros that can be used to create instrumentation in application code. It also uses a #ifdef and a defined constant CONFIG_DSUI to permit the user to choose whether the instrumentation points are compiled into their code or not. When CONFIG_DSUI is not defined, the DSUI instrumentation macros are empty. The file simple_dsui.c is simply utility code required to make everything work and of no interest to most DSUI users.

The program used to create these files is called dsui-header, and it requires a single string parameter that is a unique identifier for this application used as a prefix for file names. In this case “simple” was the prefix. The dsui-header command is called by this example’s makefile, which thus automatically generates the necessary files, but if we wanted to run dsui-header by hand to generate the simple_dsui.h and simple_dsui.c without doing anything else that the makefile might specify we would type:

bash$ dsui-header -p simple

The -p parameter specifies the prefix that is used when the files are generated. The prefix parameter is used in two other important ways:

  • It is used to name a special binary text section that stores all

    the event namespace information in the generated application programs, which describes all the instrumentation points declared. Unique names are needed so that linking DSUI applications with shared libraries that also use DSUI does not cause any naming conflicts. Therefore, in choosing this prefix string it is important to use something specific and unique enough to your application that collisions are unlikely. Thus the choice of “simple” for a prefix may have been somewhat optimistic.

  • The default file name for the binary file storing the generated

    performance data will be <prefix>.dsui.bin. So running our example will generate a file named “simple.dsui.bin”. You can always override the default file name by specifying the output file name in a DSUI configuration file or by using the --dsui-output <output-file> option when calling the instrumented application.

Also, there are a few things to note about the DSUI header and source files:

  • These files are generated independent of any information about the application. Their only function is to set up DSUI infrastructure required gather data from instrumentation points in the rest of the application.
  • All source files of an application that define instrumentation points must include the DSUI header file, <prefix>_dsui.h. The DSUI source file, <prefix>_dsui.c generated must be compiled and the object file linked with the application. If the application uses DSUI macros but does not define any instrumentation points, you should not link the object file with the application. Doing so will cause linker errors, because you are linking against <prefix>_dsui.o but none of its symbols are referenced by your application.
  • These two files need to be created just once. They will not need any editing.

Compiling With Instrumentation

All DSUI instrumentation point macro definitions use the following:

#ifdef CONFIG_DSUI
  <body-of-macro>
#endif

This ensures that by controlling the definition of the single symbol CONFIG_DSUI a developer can completely exclude the DSUI instrumentation and support code from their application. By default the CONFIG_DSUI symbol is not defined. To ensure the application is compiled with instrumentation points, CONFIG_DSUI is defined on gcc command line by adding -DCONFIG_DSUI to the list of preprocessor arguments in the examples/simple-dsui/CMakeLists.txt:

SET(CMAKE_C_FLAGS "-DCONFIG_DSUI -Wall")

Structure of simple.c

This program contains examples of how to use all the major instrumentation point types. The functions it uses really serve no purpose other than showing how useful instrumentation points can be when collecting data from a running program. The display_onto_stdout and find_cosine functions are self-explanatory. useless_loop produces and logs random numbers to a histogram, and also shows examples of how the interval and counter instrumentation points are used. bigbuf_test allocates a large character array and shows how this data can be attached to an event instrumentation point. In addition to this functionality, there are a few other things to note about simple.c:

Including the Header File

As noted above, in order to use DSUI, a DSUI header file is generated and included into the application’s source. This file contains all the instrumentation point macro definitions for the application:

#include "simple_dsui.h"

Instrumentation Point Declarations

There are several kinds of instrumentation points that can be used under DSUI to gather data from an application. All DSUI instrumentation points log data when a thread of control crosses the instrumentation point in the application code. The simplest type is called an “event” because the data logged depends only on the arguments of the instrumentation point being executed. Other types of instrumentation points depend on some form of persistent data managed by the DSUI infrastructure and so require additional macro calls to create the persistent data before the instrumentation points themselves can successfully log an event. For these applications, DSUI provides declaration macros that can create the persistent state data. These declarations must be in the global scope of the application, since the event macros using the persistent data may appear anywhere in the subroutine hierarchy defined by a given source file. These are examples of declarations for each type:

DSTRM_HISTOGRAM_DECL(FUNC_LOOP, SUM);
DSTRM_INTERVAL_DECL(FUNC_LOOP, DSUI_OVERHEAD);
DSTRM_COUNTER_DECL(FUNC_LOOP, ITER_COUNT);

These declarations correspond to the three types of instrumentation points using persistent data. All identifiers for DSUI instrumentation points are organized into a two level namespace and are thus uniquely identified by a (category-name, event-name) pair. Both the category name and the event name are specified as arbitrary strings which are then mapped to unique integers by the DSUI compilation support. The declarations above, for example, create the persistent data associated with a histogram, an interval, and a counter. All three are members of the same category whose name is FUNC_LOOP. The histogram’s identifier, for example, is thus (FUNC_LOOP,SUM).

DSUI_BEGIN and DSUI_CLEANUP

Use of DSUI requires some setup before the instrumented application begins which is supported by the DSUI_BEGIN macro. This macro takes pointers to argc and argv as arguments because among other things it looks for DSUI command line options that modify its behavior in various ways. For example, --dsui-config <dsui-config-file> specifies a configuration file that controls instrumentation point activation and other DSUI behaviors. DSUI_BEGIN removes DSUI specific arguments from the argv list, which would otherwise appear to be invalid arguments from the application’s point of view when it processes its command line options, in this case using the getopt library routine. Thus, DSUI_BEGIN must be placed as the first statement executed in main():

int main(int argc, char **argv)
{
    DSUI_BEGIN(&argc, &argv);
    ...
    <original body of your application>
    ...
    DSUI_CLEANUP();

    exit(0);
 }

Similarly, you must call DSUI_CLEANUP before your program terminates. This action will close the Data Streams, write out any histograms or counters collected, flush remaining event buffers, and close the DSUI output file.

Types of Instrumentation Points

While all instrumentation points produce some kind of data when a thread crosses them, there are different types of instrumentation points producing different kinds of data.

Events

The simplest type of instrumentation point is the event, which has four standard components: a time-stamp, the unique (category-name,event-name) event identifier, a tag value, and a pointer to optional additional data. The time-stamp is automatically added during event logging when a thread of control crosses the instrumentation point. The pointer to additional data is often NULL because in most cases any information associated with an event can be encoded within the standard 32 bit tag value which is always present. For convenience, we provide two different macro forms for logging events with and without extra data. The short macro format is:

DSTRM_EVENT(category-name, event-name, <tag>);

An example of its use which does not encode information in the tag is:

DSTRM_EVENT(FUNC_DISPLAY, EXIT, 0);

The macro internals translate the first two arguments into their integer representations and combine them into a single unique bit pattern representing the (category-name,event-name) pair. The tag argument is an unsigned integer which can be used to encode information the developer decides. Note, however, that Data Streams Post-Processing associated with the experiment must contain code understanding the information encoded in the tag value. Examples of tag uses include process PID, socket port number, network packet size, or even combinations of these or other parameters which can be encoded in 32 bits.

The long format of the event macro is:

DSTRM_EVENT(category-name, event-name, <tag>, <extra-length>, <ptr-to-extra>, <extra-id-str>);

An example which does not encode information in the tag but does attach arbitrary extra data is:

DSTRM_EVENT_DATA(FUNC_DISPLAY, ENTER, 0, strlen(str), (void *)str, "print_string");

The first three parameters are identical to the event macro that does not log extra data, in this case specifying the event ID (FUNC_DISPLAY,ENTER), and a 0 value tag. The additional data is represented by the three additional arguments. The first specifies the length of the additional data, the second provides a pointer to it, and the third is the name of the Data Streams Post-Processing (DSPP) routine used to unpack this event-specific extra data. In this case, the additional data is a string pointed to by str. The length of str is given by strlen(str), the string is cast to a void pointer to satisfy the type requirement of the event logging subroutine call included in the macro definition, and the last argument, print_string, is an identifier used to specify the DSPP Python routine which will interpret the extra data as a string and handle it appropriately. The available built-in event decoding functions are listed in the file:

$KUSPROOT/subsystems/datastreams/postprocess/event_data.py

Custom extra data unpacking functions may also be used in experiments, as described in the DSPP User Manual

DSTRM_PRINTF

This macro is provided as a more convenient format for printing strings to the log file. It is a wrapper macro for using sprintf to construct an output string and then logging an event with a reserved event ID with the output string attached as extra data:

DSTRM_PRINTF(<sprintf-format-string>, <sprintf-args>);

Intervals

Intervals can be used as a way to log the time between a thread crossing two instrumentation points in one instrumentation point. In order to do this, intervals need to have some persistent state associated with them, and thus must be declared before being used. In addition to the required declaration macro as described in Instrumentation Point Declarations, intervals also have start and end macros, which are used to mark the beginning and ending points of the interval. These macros take the category name and event name as arguments and use them just as the event macro did. The START and END macros are intended for use in matching pairs, and the category and event names used must match a global interval declaration which creates the persistent data required for proper function. Failure to create a declaration or use them as matching pairs is likely to produce either compile errors or meaningless results.

An example of an interval is in the useless_loop() function of simple.c:

DSTRM_INTERVAL_START(FUNC_LOOP, DSUI_OVERHEAD);
...
DSTRM_INTERVAL_END(FUNC_LOOP, DSUI_OVERHEAD, 0);

When a thread crosses the START macro, it records a time-stamp in the persistent data associated with the (FUNC_LOOP, DSUI_OVERHEAD) pair. When the thread subsequently crosses the END macro, another time-stamp is recorded and the interval event containing the (FUNC_LOOP, DSUI_OVERHEAD) pair, both time-stamps, and the tag value (in this case, 0) is logged.

Histograms

Histogram macros are used to create persistent storage within which distributions of specific performance variables of interest can be gathered. The DSTRM_HISTOGRAM_DECL macro creates the storage for the histogram configuration and state variables. In general terms, a histogram consists of some number of buckets and state variables specifying the (low,high) data range. The size of each bucket is thus (high-low)/number-of-buckets. In the course of execution the application may generate data it wishes to put into a histogram using DSTRM_HISTOGRAM_ADD. The ADD macro determines into which bucket the added datum should be placed by incrementing the corresponding bucket counter. If the added datum falls outside the (low,high) range then the overflow or underflow bucket is incremented as appropriate.

Each histogram instrumentation point has a few parameters that can be specified at run-time by setting parameter values for a specific histogram within a DSUI configuration file specified using -f <config-file> command line argument. The lower and upper boundaries of the histogram may be specified explicitly, or DSUI will automatically calculate the lower and upper boundaries after a certain number of data points (the tune amount) have been logged. The default tune amount is 50. The other parameter a user may specify is the number of buckets for the histogram and this defaults to 20.

An example of histogram usage is in the useless_loop() function of simple.c. This example calculates two random numbers, adds them, and logs their sum to the histogram. The numerical amount added to the histogram is a signed long long value:

long long t1, t2;
t1 = random();
t2 = random();
DSTRM_HISTOGRAM_ADD(FUNC_LOOP, SUM, t1+t2);

Finally, “snapshots” of all histograms are logged to the DSUI output file when the application completes and DSUI performs its cleanup routines (these are called by the DSUI_CLEANUP() macro which must appear at the end of the application’s main() function). However, DSUI also provides histogram instrumentation point macros that allow the user to take a “snapshot” of a histogram during application execution and to reset the data as desired:

DSTRM_HISTOGRAM_LOG(category-name, event-name);
DSTRM_HISTOGRAM_RESET(category-name, event-name);

Counters

The counter instrumentation point is a simple way to increment a counter variable whenever a thread crosses the DSTRM_COUNTER_ADD instrumentation point. The increment value used by each ADD instrumentation point can be arbitrary because counter variables can be used to track arbitrary activity. The counter value is, obviously, the persistent data which motivates the counter declaration, as described in Instrumentation Point Declarations. All counters are initialized to 0. The DSTRM_COUNTER_ADD macro increments the counter associated with the specified (category-name, event-name) pair. For example, this call to the ADD macro in the useless_loop() function of simple.c increments the counter associated with (FUNC_LOOP, ITER_COUNT) by 1:

DSTRM_COUNTER_ADD(FUNC_LOOP, ITER_COUNT, 1);

As with histograms, counter “snapshots” can be logged at will or reset:

DSTRM_COUNTER_LOG(config-name, event-name);
DSTRM_COUNTER_RESET(config-name, event-name);

Execution

Once everything is built, just run the simple binary created:

bash$ ./simple --dsui-config simple.dsui
Simple Program
Done Executing this Simple Program
bash$

There are a few things to notice here. The output file opened for logging is /tmp/simple.dsui.bin. As noted above, this is the default output logging file for a program named simple. This can be changed by specifying an output file as a command line argument when running simple (using –dsui-output), or by creating a DSUI configuration file and specifying the output file name within.

Note that this output indicates 17 instrumentation points were enabled for datastream[0]. However, if you count them, simple.c only creates 16 instrumentation points. The reason is that one type is always created and reserved for DSTRM_PRINTF, whether it is used in the application code or not. Recall that there are several types instrumentation points that produce different types of data when a thread crosses them. Events are probably the most common and they simply produce an event record. A PRINTF instrumentation point is similar, but it has the added convenience of producing a string as additional data using a printf interface. A pair of interval instrumentation points produce a single interval record. The term “entity” is used to refer to any record containing data to the output datastream. This is convenient when a counter instrumentation point increments the persistent counter data, and a histogram instrumentation adds a datum to the persistent histogram. Sometimes it is convenient to have a term for data produced by a thread a crossing an instrumentation point without referring to its type. We use the term “entity” to denote that.

Finally, consider the 30K entities that were logged to datastream[0]. Most of these are logged during the execution of useless_loop, which iterates 10,000 times. There are six instrumentation points within the loop. Two are events, two are an interval pair, and the remaining two increment a counter and add a datum to a histogram. DSTRM_EVENT(FUNC_LOOP, ITER_ONE, i) and DSTRM_EVENT(FUNC_LOOP, ITER_TWO, i) each generate an event record during each loop iteration. DSTRM_INTERVAL_START(FUNC_LOOP, DSUI_OVERHEAD) and DSTRM_INTERVAL_END(FUNC_LOOP, DSUI_OVERHEAD) together log the third entity, the interval record. The DSTRM_COUNTER_ADD(FUNC_LOOP, ITER_COUNT, 1) and DSTRM_HISTOGRAM_ADD(FUNC_LOOP, SUM, t1+t2) instrumentation points do not generate entities, instead they update persistent data structures. At least one entity for each is generated during DSUI_CLEANUP() since a record containing snapshot of the persistent data structures is added to the datastream. Note that the DSUI API also permits the program to request a snapshot of persistent data structures at any time during program execution.

--dsui-config

As a command line option, one can specify a DSUI configuration file specification. This allows the user to specify in a file which instrumentation points are enabled and disabled, as well as setting several other parameters associated with DSUI, such as output file. Using this command: bash$ ./simple --dsui-config simple.dsui only the events enabled in the simple.dsui configuration file will be logged.

When an application using DSUI is executed, all instrumentation points within it are enabled by default unless other measures taken. In general, any given experiment will use a configuration file to explicitly specify the set of data it desires in order to minimize the instrumentation effect by gathering only the data required. It is common for applications to define more instrumentation points than are used during most experiments and experiments often use a small subset of the available instrumentation points. Therefore, when using a configuration file, DSUI attempts to minimize the specification effort by assuming instrumentation points are disabled unless explicitly enabled in the configuration file.

The rest of this discussion describes post-processing of data generated when all the instrumentation points are enabled. You can most conveniently satisfy this assumption by running:

bash$ ./simple

without a configuration file argument. You should have already done this and this will produce the simple.dsui.bin file.

Post-processing

Executing the program generates 30K event records in the DSUI output file. This section of the tutorial considers how to extract information from the raw data using Data Streams Post-processing (DSPP). DSPP is supported by a tool called “postprocess” and which should have been installed in the place you designated while performing the steps outlined in Building and Installing KUSP. If you cannot run the tool, be sure to check your environment $PATH variable, to ensure that it includes the KUSP installation target directory. For more detailed information about this program, see the DSPP User Manual.

DSPP uses a simple form of data-flow as its programming model. Describing the total set of analysis performed a given experiment would often required a set of computations described by arbitrary data-flow diagrams. Separate steps are often to generate intermediate data files required for specific analyses. Obviously, separate makefile targets are a convenient way to specify the separate steps of such an analysis. However, the postprocess tool only supports specifying linear pipelines. Separate makefile targets and intermediate files are thus also used to compose a set of linear pipeline steps into arbitrary data-flow computations. In general, simple linear pipelines are often sufficient to perform the desired analysis.

The simplest DSPP filter reads the stream of raw entity records in the DSUI binary output file, presenting that information in a human readable form, and is thus called the narration filter. In general specifying and configuring the set of filters comprising a given DSPP pipeline is complex enough that a configuration file is required. However, the narrate case is so common, and so simple, that a command line option is also available:

bash$ postprocess n /tmp/simple.dsui.bin

However, simply narrating the 30K events produced by this program is not terribly helpful because it drowns the user in information. This illustrates the extremely common situation where a literal view of the raw data is insufficient. Instead, more extensive analysis is required to extract useful views of program performance from the raw data.

The pipeline configuration file simple.pipes extracts several meaningful views from the raw data, including: a graph of the histogram gathered directly in simple.c, a graph of a generated histogram derived from the interval events, synthesized interval events representing the elapsed time of each useless_loop iteration, two synthesized interval events used to represent the median values of the synthesized loop iteration intervals and the directly generated intervals representing the useless_loop iteration elapsed time. Finally, the specified pipeline prints a narrative of the entities which remain in the datastream, after the vast majority are consumed during analysis.

To use the simple.pipes configuration file with the postprocess tool, use the following command:

bash$ postprocess f simple.pipes

After the post-processing is completed, there should be two new histograms (stored as .ps files) and a simple.narrate.txt file. These files are the results of running the data in /tmp/simple.dsui.bin through the filters specified in simple.pipes. In order to understand this output, it is important to understand the filtering configuration file, simple.pipes. The configuration file has been extensively commented and should be read in parallel with the following discussion.

simple.pipes

A filtering configuration file is a collection of one or more post-processing graphs, with each graph consisting of a set of linked pipelines. Each graph is a top-level block in the simple.pipes configuration file. The simple.pipes file contains one graph named main:

<main>
filters = {
    ...

Each graph in a filtering configuration file holds a dictionary of pipelines called filters. The key for each entry in the filters dictionary is an arbitrary name for a pipeline that may be referenced by other pipelines in the filter. In this example, there is just one pipeline named “f1”:

<main>
filters = {
    f1 = [
       ...

Each pipeline is a list of filters with their parameters. The filters, in this sense, are simply a set of the available post-processing functions that can operate on some logged output data with the eventual goal of producing more concise and more meaningful output. This may seem confusing now, but remember, each graph holds a dictionary called filters, this dictionary holds an arbitrary number of arbitrarily named pipelines, and each pipeline specifies a series of filters (i.e. post-processing functions) that are processed linearly.

The computation specified by the pipeline is executed by an independent thread, generated by the framework during the initial pipeline construction. The independent thread controlling the pipeline’s execution collects data from its input sources and pushes the entities through all the other filters in the pipeline.

Head Filter

The first filter in every pipeline is a special kind of filter called a head filter. The head filter is used to setup the input datastream to the pipeline as well as to initialize a number of parameters for the pipeline. For a more complete description of the head filter, see the DSPP User Manual. The head filter in this example has two parameters: a list of input files to read, and some namespace information for events created later in the pipeline:

head.input(
  file = ["/tmp/simple.dsui.bin"]
  namespace = {
    SIMPLEPIPE = {
      desc = "simple pipe"
      entities = {
        TIMEHIST = histogram(
                     desc = "histogram"
                     units = "ns"
                   )
      }
    }
    FUNC_LOOP = {
      entities = {
        INTERVAL_MEDIAN = interval(
                            desc = "median of loop intervals"
                          )
        INTERVAL_DERIVED = interval(
                             desc = "created from ITER_ONE and ITER_TWO"
                           )
        INTERVAL_DERIVED_MEDIAN = interval(
                                    desc = "median"
                                  )
      }
    }
  }
)

The file parameter specifies the files on the system the pipeline will read as input. The entities that are logged in these files are now added to the datastream all the other filters in this pipeline will read from. Notice that it is possible to read from multiple files at once. If multiple files are specified, a simple merge-sort on the timestamps of the individual events is used to create a single merged stream. However, if there is performance data that was not all gathered on the same machine, and thus stamped by different clocks, additional measures must be taken as described in the Global Time Line Section of the DSPP User Manual.

The namespace section of the head.input filter is used to declare any namespace information DSPP will use later in the pipeline. This is important because the filters in the pipeline can be used to construct derived entities from the raw data that was gathered. For example, the SIMPLE_PIPE/TIMEHIST is a histogram that we construct from the intervals in the raw data. Since all entities must be declared before they are used, the SIMPLE_PIPE/TIMEHIST is declared in the head filter.

Other Filters

After processing the head filter, all of the entities that were logged by the execution of simple will be in the input datastream. Each of the following filters will operate on all of these entities, in turn:

utility.timestamp()

This is the first filter after the head filter, which converts TSC-based timestamps into nanoseconds. This can be very useful when comparing events with timestamps from different machines. The (FIXMEexit.D refer to new filter library component(s) when ready) utility module has a number of useful filters that can be used to modify and analyze the input stream. It is recommended to read through the code for the utility module (and each of the other filtering modules) in kusp/datastreams/src/datastreams/postprocess2/filters. The next set of filters accumulates a histogram:

conversion.interval_to_histogram(
   interval = "FUNC_LOOP/DSUI_OVERHEAD"
   histogram = "SIMPLEPIPE/TIMEHIST"
   buckets = 40
)
graph.histogram(
   histogram = "SIMPLEPIPE/TIMEHIST"
   title = "time hist"
)

During the execution of simple, the raw datastream gathered an execution interval for each iteration in useless_loop. This information is not very useful in its raw form, and it would be nice to have a graph of the collected data. The conversion.interval_to_histogram filter generates a post-processing histogram (as opposed to a run-time histogram collected directly during execution) with 40 buckets, getting its data from the FUNC_LOOP/DSUI_OVERHEAD interval. Notice that the generated histogram SIMPLEPIPE/TIMEHIST had to be declared in the head filter. The conversion.interval_to_histogram filter will read through the entire input stream before writing the collected information to the SIMPLEPIPE/TIMEHIST histogram entity. The graph.histogram filter reads the generated SIMPLEPIPE/TIMEHIST histogram and creates a GNUPLOT graph (in .ps format by default) from it.

Note

.ps stands for PostScript. You can display them by typing:

bash$: display <ps-file>

if this does not work then you may need to install software that can view .ps files, such as Inkscape.

The next filter plots a histogram accumulated at run-time:

graph.histogram(
  histogram = "FUNC_LOOP/SUM"
  title = "random"
)

This filter is the same as what was used to plot the SIMPLEPIPE/TIMEHIST histogram, but this operates on an entity that was created at run-time. Notice how each entity is treated the same way once it is in the input stream. This filter will cycle through the entire input stream and only plot the matching histogram. If no matching histogram is found, DSPP will throw an exception. We also wish to store sets of events output by a DSPP pipeline:

output.pickle(
   filename = "simple.pp2"
)

Output filters serialize the datastream to the disk. Calling output.pickle in the middle of the pipeline saves the state of the event stream at this point. This is useful because some filters actually delete events from the datastream. This makes it possible to save an image of the entire datastream before calling these filters.

The Pickle data serialization format is more convenient as a general file format for performance data that is processed by Python based filters, and it is different from the binary run-time output of DSUI/DSKI because the binary format is optimized to minimize run-time instrumentation overhead. This is one of the file formats DSPP will automatically recognize and read entities from with its format-detection features. For more information see the Input Sources section of the DSPP User Manual. The Pickle format is currently the only format supported by the output module. However, while storing event data is ofter required, there are also many times when it is desirable to reduce a set of event data to aggregate stats:

reduction.interval(
    operation = median
    src_interval = "FUNC_LOOP/DSUI_OVERHEAD"
    dest_event = "FUNC_LOOP/INTERVAL_MEDIAN"
    consume = true
)

The reduction module has built in functions to reduce a set of event data by mean, median, sum, min, and max operations. The reduction.interval filter uses the duration of the interval of each of the matching entities as its set of event data. It is also possible to reduce data from a set of generic events by using reduction.event and specifying which data from the events to operate on (the default is the tag). This example finds the median duration of the FUNC_LOOP/DSUI_OVERHEAD intervals and saves the result as extra data to another event FUNC_LOOP/INTERVAL_MEDIAN. The consume flag means that the source intervals, once read, are deleted from the event stream. This is important because it allows you to remove entities from the taste while you are processing it. It can also be useful in removing insignificant data from the final output. Converting pairs of events to intervals and then reducing is also often convenient:

conversion.event_to_interval(
   start_event = "FUNC_LOOP/ITER_ONE"
   end_event = "FUNC_LOOP/ITER_TWO"
   interval = "FUNC_LOOP/INTERVAL_DERIVED"
   consume = true
)
reduction.interval(
   operation = median
   src_interval = "FUNC_LOOP/INTERVAL_DERIVED"
   dest_event = "FUNC_LOOP/INTERVAL_DERIVED_MEDIAN"
   consume = true
)

Another filter the conversion module has allows you to create intervals from existing events. The execution of simple logged two events, FUNC_LOOP/ITER_ONE and FUNC_LOOP/ITER_TWO, for each iteration of useless_loop. The conversion.event_to_interval filter will match one of each of these events in the input stream and emit a FUNC_LOOP/INTERVAL_DERIVED interval for each pair (Remember that we had to declare this derived interval in the head filter’s namespace parameters. Along with functionality for creating intervals from existing events, the conversion module has functionality for creating histograms from existing intervals (example discussed previously) or existing events (using conversion.event_to_histogram. By default, the data placed in the buckets of the histogram are the events’ tag data). The reduction filter operates similarly as described above. It obtains the median execution interval for the newly created FUNC_LOOP/INTERVAL_DERIVED.

Notice the aggressive consuming behavior of these two filters. The conversion.event_to_interval filter emits intervals, deleting the events they were derived from. The subsequent reduction filter consumes these intervals, and emits a single event showing the median value at the end of the datastream:

utility.narrate(
   divisor = 1000000
   output = "simple.narrate.txt"
)

The final filter prints the remaining input stream to the simple.narrate.txt file. The divisor parameter will convert all timestamps (which were converted to nanoseconds by the utility.timestamp filter) to milliseconds by dividing by 1 million. Because this filter is at the end of our filtering configuration file, the input stream to this to this filter will only contain those entities that were not consumed by the filters above. This makes the final output file much simpler to read.

Output

After running DSPP on the event data logged by simple with the simple.pipes filtering configuration file, there should be three output files that are created: FUNC_LOOP-SUM.ps, SIMPLEPIPE-TIMEHIST.ps, and simple.narrate.txt. How each of these files is created was described in the last section, so please read through it if you have not done so.

The histograms that were created are fairly straightforward to analyze. FUNC_LOOP-SUM shows the distribution of the sums of random numbers that were generated and logged during the execution of simple. The distribution appears to resemble the Normal (Gaussian) distribution, and this is no surprise, as the random number generator that was used generated pseudo-normally distributed values. The SIMPLEPIPE-TIMEHIST is slightly more complicated. Most of the values fall in the smallest bucket. We know there are outliers because of the average and max values, but it is hard to see them on the histogram because of the scale of the y-axis. This can be changed by telling the histogram graph to plot the y-axis on a logarithmic scale in simple.pipes:

graph.histogram(
      histogram = "SIMPLEPIPE/TIMEHIST"
      title = "time hist"
      yaxis_log = true
)

Now, rerun the post-processing. Now you can easily which buckets the outliers fall in and how many there are. As an exercise, try to think of explanations for why there are outliers (e.g. Is it possible for any I/O blocking to occur inside the interval? Is there any extra overhead for the first iteration of the loop as opposed to subsequent iterations?)

Finally, open simple.narrate.txt. This is a printout of all the entities that were in the input stream when the utility.narrate filter was called. The first several events with the ID DSTREAM_ADMIN_FAM/NAMESPACE are administrative events needed to make the framework work correctly. The interesting results come after these and start with the event:

+0.160 E FUNC_MAIN/IN_MAIN_FUNC:  (0)

The number in the first column is the time (in milliseconds) elapsed since the last event was logged (for histograms this is not true, but irrelevant). The next column shows the type of entity (i.e. event, counter, etc.) that was logged. The next column is the CATEGORY/EVENT ID of the entity if it exists (DSTRM_PRINTF entities will not have this). The remaining columns show any extra data that may have been attached to the entity (notice the tag number in parentheses). Recall that simple logged thousands of entities in useless_loop, but there are only tens of entities printed by utility.narrate. This is because the consume tag in simple.pipes removed most of the entities from the input stream before the pipeline reached utility.narrate.

See Also

DSPP User Manual

Configfile API - FIXME.D fix link to this page

For post-processing, it is helpful to read through the modules in:

$KUSPSRC/datastreams/src/datastreams/postprocess2/filters

For a better understanding of DSUI, it is advised to read through the source in the Data Streams libraries found at:

$KUSPSRC/datastreams/src/dsui

Indices and tables