Profiler - lms-org/lms GitHub Wiki

The profiler provides to simple methods that allows the framework to measure the duration of certain processes. The framework and its helper classes will invoke those methods in order to give the user information about timing relevant issues and a wide overview and detailed report over all modules.

Enable the Profiler

The profiler will write all relevant data to a file. It can be enabled on start-up time with a command line argument:

./lms --profiling profile.csv

Profiling Format

The profiler saves everything as a CSV file where each line is delimited by a single LF. Each line is separated by commas (,) and the first cell is a short integer describing the type of the line:

  • 0: Marks the begin of a process
  • 1: Marks the end of a process
  • 2: String mapping (mapping_id -> mapping_string)

Now each line is one of the following three types:

  • 0, mapping_id, diff_time
  • 1, mapping_id, diff_time
  • 2, mapping_id, mapping_string

The diff_time is a time difference with microsecond precision that denotes the difference to the last 0- or 1-type line. Timing starts with 0.

For every 0-type line marking the beginning there must be a 1-type line that marks the ending with the same mapping_id. Instead of directly printing the label given in the markBegin/markEnd methods, the label is mapped to an integer. That is what 2-type lines are for: The map ascending non-negative integers to strings. 2-type lines must be printed before any 0-type or 1-type line may reference it in the mapping_id.

Example

Here I will show you how parsing a profiling could be done. But please do not do it this way, it is just for educational purposes.

2,0,reader
0,0,10
1,0,990
2,1,writer
0,1,0
1,1,200
0,0,10
1,0,700

First step: Replace mapping_id by mapping_string and remove 2-type lines. Replace 0 by begin and 1 by end.

begin,reader,10
end,reader,990
begin,writer,0
end,writer,200
begin,reader,10
end,reader,700

Second step: Instead of relative times use absolute time points.

begin,reader,10
end,reader,1000
begin,writer,1000
end,writer,1200
begin,reader,1210
end,reader,1910

Now the interpretation:

  • Process reader was executed two times in the intervals (10,1000) and (1210,1910)
  • Process writer was executed one time in the interval (1000,1200)