Event log

The event log stores information about each non-deterministic event that affects the execution of the program. These events include:

  1. System calls.

  2. Reads from shared memory.

  3. Asynchronous signal delivery.

  4. Thread switches and thread interactions.

  5. Non-deterministic machine instructions.

Event log rotation

In the default (circular) mode, the Undo Engine discards events from the beginning of the event log in order to make space for new events. This means that the program can continue to run without allocating extra space for the event log.

Note

When an event is discarded from the event log, the execution history prior to the event can no longer be replayed.

Note

When UDB is loading a recording, this setting is ignored and the complete event log is loaded.

Configuring event log size

Memory is allocated dynamically for the event log as required, and by default is limited to 1GB on x64 and 256MB on other platforms. This limit can be configures when starting UDB, either using the --max-event-log-size command-line option, for example:

$ udb --max-event-log-size 1G

or using the UNDO_event_log_max environment variable:

$ UNDO_event_log_max=2G udb

In either case specify the maximum size as a number followed by an optional multiplier (K for kilobytes, M for megabytes, or G for gigabytes), or as 0 to choose a suitable size.

Note

It’s recommended to set the event log size to a value that is substantially smaller than the available system memory, otherwise UDB risks being killed by the Linux out-of-memory (OOM) killer.

Note

When UDB is loading a recording, this setting is ignored and the complete event log is loaded.

set max-event-log-size size[K|M|G]

Set the maximum size to which the event log may grow.

For example:

recording 9,602> set max-event-log-size 268435456
recording 9,602> set max-event-log-size 512M
recording 9,602> set max-event-log-size 1G

show max-event-log-size

The maximum size of the event log.

For example:

recording 9,602> show max-event-log-size
maximum event log size is 1073741824 bytes (1.00G)

Using a straight event log

If you prefer the event log not be rotated, you can switch to the “straight” event log mode. In this mode, when the event log is full, UDB stops the program and emits this message:

ERROR: The Undo Engine's event log is full, so no more history can be recorded.
You may still use UDB commands to go backwards, or alternatively:  Use "set
max-event-log-size <size>[K|M|G]" to increase the event log size, or use "set
event-log-mode circular" to use a circular event log.  The current event log
size is 67108864 bytes (64.00M).

At this point you can increase the maximum event log size using the set max-event-log-size, or switch to a circular event log using the set event-log-mode command.

Configure the event log when starting UDB, either using the --event-log-mode command-line option, for example:

$ udb --event-log-mode straight

or using the UNDO_event_log_mode environment variable:

$ UNDO_event_log_mode=straight udb

set event-log-mode circular|straight

Set the event log mode.

For example:

recording 9,602> set event-log-mode straight

The default (circular) event log mode can be restored using:

recording 9,602> set event-log-mode circular

Event navigation

Query the event log using the info events command, and jump to the time of the next or previous event using the ugo event command.

Event condition

All the event navigation commands optionally take a condition, which is a Python expression. it is evaluated for each event considered by the command. If condition tests true, the event is included by the command; if it tests false, the event is excluded. The expression can use the following variables:

  • address: The base address of a shared memory update, for SHMEM_FIXUP events, or 0 for other events.

  • bbcount: The bbcount.

  • name: The event type or system call name.

  • pc: The program counter.

  • result: The value returned by the system call, or 0 for other events.

  • signum: The signal number, for SIGNAL, SIG_TOCHILD and STATUS_TODEBUGGER events, or 0 for other events.

  • size: The size of the event in bytes.

  • syscall: The system call number, or None for other events.

  • tid: The thread id of the thread switched to, for NEWTHREAD and THREADSWITCH events, or 0 for other events.

  • timestamp: The time stamp counter read by the RDTSC instruction, or 0 for other events.

For example, to list the openat() system calls among the first 100 events:

recording 231,025> info events -l 100 name == 'openat'
time=3,421:0xffffffffffffffff: openat. result=0x3 size=80.
time=3,527:0xffffffffffffffff: openat. result=0x3 size=80.
time=3,807:0xffffffffffffffff: openat. result=0x3 size=80.

