Measuring Runtime Consumption with ABAP Profiling

You can start the ABAP Profiler for an individual ABAP program directly from the ABAP source code editor or from the Project Explorer view. Watch the demo "How to Profile an ABAP Program and Analyze the Result" later in this lesson to learn how to do this.

Using the trace parameters, you influence the size and granularity of the trace result. As shown in the figure, the most important settings are:

Profiling an ABAP Program is best done in the ABAP Profiling perspective. Watch the demo "How to Profile an ABAP Program and Analyze the Result" later in this lesson to learn how to do this.

In its standard configuration, the Profiling perspective consists of three parts:

When you double-click on an entry in the ABAP Traces view, the ABAP trace result opens on a new tab in the editor area.

By default, the focus lies on the Overview tab. This is the starting point for further analysis. The trace overview consists of the following parts:

The Condensed Hit List allows you to find the most expensive procedural units, for example, methods.

This list displays runtime measurements for trace events. It is called condensed because it restricts itself to procedural units. Database accesses and other trace events are not listed here.

Hint

If you are interested in all trace events, refer to the Hit List instead.

The list displays the data in aggregated form. Each procedural unit appears only once, no matter how often it was called and in how many different places. Columns Executions and Callers display the overall number of executions and the number of distinguishable direct call positions for this unit.

Column Total Time displays the amount of runtime in microseconds from the start to the finish of the call. If the unit was called more than once, the column displays the sum of the individual calls. Total Time lets you see the total contribution of the procedure calls. In the example, the program spent a total of 15,485 µs executing method MAIN( ) and a total of 3,451 µs executing method GET_FLIGHTS( ) .

Column Own Time (Specified and Unspecified ABAP Statements) displays the amount of runtime in microseconds without the time spent waiting for other procedural units. Let's have a closer look at method MAIN( ) . Although the total time is 15,485 µs , the value in this column is only 18 µs. This means that the method did hardly any processing itself but spent most of the time waiting for methods it called.

Column Own Time displays the amount of runtime in microseconds without the time spent waiting - not only for called procedural units but also for ABAP statements specified in the trace parameters. In the example, method GT_FLIGHTS( ) does not call any other methods therefore the value in Own Time (Specified and Unspecified ABAP Statements) is the same as the total time. But the value in Own Time is only 4 µs because the method spent almost all its time waiting for a database access.

The Aggregated Call Tree allows you to analyze the sequence in which procedural units were called.

If a call of a procedural is repeated (for example, in a loop), then the call only appears once in the aggregated Call Tree. The number in column Executions displays the number of repetitions.

Hint

If you are interested in an unaggregated display, refer to the Call Sequence instead.

In the example, method GET_FLIGHTS( ) was called by method MAIN( ) but did not call any other procedural units. Method WRITE( ) was also called by method MAIN( ), and it called method EXEC_WRITE( ), which in turn called method GET_NAME( ) and so on.

The Call Timeline allows you to visualize the call sequence and time consumed in the form of a diagram.

The diagram consists of two parts: An overview of the whole trace at the bottom and an enlarged detail on top. A toolbar on the left allows you to zoom in or out and to move the focus.

The ruler above the details diagram indicates the time going from left to right. Each bar illustrates one trace event with its start end time. The wider a bar is the more time was consumed by that trace event.

Left-click a bar to display its details in the Details Section of the Profiling Perspective. This way, you can find out the trace event a certain bar represents.

The diagram uses colors to distinguish different types of trace events : grey in different shades for system programs, green in different shades for procedural units, orange for database access, and so on.

Hint

Open the context menu anywhere on the diagram to show or hide the color legend. In our example, we hid the legend to keep the graphic simple.

Let's have a look at an example:

The long grey bar at the very top represents the runtime analysis.

In the second row, we see that the runtime analysis performs two preparatory database accesses before it calls the MAIN( ) method of the application.

In the third row, we see that the MAIN( ) method calls two methods, the GET_FLIGHTS( ) method and the WRITE( ) method.

The fourth row reveals the structure of methods GET_FLIGHTS( ) and WRITE( ). We can see that GET_FLIGHTS( ) does not call any procedural units (no green below the bar representing this method), but performs a single database access (one orange bar). The WRITE( ) method on the other hand does nothing else but call a single other method. This method is represented by the green bar below the bar that represents the WRITE method.

The graphical display in the Call timeline is a very good way to identify repeated database accesses.

Let's have a look at an example: The regular, comb-like pattern in the forth and fifth row hints at an iteration. The orange color makes it obvious that is not just ABAP coding but involves a repeated database access.

The Database Accesses tool allows you to find the database objects that were accessed and to identify the top consumers among database accesses. It is also a good way to identify repeated selects from the same database table.

The Database Accesses tool only displays trace events related to the database. For repeated database accesses, the runtime is aggregated. You find the number of executions in column Executions.

In the example, two tables were accessed: /DMO/AIRPORT and /DMO/CONNECTION. The one SELECT statement reading data from /DMO/CONNECTION took 16,525 µs, which was 5 % of the overall runtime, and the 40 executions of a SELECT SINGLE statement reading from /DMO/AIRPORT consumed 59,894 µs, or 18 % of the overall runtime.