wspy – followup: support for ptrace as well as ftrace
As a followup to my post about ptrace vs ftrace I have added a basic ptrace support to wspy.
A compare/contrast of information created shows ptrace:
[15357] cpu=1 user=0.00 system=0.00 vsize=4592k openssl pcount=10 [15358] cpu=5 user=0.00 system=0.00 vsize=16500k openssl pcount=9 [15359] cpu=2 user=20.03 system=0.00 vsize=16632k openssl pcount=1 [15360] cpu=5 user=20.01 system=0.00 vsize=16632k openssl pcount=1 [15361] cpu=1 user=20.03 system=0.00 vsize=16632k openssl pcount=1 [15362] cpu=4 user=20.02 system=0.00 vsize=16632k openssl pcount=1 [15363] cpu=6 user=20.01 system=0.00 vsize=16632k openssl pcount=1 [15364] cpu=0 user=20.02 system=0.00 vsize=16632k openssl pcount=1 [15365] cpu=3 user=20.02 system=0.00 vsize=16632k openssl pcount=1 [15366] cpu=7 user=20.01 system=0.00 vsize=16632k openssl pcount=1
As compared to ftrace:
[15055] cpu=6 elapsed=20.03 start= 2.59 finish=22.63 ./openssl pcount=10 [15056] cpu=3 elapsed=20.03 start= 2.59 finish=22.63 ./openssl-1.1.0f/apps/openssl pcount=9 [15057] cpu=1 elapsed=20.03 start= 2.60 finish=22.62 openssl pcount=1 [15058] cpu=0 elapsed=20.02 start= 2.60 finish=22.62 openssl pcount=1 [15059] cpu=7 elapsed=20.03 start= 2.60 finish=22.63 openssl pcount=1 [15060] cpu=5 elapsed=20.03 start= 2.60 finish=22.63 openssl pcount=1 [15061] cpu=4 elapsed=20.03 start= 2.60 finish=22.63 openssl pcount=1 [15062] cpu=6 elapsed=20.03 start= 2.60 finish=22.63 openssl pcount=1 [15063] cpu=2 elapsed=20.03 start= 2.60 finish=22.63 openssl pcount=1 [15064] cpu=3 elapsed=20.03 start= 2.60 finish=22.62 openssl pcount=1
Some similarities and differences to note:
- The set of events that construct the trees are the same in terms of fork/exec/exit and hence topologically, the trees are the same. Information such as the process count are thus also the same
- Information about the name of the process is sometimes slightly different. For ftrace, I use either “filename=” or “comm=” fields given by the kernel tracer. For ptrace, I tried several things before settling on the “comm” field. This is often the simplest. The “filename” has a symbolic link to an *.exe file but this then can have multiple further symbolic links that at times are obscure. The “command” field was an other option, though this also seemed more verbose.
- The start and finish come easily from ftrace kernel events since everything has a timestamp. In ptrace a process has a starttime, but without explicitly querying at exit, I don’t have the finish times as easily. Perhaps I may add these back in later
- Information for ptrace can easily come from /proc/[pid]/stat, /proc/[pid]/statm, /proc/[pid]/io at process completion. This is where the vsize (and CPU) fields come from currently. Still need to figure out what is most interesting here and perhaps add some options display the appropriate ones.
There are also three further areas of further refinement:
- At present, one can’t use both tracers simultaneously. Two reasons (1) while wspy is a multi-threaded program, I haven’t made provisions to have the process table information updated by two threads at the same time (2) since the names of processes are sometimes different, this is also a potential issue.
- I print the utime/stime fields from the process at system exit. In examples above, they are fine. I have however noticed for a program like c-ray, this information isn’t quite correct. Not quite sure yet what is going on here or how extensive this information is.
- One nice thing about ptrace is that it also gives me “hooks” for further instrumentation. In my previous tool, I could collect performance counters at start/end of processes rather than for cores as a whole. Both types of instrumentation are interesting, but in different situations and different times. I’ve also got ability to more precisely show I/O, network and similar statistics broken down by processes in the program
Overall, a few rough edges for refinement, but also a useful addition to wspy.
Followup:
I have added support to use both tracers together with –processtree-engine all alternative. It took a little bit to get the locking correct, but believe this one works without issue.
I also have a hypothesis on the “user time is too high” situation, but not yet a fix. I think it comes when multiple threads are used. The system is reporting an “exit()” event, but this is of the thread and not the entire process. As a result, the process has a much higher user time because it includes threads other than this one. I printed out the “num_threads” value in /proc/[pid]/stat if it is larger than 1 and notice that this seems to particularly happen for c-ray where many threads are created.
Next steps to test this hypothesis is to (1) separately keep track of clone(2) calls and (2) if it is a clone look in /proc/[pid]/task/[tid] first to see if information is found there.
Followup:
I am now able to see a more reasonable user and system time for threads.
I did the test described in preceding command to look in /proc/[pid]/task/[tid] and the numbers are what I expected.
wspy has been fixed for this issue.