Performance regression in `gix-blame`

[Byron]

gix blame on tag gix-blame-v0.1.0 is much faster than on main. The main difference is the usage of zlib-ng than zlib-rs.

❯ hyperfine './gix-main blame README.md' './gix-0.1 blame README.md' 'git blame README.md'
Benchmark 1: ./gix-main blame README.md
  Time (mean ± σ):     157.4 ms ±   0.6 ms    [User: 149.5 ms, System: 5.9 ms]
  Range (min … max):   156.1 ms … 158.4 ms    18 runs

Benchmark 2: ./gix-0.1 blame README.md
  Time (mean ± σ):      50.9 ms ±   0.5 ms    [User: 41.7 ms, System: 6.9 ms]
  Range (min … max):    50.0 ms …  52.6 ms    56 runs

Benchmark 3: git blame README.md
  Time (mean ± σ):      52.1 ms ±   0.7 ms    [User: 43.7 ms, System: 6.3 ms]
  Range (min … max):    49.9 ms …  53.2 ms    54 runs

Summary
  ./gix-0.1 blame README.md ran
    1.02 ± 0.02 times faster than git blame README.md
    3.10 ± 0.03 times faster than ./gix-main blame README.md

gix-blame.trace.zip

Before we jump to conclusions, I may also note that this could be related to the object caching being less effective or disabled for some reason. Also, the traversal algorithm changed and maybe it does more work.

Maybe a good first check would be to bring back zlib-ng for a test-run on main.

diff --git a/gix-features/Cargo.toml b/gix-features/Cargo.toml
index a955c1f2f0..7996f9d7fe 100644
--- a/gix-features/Cargo.toml
+++ b/gix-features/Cargo.toml
@@ -121,7 +121,7 @@ bytesize = { version = "2.0.1", optional = true }
 bytes = { version = "1.0.0", optional = true }
 
 # zlib module
-flate2 = { version = "1.1.1", optional = true, default-features = false, features = ["zlib-rs"] }
+flate2 = { version = "1.1.1", optional = true, default-features = false, features = ["zlib-ng"] }
 thiserror = { version = "2.0.0", optional = true }
 
 once_cell = { version = "1.21.3", optional = true }

Turns out that zlib-ng is slower than zlib-rs, and that the ZLIB backend is only hit more in main, it's not slower.

[Byron]

CC @cruessler - I recommend to bisect it.

[cruessler]

For the record, the results of bisecting and running gix blame README.md at each step.

❯ git bisect bad
96164c5936032b4edb973828178cc55793dd57cc is the first bad commit

96164c5 is the commit that switched gitoxide to zlib-rs. While this finding explains my initial observations, it still somehow feels wrong as that switch was supposed to make everything faster. :-)

Details

8d8dba212-main

❯ hyperfine 'bin/gix-8d8dba212-main blame README.md'
Benchmark 1: bin/gix-8d8dba212-main blame README.md
  Time (mean ± σ):     276.0 ms ±   2.7 ms    [User: 253.9 ms, System: 20.9 ms]
  Range (min … max):   271.1 ms … 281.4 ms    10 runs

4f2717960

❯ hyperfine 'bin/gix-4f2717960 blame README.md'
Benchmark 1: bin/gix-4f2717960 blame README.md
  Time (mean ± σ):     280.6 ms ±   2.4 ms    [User: 257.8 ms, System: 21.1 ms]
  Range (min … max):   277.8 ms … 285.0 ms    10 runs

f965540c1

❯ hyperfine 'bin/gix-f965540c1 blame README.md'
Benchmark 1: bin/gix-f965540c1 blame README.md
  Time (mean ± σ):     278.9 ms ±   4.8 ms    [User: 255.3 ms, System: 19.7 ms]
  Range (min … max):   273.9 ms … 288.2 ms    10 runs

49fa9f381

