10.3 Visualizing Call Sequences of Functions-Enter/Exit Logging

The term function in this section refers to functions or methods from programming languages and not to analyze functions used by Ascolog Insight.

The video tutorial Enter/Exit Logging of Functions and Profiling on Youtube will explain how to use profiling like enter/exit logging of functions.

Ascolog Insight provides some useful methods for visualizing call sequences of functions:

  • Visualization in a graph using alternating lines

  • Predefined custom columns

You can only use these methods when the log records contain keywords which can be used to identify the beginning and the end of a function call. These keywords must be located at the beginning of the log record's description part (the description is represented by the TEXT column). The keywords which are supported by Ascolog Insight are

  • Enter, Entering, Enter Function, Exit Function

  • Leave, Leaving, Leave Function, Leaving Function

  • Exit, Exit Function

The recognition of these keywords is case-insensitive. Example A log using the keywords "ENTER" and "EXIT" shows a log which uses the keyword “ENTER” and “EXIT”.

2013-02-27 23:11:02,675 I 0x1D50 ENTER Function1
2013-02-27 23:11:04,703 I 0x1D50 ENTER Function2
2013-02-27 23:11:04,703 I 0x1D50 LogLine
2013-02-27 23:11:04,883 I 0x1D50 EXIT Function2
2013-02-27 23:11:09,911 I 0x1D50 ENTER Function3
2013-02-27 23:11:22,102 I 0x1D50 LogLine
2013-02-27 23:11:22,104 I 0x1D50 LogLine
2013-02-27 23:11:22,104 I 0x1D50 ENTER Function4
2013-02-27 23:11:22,104 I 0x1D50 LogLine
2013-02-27 23:11:27,756 I 0x1D50 LogLine
2013-02-27 23:11:27,763 I 0x1D50 EXIT Function4
2013-02-27 23:11:27,764 I 0x1D50 LogLine
2013-02-27 23:11:27,813 I 0x1D50 LogLine
2013-02-27 23:12:29,380 I 0x1D50 LogLine
2013-02-27 23:12:31,313 I 0x1D50 LogLine
2013-02-27 23:12:31,315 I 0x1D50 EXIT Function3
2013-02-27 23:12:31,463 I 0x1D50 LogLine
2013-02-27 23:12:42,354 I 0x1D50 LogLine
2013-02-27 23:12:42,378 I 0x1D50 LogLine
2013-02-27 23:25:17,691 I 0x1D50 ENTER Function2
2013-02-27 23:25:19,639 I 0x1D50 LogLine
2013-02-27 23:25:19,640 I 0x1D50 LogLine
2013-02-27 23:25:19,785 I 0x1D50 LogLine
2013-02-27 23:25:42,163 I 0x1D50 LogLine
2013-02-27 23:25:42,164 I 0x1D50 LogLine
2013-02-27 23:25:42,165 I 0x1D50 EXIT Function2
2013-02-27 23:25:42,186 I 0x1D50 EXIT Function1

 

A log using the keywords "ENTER" and "EXIT"

The predefined columns (FMT_TEXT, PROF_FUNC and PROF_FUNC_ENTER_EXIT) are described in chapter 10 Custom Columns Definitions (CCD), Table 5.3 Filter expressions.

About FMT_TEXT and PROF_* columns and grammars

When creating a grammar it is very IMPORTANT to assign any whitespace between the header and the description of a log record to the header, otherwise formatting and profiling of call sequences of functions won't work correctly. When such whitespace is not part of the header it becomes part of the FMT_TEXT column, i.e. the FMT_TEXT column starts with whitespace. However, the FMT_TEXT must start with one of the keywords allowed for enter/exit logging and not with a whitespace.

In the Graph dialog there is the possibility to set the Draw mode for lines to alternating. Alternating lines are intended to visualize call sequences of functions. The idea is that a line is drawn during the execution of the function, i.e. the line starts when in a computer program a function is entered and it ends when the function is left.

Let's look at an example to understand why it is called alternating lines. When the log records A, B, C, D, E, F are drawn in a graph and alternating lines is selected in the graph options, Ascolog Insight will draw a line between A and B, C and D, E and F. No lines will be drawn between B and C, D and E.

In order to draw a call sequence of a function you have to set the Draw mode to one of the alternating styles but you also have to create a graph which draws a graphical node for all log records logging the entering and the exit of this function. For the function with the name Function2 from example A log using the keywords "ENTER" and "EXIT" possible filter expressions for the graph are shown in example Filter expression for Function2 using the FULLROW column and example Filter expression for Function2 using the PROF_FUNC_ENTER_EXIT column.

You can check if the log record contains the function name in the FULLROW column as it is done in the following example:

FULLROW ~= "Function2"

Filter expression for Function2 using the FULLROW column

Alternatively, you can use the predefined custom column PROF_FUNC_ENTER_EXIT which only contains the function name (and nothing else) and check if the column contains the function name as shown in the following example:

PROF_FUNC_ENTER_EXIT == “Function2”

Filter expression for Function2 using the PROF_FUNC_ENTER_EXIT column

Each function has to be displayed on its own timeline, it is not useful to display two or more functions on the same timeline, i.e. for each function you have to create an own graph and an own filter expression. Hint: Use the Group command for creating all these graphs in a single step. Right-click on the PROF_FUNC_ENTER_EXIT column and select Group/Graph/Timeline/Auto from the context menu.

If in a log file each entering of a function is followed by an exit the Draw mode Alternating will have the effect that a line is drawn between the graphical node representing the entering of a function and the graphical node representing the exit of a function.

If in the log files there is a log record that logs the exit of a function before a record logs an entering you have to filter out this “exit” log record, otherwise lines will be drawn when the program is not executing the function which is wrong. A filter to correct this where “2013-10-16 14:35:49,951” is the timestamp of the “exiting” log record could look like in Filtering out the first "exit" log record.

(FULLROW ~= "Function2" && !( ISO_TIMESTAMP == "2013-10-16 14:35:49,951" ))

Please note that the exclamation mark in the expression filter represents a logical NOT.

Filtering out the first "exit" log record

If you want to use alternating lines for multi-threaded applications you have to create an expression filter that can distinguish between the different threads, i.e. the information what thread has logged a log record has to be part of the log record.