Re: Generate call graphs in run-time

On 01/17/2012 11:13 AM, Joel Jacobson wrote:
> Since you only care about the parentfuncid in one level, it looks like
> you will only be able to get a total call graph of all possible
> function calls, and not each unique call graph per transaction.

True, for my purposes (function dependencies and performance analysis)
the global graph is sufficient.

> Also, why remove the parent oid when uploading the statistics to the collector?
> It would be nice to have the statistics for each function per parent,
> to see where you have a bottleneck which might only be occurring in a
> function when called from a specific parent.

I guess I was just lazy at the time I wrote it. But it shouldn't be too
much of an effort to store the global call graph in statistics
collector. Unique call graphs would be somewhat more complicated I
guess.

>> There is a patch for this and we do use it in production for occasional
>> troubleshooting and dependency analysis. Can't attach immediately
>> though -- it has some extra cruft in it that needs to be cleaned up.
>
> I would highly appreciate a patch, don't worry about cleaning up, I
> can do that, unless it's some code you can't share for other reasons.
>

Patch attached. It was developed against 9.1, but also applies to
HEAD but gives some fuzz and offsets.

It adds 2 GUC variables: log_function_calls and log_usage_stats. The
first just output function statistics to log (with no parent info).
With log_usage_stats enabled, it also outputs detailed function usage
plus relation usage. So you basically get output such as:

# select * from pgq.get_consumer_info();
LOG: duration: 11.153 ms statement: select * from pgq.get_consumer_info();
LOG: function call: pgq.get_consumer_info(0) calls=1 time=9726
self_time=536
LOG: USAGE STATISTICS
DETAIL: ! object access stats:
! F 1892464226 0 pgq.get_consumer_info(0) calls=1 time=9726 self_time=536
! F 1892464228 1892464226 pgq.get_consumer_info(2) calls=1 time=9190
self_time=9190
! r 167558000 pgq.queue: blks_read=28 blks_hit=28
! r 167557988 pgq.consumer: blks_read=56 blks_hit=56
! r 167558021 pgq.subscription: blks_read=54 blks_hit=50
! r 167558050 pgq.tick: blks_read=103 blks_hit=102
! i 1892464189 pgq.queue_pkey: scans=1 tup_ret=37 tup_fetch=37
blks_read=2 blks_hit=2
! i 167557995 pgq.consumer_pkey: scans=56 tup_ret=56 tup_fetch=56
blks_read=57 blks_hit=56
! i 1892464195 pgq.subscription_pkey: scans=37 tup_ret=156 tup_fetch=56
blks_read=127 blks_hit=123
! i 167558058 pgq.tick_pkey: scans=112 tup_ret=103 tup_fetch=103
blks_read=367 blks_hit=366

> funcid->parentfuncid might be sufficient for performance
> optimizations, but to automatically generate directional graphs of all
> unique call graphs in run-time, you would need all the unique pairs of
> funcid->parentfuncid as a singel column, probably a sorted array of
> oids[][], example: [[1,2],[1,3],[2,4],[2,5]] if the call craph would
> be {1->2, 1->3, 2->4, 2->5}.
>

Hmm, array would probably work, although I wonder if there is a
more elegant solution ...

regards,
Martin