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(&current_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-07T15:45:25.763437Z +/- 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-07T16:05:03.246406Z +/- 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-07T16:05:04.173958Z +/- 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 +01:00 will be interpreted as referring to Central European Time (one hour ahead of UTC), while one ending with -06:00 will be interpreted as referring to Central Standard Time (six hours behind UTC).

If no timezone information is specified the time is interpreted as UTC (Coordinated Universal Time). You can change this with the uset timezone command:

(udb) uinfo wallclock
2020-02-07T16:05:04.948217Z +/- 0 microseconds
(udb) uset timezone US/Pacific
Wallclock timezone set to US/Pacific
(udb) uinfo wallclock
2020-02-07T08:05:04.948217-08:00 +/- 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-07T08:05:05.549631-08:00 +/- 0 microseconds

The current default timezone can be displayed with the ushow timezone command, and the default 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