Re: [PATCH] RFC: refs: add GIT_DEBUG_REFS debugging mechanism

[Jonathan Nieder <jrnieder@gmail.com>]

(+Peff and Josh, trace experts)
Jonathan Tan wrote:
> Han-Wen Nienhuys wrote:

>> This should be integrated with the trace2 sub-system, and I would appreciate
>> pointers on how to start.
>
> The trace2 subsystem seems to be designed to detect errors coarsely
> (e.g. by looking at process invocations) and log timings. It currently
> doesn't seem to be made for this kind of fine debugging information -
> and perhaps this is by design, because such logging information would
> not be useful to most users and would just clutter up the logs.
>
> But I think there is a place for this in Git - in particular, we have
> packet tracing (GIT_TRACE_PACKET), and this has been useful both in
> automated tests (t/????-*.sh) and in manual tests. Ref backend tracing
> seems to be similar. But this would be best if we had an additional
> option that could control whether ref backend tracing was on or off,
> independent from other things like the trace2 target.
>
> Is the plan to migrate all usages of "trace" to "trace2" or for both to
> exist simultaneously? If the latter, then ref backend tracing could just
> use "trace", but if the former, we'd have to designing this additional
> option.

Here's my not-completely-thought-through take:

trace.h defines a convenient and simple API for unstructured traces.
You can define a key

	static struct trace_key trace_refs = TRACE_KEY_INIT(REFS);

and then you have available

	trace_want(&trace_refs)
	trace_printf_key(&trace_refs, fmt, args...)
	trace_strbuf(&trace_refs, data)

and so on.

One use of trace_printf (i.e. tracing without a key) is to print lines
for important events like starting a subprocess.  For those, trace2 is a
natural replacement, with the advantage that the resulting event is
associated with any enclosing trace2 regions.

One design goal of trace2 was to be able to replace the original trace
subsystem completely.  Its output routines are flexible that it should
be able to produce GIT_TRACE style output.  It should be possible to
implement a trace_printf style API on top of trace2.

For ref tracing, do we care much about the human-friendliness of the
output?  Do we expect this to be useful for debugging once reftable is
more established?  Is it something we'd want to extract timing regions
from and use for performance improvements?

For ad hoc debugging, the structured tracing features of trace2 are
not all that important.  So if using the trace_key API is simpler,
then for that application I'd say go for it.  Some day we could
reimplement that same API on top of trace2 (or use a coccinelle
transform to a similar API) and your could would still work. :)

For producing logs that get aggregated, the structured output of
trace2 tends to be quite useful.  Event tracing doesn't have a notion
of setting which subsystems to trace on but it would be a natural
thing to add.  See TR2_SYSENV_CFG_PARAM for an example of configurable
"what to trace" information used by GIT_TRACE2_EVENT.  Happy to
provide more advice if this seems applicable for the problem at hand.

Summary:

- if this is only going to be used for tests and for ad hoc debugging,
  I'd suggest sticking to the simple trace_key based unstructured
  tracing API

- if we expect it to be something we want to aggregate over many runs
  and query, then structure becomes more important and trace2 starts
  to pull its weight

Thanks,
Jonathan