pageserver: Reduce tracing overhead in timeline::get

[ivaxer]

Problem

Compaction process (specifically the image layer reconstructions part) is lagging behind wal ingest (at speed ~10-15MB/s) for medium-sized tenants (30-50GB). CPU profile shows that significant amount of time (see flamegraph) is being spent in tracing::span::Span::new.

mainline (commit: 0ba4cae):

Summary of changes

By lowering the tracing level in get_value_reconstruct_data and get_or_maybe_download from info to debug, we can reduce the overhead of span creation in prod environments. On my system, this sped up the image reconstruction process by 60% (from 14500 to 23160 page reconstruction per sec)

pr:

create_image_layers() (it's 1 CPU bound here) mainline vs pr:

Checklist before requesting a review

• I have performed a self-review of my code.
• If it is a core feature, I have added thorough tests.
• Do we need to implement analytics? if so did you add the relevant metrics to the dashboard?
• If this PR requires public announcement, mark it with /release-notes label and add several sentences in this section.

Checklist before merging

• Do not forget to reformat commit message to not include the above checklist

[github-actions]

2190 tests run: 2105 passed, 0 failed, 85 skipped (full report)

---

Flaky tests (1)

Postgres 15

• test_issue_5878: release

Code coverage (full report)

• functions: 55.1% (9680 of 17563 functions)
• lines: 82.4% (55639 of 67543 lines)

---

_{The comment gets automatically updated with the latest test results
ce692a6 at 2023-12-18T13:07:46.072Z :recycle:}

[koivunej]

I think it would be great to comment on why those are debug spans, also I did not work plain "debug" would work, but this is a good find anyways.

I will add the comment when I reshuffle the spans to be on the public api of the layer in a follow-up PR later this week.

[problame]

The main concern I have is with losing context in case we log an error inside the code whose level you demote to debug in this PR.
Take for example

neon/pageserver/src/tenant/storage_layer/layer.rs

Line 884 in 52718bb

tracing::error!("layer file download failed, and additionally failed to communicate this to caller: {e:?}");

Currently if we log something there it contains the layer= field.

My understanding is that we'll lose that layer field with this PR.

Of course this can be fixed by rigoruously including layer= field in all the tracing::{info,warn,error}! usage in the call graph of get_or_maybe_download.

So I guess it's a trade-off between performance and convenience.

That being said, the performance gains are impressive.

I assume your workload didn't actually do any ondemand downloads.

Wondering if we can delay the creation of the span (remaining at info level) until we know we're off the hot path.

At least for get_or_maybe_download, it seems straight forward.
@koivunej , thoughts?

[koivunej]

Good point. The delayed span creation can be implemented by creating the span only at this line:

neon/pageserver/src/tenant/storage_layer/layer.rs

Line 744 in 8460654

};

so the span is created only when the factory is called to actually download and initialize, not before.

Span needed there is:

neon/pageserver/src/tenant/storage_layer/layer.rs

Line 654 in 8460654

#[tracing::instrument(skip_all, fields(layer=%self))]

so:

-}
+}.instrument(tracing::info_span!("get_or_maybe_download", layer=%self))

[ivaxer]

I assume your workload didn't actually do any ondemand downloads.

Yes, I hope this is typical when generating images in the timeline::compact().

I'll try @koivunej suggestion, thanks.

[problame]

Can we do something similar for get_value_reconstruct_data?

[problame]

IIUC the contribution of get_value_reconstruct_data and get_or_maybe_download is roughly 50:50 in your benchmarks?

If so, let's get the get_or_maybe_download part merged as part of this PR and create a follow-up to improve the get_value_reconstruct_data.

[ivaxer]

IIUC the contribution of get_value_reconstruct_data and get_or_maybe_download is roughly 50:50 in your benchmarks?

Yes.

If so, let's get the get_or_maybe_download part merged as part of this PR

Ok.

and create a follow-up to improve the get_value_reconstruct_data.

Ok. Span::new will take >20% CPU time of Timeline::get_reconstruct_data. Any ideas on how to do this other than not creating new span?

flamegraph:

[shanyp]

@ivaxer thanks for your contribution