This is Part I of a two-part post on Function Tracing in
Part II is now online!
Go is pretty cool, and fairly fast. A few weeks ago, I finally got around to messing with it. I wrote a couple of simple library functions, and decided that I wanted to build a small lib to trace functions in golang.
The following is an attempt to document my previously stated journey. Be warned, I have only been
Going for the better part of the week.
Say we have the following code in file foo.go:
Running the code above with
go run foo.go would produce something eerily similar to this:
The above code just prints function names on entry (how boring). What if we also wanted to log the function exit? What if we wanted to visualize the nesting of calls?
Track Function Enter / Exit (… easily)
Clearly, the naive approach here would be to just tag the Enter of a function on function entry (as we did), and then tag the Exit before any branches which invoke a return. Even thinking about that makes me feel icky.
Go provides us with this nifty
defer statement, which we just might have to abuse a little.
From the documentation for
So if we
defer something immediately after we enter a function, then
Go will invoke said deferred statement once the function we are executing returns. This is really cool! Without this, we would have to cover every returning branch of code with the exit message.
Now the same code, enriched with the power of
go run foo.go produces:
Great! We avoided having to print an exit statement for each branch which returned from the function. Wouldn’t it be nice if we did not have to explicitly name the function in our
Extracting Function Names (at runtime)
Go includes a package
runtime which will allow us to interact with
Go’s runtime system. We will use this to figure out the function we are trying to trace by walking the current function stack.
The above code also uses the
regexp package. Note that we pass
runtime.Caller(), this is done to skip the current function’s program counter. You can read all about the
After that, we fetch the
Func object by means of the
FuncForPC() method. A
Func object contains finer details about the function pointed to by the appropriate
pc. Finally, since
Func.Name() returns a decorated name, we do some parsing to fetch just the parent’s “name” as we defined it.
We also probably don’t want a bunch of
fmt.Printf(getFunctionName()) statements littering our code, so lets write little nifty
_exit() functions. Here is an updated foo.go:
Looking better, so now running
go run foo.go produces:
Seems like we lost the parameter logging, we will re-visit that later. Also, being the keen reader, and disciplined coder you are, the copy-pasted section in
_exit() is probably irking you. Good, we are on the same page.
One option to remedy the above issue is to invoke another helper function to simply fetch the caller’s caller’s name (change the “skip” in
2), another option is explored below.
One* for the price of Two
So now we have this code block in every function we wish to trace:
We could move them to the same line by simply adding a
; between them to tell
Go that these are independent statements.
Ideally, we only invoke the
runtime.Caller() method once per function being traced. Currently it is done twice (once for
_enter() and once for
_exit()). We also would like to express the trace function as a single statement.
What if the
_enter() function, figured out the function being traced, and returned said function name to the
_exit() function? Ignoring the changes in the function signature, the usage would become something like this:
This only ameliorates the duplicate code issue, we still have two statements (arguably more complicated than before).
Lets re-visit the
defer statement. The excerpt for
defer, tells us that any arguments, to any functions which are being deferred, will be computed at the time of “deferring” and not when the function is eventually executed. This simplifies the above code to:
Putting it all together, foo.go should look like this (note that we made the function finding code more readable as well):
Sweet! Hope that was informative.
Part II, we will investigate moving this code to a library and extending it with some simple options.