Measuring Runtime Consumption with ABAP Profiling

Objectives

After completing this lesson, you will be able to:

  • Profile an ABAP program
  • Detect sequential reads using ABAP Profiling

The ABAP Profiler Tool

The ABAP Profiler is an ABAP tracing tool that has been integrated into ABAP Development Tools (ADT). It is available for all executable ABAP code, for example, global classes or ABAP unit tests.

Starting from the ABAP trace (the results of the ABAP Profiler), you can:

Analyze the Performance

  • Identify runtime-expensive statements
  • Identify performance hot spots where you might want to concentrate your refactoring effort
  • Compare the performance of different implementations to choose the most effective design

Analyze the Program Flow

  • Analyze the call hierarchy in your application
  • Identify excessive or unnecessary use of modularization units

Analyze the Database Access

  • Identify repeated database operations, for example, SELECT statements in loops
  • Identify the database objects (tables and views) that are accessed by your application

ABAP Profiler Execution

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.

Trace Parameters

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

Aggregation Settings

In this section you specify how the profiler handles repeated executions, for example, repeated calls of the same method. The more the profiler aggregates, the less space is needed to store the trace result. As a kind of a drawback, some analysis tools are not available on aggregated trace results.

You can choose from three options:

  • No aggregation, largest file size, all tools available.
  • Partial aggregation (per call statement) , medium file size, Call Sequence not available.
  • Full aggregation, smallest file size, Aggregated Call Tree not available.

Statement Granularity

In this section, you can specify how granular the measurement will be. You can choose from three popular presets or, by choosing Custom Statements, enter your own selection under Details.

Again, your choice has an influence on the file size and the informative value of the trace result.

The following presets exist:

  • Only procedural units – small file size, the runtime of all statements is attributed to the surrounding procedural unit (method).
  • Procedural units, SQL – medium file size, the runtime of database accesses is traced separately and not attributed to the surrounding procedural.
  • Procedural units, SQL, internal tables – large file size, the runtime of database accesses and operations on internal tables are traced separately and not attributed to the surrounding procedural.

Start option

In this section, you can choose when you want to start the trace. You have the following options:

  • Immediately – the entire program execution will be traced.
  • Explicit switch on and off – the program execution starts with the trace switched off. When the program reaches a breakpoint, you can choose Switch ABAP Trace On/Off from the context menu for the breakpoint.

The ABAP Profiling Perspective

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:

Editor Area

The editor area is identical to the editor area in the ABAP perspective and the Debugger perspective. When you open a trace result, it will be displayed in this area on a new tab.

Trace Area

By default, this area consists of the following views:

The ABAP Traces view displays the trace results, organized by project and filtered by your user.

On the ABAP Trace Requests view, you can manage your requests and create new ones.

Details Area

By default, this area contains the Properties view. If in the Editor area the focus lies on a repository object, the properties view displays the metadata of this repository object.

When analyzing a trace result, the properties view is used to display the properties of a runtime measurement.

The Trace Overview

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:

General Information

In the general Information section, you find administrative information about this trace result:

When was the trace created? who created it? With which aggregation settings? And, so on.

Runtime Distribution

The runtime distribution provides you with an information of how the traced runtime was distributed across the following ABAP components.

  • ABAP – the run time spent processing ABAP code, not including ABAP system programs.
  • Dababase – The run time spent in the database, performing database operations.
  • System – The run time spent processing ABAP code in system programs.

Analysis Tools

This section gives you a short description of the analysis tools integrated into the trace result display. Choose one of the links to navigate into the respective tool. Alternatively, you can navigate using the tabs below the Overview display.

ABAP Trace Analysis Tools

The Condensed Hit List

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

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.

How to Profile an ABAP Program and Analyze the Result

In this demonstration, you will see how to profile an ABAP application and analyze the results.

Timeline Tools

The Aggregated Timeline

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:

First row

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

Second Row

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

Third Row

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

Fourth Row

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.

Repeated Database Accesses in the Call Timeline

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.

Database Accesses

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.

How to Detect Sequential Selects Using ABAP Profiling

In this demonstration, you will see how to analyze a program containing repeated SELECT statements.

Detect Performance Issues Using ABAP Profiling

You notice that your code takes a long time to run. You perform a runtime analysis using ABAP Profiling and improve the performance of your code.

Template:

  • /LRN/CL_S4D401_ATS_UNIT_TEST (Global Class)

Solution:

  • /LRN/CL_S4D401_ATS_PROFILING (Global Class)

Task 1: Copy Template (Optional)

Copy the template class. If you finished the previous exercise, you can skip this task and continue editing your class ZCL_##_SOLUTION.

