A line in a SQL trace might contain a timestamp information, among others :
WAIT #140736371587856: nam='PGA memory operation' ela= 1458 p1=0 p2=0 p3=0 obj#=-1 tim=13218904558749This timestamp is derived from an OS kernel high-resolution time [1]. The high-resolution time is elapsed time since some arbitrary time in the past. In other words, it isn’t correlated in any way to the time of the day or boot time. Consequently, it can’t be simply converted to Unix Epoch time. Normally, that isn’t an issue, because high-resolution timestamps are used for measuring intervals, not for timestamping. However, once I had to correlate a single wait event outlier to OS performance data and ASH, and therefore, had to find a way to convert the high-resolution time to a human readable format. In this blog post, I’ll be presenting the methodology I came up with, and provide a couple of C programs as well. I chose C because of its low overhead, which is relevant when measuring time in microseconds. All programs compile on Linux and Solaris – I used conditional compiling for calling specific low-level OS kernel functions.
But, in the first place, why would somebody use arbitrary timestamps instead of wall clock time for measuring time intervals? One reason is efficiency – the former introduces far less overhead, which can be easily measured with benchmark_timer.c:
benchmark_timer
Duration of getting timestamps [ns]:
------------------------------------
high-resolution: 99
wall clock : 8421
high-resolution: 57
wall clock : 100
high-resolution: 59
wall clock : 73
high-resolution: 60
wall clock : 68The other is that, unlike wall clock time, high-resolution time isn’t a subject to adjustments:
The gethrtime() function returns the current high-resolution real time.
Time is expressed as nanoseconds since some arbitrary time in the past.
It does not necessarily represent time elapsed since boot, nor it is
not correlated in any way to the time of day, and thus is not subject
to resetting or drifting by way of adjtime(2) or settimeofday(3C). The
hi-res timer is ideally suited to performance measurement tasks, where
cheap, accurate interval timing is required.
In other words, although the reference point is arbitrary, it doesn’t change over time until the server reboot.
I visualized both time systems in order to work out the high-resolution time reference point:
Legend:
t_hr : current high-resolution time,
t_epoch(t_hr): current time expressed as UNIX Epoch time,
t_epoch(0) : high-resolution reference time expressed as UNIX Epoch time.
As the units in both time systems are the same, any high-resolution time t_hr can be converted to Unix Epoch time as follows:
(1) t_epoch(t_hr) = t_epoch(0) + t_hr
While t_hr and t_epoch(t_hr) can be easily retrieved from OS, t_epoch(0) is unknown.
But, the equation (1) can be rewritten as follows:
(2) t_epoch(0) = t_epoch(t_hr) – t_hr
The equation (2) tells us that, if we get both Unix Epoch and high-resolution time at the “same” time, we can calculate the high-resolution reference time in Epoch. So, I wrote get_t_hr0.c which, basically, gets the current Unix Epoch and high-resolution times and calculates their difference:
get_t_hr0
1558015736559599The returned time is in microseconds – to match the timestamp in the SQL trace.
Of course, there’ll inevitably be some marginal error, because the calls to get the current high-resolution and Unix Epoch time are executed sequentially. However, as the program is written in C, this error is negligible. Another possible source of error is a wall clock time drift, so it’s best to run get_t_hr0 during or immediately after tracing.
Finally, convert_tim_to_localtime.py converts the timestamp from the trace file to a human readable format. The script takes the timestamp from SQL trace and high-resolution reference time expressed in Unix Epoch time (in microseconds) as its arguments, sums them and displays the time in a human readable format.
python convert_tim_to_localtime.py 13218904558749 1558015736559599
2019-10-16 16:04:01.118348In summary, take the following steps to convert the timestamp from SQL trace (tim) to the human readable format:
1. Get the high-resolution time reference in Unix Epoch Time (get_t_hr0.c)
2. Take the time from Oracle trace.
3. Convert the timestamp to the human readable format (convert_tim_to_localtime.py tim t_hr0).
References:
[1] Cary V. Millsap, Mastering Oracle Trace Data, 2nd edition. August 4, 2016
