execsnoop output out of order

[raph431]

The output of execsnoop can be out of order, which results in child processes being printed before their parent process.
For example:
TIME UID PCOMM PID PPID RET ARGS
18:28:39 0 cmp 2391921 2391920 0 /usr/bin/cmp -s apt.extended_states.0 /var/lib/apt/extended_states
18:28:39 0 apt-config 2391922 2391920 0 /usr/bin/apt-config shell AutoAptEnable APT::Periodic::Enable
18:28:39 0 apt-get 2391926 2391920 0 /usr/bin/apt-get check -qq
18:28:39 0 apt.systemd.dai 2391920 2391916 0 /usr/lib/apt/apt.systemd.daily lock_is_held update
18:28:39 0 apt-config 2391924 2391920 0 /usr/bin/apt-config shell VERBOSE APT::Periodic::Verbose
18:28:39 0 date 2391929 2391920 0 /usr/bin/date +%s

Here you can see, that apt.systemd.daily (PID 2391920) is the parent process of "/usr/bin/cmp -s apt.extended_states.0 /var/lib/apt/extended_states" (PID 2391921), which is printed before its parent.

[yonghong-song]

I suspect two pid's are running on two different cpus. You can try to tweak the script to add CPU info. The perf buffer is per cpu so reordering in user space is possible. If we really want ordering, ringbuf is the option. See an example in ttysnoop.py.

[raph431]

It seems to be even worse than just out of order. Execsnoop seems to miss some processes.
TIME UID PCOMM PID PPID RET ARGS
06:00:01 100000cron-apt 2057199 2057198 0 /usr/sbin/cron-apt
06:00:01 100000sed 2057202 2057200 0 /bin/sed s|/|_-_|g
06:00:01 100000mktemp 2057226 2057199 0 /bin/mktemp -d -t cron-apt.XXXXXX
06:00:02 100000stat 2057242 2057199 0 /bin/stat --file-system --format=%S /tmp/cron-apt.PpzzG6
06:00:02 100000stat 2057243 2057199 0 /bin/stat --file-system --format=%a /tmp/cron-apt.PpzzG6
06:00:02 100000date 2057244 2057199 0 /bin/date
06:00:02 100000dd 2057247 2057246 0 /bin/dd if=/dev/urandom count=1
06:00:02 100000awk 2057249 2057246 0 /bin/awk {print$1}
06:00:02 100000cksum 2057248 2057246 0 /bin/cksum
06:00:02 100000sleep 2057265 2057199 0 /bin/sleep 725
06:12:07 100000date 2065768 2057199 0 /bin/date
06:12:07 100000stat 2065769 2057199 0 /bin/stat --file-system --format=%S /tmp/cron-apt.PpzzG6
06:12:07 100000stat 2065770 2057199 0 /bin/stat --file-system --format=%a /tmp/cron-apt.PpzzG6
06:12:07 100000dotlockfile 2065771 2057199 0 /bin/dotlockfile -l -p -r 10 /var/lib/cron-apt/lockfile
06:12:07 100000cp 2065772 2057199 0 /bin/cp /tmp/cron-apt.PpzzG6/initlog /tmp/cron-apt.PpzzG6/runmail
06:12:07 100000cp 2065773 2057199 0 /bin/cp /tmp/cron-apt.PpzzG6/initlog /tmp/cron-apt.PpzzG6/runlog
06:12:07 100000cp 2065774 2057199 0 /bin/cp /tmp/cron-apt.PpzzG6/initlog /tmp/cron-apt.PpzzG6/runsyslog
06:12:07 100000cp 2065775 2057199 0 /bin/cp /tmp/cron-apt.PpzzG6/initlog /tmp/cron-apt.PpzzG6/runerror
06:12:07 100000rm 2065776 2057199 0 /bin/rm -f /tmp/cron-apt.PpzzG6/initlog
06:12:07 100000ls 2065778 2065777 0 /bin/ls /etc/cron-apt/action.d
06:12:07 100000expr 2065779 2065777 0 /bin/expr 0-update : [[:alnum:]_-]\+$
06:12:07 100000expr 2065783 2065777 0 /bin/expr 3-download : [[:alnum:]_-]\+$
06:12:07 100000expr 2065784 2065777 0 /bin/expr 6-upgrade : [[:alnum:]_-]\+$

In this example execsnoop does not print the processes with PID 2057200, PID 2057246 and PID 2065777.
I use execsnoop -T -U -c /sys/fs/cgroup/unified/lxc.payload.<container-name> to monitor the processes of a lxc container.