Statistical Records Part 2: RFC Statistics
My Statistical Records Part 1: Inside STAD  introduced the statistical records of an ABAP application server. This time I would like to talk about the internal structure of the statistical records. As an example the RFC records are introduced. This blog is about SAP_BASIS 700 which comes with Netweaver 2004s. The overall concept described here has not changed very much since release 4.6C, but details could be different.
Structure of Statistical Records
First let’s have a look at the structure of the statistical records. A statistical record consists of several parts. The first part is the so-called main record where we find information like transaction code and program name, start and end time, response time, etc. This main record is part of every statistical record.
Additionally we may find other optional parts. Whenever database operations have been performed we will get a database subrecord for this dialog step. If stored procedures were executed on the database we will get a subrecord for DB procedures. If a report has been executed as a batch job we will get a batch subrecord, telling us e. g. the job name and job ID. The following picture illustrates the structure of a statistical record.
All these subrecords are optional, and the SAP kernel will generate these on demand. This saves a lot of disk space in the file system and speeds up writing and reading the statistics file. Here is the complete list of subrecords:
- batch subrecords
- database subrecords
- db table subrecords
- db procedure subrecords
- spool print subrecords
- spool activity subrecords
- ADM message subrecords
- client information subrecords
- RFC client subrecords
- RFC server subrecords
- RFC client destination subrecords
- RFC server destionation subrecords
- http client subrecords
- http server subrecords
- http client destination subrecords
- http server destionation subrecords
- smtp client subrecords
- smtp server subrecords
- smtp client destination subrecords
- smtp server destionation subrecords
- VMC subrecords
- ESI subrecords (SAP_BASIS 710)
- ESI destination subrecords (SAP_BASIS 710)
Don’t get confused, we’ll not discuss all of them in detail now. Instead let’s have a closer look at the RFC subrecords.
What are RFC statistics records?
The RFC statistical records can tell us some details of the RFC activity of a program. If a program performs RFC calls then you will get RFC client and RFC client destination records. An RFC server process receives RFC calls and will write RFC server and RFC server destination records. If the RFC server process itself performs RFC calls then it is a client and a server simultaneously. In this case you will see all four different RFC subrecords within one statistical record. STAD displays the RFC overview, if RFC subrecords are present.
Let’s start with the RFC client records. The following picture is a screenshot from STAD for an overview of RFC client process.
We can see that 30 RFC calls have been performed over (at least) 5 connections to 5 destinations for this dialog step. The calling time for the client was 7.212 ms in total, while the remote execution time (for all servers) was 6.688 ms. The calling time includes codepage conversions and network transport. The remote execution time is measured by the RFC server and includes authority check and function execution only. 11.330 bytes have been sent to the servers, and 14.225 bytes have been received. The idle time is the time between two subsequent RFC calls for an open connection. There are two highlighted fields on this screen: Connections and Calls. You may click on these fields to display more details. Let’s continue with the calls, which will display the RFC client records.
An RFC client record describes exactly one single RFC call. The most important information is the function name, the execution time of this function, and the amount of data transported in both directions. The following screenshot of STAD shows an RFC client record.
This screen shows an RFC call of a function called START_TCOLL_REPORT. The Call number is 6, indicating that this call is the 6th call over this particular RFC connection. The Connection ID of this connection is displayed (a GUID) as well as the name of the destination. The calling time and the remote execution time are given, and a few hundred bytes have been transferred between client and server. The time for data transfer (data send time and data receive time) is less than 1 ms. The field communication step shows that sending and receiving happened during the same dialog step which should be the normal situation for a synchronous RFC. For asynchronous RFC sending and receiving may happen during different dialog steps.
Of course it is not possible to log each individual RFC call in this way. The amount of data would be too large to handle. Instead the SAP kernel logs the five most expensive RFC client records only, all others are discarded. Expensive means “expensive in terms of execution time”. The profile parameter stat/rfcrec controls the maximum number of RFC subrecords (default value = 5). Increasing this value is dangerous, because the file system will be flooded with statistical records. And it affects the system performance, because all these statistical records have to be processed by the SAP workload collector (which will be the topic of another blog).
Instead of logging every single RFC call the RFC client information is summarized, and for each RFC connection an RFC client destination record is written. From this record we can see how many RFC calls were performed for this particular connection, how many bytes have been transported in total, and of course the total execution time. Again the maximum number of RFC client destination records is limited by the profile parameter stat/rfcrec. If a client performs RFC calls across more than 5 connections than only the 5 most expensive connections (in terms of execution time) are logged. The following screenshots of STAD shows an RFC client destination record.
This screen shows the details for a particular RFC connection. We can see the connection ID, the type of RFC (synchronous), the types of the local and the partner engines (R/3 System in both cases), and the combination of user name and client number used for logon. Destination is the name of the RFC destination (see Tx SM59). Instance is the name of the local application server from where this call was issued, and IP address is the local IP address. From the remote application server we see Partner instance, Partner IP address, and Partner Release (not all RFC server will provide this information, but a SAP application server will do so). In total six calls have been performed for this particular connection during this dialog step, and the total calling time was 2624 ms.
To show the complete picture the following STAD screenshots depicts the RFCserver records. Again we start with the overview.
This screen shows the overview for an RFC server process during a dilaog step. One incoming RFC call from one connection has been received. The RFC server has received 12.415.680 bytes, and the server execution time (authority check and function module execution) was 711 ms, while the calling time (including code page conversions and network transfer) was 6.656 ms.
Let’s go to the details of that particular RFC call (click on the hotspot behind the field Calls). The following screen is very similar to the one of an RFC client. We can see the name of the executed function module, the connection ID, and the destination name NONE (an RFC call within the same application server) as well as the performance metrics.
The next screenshot shows the RFC server destination record. It shows the details of the RFC connection and the summary of all RFC calls for this connection. We can see that this connection has been used for an asynchronous call without a response. The details of this screen are similar to the RFC client destination record (see above).
Please note that the lifetime of an RFC connection is independent of a dialog step. Depending of the scenario and the implementation an RFC connection may be used during several subsequent dialog steps of an application or program. The RFC client/server destination records are created in the context of a dialog step and will always show the activity for a connection during this dialog step.
There are some details of an RFC server process which are important to know. Let’s assume an RFC client performs several calls to an RFC server. If the connection is not closed explicitly then it will be used for all these calls. But when will the RFC server process write a statistical record? After each RFC call? No, that’s not the case. The SAP kernel will write a statistical record after the roll-out of the RFC server process from the work process, and the roll-out will occur if no subsequent RFC call is received within a timeframe of 500 ms. At that point the data for the statistical record is collected, and this includes the RFC subrecords, of course. If subsequent RFC calls follow within 500 ms then the context of the RFC server will not be rolled out from the work process. This is a performance optimization, because it avoids frequent roll-out and roll-in which would increase the RFC execution time. Please note that the overall response time of an RFC server process may be 500 ms larger than the calling time. The overall response time is shown by STAD on the main list, while the calling time is shown with the RFC details (see the RFC server destination record).
The design principle of client/server single records and client/server destination records has also been used in a similar way for the http and smtp subrecords. Check it out, STAD will display all of them.
To learn more about RFC please read the interesting article by Masoud Aghadavoodi Jolfaei and Eduard Neuwirt : Master the five remote function call (RFC) types in ABAP.
If you want to learn more about SAP performance optimization the following book might be interesting for you: T. Schneider, SAP Performance Optimization Guide, 4th ed., SAP PRESS, ISBN 978-1-59229-069-7