Re: GIT_TRACE_PERFORMANCE and pager

[Christian Couder <christian.couder@gmail.com>]

On Mon, Feb 29, 2016 at 12:39 PM, Jeff King <peff@peff.net> wrote:
> On Mon, Feb 29, 2016 at 12:25:49PM +0100, Christian Couder wrote:
>
>> Setting GIT_TRACE to 1 or 2 seems to work, but maybe it is because it
>> outputs stuff at the beginning of the process and not at the end.
>
> Yeah, I think so. Try this (on Linux):
>
>   $ GIT_PAGER='sed s/^/paged:/' \
>     GIT_TRACE_PERFORMANCE=1 \
>     strace -f -e write -e 'signal=!sigchld' git -p rev-parse
>   strace: Process 31155 attached
>   strace: Process 31156 attached
>   [pid 31156] +++ exited with 0 +++
>   [pid 31155] +++ exited with 0 +++
>   write(2, "06:32:30.486995 [pid=31154] trac"..., 114) = -1 EBADF (Bad file descriptor)
>   write(2, "Could not trace into fd given by"..., 99) = -1 EBADF (Bad file descriptor)
>   +++ exited with 0 +++

Yeah, I get the same thing.

> We redirect stderr to the pager (note that GIT_TRACE=1 still goes to
> stderr; it never goes to stdout). We wait() on the pager process before
> we exit the main git process, and we don't print the performance stats
> until atexit(). So by the time we get there, the pager must be dead, and
> the pipe descriptor is closed (I'm actually kind of surprised we don't
> get EPIPE, but it looks like we close the descriptors in
> wait_for_pager()).
>
> One workaround is something like:
>
>   GIT_TRACE_PERFORMANCE=3 3>&2 git ...

Yeah, that works.

> though I guess I'd question whether trace-performance is interesting at
> all for a paged command, since it is also counting the length of time
> you spend looking at the pager waiting to hit "q".

In case of "GIT_TRACE_PERFORMANCE=2 git log -1", it doesn't count the
time spent looking at the pager because the output is small, so 'less'
exits immediately, and it could give the impression that
GIT_TRACE_PERFORMANCE is not working.

I am preparing a patch to Documentation/technical/api-trace.txt to
warn about that.