❯ hyperfine 'bin/gix-49fa9f381 blame README.md'
Benchmark 1: bin/gix-49fa9f381 blame README.md
  Time (mean ± σ):     275.1 ms ±   1.1 ms    [User: 252.0 ms, System: 21.7 ms]
  Range (min … max):   273.8 ms … 276.9 ms    10 runs

46227e6d1

❯ hyperfine 'bin/gix-46227e6d1 blame README.md'
Benchmark 1: bin/gix-46227e6d1 blame README.md
  Time (mean ± σ):     277.4 ms ±   1.9 ms    [User: 254.3 ms, System: 21.6 ms]
  Range (min … max):   274.3 ms … 281.6 ms    10 runs

aa91f9ae4

❯ hyperfine 'bin/gix-aa91f9ae4 blame README.md'
Benchmark 1: bin/gix-aa91f9ae4 blame README.md
  Time (mean ± σ):     275.0 ms ±   1.7 ms    [User: 253.9 ms, System: 19.9 ms]
  Range (min … max):   272.1 ms … 277.5 ms    10 runs

633f0a86b

❯ hyperfine 'bin/gix-633f0a86b blame README.md'
Benchmark 1: bin/gix-633f0a86b blame README.md
  Time (mean ± σ):     275.9 ms ±   1.7 ms    [User: 253.4 ms, System: 20.9 ms]
  Range (min … max):   273.2 ms … 279.9 ms    10 runs

96164c593

❯ hyperfine 'bin/gix-96164c593 blame README.md'
Benchmark 1: bin/gix-96164c593 blame README.md
  Time (mean ± σ):     277.3 ms ±   3.0 ms    [User: 254.6 ms, System: 20.8 ms]
  Range (min … max):   274.5 ms … 283.3 ms    10 runs

f3684a4f6

❯ hyperfine 'bin/gix-f3684a4f6 blame README.md'
Benchmark 1: bin/gix-f3684a4f6 blame README.md
  Time (mean ± σ):     154.5 ms ±   2.0 ms    [User: 122.8 ms, System: 30.9 ms]
  Range (min … max):   151.2 ms … 160.3 ms    18 runs

d139fa469

❯ hyperfine 'bin/gix-d139fa469 blame README.md'
Benchmark 1: bin/gix-d139fa469 blame README.md
  Time (mean ± σ):     155.9 ms ±   1.9 ms    [User: 124.0 ms, System: 30.5 ms]
  Range (min … max):   152.5 ms … 160.3 ms    18 runs

b41312b47-gix-blame-v0.1.0

❯ hyperfine 'bin/gix-b41312b47-gix-blame-v0.1.0 blame README.md'
Benchmark 1: bin/gix-b41312b47-gix-blame-v0.1.0 blame README.md
  Time (mean ± σ):     166.3 ms ±   1.6 ms    [User: 136.2 ms, System: 28.8 ms]
  Range (min … max):   164.2 ms … 170.0 ms    17 runs

[Byron]

The strange thing is that I have no idea how that can be, i.e. when reverting 96164c5 I think performance actually went down, i.e. zlib-ng is slightly slower at the same task.
Is this something you could validate? Alternatively, the patch above can be used as well, but I'd recommend to double-check everything.
Thanks again for your help with this!

[cruessler]

I reverted 96164c5 and performance went back to roughly as fast as it was before. My changes are in this commit cruessler@065d578, on a branch called bisect-gix-blame-performance:

❯ hyperfine 'bin/gix-96164c593-reverted blame README.md'
Benchmark 1: bin/gix-96164c593-reverted blame README.md
  Time (mean ± σ):     161.3 ms ±   2.0 ms    [User: 130.5 ms, System: 29.9 ms]
  Range (min … max):   158.7 ms … 165.6 ms    18 runs

The only difference to the state pre 96164c5 is that I had to go back to zip 2.4.2 because the version originally used pre 96164c5 (2.6.1) had been yanked in the meantime.