info events [options] [condition]

Show events.

-limit N, -l N

Consider at most N events.

-min BBCOUNT, -after BBCOUNT, -a BBCOUNT

Only show events at BBCOUNT or later. BBCOUNT may contain commas.

The string now can be used to specify the current bbcount.

If BBCOUNT starts with + or -, it is relative to the current bbcount.

-max BBCOUNT, -before BBCOUNT, -b BBCOUNT

Only show events before BBCOUNT. See the -min option.

-quiet, -q

Don’t print progress information during the search for events.

See Event condition for the condition argument.

For example, to list all the read() system call events:

recording 231,025> info events name == 'read'
time=3,529:0xffffffffffffffff: read. result=0x340 size=928.
time=3,809:0xffffffffffffffff: read. result=0x340 size=928.

To show the event at the current bbcount, if any:

1% 3,529> info events -a now -b +1
time=3,529:0xffffffffffffffff: read. result=0x340 size=928.

To show five events at or after the current bbcount:

1% 3,529> info events -a now -l 5
time=3,529:0xffffffffffffffff: read. result=0x340 size=928.
time=3,549:0xffffffffffffffff: fstat. result=0x0 size=240.
time=3,560:0xffffffffffffffff: mmap. result=0x7ffff7fb4000 size=129.
time=3,601:0xffffffffffffffff: mmap. result=0x7ffff7e6f000 size=225.
time=3,604:0xffffffffffffffff: mmap. result=0x7ffff7e7e000 size=225.

ugo event next|prev [condition]

Jump to the next or previous event.

With a condition, jump to the next or previous event matching the condition. See Event condition for details.

For example, to jump to the next write() system call event:

1% 3,529> ugo event next name == 'write'

To jump to the previous read() system call event:

6% 14,129> ugo event prev name == 'read'

If the ugo event command succeeds, the program is stopped at the instruction just before the event, so that the stepi command will replay the event.

Note

In a multi-threaded program, the instruction just before the event might be in another thread. This case can be surprising because the backtrace does not show the expected function call, but the stepi command will switch threads and replay the event.

For example:

74% 15,486> ugo event next name == "read"
Going to: time=15,496:0xffffffffffffffff: read. result=0x8 size=104.
0x00007ffff7fa523d in __libc_write (nbytes=8, buf=0x7ffff7dcee10, fd=6) at ../sysdeps/unix/sysv/linux/write.c:26
26      ../sysdeps/unix/sysv/linux/write.c: No such file or directory.
74% 15,496> backtrace
#0  0x00007ffff7fa523d in __libc_write (nbytes=8, buf=0x7ffff7dcee10, fd=6) at ../sysdeps/unix/sysv/linux/write.c:26
#1  __libc_write (fd=6, buf=0x7ffff7dcee10, nbytes=8) at ../sysdeps/unix/sysv/linux/write.c:24
#2  0x00005555555552fa in write_packet (packet=0x7ffff0000b60 "A", length=1, fd=6) at workers.c:49
#3  0x00005555555554e1 in worker_thread (arg=0x0) at workers.c:81
#4  0x00007ffff7f9bfb7 in start_thread (arg=<optimized out>) at pthread_create.c:486
#5  0x00007ffff7ecd1af in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

The backtrace shows that the program is in a call to write(). But listing the events at the current time shows that the program is about to switch threads and complete a call to read(), and the stepi command confirms this.

74% 15,496> info events -a now -b +1
time=15,496:0xffffffffffffffff: THREADSWITCH. tid=3201907 size=56.
time=15,496:0xffffffffffffffff: read. result=0x8 size=104.
74% 15,496> stepi

Thread 1 received signal SIGTRAP, Trace/breakpoint trap.
[Switching to Thread 3201907.3201907]
__libc_read (nbytes=8, buf=0x7fffffffdc38, fd=5) at ../sysdeps/unix/sysv/linux/read.c:26
26      ../sysdeps/unix/sysv/linux/read.c: No such file or directory.