strace a short-lived process

Question

I'm trying to learn about the behavior of a short-lived process that's created by one of my applications. I know these things about this process:

1. Part of the name of the process.
2. The name and PID of the application that will create this process.
3. Approximately when the process will start (within 5-10 minutes).
4. After the process has exited, the PID of the process.

Ideally, I would like to:

1. Have the kernel (or something) notify my script that this process has started.
2. Run a bunch of tools against the process (iostat, strace, etc).

Is there a way to have the kernel notify me that a certain process has started, so I can take some action on it?

Running something like while true; do ps -ef | grep ${MY_PROCESS_NAME}; done seems bulky and bad. I would like to be able to be notified when it happens, rather than brute-force search for it.

Or, will I just have to run the tools against the parent process and all child processes, then filter through the output later? For example, strace -ff -o ./some.trace -p ${PARENT_PID}.

Answer 1

You might want to look at execsnoop (assuming your kernel was configured with CONFIG_FTRACE, which is usually the case). This is one of many scripts from the Brendan Gregg trace and performance collection. With no args it shows all commands as they start on the system, or you can give it a regexp to watch.

For example, to look for commands that any existing or new zsh might be starting, do:

sudo /opt/perf-tools-master/bin/execsnoop zsh

It shows me this output when I start a new zsh:

Tracing exec()s issued by process name "zsh". Ctrl-C to end.
Instrumenting sys_execve
   PID   PPID ARGS
 21920  21919 /usr/libexec/grepconf.sh -c
 21923  21922 /usr/bin/tty -s
 21922  21919 /usr/bin/tput colors
 21924  21919 /usr/bin/dircolors --sh /etc/DIR_COLORS.256color
 21925  21919 /usr/bin/grep -qi ^COLOR.*none /etc/DIR_COLORS.256color
 21926  21919 /usr/libexec/grepconf.sh -c
 21928  21919 /usr/libexec/grepconf.sh -c
 21930  21919 uname -m
 21932  21919 /bin/grep -q /usr/lib64/qt-3.3/bin
 21934  21933 /usr/bin/id -u

Once you know the full name of the program being run, typically you would replace that file with a script that runs the original program after adding your hooks. If you cannot do that, you can use something like fanotify(7) to have your snooping program intervene before every file open is allowed to complete. Or perhaps inotifywatch would be fast enough for you to attach an strace to the process.

Answer 2

Take a look at sysdig, it's a tool that will let you monitor system calls. If you know the pid of the process that will create your process, you could do:

$ sudo sysdig proc.ppid=<PID>

That will generate output for any system call executed by a process whose parent pid is the given PID. If you knew the full name of the target program, you could include that in the filter:

$ sudo sysdig proc.ppid=<PID> and proc.name=<NAME>

That will give you something that might be a suitable substitute for strace. For example, I'll use the above command to monitor my shell and look for the execution of ls:

$ sudo sysdig proc.ppid=18659 and proc.name=ls
9762 16:07:05.911583406 0 ls (20545) < execve res=0 exe=ls args=-F.--color=auto. tid=20545(ls) pid=20545(ls) ptid=18659(zsh) cwd= fdlimit=1024 pgft_maj=0 pgft_min=69 vm_size=452 vm_rss=16 vm_swap=0 comm=ls cgroups=cpuset=/.cpu=/.cpuacct=/.io=/.memory=/.devices=/.freezer=/.net_cls=/.perf_eve... env=LANG=en_US.utf8.USER=user.LOGNAME=user.HOME=/home/user.PATH=/usr/loc... tty=34818 pgid=20545(ls) loginuid=1000
9763 16:07:05.911608835 0 ls (20545) > brk addr=0
9764 16:07:05.911609493 0 ls (20545) < brk res=557E882FF000 vm_size=452 vm_rss=176 vm_swap=0
9765 16:07:05.911652583 0 ls (20545) > access mode=4(R_OK)
9766 16:07:05.911657425 0 ls (20545) < access res=-2(ENOENT) name=/etc/ld.so.preload
9767 16:07:05.911663159 0 ls (20545) > openat
9768 16:07:05.911686542 0 ls (20545) < openat fd=3(<f>/etc/ld.so.cache) dirfd=-100(AT_FDCWD) name=/etc/ld.so.cache flags=4097(O_RDONLY|O_CLOEXEC) mode=0 dev=800
9769 16:07:05.911688872 0 ls (20545) > fstat fd=3(<f>/etc/ld.so.cache)
9770 16:07:05.911690846 0 ls (20545) < fstat res=0
9771 16:07:05.911691850 0 ls (20545) > mmap addr=0 length=44827 prot=1(PROT_READ) flags=2(MAP_PRIVATE) fd=3(<f>/etc/ld.so.cache) offset=0
9772 16:07:05.911694436 0 ls (20545) < mmap res=7FD38EDE7000 vm_size=496 vm_rss=256 vm_swap=0
9773 16:07:05.911695345 0 ls (20545) > close fd=3(<f>/etc/ld.so.cache)
9774 16:07:05.911695808 0 ls (20545) < close res=0
...
11068 16:07:05.913562304 0 ls (20545) > close fd=1(<f>/dev/pts/2)
11069 16:07:05.913562881 0 ls (20545) < close res=0
11070 16:07:05.913564527 0 ls (20545) > close fd=2(<f>/dev/pts/2)
11071 16:07:05.913564857 0 ls (20545) < close res=0
11072 16:07:05.913572008 0 ls (20545) > exit_group
11073 16:07:05.913622981 0 ls (20545) > procexit status=0

You can see the user guide for more options to configured the filtering and the information that it generates. With that, you could customize what it prints, have a script read that output, then execute whatever other tools you might like.

Answer 3

Use strace with -f on bash. Kick off the short lived program from the shell.

Here's how I filter output for any system call that runs longer than 0.1 sec. 32330 is the PID of my shell. I ignore "read(0," because these are from my shell and they have long elapsed time due to the shell waiting for input.

$ strace -p 32330 -f -T -tt |&
awk '$2 != "read(0," {
    elapsed=$(NF)
    l=length(elapsed)
    elapsed=substr(elapsed,2,l-2)+0
    if (elapsed>0.1) {
        print
    }
}'

Here's the output when i run sleep 2 in my shell.

[pid 28454] 17:09:34.271522 nanosleep({2, 0}, NULL) = 0 <2.000138>
17:09:36.271900 <... wait4 resumed> [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], WSTOPPED|WCONTINUED, NULL) = 28454 <2.002035>