SAPTechno

Note 851012 - SAPGUI: Performance trace - technical details

Header
Version / Date 1 / 2005-06-06
Priority Recommendations/additional info
Category Help for error analysis
Primary Component BC-FES-GUI Graphical User Interface
Secondary Components

Summary
Symptom

This note explains the content of the SAPGUI performance trace.

Other terms

performance mesasuring time roundtrip

Solution

Please use at least SAPGUI 6.40 patchlevel 10.

Activation:
1. In the option dialog <Hyperlink>|@44@|, select the "Options... " menu option and then choose the Trace tab. Under Mode, now activate Errors and Warnings. In the selection window, also activate the following switches:
[x] Performance
[x] Detailed Output

Details

ResponseTime =
time when packet is sent to server and a new packet from server returns. Network time is of course included. The difference between PauseResponseTime/EndResponseTime and BeginResponseTime/ResumeResponseTime is traced in brackets: (diff=16 ms)

Begin or Resume:
a communication step consisting of >= 1 roundtrips starts with a BeginResponseTime. From roundtrip 2 on ResumeResponseTime is traced since the response time is aggregated. Begin/ResumeInterpretationTime are similar.

Executing RFC request:
when RFC packets are sent this line can be traced more than once until the complete data is at the frontend.
When "Executing RFC request" is immediately followed by a "Sending RFC answer or Acknowledge", the RFC data is not complete yet. Then an Acknowledge is sent back and the next RFC packet comes. When finished the RFC calls are execute, e.g. OLE_FLUSH_CALL, DP_PUT_CLIENT_TABLE45A, TrSetProgressIndicator, etc.

Time aggregation:
When the whole communication is finished the aggregated times are traced.
This is the sum of all diffs between Begin/ResumeInterpretationTime and End/PauseInterpretationTime.
Aggregated frontend interpretation time :          1407 ms

This is the time diff which is sent to R/3 via diag (s. note 364625). It starts measuring when
the 1st packet is sent to R/3 and stops when the last packet returns from R/3:
Complete Request-answer time            :          2813 ms (from first frontend-request to last R/3 anser packet)

This is the sum of all diffs between Begin/ResumeResponseTime and End/PauseResponseTime.
Aggregated server response time         :          1203 ms (for 3 roundtrips)

Asymmetry of communication:
Complete Request-answer time >= Aggregated frontend interpretation time + Aggregated server response time
In asymmetric communication (e.g. 1 packet to server - 2 packets from server) we can't measure the server response time for the 2nd packet. Therefore this time is not included in the aggregated server response time.

Examples

*************** data to server ***************

=14>Performance: #roundtrips=1
=14>Performance: BeginResponseTime                      : 678665093 ms

We are sending packet 14 to the server and start measuring the time waiting for the server's response.

*************** data from server ***************

<15=Performance: PauseResponseTime                      : 678665109 ms (diff=16 ms)


<15=Performance: BeginInterpretationTime                : 678665109 ms
<15=Performance: Executing RFC request
<15=Performance:    RFC TrSetProgressIndicator
<15=Performance: PauseInterpretationTime                : 678665109 ms (diff=0 ms)

Packet 15 has arrived and is processed. It contain an RFC call TrSetProgressIndicator (maybe the "compiling" status message). The time for interpreting the packet was almost 0 ms.

*************** data from server ***************

<16=Performance: ResumeInterpretationTime                : 678665312 ms
<16=Performance: Executing RFC request
<16=Performance:    OLE_FLUSH_CALL (+ RFC queue): 322654 microsec
<16=Performance: PauseInterpretationTime                : 678665640 ms (diff=328 ms)

The measuring of the interpretation time is now resumed not begin! Packet 16 contains an RFC OLE_FLUSH_CALL. The execution of all the automation calls needed 322654 microsec. For details for every call you have to switch on the automation trace according to note 158985.

<16=Performance: Sending RFC answer or Acknowledge
*************** data to server ***************

=16>Performance: communication step goes on: #roundtrips=2
=16>Performance: ResumeResponseTime                      : 678665640 ms

