{"thread":{"id":"41565","subject":"GIT_TRACE_PERFORMANCE and pager","startedAt":"2016-02-29T11:25:49Z","lastAt":"2016-02-29T21:30:27Z","messageCount":5,"participants":["Christian Couder","Jeff King","Junio C Hamano"],"isPatch":false,"patchVersion":null,"patchTotal":null},"messages":[{"id":"279767","messageId":"CAP8UFD2zFBV7gRVvLB-gGEB=cfZJmYKrfiD2vdTdxgEgYU6jHQ@mail.gmail.com","threadId":"41565","inReplyTo":null,"subject":"GIT_TRACE_PERFORMANCE and pager","fromName":"Christian Couder","fromEmail":"christian.couder@gmail.com","sentAt":"2016-02-29T11:25:49Z","receivedAt":"2016-02-29T11:25:49Z","isPatch":false,"sender":{"key":"christian.couder@gmail.com","avatar":"https://avatars.githubusercontent.com/u/208954?v=4"},"body":"Hi,\n\nIt looks like setting GIT_TRACE_PERFORMANCE to 1 or 2 (for stdout or\nstderr) does not always work well with commands that use a pager, for\nexample:\n\n-------------\n> GIT_TRACE_PERFORMANCE=2 git log -1\ncommit f02fbc4f9433937ee0463d0342d6d7d97e1f6f1e\nAuthor: Junio C Hamano \nDate: Fri Feb 26 13:45:26 2016 -0800\n\n Git 2.8-rc0\n\n Signed-off-by: Junio C Hamano \n-------------\n\nIn the above the GIT_TRACE_PERFORMANCE output is missing.\n\nWhen I use \"--no-pager\", I get the GIT_TRACE_PERFORMANCE output:\n\n-------------\n> GIT_TRACE_PERFORMANCE=2 git --no-pager log -1\ncommit f02fbc4f9433937ee0463d0342d6d7d97e1f6f1e\nAuthor: Junio C Hamano \nDate: Fri Feb 26 13:45:26 2016 -0800\n\n Git 2.8-rc0\n\n Signed-off-by: Junio C Hamano \n12:16:31.258462 trace.c:420 performance: 0.001415428 s:\ngit command: 'git' '--no-pager' 'log' '-1'\n-------------\n\nSetting GIT_TRACE to 1 or 2 seems to work, but maybe it is because it\noutputs stuff at the beginning of the process and not at the end.\n\nCheers,\nChristian.\n"},{"id":"279768","messageId":"20160229113924.GC29769@sigill.intra.peff.net","threadId":"41565","inReplyTo":"CAP8UFD2zFBV7gRVvLB-gGEB=cfZJmYKrfiD2vdTdxgEgYU6jHQ@mail.gmail.com","subject":"Re: GIT_TRACE_PERFORMANCE and pager","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2016-02-29T11:39:25Z","receivedAt":"2016-02-29T11:39:25Z","isPatch":false,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Mon, Feb 29, 2016 at 12:25:49PM +0100, Christian Couder wrote:\n\n> Setting GIT_TRACE to 1 or 2 seems to work, but maybe it is because it\n> outputs stuff at the beginning of the process and not at the end.\n\nYeah, I think so. Try this (on Linux):\n\n $ GIT_PAGER='sed s/^/paged:/' \\\n GIT_TRACE_PERFORMANCE=1 \\\n strace -f -e write -e 'signal=!sigchld' git -p rev-parse\n strace: Process 31155 attached\n strace: Process 31156 attached\n [pid 31156] +++ exited with 0 +++\n [pid 31155] +++ exited with 0 +++\n write(2, \"06:32:30.486995 [pid=31154] trac\"..., 114) = -1 EBADF (Bad file descriptor)\n write(2, \"Could not trace into fd given by\"..., 99) = -1 EBADF (Bad file descriptor)\n +++ exited with 0 +++\n\nWe redirect stderr to the pager (note that GIT_TRACE=1 still goes to\nstderr; it never goes to stdout). We wait() on the pager process before\nwe exit the main git process, and we don't print the performance stats\nuntil atexit(). So by the time we get there, the pager must be dead, and\nthe pipe descriptor is closed (I'm actually kind of surprised we don't\nget EPIPE, but it looks like we close the descriptors in\nwait_for_pager()).\n\nOne workaround is something like:\n\n GIT_TRACE_PERFORMANCE=3 3>&2 git ...\n\nthough I guess I'd question whether trace-performance is interesting at\nall for a paged command, since it is also counting the length of time\nyou spend looking at the pager waiting to hit \"q\".\n\n-Peff\n"},{"id":"279778","messageId":"CAP8UFD30fWvFPtSgY_6mVMCeQ9rMR-0EODaKbZdMmz_fo-qfKw@mail.gmail.com","threadId":"41565","inReplyTo":"20160229113924.GC29769@sigill.intra.peff.net","subject":"Re: GIT_TRACE_PERFORMANCE and pager","fromName":"Christian Couder","fromEmail":"christian.couder@gmail.com","sentAt":"2016-02-29T13:46:12Z","receivedAt":"2016-02-29T13:46:12Z","isPatch":false,"sender":{"key":"christian.couder@gmail.com","avatar":"https://avatars.githubusercontent.com/u/208954?v=4"},"body":"On Mon, Feb 29, 2016 at 12:39 PM, Jeff King wrote:\n> On Mon, Feb 29, 2016 at 12:25:49PM +0100, Christian Couder wrote:\n>\n>> Setting GIT_TRACE to 1 or 2 seems to work, but maybe it is because it\n>> outputs stuff at the beginning of the process and not at the end.\n>\n> Yeah, I think so. Try this (on Linux):\n>\n> $ GIT_PAGER='sed s/^/paged:/' \\\n> GIT_TRACE_PERFORMANCE=1 \\\n> strace -f -e write -e 'signal=!sigchld' git -p rev-parse\n> strace: Process 31155 attached\n> strace: Process 31156 attached\n> [pid 31156] +++ exited with 0 +++\n> [pid 31155] +++ exited with 0 +++\n> write(2, \"06:32:30.486995 [pid=31154] trac\"..., 114) = -1 EBADF (Bad file descriptor)\n> write(2, \"Could not trace into fd given by\"..., 99) = -1 EBADF (Bad file descriptor)\n> +++ exited with 0 +++\n\nYeah, I get the same thing.\n\n> We redirect stderr to the pager (note that GIT_TRACE=1 still goes to\n> stderr; it never goes to stdout). We wait() on the pager process before\n> we exit the main git process, and we don't print the performance stats\n> until atexit(). So by the time we get there, the pager must be dead, and\n> the pipe descriptor is closed (I'm actually kind of surprised we don't\n> get EPIPE, but it looks like we close the descriptors in\n> wait_for_pager()).\n>\n> One workaround is something like:\n>\n> GIT_TRACE_PERFORMANCE=3 3>&2 git ...\n\nYeah, that works.\n\n> though I guess I'd question whether trace-performance is interesting at\n> all for a paged command, since it is also counting the length of time\n> you spend looking at the pager waiting to hit \"q\".\n\nIn case of \"GIT_TRACE_PERFORMANCE=2 git log -1\", it doesn't count the\ntime spent looking at the pager because the output is small, so 'less'\nexits immediately, and it could give the impression that\nGIT_TRACE_PERFORMANCE is not working.\n\nI am preparing a patch to Documentation/technical/api-trace.txt to\nwarn about that.\n"},{"id":"279789","messageId":"CAPc5daWp+ACy_5=prqa2f_ry4Z92B7mOEw_mC_-arCSNeX=3Kw@mail.gmail.com","threadId":"41565","inReplyTo":"20160229113924.GC29769@sigill.intra.peff.net","subject":"Re: GIT_TRACE_PERFORMANCE and pager","fromName":"Junio C Hamano","fromEmail":"gitster@pobox.com","sentAt":"2016-02-29T16:47:08Z","receivedAt":"2016-02-29T16:47:08Z","isPatch":false,"sender":{"key":"gitster@pobox.com","avatar":"https://avatars.githubusercontent.com/u/54884?v=4"},"body":"On Mon, Feb 29, 2016 at 3:39 AM, Jeff King wrote:\n> One workaround is something like:\n>\n> GIT_TRACE_PERFORMANCE=3 3>&2 git ...\n>\n> though I guess I'd question whether trace-performance is interesting at\n> all for a paged command, since it is also counting the length of time\n> you spend looking at the pager waiting to hit \"q\".\n\nYup, exactly. I see Christian tried to add something to the documentation,\nbut I think it is sufficient to suggest running commands with --no-pager.\n"},{"id":"279848","messageId":"20160229213026.GB25342@sigill.intra.peff.net","threadId":"41565","inReplyTo":"CAP8UFD30fWvFPtSgY_6mVMCeQ9rMR-0EODaKbZdMmz_fo-qfKw@mail.gmail.com","subject":"Re: GIT_TRACE_PERFORMANCE and pager","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2016-02-29T21:30:27Z","receivedAt":"2016-02-29T21:30:27Z","isPatch":false,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Mon, Feb 29, 2016 at 02:46:12PM +0100, Christian Couder wrote:\n\n> > though I guess I'd question whether trace-performance is interesting at\n> > all for a paged command, since it is also counting the length of time\n> > you spend looking at the pager waiting to hit \"q\".\n> \n> In case of \"GIT_TRACE_PERFORMANCE=2 git log -1\", it doesn't count the\n> time spent looking at the pager because the output is small, so 'less'\n> exits immediately, and it could give the impression that\n> GIT_TRACE_PERFORMANCE is not working.\n\nAh, right. I don't use \"-F\" with less, so mine hangs around until I\nquit.\n\n-Peff\n"}]}