2018-12-23
The Advent of Void: Day 23: extrace
Today’s tool is extrace(1), a small, simple and powerful tool to trace program executions.
By default extrace(1) will look at system wide executions, alternatively it can start a new process or start looking for executions in child processes of a specified pid.
The output is a tree like structure including the process id, the command and its arguments, additional flags can add the environment of the process, the executing user or even the exit status and runtime duration.
The following example is the truncated extrace(1) output of checking the dhcpcd(8) man page and then executing dhcpcd -k to release all interfaces followed by executions from dhcpcd hooks.
$ extrace
911 man dhcpcd
912 less -T /tmp/man.XXXXH357hT /tmp/man.XXXXEOs5Na
930 doas dhcpcd -k
930 dhcpcd -k
932 /bin/sh /usr/libexec/dhcpcd-run-hooks
933 rm -f /run/dhcpcd/resolv.conf/br0.ra
936 sed -n 's/^domain //p' br0.dhcp
938 sed -n 's/^search //p' br0.dhcp
941 sed -n 's/^nameserver //p' br0.dhcp
943 cat /etc/resolv.conf.head
944 cmp -s /etc/resolv.conf /run/dhcpcd/resolv.conf.br0.ra
945 cat /run/dhcpcd/resolv.conf.br0.ra
946 rm -f /run/dhcpcd/resolv.conf.br0.ra
947 chmod 644 /etc/resolv.conf
948 rm -f /run/dhcpcd/resolv.conf.br0.ra
950 sed '/^# Generated by dhcpcd/,/^# End of dhcpcd/d' /etc/ntpd.conf
951 cmp -s /etc/ntpd.conf /run/dhcpcd/ntp.conf.br0.ra
952 rm -f /run/dhcpcd/ntp.conf.br0.ra
...
Here is another example where we trace the executions by make into a file, with the -t flag extrace(1) adds the exit status and the duration.
mblaze$ extrace -t -o make.extrace make
cc -Wall -Wno-switch -Wextra -g -O2 -fstack-protector-strong -D_FORTIFY_SOURCE=2 -c -o msed.o msed.c
cc msed.o blaze822.o mymemmem.o mytimegm.o seq.o slurp.o -lrt -o msed
mblaze$ cat make.extrace
1992+ make
1993+ uname
1993- uname exited status=0 time=0.000s
1994+ cc -Wall -Wno-switch -Wextra -g -O2 -fstack-protector-strong '-D_FORTIFY_SOURCE=2' -c -o msed.o msed.c
1995+ /usr/lib/gcc/x86_64-unknown-linux-gnu/8.2.0/cc1 -quiet -D '_FORTIFY_SOURCE=2' msed.c -quiet -dumpbase msed.c '-mtune=generic' '-march=x86-64' -auxbase-strip msed.o -g -O2 -Wall -Wno-switch -Wextra -fstack-protector-strong -o /tmp/ccDnNZ91.s
1995- /usr/lib/gcc/x86_64-unknown-lin exited status=0 time=0.212s
1996+ as --64 -o msed.o /tmp/ccDnNZ91.s
1996- as exited status=0 time=0.019s
1994- cc exited status=0 time=0.234s
1997+ cc msed.o blaze822.o mymemmem.o mytimegm.o seq.o slurp.o -lrt -o msed
1998+ /usr/lib/gcc/x86_64-unknown-linux-gnu/8.2.0/collect2 [...]
1999- /usr/bin/ld exited status=0 time=0.027s
1998- /usr/lib/gcc/x86_64-unknown-lin exited status=0 time=0.029s
1997- cc exited status=0 time=0.031s
2000+ /bin/sh -c 'test -n "$SOURCE_DATE_EPOCH" || BUILDDATE=$(date '\''+ (%Y-%m-%d)'\''); \'$'\n'' printf '\''#!/bin/sh\nprintf "User-Agent: mblaze/%s%s\\n"\n'\'' \'$'\n'' "$({ git describe --always --dirty 2>/dev/null || cat VERSION; } | sed '\''s/^v//'\'')" \'$'\n'' "$BUILDDATE" >museragent'
2001+ date '+ (%Y-%m-%d)'
2001- date exited status=0 time=0.000s
2004+ sed 's/^v//'
2005+ git describe --always --dirty
2005- git exited status=0 time=0.008s
2004- sed exited status=0 time=0.009s
2000- /bin/sh exited status=0 time=0.012s
2006+ chmod +x museragent
2006- chmod exited status=0 time=0.001s
1992- make exited status=0 time=0.286s