Next, I’m going to try and figure out if there’s a more specific change responsible, such as a feature toggle or a dependency upgrade.

[Byron]

Alright, if bisect wasn't enough, this is clear proof that the zlib-rs introduction had this effect.
It's impossible that it's this slow, I would have noticed, so this is still puzzling to me.

But the results could be more clear on AARCH64 either.

❯ hyperfine './gix-main blame README.md' './gix-96164c5-reverted blame README.md'
Benchmark 1: ./gix-main blame README.md
  Time (mean ± σ):     154.8 ms ±   2.4 ms    [User: 146.0 ms, System: 6.2 ms]
  Range (min … max):   151.8 ms … 160.3 ms    19 runs

Benchmark 2: ./gix-96164c5-reverted blame README.md
  Time (mean ± σ):      46.3 ms ±   0.7 ms    [User: 36.7 ms, System: 7.3 ms]
  Range (min … max):    44.2 ms …  48.3 ms    60 runs

Summary
  ./gix-96164c5-reverted blame README.md ran
    3.34 ± 0.07 times faster than ./gix-main blame README.md

Could we get a quick sanity-check from @folkertdev about cruessler@065d578 - how can it possibly be that it's so much slower here if my verify-pack tests (which decode a lot of small packed objects in an optimised fashion) come out faster than zlib-ng?
I am still puzzled about this, and the factor of 3.3x makes no sense.

Thanks so much!

[folkertdev]

Hmm, it does look like zlib-rs is slower here, but I can't reproduce your 3x numbers. I get

> poop 'target/release/gix-zlib-rs blame README.md' 'target/release/gix-zlib-ng blame README.md' 'git blame README.md'
Benchmark 1 (21 runs): target/release/gix-zlib-rs blame README.md
  measurement          mean ± σ            min … max           outliers         delta
  wall_time           248ms ± 1.36ms     246ms …  251ms          0 ( 0%)        0%
  peak_rss           90.6MB ±  213KB    90.3MB … 90.9MB          0 ( 0%)        0%
  cpu_cycles         1.04G  ± 4.75M     1.04G  … 1.06G           0 ( 0%)        0%
  instructions       3.12G  ±  640K     3.12G  … 3.12G           0 ( 0%)        0%
  cache_references   32.5M  ±  348K     32.0M  … 33.3M           0 ( 0%)        0%
  cache_misses       2.14M  ± 44.7K     2.09M  … 2.25M           0 ( 0%)        0%
  branch_misses      5.21M  ±  110K     5.11M  … 5.48M           2 (10%)        0%
Benchmark 2 (22 runs): target/release/gix-zlib-ng blame README.md
  measurement          mean ± σ            min … max           outliers         delta
  wall_time           228ms ± 5.10ms     225ms …  248ms          2 ( 9%)        ⚡-  8.2% ±  0.9%
  peak_rss           90.3MB ±  116KB    90.0MB … 90.5MB          0 ( 0%)          -  0.4% ±  0.1%
  cpu_cycles          949M  ± 18.9M      940M  … 1.03G           1 ( 5%)        ⚡-  9.1% ±  0.8%
  instructions       2.50G  ±  107K     2.50G  … 2.50G           0 ( 0%)        ⚡- 19.9% ±  0.0%
  cache_references   28.7M  ± 1.49M     27.6M  … 33.2M           3 (14%)        ⚡- 11.8% ±  2.1%
  cache_misses       2.13M  ±  159K     2.04M  … 2.83M           2 ( 9%)          -  0.7% ±  3.4%
  branch_misses      5.23M  ± 75.4K     5.17M  … 5.45M           2 ( 9%)          +  0.6% ±  1.1%
