measure http execution (req./res.) time
problem
When measuring HTTP response times in ABAP, the class CL_ABAP_RUNTIME unexpectedly returns microseconds instead of the expected seconds.
requirement
In an implementation project I had the requirement of adding some simple observability when calling an external API. We wanted to track the time it took for an HTTP request to actually receive a response (before running into a timeout, that is). The tracked time is then simply logged.
Sounds simple, right?
implementation, insights and learning
I thought so too! So I started by implementing it using the more "modern" approach, the class CL_ABAP_RUNTIME and its high precision timer (CREATE_HR_TIMER).
This is straight forward and looks like this:
DATA(timer) = cl_abap_runtime=>create_hr_timer( ).
DATA(timer_start) = timer->get_runtime( ).
DATA(lo_response) = lo_client->execute( if_web_http_client=>get ).
DATA(timer_end) = timer->get_runtime( ).
" log actual time taken in seconds
To my surprise the logged result (in seconds) didn't match the actual observed behavior at all! Instead of actually logging N-seconds it was usually just a few µ-seconds. That didn't make a lot of sense to me so I started digging and came to the conclusion that the regular, good old, GET RUN TIME FIELD ... statement does the job and gives us exactly the time back we expected.
But ... why is that?
An excellent question! Within the documentation of the class as well as the direct ABAP statement there are some hints but nothing concrete. For example, the system class documentation talks about:
- "In contrast to the statement GET RUN TIME, these objects can be used to perform different measurements with different levels of precision ... for each internal session."
But it doesn't actually show/tell what the different "levels of precisions" are. In contrast the GET RUN TIME documentation states:
- "... does not accumulate the time taken to execute individual ABAP statements. Instead it defines actual points in time with respect to the processor time." and
- "... the statement respects the time taken for an internal session to be rolled out of the memory ..."
conclusion
So what does all of this tell us?
I came to the conclusion that the actual AS ABAP session is rolled out when waiting for an HTTP response and waits until the ICM has handled all the network stuff for us, coming back to the ABAP session with a response. This 'waiting' is better captured by the GET RUN TIME ... statement as - and I quote - "In a conceptual sense, a time defined using GET RUN TIME can be viewed as a time stamp".
The runtime class therefore seems to be "too precise" (even with low precision?) as it measures active CPU load/processing time within ABAP sessions, excluding roll out periods. But since we're interested in the wall-clock time of the HTTP execution including the network wait time (the roll out period) using the classic GET RUN TIME FIELD ... statement gives us the solution.
References/Links
Technical Context:
SAP EWM, S/4 On-Prem, no SAP AIF, classic /SCWM/CL_LOG for logging