Re: [PATCH 0/4] some chainlint fixes and performance improvements

From: Jeff King <peff@peff.net>
Date: Mar 30, 2023, 22:08 UTC
Message-ID: <20230330220823.GA130426@coredump.intra.peff.net>
In-Reply-To: <20230328210814.GA1754178@coredump.intra.peff.net>

On Tue, Mar 28, 2023 at 05:08:15PM -0400, Jeff King wrote:

Show 15 quoted lines

> BTW, I noticed something really funky when timing t3070 for this series.
> 
>   $ time ./t3070-wildmatch.sh
>   [a bunch of output]
>   real	0m4.750s
>   user	0m3.665s
>   sys	0m0.955s
> 
>   $ time ./t3070-wildmatch.sh >/dev/null
>   real	0m18.664s
>   user	0m9.185s
>   sys	0m9.495s
> 
> Er, what? It gets way slower when redirected to /dev/null. I can't
> figure out why.

In case anyone is curious (and I know you were all on the edge of your seats), I figured this out. The issue is that with the "powersave" CPU governor in place, we never ratchet up the CPU frequency. Perhaps because no process is pegging the CPU, but we just have tons of small processes that quickly exit (which seems like a blind spot in the governor, but at least makes some sense).

When the output is going to the terminal, then the terminal is consuming CPU, and the frequency scales up. So it's faster when we show the output, even though we're doing more work, because the CPU clock is faster. Switching to the "performance" governor makes the problem go away.

I cared for this series, of course, because I wanted to run t3070 under hyperfine, which behaves like the /dev/null case (unless you pass --show-output, which mangles the screen, and is why the hyperfine output I showed earlier was so terse). So with the performance governor in place, here's the hyperfine output for the whole series (this is on the 5-patch v2):

  $ hyperfine -P parent 0 5 -s 'git checkout jk/chainlint-fixes~{parent}' \
      -n 't3070 on jk/chainlint-fixes~{parent}' ./t3070-wildmatch.sh

  Benchmark 1: t3070 on jk/chainlint-fixes~0
    Time (mean ± σ):      3.677 s ±  0.047 s    [User: 2.893 s, System: 0.677 s]
    Range (min … max):    3.606 s …  3.725 s    10 runs
  
  Benchmark 2: t3070 on jk/chainlint-fixes~1
    Time (mean ± σ):      3.720 s ±  0.013 s    [User: 2.941 s, System: 0.676 s]
    Range (min … max):    3.698 s …  3.738 s    10 runs
  
  Benchmark 3: t3070 on jk/chainlint-fixes~2
    Time (mean ± σ):      4.224 s ±  0.019 s    [User: 3.291 s, System: 0.850 s]
    Range (min … max):    4.191 s …  4.254 s    10 runs
  
  Benchmark 4: t3070 on jk/chainlint-fixes~3
    Time (mean ± σ):      4.227 s ±  0.018 s    [User: 3.293 s, System: 0.856 s]
    Range (min … max):    4.198 s …  4.252 s    10 runs
  
  Benchmark 5: t3070 on jk/chainlint-fixes~4
    Time (mean ± σ):      4.604 s ±  0.014 s    [User: 3.599 s, System: 0.887 s]
    Range (min … max):    4.583 s …  4.629 s    10 runs
  
  Benchmark 6: t3070 on jk/chainlint-fixes~5
    Time (mean ± σ):      4.603 s ±  0.010 s    [User: 3.578 s, System: 0.904 s]
    Range (min … max):    4.583 s …  4.617 s    10 runs
  
  Summary
    't3070 on jk/chainlint-fixes~0' ran
      1.01 ± 0.01 times faster than 't3070 on jk/chainlint-fixes~1'
      1.15 ± 0.02 times faster than 't3070 on jk/chainlint-fixes~2'
      1.15 ± 0.02 times faster than 't3070 on jk/chainlint-fixes~3'
      1.25 ± 0.02 times faster than 't3070 on jk/chainlint-fixes~5'
      1.25 ± 0.02 times faster than 't3070 on jk/chainlint-fixes~4'

Which is what we'd expect. We got about 1.25x faster, in two jumps at ~3 and ~1, which were the patches removing subshells (marking commits by their parent number is rather confusing; I think it might be worth making a small hyperfine wrapper that feeds the commit summary to "-n").

So no effect on the series (good), but I didn't want to leave the mystery unsolved on the list. :)

-Peff