Benchmark 3 (46 runs): git blame README.md
  measurement          mean ± σ            min … max           outliers         delta
  wall_time           110ms ± 1.22ms     109ms …  118ms          2 ( 4%)        ⚡- 55.5% ±  0.3%
  peak_rss           62.4MB ± 85.0KB    62.2MB … 62.6MB          0 ( 0%)        ⚡- 31.2% ±  0.1%
  cpu_cycles          444M  ± 3.00M      441M  …  461M           3 ( 7%)        ⚡- 57.5% ±  0.2%
  instructions       1.05G  ± 54.0K     1.05G  … 1.05G           2 ( 4%)        ⚡- 66.3% ±  0.0%
  cache_references   21.4M  ±  168K     21.1M  … 21.8M           0 ( 0%)        ⚡- 34.3% ±  0.4%
  cache_misses       1.24M  ± 27.0K     1.18M  … 1.30M           0 ( 0%)        ⚡- 42.4% ±  0.8%
  branch_misses      3.60M  ± 63.0K     3.53M  … 3.78M           6 (13%)        ⚡- 30.8% ±  0.8%

This is on f7bfff4, I've compiled with cargo build --bin gix --profile=bench. This is on linux/x86_64. Has all of your profiling been on aarch64/macos?

The workload here appears to consist of many tiny invocations. I'll look into updating our benchmarks with such a workload.

[Byron]

Thanks so much!

It's good to know that this doesn't seem to be happening everywhere.

This is on f7bfff4, I've compiled with cargo build --bin gix --profile=bench. This is on linux/x86_64. Has all of your profiling been on aarch64/macos?

My testing has been on MacOS/aarch64 always, but @cruessler may also have been on linux/x86-64 if I remember correctly, seeing differences of 2x (please correct me though).

The workload here appears to consist of many tiny invocations. I'll look into updating our benchmarks with such a workload.

Yes, this is what happens when the packed entries are decoded, and that's particularly intense when verifying packs after cloning for instance. However, that is what I tested before switching to zlib-rs, and even though it might be a little slower under these conditions, ultimately it was a little faster overall. There was no issue, particularly not a 3x one.

My test-runs were with --release only, maybe that's related.

[profile.release]
overflow-checks = false
lto = "thin"
# This bloats files but assures destructors are called, important for tempfiles. One day I hope we
# can wire up the 'abrt' signal handler so tempfiles will be removed in case of panics.
panic = "unwind"
incremental = false

Just to be sure, I re-ran with --profile=bench and have the same result.

❯ hyperfine './gix-8d8dba2-bench-zlib-ng blame README.md' './gix-f7bfff4-bench-zlib-rs blame README.md'
Benchmark 1: ./gix-8d8dba2-bench-zlib-ng blame README.md
  Time (mean ± σ):      46.7 ms ±   0.6 ms    [User: 36.9 ms, System: 7.3 ms]
  Range (min … max):    45.0 ms …  48.1 ms    61 runs

Benchmark 2: ./gix-f7bfff4-bench-zlib-rs blame README.md
  Time (mean ± σ):     157.7 ms ±   1.4 ms    [User: 148.7 ms, System: 6.6 ms]
  Range (min … max):   155.5 ms … 160.0 ms    18 runs

Summary
  ./gix-8d8dba2-bench-zlib-ng blame README.md ran
    3.38 ± 0.05 times faster than ./gix-f7bfff4-bench-zlib-rs blame README.md