The RFC answer is sent to the backend.

*************** data from server ***************

<17=Performance: PauseResponseTime                      : 678666093 ms (diff=453 ms)
<17=Performance: ResumeInterpretationTime                : 678666093 ms
<17=Performance: Executing RFC request
<17=Performance:       DP_PUT_CLIENT_TABLE45A:   3050 microsec
<17=Performance:       DP_PUT_CLIENT_TABLE45A:    729 microsec
<17=Performance:       DP_PUT_CLIENT_TABLE45A:   1101 microsec
<17=Performance:       DP_PUT_CLIENT_TABLE45A:   1591 microsec
<17=Performance:       DP_PUT_CLIENT_TABLE45A:    686 microsec
<17=Performance:       DP_PUT_CLIENT_TABLE45A:    981 microsec
<17=Performance:       DP_PUT_CLIENT_TABLE45A:    821 microsec
<17=Performance:       DP_PUT_CLIENT_TABLE45A:   1554 microsec
<17=Performance:       DP_PUT_CLIENT_TABLE45A:   1377 microsec
<17=Performance:       DP_PUT_CLIENT_TABLE45A:    715 microsec
<17=Performance:       DP_PUT_CLIENT_TABLE45A:   1112 microsec
<17=Performance:    OLE_FLUSH_CALL (+ RFC queue): 989679 microsec
<17=Performance: PauseInterpretationTime                : 678667078 ms (diff=985 ms)
<17=Performance: Sending RFC answer or Acknowledge
*************** data to server ***************
=17>Performance: communication step goes on: #roundtrips=3
=17>Performance: ResumeResponseTime                      : 678667078 ms

Packet 17 contains many data provider RFC calls (DP_PUT_*: sending tables backend=>frontend, DP_GET_*: frontend=>backend). These Dataprovider RFC calls are always piggy-backed by an OLE_FLUSH_CALL.
Every RFC is followed by an answer or Acknkowledge packet.

*************** data from server ***************
<18=Performance: PauseResponseTime                      : 678667812 ms (diff=734 ms)
<18=Performance: ResumeInterpretationTime                : 678667812 ms
<18=Performance: ActivateSessionForUserInput
<18=Performance: EndInterpretationTime                  : 678667906 ms
<18=Performance: Aggregated frontend interpretation time : 1407 ms
<18=Performance: Complete Request-answer time            : 2813 ms (from first frontend-request to last R/3 anser packet)
<18=Performance: Aggregated server response time         : 1203 ms (for 3 roundtrips)

The last packet 18 for this step arrives. Therefore the aggregated interpretation time and server response time is traced.

Example with a big Dynpro (> 30k)

Big Dynpro are sent as blobs via an RFC call (VER01736)
This leads to many RFC roundtrips before execution of RFC func GUICORE_BLOB_DIAG_PARSER.

*************** data to server ***************

=34>Performance:    #roundtrips=1
=34>Performance:    BeginResponseTime                      : 679424406 ms

*************** data from server ***************

<35=Performance: PauseResponseTime                      : 679424703 ms (diff=297 ms)
<35=Performance: BeginInterpretationTime                : 679424703 ms
<35=Performance: Executing RFC request
<35=Performance: PauseInterpretationTime                : 679424703 ms (diff=0 ms)
<35=Performance: Sending RFC answer or Acknowledge

RFC call not finished, because not all data here => wait for next packet

...

*************** data from server ***************

<41=Performance: PauseResponseTime                      : 679424781 ms (diff=16 ms)
<41=Performance: ResumeInterpretationTime                : 679424781 ms
<41=Performance: Executing RFC request
<41=Performance:    RFC GUICORE_BLOB_DIAG_PARSER
<41=:

The RFC can be executed finally when all packets are there (35-41).

Affected Releases
Software Component Release From Release To Release And subsequent
BC-FES-GUI60640640

Related Notes
1520240Slow SAPGUI in Netweaver Business Client (NWBC)
521343SAP GUI: Performance trace
364625Interpretation of response time in 4.6
158985Automation: How do I generate an automation trace?