Question

`Ugo event` seemingly going to the wrong event

  • 16 April 2021
  • 1 reply
  • 43 views
etesta
Rank
Badge +1

Recently while investigating an issue for a customer I noticed the following:

 

(udb) ugo event prev name=='write'
going to: ref=0x1fc054f4c170 in_code=0 time_bbcount=223466223298 time_extra=18446744073709551615 code=write size=80 result=7
0x00007f4fc89e0c0b in write () from /tmp/undodb.8444.1617966303.9400325.18ca8bac04951ecc/debuggee-1-bamqf2b_/symbol-files/lib64/libpthread.so.0
OK(udb) ugo event prev name=='write'
going to: ref=0x1fc054f4c0b8 in_code=0 time_bbcount=223466223040 time_extra=18446744073709551615 code=write size=80 result=6
[Switching to Thread 12978.12978]
0x00007f4fc3843f81 in epoll_wait () from /tmp/undodb.8444.1617966303.9400325.18ca8bac04951ecc/debuggee-1-bamqf2b_/symbol-files/lib64/libc.so.6
WHAT?(udb) ugo event prev name=='write'
going to: ref=0x1fc0540a8d00 in_code=0 time_bbcount=223403831487 time_extra=18446744073709551615 code=write size=80 result=8
[Switching to Thread 12978.13072]
0x00007f4fc38367ab in write () from /tmp/undodb.8444.1617966303.9400325.18ca8bac04951ecc/debuggee-1-bamqf2b_/symbol-files/lib64/libc.so.6OK

 

This seems wrong, what is the explanation?

Life is too short to be spent debugging

1 reply

G

I’ve added the following to the “Event log” documentation to explain what is going on here.

................

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% 14,644> ugo event next name == "read"
Going to: time=14,654:0xffffffffffffffff: read. result=0x8 size=104.
0x00007ffff7bc53a5      27      ../sysdeps/unix/sysv/linux/write.c: No such file or directory.
74% 14,654> backtrace
#0  0x00007ffff7bc53a5 in __libc_write (fd=6, buf=0x7ffff77c1e10, nbytes=8) at ../sysdeps/unix/sysv/linux/write.c:27
#1  0x0000555555554abf in write_packet (packet=0x7ffff0000b20 "A", length=1, fd=6) at workers.c:49
#2  0x0000555555554ca6 in worker_thread (arg=0x0) at workers.c:81
#3  0x00007ffff7bbb6db in start_thread (arg=0x7ffff77c2700) at pthread_create.c:463
#4  0x00007ffff78e471f 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% 14,654> uinfo events -a now -b +1
time=14,654:0xffffffffffffffff: THREADSWITCH. tid=21080 size=56.
time=14,654:0xffffffffffffffff: read. result=0x8 size=104.
74% 14,654> stepi

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

Reply