proposal to use python tracing for profiling

[vsoch]

Problem: PerfFlowAspect currently requires hard coding python decorators to use it.
Solution: Try using Python tracing to enable dynamic tracing.

For some background, Python has a sys.settrace and the equivalent for the threading module (I always come back here https://explog.in/notes/settrace.html) to remember the details! It's really cool because (in layman's terms) you turn it on and off, and when it's on, you provide a custom function that Python sends "all the guts" of a trace to, including generally the event and metadata about the function signature. This would extend beyond a single module in question and trace everything that is run, down to the system libraries. I originally explored this when I was interested in ABI, and while it's too slow for that particular use case, it's very well suited for scoped / specific traces, e.g., "tell me about this set of functions A,B,C).

To step back, I started with a python test case, this one and saw it was using around from here. Looking more closely at that decorator, all it's doing is capturing some metrics before and after ("around") a function call. We can mimic that same "wrapping" idea with sys.settrace because we know the events for when a function is called ("call") and when it returns ("return") and basically keep track of those same numbers coordinated with those events.

For a dummy example, I put together https://github.com/rse-ops/trace-example that shows doing exactly this. The first example shows asking to trace specific functions, and the final one (in the details block) is a function that is deeply within Python somewhere, some level of dependency I wasn't even aware of being used. If you look at the test file test.py you'll see no special decorators - just the original code (and this could be a strength I think).

What I didn't take time to do is figure out the format that you need to output in, I just dumped into generic json, but that could be done. I also might have entirely missed there is some compiled C code that needs to run too (e.g., I have no idea what the PERFFLOW_OPTIONS are for but maybe something else?)

PerfFlowAspect/src/python/perfflowaspect/advice_chrome.py

Lines 123 to 141 in 4852a48

	# PERFFLOW_OPTIONS envVar
	# To specify the name of this workflow component (default: name=generic)
	# PERFFLOW_OPTIONS="name=foo"
	# To customize output filename (default: log-filename-include=hostname,pid)
	# PERFFLOW_OPTIONS="log-filename-include=<metadata1, metadata2, ...>
	# Supported metadata:
	# name: workflow component name
	# instance-path: hierarchical component path
	# hostname: name of the host where this process is running
	# pid: process id
	# To change the directory in which the log file is created
	# PERFFLOW_OPTIONS="log-dir=DIR"
	# To disable logging (default: log-enable=True)
	# PERFFLOW_OPTIONS="log-enable=False"
	# To collect CPU and memory usage metrics (default: cpu-mem-usage=False)
	# PERFFLOW_OPTIONS="cpu-mem-usage=True"
	# To collect B (begin) and E (end) events as single X (complete) duration event (default: log-event=Verbose)
	# PERFFLOW_OPTIONS="log-event=Compact"
	# You can combine the options in colon (:) delimited format

but if that's the case, I don't see why we couldn't integrate in this same setup. If you like this approach, we also need a better way to give function calls UIDs to match calls with returns. My code assumes a serial run (so a return is associated with the last call) but that might not always be the case!

Let me know if this could be wanted! If not wanted, maybe just interesting. If not interesting, maybe just fun to work on :) (it was)