Log Jump¶
The Log Jump features bridge the gap between log files and LiveRecorder recordings by allowing users to match lines in log entries with particular times during the execution history of a program. This matching can be achieved in two different ways:
- Using human-readable wall clock times (a date and time) in log entries.
- Adding the UDB time in execution history to log entries.
Using wall clock times¶
The ugo wallclock
command in UDB can be used to go to the point in execution history
corresponding to a wall clock time.
This feature uses calls to gettimeofday
or clock_gettime
(with clock ID set to
CLOCK_REALTIME
) made by the recorded process.
See the availability of wall clock times section for details.
For example an application produces the following log file:
[2020-02-07 15:45:24.235925Z] Doing something: my_variable=42 [2020-02-07 15:45:25.201735Z] Something else [2020-02-07 15:45:25.256095Z] Doing something: my_variable=3 [2020-02-07 15:45:25.763437Z] Doing something: my_variable=-1 [2020-02-07 15:45:25.768799Z] Doing something: my_variable=12 [2020-02-07 15:45:26.374479Z] Something else
Investigation shows that something unexpected happened at the highlighted line. It’s possible to load the recording and go to the time at which the highlighted log line was produced:
$ udb program-recording.undo [...] (udb) ugo wallclock 2020-02-07 15:45:25.763437Z Going to time 241,990. Program received signal SIGTRAP, Trace/breakpoint trap. 0x00007ffe0affdc50 in gettimeofday () (udb) backtrace #0 0x00007ffe0affdc50 in gettimeofday () #1 0x000055d4ef0a2258 in format_current_time () at logging.c:200 #2 0x000055d4ef0a22ef in my_log (...) at logging.c:350 #3 0x000055d4ef0a2366 in do_work (...) at my_program.c:300 #4 0x000055d4ef0a23a7 in main_loop () at my_program.c:500 #5 0x000055d4ef0a23bc in main () at my_program.c:600
The ugo wallclock
command jumps to the point in the recording where the gettimeofday()
function was called.
The above backtrace is inside the logging functions, but it’s possible to go back to the code which
called my_log
by using the reverse-finish
command multiple times:
(udb) reverse-finish 200 gettimeofday(¤t_time, NULL); (udb) reverse-finish 350 printf("[%s] %s\n", format_current_time(), message); (udb) reverse-finish 300 my_log("Doing something: my_variable=%d", my_variable); (udb) print my_variable $1 = -1
It’s also possible to display the wall clock time at the current point in execution history:
(udb) ugo wallclock 2020-02-07 15:45:25.763437Z Going to time 241,990. [...] (udb) uinfo wallclock 2020-02-07 15:45:25.763437 UTC+0000 +/- 0 microseconds
Availability of wall clock times¶
UDB’s representation of time in execution history is related to the flow of the program, not the
actual wall clock time. To provide a match between the two, UDB inspects the recording and finds
calls to the gettimeofday
function or the clock_gettime
function (with clock ID, the first
argument, set to CLOCK_REALTIME
).
This means that an exact match between wall clock time and a point in the execution history can be
obtained only at the exact time when one of the supported functions are called.
For all other times, a linear interpolation between nearby calls to time functions is performed and
the confidence interval is shown (+/- N microseconds
).
For instance, in the following example, a wall clock time corresponding to a gettimeofday
function call is shown with +/- 0 microseconds
as the confidence interval.
Moving to some other code, for instance by setting a breakpoint and continuing, will show an
approximate wall clock time with +/- 928151 microseconds
confidence interval:
(udb) ugo wallclock 2020-02-07 16:05:03.246406Z Going to time 17,998. [...] (udb) uinfo wallclock 2020-02-07 16:05:03.246406 UTC+0000 +/- 0 microseconds (udb) break some_other_function Breakpoint 1 at 0x55d4ef0a2310: file my_program.c, line 550. (udb) continue Continuing. Breakpoint 1, some_other_function () at my_program.c:550 550 { (udb) uinfo wallclock 2020-02-07 16:05:04.173958 UTC+0000 +/- 928151 microseconds
Warning
clock_gettime
is supported only when used with CLOCK_REALTIME
as clock ID.
CLOCK_REALTIME_COARSE
can generate wall clock times with very low accuracy, lower than
gettimeofday
, so the results would be confusing.
Other types of clocks produce values which cannot be correlated to the wall clock time.
Timezones¶
The ugo wallclock
command understands timezones passed as part of the wall clock time, for
instance a time string ending with CET+0100
will be interpreted as referring to Central European
Time, while one ending with CST-0600
will be interpreted as referring to Central Standard Time.
If no timezone information is specified the time is interpreted as being relative to UTC
(Coordinated Universal Time) by default. You can change this with the uset timezone
command:
(udb) uinfo wallclock 2020-02-07 16:05:04.948217 UTC+0000 +/- 0 microseconds (udb) uset timezone US/Pacific Wallclock timezone set to US/Pacific (udb) uinfo wallclock 2020-02-07 08:05:04.948217 PST-0800 +/- 0 microseconds
Timezones are specified using the format “Area/Location” used by the tz database (also known as IANA timezone database or Olson database). See the corresponding Wikipedia article for a full list of timezone names.
After setting the timezone, all times without an explicit timezone will be interpreted as referring to the specific timezone:
(udb) ugo wallclock 2020-02-07 08:05:05.549631 [...] (udb) uinfo wallclock 2020-02-07 08:05:05.549631 PST-0800 +/- 0 microseconds
The current default timezone can be displayed with the ushow timezone
command, and the
timezone can be reset to UTC with the uclear timezone
command.
Formats¶
The ugo wallclock
command supports most commonly used formats with various delimiters for the
date/time fields and with or without timezones.
The handling of ambiguous formats is undefined.
Limitations¶
- Log Jump using wall clock times depends on the presence of calls to
gettimeofday
. Without any call to this function, the feature is not available. - If calls to
gettimeofday
are few and far between the confidence interval can be large. This feature is primarly useful to jump at an exact time as reported in a log file. - In case of long running programs, finding the wall clock time in recordings can be slow.
The ugo wallclock
and uinfo wallclock
commands work out of the box with any recorded
application which uses gettimeofday
but, if it’s possible to modify the source code of the
application, a more powerful option is to include timestamps in UDB’s time notation in log
entries. See the following section for details.
Using UDB time notation¶
If it’s possible to modify the logging code in the application which needs debugging, then it’s possible to add timestamps in UDB’s time notation rather than relying on wall clock times.
Adding timestamps in UDB’s time notation to log entries¶
This functionality is provided by the undoex_get_bbcount
function declared in
undoex/undoex-engine-status.h
in the libundoex
library.
The time in execution history is returned as an unsigned 64-bit integer representing the
bbcount
, see the UDB time notation for details.
The undoex_get_bbcount
function can be used as follows:
#include <errno.h> #include <inttypes.h> #include <stdio.h> #include <undoex/undoex-engine-status.h> static void print_current_bbcount(void) { uint64_t bbcount = undoex_get_bbcount(); if (bbcount > 0) { printf("The current time in execution history is: %" PRIu64 "\n", bbcount); } else if (errno == ENOTSUP) { printf("Not currently recording\n"); } else { perror("Couldn't access the time in execution history"); } }
The functions in the libundoex
library work both when the program is recorded under the
interactive UDB debugger and when recorded through the LiveRecorder API.
If called when the program is not being recorded, undoex_get_bbcount
will return 0
(which is
not a valid time in execution history) and set errno
to ENOTSUP
.
Using the bbcount
¶
The bbcount
produced by undoex_get_bbcount
can be used in UDB, after loading the
corresponding recording file, to go to the point in history when the function was called.
For instance, if the code above produces:
The current time in execution history is: 41798
Then it’s possible to use the ugo time
command to go to that time. UDB will then make sure
that execution is moved back to the point when undoex_get_bbcount
was called rather than ending
up inside the libundoex
library.
For instance:
(udb) ugo time 41798 Program received signal SIGTRAP, Trace/breakpoint trap. 0x00007f4a0fab4670 in ?? () Moving out from libundoex into user code. You can disable this behaviour by using the '--exact' option. 10 uint64_t bbcount = undoex_get_bbcount(); (udb) list 8 print_current_bbcount(void) 9 { 10 uint64_t bbcount = undoex_get_bbcount(); 11 if (bbcount > 0) 12 {
Integrating the libundoex
library¶
You can find the libundoex
library and header files in the undoex
subdirectory of an UDB
release:
undo-<version>/ ... undoex/ libundoex_pic_x64.a libundoex_x64.so undoex-engine-status.h ...
The library is available as both a statically linked library (libundoex_pic_<arch>.a
) and a
dynamically linked library (libundoex_<arch>.so
). There are no extra dependencies, so the build
command
will be similar to:
gcc -g -o example example.c libundoex_pic_x64.a