23.12.2018

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