The version I use for zlib-ng isn't the very latest, that shoudln't be material (it's cruessler@065d578).

[cruessler]

Thanks a lot!

My numbers all come from linux/x86_64 (but I was able to confirm the rough magnitude of the effect on macos/aarch64).

[folkertdev]

I've tried to isolate the pattern here

trifectatechfoundation/zlib-rs#411

could you give that branch/example a go and see if that still reproduces the 3X difference? If so, I truly have no idea what is happening there. I've tried a bunch of rust versions (hence LLVM versions), but that does not help much.

On my machine that example is 6% slower with zlib-rs versus zlib-ng.

Benchmark 1 (6 runs): target/release/examples/gix-blame ng
  measurement          mean ± σ            min … max           outliers         delta
  wall_time           924ms ± 9.55ms     914ms …  936ms          0 ( 0%)        0%
  peak_rss           3.39MB ± 53.5KB    3.28MB … 3.41MB          1 (17%)        0%
  cpu_cycles         4.25G  ± 44.3M     4.21G  … 4.32G           0 ( 0%)        0%
  instructions       10.1G  ±  272      10.1G  … 10.1G           0 ( 0%)        0%
  cache_references   61.3M  ± 16.3M     50.1M  … 84.4M           0 ( 0%)        0%
  cache_misses        596K  ±  108K      409K  …  727K           0 ( 0%)        0%
  branch_misses      20.2M  ±  111K     20.0M  … 20.3M           0 ( 0%)        0%
Benchmark 2 (6 runs): target/release/examples/gix-blame rs
  measurement          mean ± σ            min … max           outliers         delta
  wall_time           977ms ± 33.9ms     961ms … 1.05s           0 ( 0%)        💩+  5.8% ±  3.5%
  peak_rss           3.41MB ±    0      3.41MB … 3.41MB          0 ( 0%)          +  0.6% ±  1.4%
  cpu_cycles         4.49G  ±  158M     4.41G  … 4.81G           0 ( 0%)        💩+  5.6% ±  3.5%
  instructions       12.7G  ±  236      12.7G  … 12.7G           0 ( 0%)        💩+ 26.1% ±  0.0%
  cache_references   66.2M  ± 22.6M     56.4M  …  112M           0 ( 0%)          +  7.9% ± 41.4%
  cache_misses        569K  ± 98.2K      419K  …  721K           0 ( 0%)          -  4.5% ± 22.3%
  branch_misses      21.7M  ±  179K     21.5M  … 22.0M           0 ( 0%)        💩+  7.6% ±  0.9%

So we'll have to shave that down. It's a pattern of input we haven't really looked at, so I'm assuming we'll be able to get on-par performance here.

[cruessler]

I ran your example on my linux/x86_64 machine. The difference is almost completely gone:

zlib-rs on gix-blame-example is 📦v0.5.2 via v1.89.0 took 11s
❯ poop 'target/release/examples/gix-blame ng' 'target/release/examples/gix-blame rs'
Benchmark 1 (4 runs): target/release/examples/gix-blame ng
  measurement          mean ± σ            min … max           outliers         delta
  wall_time          1.47s  ± 9.48ms    1.46s  … 1.48s           0 ( 0%)        0%
  peak_rss           3.46MB ± 61.5KB    3.39MB … 3.53MB          0 ( 0%)        0%
  cpu_cycles         5.21G  ± 25.3M     5.19G  … 5.25G           0 ( 0%)        0%
  instructions       9.92G  ±  121      9.92G  … 9.92G           0 ( 0%)        0%
  cache_references    292K  ± 45.6K      245K  …  337K           0 ( 0%)        0%
  cache_misses       9.05K  ± 2.08K     6.74K  … 11.6K           0 ( 0%)        0%
  branch_misses      38.1M  ± 83.6K     38.0M  … 38.2M           0 ( 0%)        0%
Benchmark 2 (4 runs): target/release/examples/gix-blame rs
  measurement          mean ± σ            min … max           outliers         delta
  wall_time          1.48s  ± 11.4ms    1.47s  … 1.50s           0 ( 0%)          +  0.6% ±  1.2%
  peak_rss           3.45MB ± 56.4KB    3.37MB … 3.50MB          1 (25%)          -  0.2% ±  3.0%
  cpu_cycles         5.25G  ± 37.1M     5.22G  … 5.30G           0 ( 0%)          +  0.7% ±  1.1%
  instructions       13.2G  ±  187      13.2G  … 13.2G           0 ( 0%)        💩+ 32.9% ±  0.0%
  cache_references    579K  ± 92.3K      473K  …  683K           0 ( 0%)        💩+ 98.4% ± 43.1%
  cache_misses       8.41K  ± 2.18K     6.43K  … 10.5K           0 ( 0%)          -  7.0% ± 40.7%
  branch_misses      35.2M  ±  169K     35.0M  … 35.4M           0 ( 0%)        ⚡-  7.7% ±  0.6%

In case that matters, my machine’s already a bit older, running an Intel(R) Core(TM) i5-4570 CPU from around 2013.

[Byron]

Thanks so much! On my machine, the 3x result doesn't reproduce at all, and to add some spice, zlib-rs is a whopping 13% faster:

❯ cargo build --release --examples && hyperfine 'target/release/examples/gix-blame ng' 'target/release/examples/gix-blame rs'
    Finished `release` profile [optimized + debuginfo] target(s) in 0.01s
Benchmark 1: target/release/examples/gix-blame ng
  Time (mean ± σ):     906.1 ms ±  41.0 ms    [User: 889.2 ms, System: 4.1 ms]
  Range (min … max):   890.5 ms … 1022.7 ms    10 runs

  Warning: The first benchmarking run for this command was significantly slower than the rest (1.023 s). This could be caused by (filesystem) caches that were not filled until after the first run. You should consider using the '--warmup' option to fill those caches before the actual benchmark. Alternatively, use the '--prepare' option to clear the caches before each timing run.

Benchmark 2: target/release/examples/gix-blame rs
  Time (mean ± σ):     800.5 ms ±   3.6 ms    [User: 795.6 ms, System: 4.1 ms]
  Range (min … max):   797.1 ms … 809.0 ms    10 runs

Summary
  target/release/examples/gix-blame rs ran
    1.13 ± 0.05 times faster than target/release/examples/gix-blame ng

❯ rustc --version
rustc 1.89.0 (29483883e 2025-08-04)

The question is if this is still equivalent to the issue we are measuring here as well.

[folkertdev]

Interesting. and weird.

That example file uses the first 100 inputs to zlib-{rs, ng} that gix passes. Apparently that is not representative, but using much more input is kind of cumbersome (e.g. the file with the inputs is already 5kloc).

I guess I'll see if I can capture the longest-running inputs from that gix blame run, or is there some other pattern in the data that you think might be interesting (e.g. are the first or last inputs larger/smaller or harder/easier to decompress)?

[Byron]

I really like this approach! Somehow I have trouble imagining that multiple sequential inputs influence to the point where there is such a slowdown, but at least in theory it's possible as there is shared state:

gitoxide/gix-features/src/zlib/mod.rs

Lines 34 to 43 in beba720

	pub fn once(&mut self, input: &[u8], out: &mut [u8]) -> Result<(flate2::Status, usize, usize), inflate::Error> {
	let before_in = self.state.total_in();
	let before_out = self.state.total_out();
	let status = self.state.decompress(input, out, flate2::FlushDecompress::None)?;
	Ok((
	status,
	(self.state.total_in() - before_in) as usize,
	(self.state.total_out() - before_out) as usize,
	))
	}

This method is used for decoding packs, which is where many small inputs are coming from.

gitoxide/gix-pack/src/data/file/decode/entry.rs

Lines 119 to 132 in fce7095

	pub(crate) fn decompress_entry_from_data_offset(
	&self,
	data_offset: data::Offset,
	inflate: &mut zlib::Inflate,
	out: &mut [u8],
	) -> Result<usize, zlib::inflate::Error> {
	let offset: usize = data_offset.try_into().expect("offset representable by machine");
	assert!(offset < self.data.len(), "entry offset out of bounds");
	inflate.reset();
	inflate
	.once(&self.data[offset..], out)
	.map(|(_status, consumed_in, _consumed_out)| consumed_in)
	}

I see that the reset is also happening in the minimised example that doesn't go through flate2, so I don't know what else it could be except for some phenomenal miscompilation. Maybe you already ruled that out though.