Steps

  1. Copy class /LRN/CL_S4D401_ATS_UNIT_TEST to a class in your own package (suggested name: ZCL_##_SOLUTION, where ## stands for your group number).

    1. In the Project Explorer view, right-click class /LRN/CL_S4D401_ATS_UNIT_TEST to open the context menu.

    2. From the context menu, choose Duplicate ....

    3. Enter the name of your package in the Package field. In the Name field, enter the name ZCL_##_SOLUTION, where ## stands for your group number.

    4. Adjust the description and choose Next.

    5. Confirm the transport request and choose Finish.

  2. Activate the copy.

    1. Press Ctrl + F3 to activate the class.

Task 2: Profile the Code

Perform a runtime measurement with the ABAP Profiler using the default settings. Then display and analyze the result.

Steps

  1. Start the runtime measurement with the ABAP Profiler.

    1. Display the source code of your ABAP class (ZCL_##_SOLUTION) in the editor.

    2. Right-click in the editor and choose Profile As → ABAP Application (Console).

    3. In the Trace Parameters dialog box, choose Finish without changing any of the settings.

  2. Switch to the Profiler perspective.

    1. Choose Window → Perspective → Open Perspective → Other.

    2. Choose ABAP Profiling and press Enter.

  3. Wait for the trace to finish (wait for green progress indicator in the bottom right corner to disappear). Then open the trace result.

    1. In the ABAP Traces view on the bottom, right-click on your project and choose Refresh.

    2. Double-click the most recent trace (this is the topmost entry under your project). The trace opens in the view above the list.

  4. Analyze the trace overview.

    1. The overall runtime and the distribution between ABAP and Database are displayed in the lower section of the Overview,

  5. Analyze the trace details to answer the following questions:

    1. To find the processing block that consumed the most runtime, switch to the Condensed Hit List tab and sort the display descending by the eighth column, labeled % Own Time (specified and Unspecified ABAP Statements).

    2. To find the most expensive statements, switch to the Hit List tab and sort the display descending by the sixth column, labeled % Own Time.

    3. To locate the most expensive code in the call tree, switch to the Aggregated Call Tree view.

  6. Display the Call Timeline (not aggregated) and zoom in to visualize the repeated SELECT statements.

    1. Switch to the Call Timeline tab.

    2. Use the slider on the left to zoom in until you can see the striped orange and white pattern that indicates the presence of database accesses that are repeated in a high frequency.

Task 3: Improve Code

Eliminate the repeated SELECT SINGLE access to database table /LRN/PASSFLIGHT. To do so, extend the SELECT statement in method get_flights_by_carrier of class lcl_passenger_flight to read all required data for the passenger flights. Buffer the data in a static attribute of table-like type (suggested name: flights_buffer). In the constructor of class lcl_passenger_flight, first try to read the data from flights_buffer. Only if that is unsuccessful, read the data from the database.

Steps

  1. Return to the ABAP perspective and edit the implementation of method get_flights_by_carrier of class lcl_passenger_flight. Extend the field list of the SELECT statement to also read the airplane type, the number of maximum and occupied seats, the ticket price, and the currency code.

    1. From the Eclipse menu, choose Window → Perspective → Open Perspective → ABAP. Alternatively, choose the short cut icon in the upper right corner of the Eclipse window.

    2. Open the implementation of method get_flights_by_carrier of class lcl_passenger_flight and adjust the code as follows:

      Code Snippet
      Copy code
      Switch to dark mode
      123456789
      
    SELECT
      FROM /lrn/passflight
    FIELDS carrier_id, connection_id, flight_date,
           plane_type_id, seats_max, seats_occupied,
           price, currency_code
     WHERE carrier_id = @i_carrier_id
      INTO TABLE @DATA(keys).

  2. Use quick fixes to rename the inline declared variable keys to flights_buffer and key to flight.

    1. In the INTO clause of the SELECT statement, place the cursor on keys and press Ctrl + 1 to display a list of available quick fixes.

    2. From the list of quick fixes, choose Rename keys.

    3. While keys is still highlighted, enter the new name flights_buffer.

    4. In the INTO clause of the LOOP AT statement, place the cursor on key and press Ctrl + 1 to display a list of available quick fixes.

    5. From the list of quick fixes, choose Rename key.

    6. While key is still highlighted, enter the new name flight.

  3. Use a quick fix to convert local variable flights_buffer to a (static) attribute.

    1. In the INTO clause of the SELECT statement, place the cursor on flights_buffer and press Ctrl + 1 to display a list of available quick fixes.

    2. From the list of quick fixes, choose Convert flights_buffer to attribute.

  4. Navigate to the definition of static attribute flights_buffer and complete the definition of structure type helper_type.

    1. Place the cursor on flights_buffer and press F3.

      Alternatively, hold down the Ctrl key and left-click on flights_buffer.

    2. Add suitable types for the components of structure type helper_type.

      Note

      The easiest way is to use the corresponding fields of database table definition /LRN/PASSFLIGHT .

    3. Complete the definition of type helper_type as follows:

      Code Snippet
      Copy code
      Switch to dark mode
      12345678910111213
      
  TYPES: BEGIN OF helper_type,
           carrier_id     TYPE /lrn/passflight-carrier_id,
           connection_id  TYPE /lrn/passflight-connection_id,
           flight_date    TYPE /lrn/passflight-flight_date,
           plane_type_id  TYPE /lrn/passflight-plane_type_id,
           seats_max      TYPE /lrn/passflight-seats_max,
           seats_occupied TYPE /lrn/passflight-seats_occupied,
           price          TYPE /lrn/passflight-price,
           currency_code  TYPE /lrn/passflight-currency_code,
         END OF helper_type.
  CLASS-DATA: flights_buffer TYPE TABLE OF helper_type.

  5. Use a quick fix to rename structure type helper_type to st_flights_buffer.

    1. In the TYPES statement, place the cursor on helper_type and press Ctrl + 1 to display a list of available quick fixes.

    2. From the list of quick fixes, choose Rename helper_type.

    3. While helper_type is still highlighted, enter the new name st_flights_flight.

  6. Adjust the implementation of the constructor of lcl_passenger_flight. Before the SELECT SINGLE statement, read a single row from internal table flights_buffer. Use the import parameters of the constructor to identify the table row.

    1. At the beginning of the method, add the following code:

      Code Snippet
      Copy code
      Switch to dark mode
      12345
      
  DATA(flight_raw) = flights_buffer[ carrier_id = i_carrier_id
                                     connection_id = i_connection_id
                                     flight_date = i_flight_date ].

  7. Adjust the INTO clause of the SELECT SINGLE statement. Reuse the already declared structure flight_raw and add addition CORRESPONDING FIELDS OF.

    1. In the INTO clause of the SELECT SINGLE statement, replace@DATA(flight_raw) with @flight_raw. Note the syntax error The data type of the component "CONNECTION_ID" of "FLIGHT_RAW" is not compatible with the data type of "SEATS_MAX" (see long text).

    2. Adjust the code as follows:

      Code Snippet
      Copy code
      Switch to dark mode
      123456789
      
SELECT SINGLE
      FROM /lrn/passflight
    FIELDS plane_type_id, seats_max, seats_occupied, price, currency_code
     WHERE carrier_id    = @i_carrier_id
       AND connection_id = @i_connection_id
       AND flight_date   = @i_flight_date
      INTO CORRESPONDING FIELDS OF @flight_raw .

  8. Surround the read access to flights_buffer with an exception handling. Make sure you only read the flight data from the database in case the ABAP runtime raises exception CX_SY_ITAB_LINE_NOT_FOUND.

    1. Adjust the code as follows:

      Code Snippet
      Copy code
      Switch to dark mode
      12345678910111213141516
      
  TRY. 
    DATA(flight_raw) = flights_buffer[ carrier_id = i_carrier_id
                                       connection_id = i_connection_id
                                       flight_date = i_flight_date ].

   CATCH cx_sy_itab_line_not_found. 
     SELECT SINGLE
       FROM /lrn/passflight
     FIELDS plane_type_id, seats_max, seats_occupied, price, currency_code
      WHERE carrier_id    = @i_carrier_id
        AND connection_id = @i_connection_id
        AND flight_date   = @i_flight_date
       INTO CORRESPONDING FIELDS OF @flight_raw .
 ENDTRY.

  9. Adjust the IF condition after the SELECT statement. Instead of probing system field sy-subrc make sure structure flight_raw is not empty.

    1. Replace IF sy-subrc = 0. with IF flight_raw IS NOT INITIAL.

Task 4: Re-check the Code

Activate and test your global class. Execute the class as console app. Repeat the profiling to measure the performance improvement.

Note

If you want, you can re-run the unit test and the ABAP Test Cockpit analysis to make sure you did not introduce any new issues.

Steps

  1. Activate your global class and execute it as console app.

    1. Press Ctrl + F3 to activate the class.

    2. Press F9 to execute the class as console app.

  2. Start the runtime measurement with the ABAP Profiler.

    1. Right-click in the editor and choose Profile As → ABAP Application (Console).

    2. In the Trace Parameters dialog box, choose Finish without changing any of the settings.

  3. Switch to the Profiler perspective and analyze the trace overview.

    1. Choose Window → Perspective → Open Perspective → ABAP Profiling.

    2. In the ABAP traces view, choose Refresh. Alternatively, you can place the cursor anywhere in the ABAP Traces view and press F5 to re-load the list of trace results.

    3. Double-click the most recent trace (this is the topmost entry under your project).

    4. The overall runtime and the distribution between ABAP and Database are displayed in the lower section of the Overview.

  4. Analyze the trace details to answer the following questions:

    1. To find the processing block that consumed the most runtime, switch to the Condensed Hit List tab and sort the display descending by the eighth column (% Own Time (specified and Unspecified ABAP Statements).

    2. To find the most expensive statements, switch to the Hit List tab and sort the display descending by the sixth column, labeled % Own Time.

Log in to track your progress & complete quizzes