clean up logging around on-demand downloads #4030

problame · 2023-04-14T12:39:18Z

Remove repeated tenant & timeline from span
Demote logging of the path to debug level
Log completion at info level, in the same function where we log errors
distinguish between layer file download success & on-demand download succeeding as a whole in the log message wording
Assert that the span contains a tenant id and a timeline id

Before:

  INFO compaction_loop{tenant_id=$TENANT_ID}:compact_timeline{timeline=$TIMELINE_ID}:download_remote_layer{tenant_id=$TENANT_ID timeline_id=$TIMELINE_ID layer=000000000000000000000000000000000000-FFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFF__00000000020C8A71-00000000020CAF91}: download complete: /storage/pageserver/data/tenants/$TENANT_ID/timelines/$TIMELINE_ID/000000000000000000000000000000000000-FFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFF__00000000020C8A71-00000000020CAF91
  INFO compaction_loop{tenant_id=$TENANT_ID}:compact_timeline{timeline=$TIMELINE_ID}:download_remote_layer{tenant_id=$TENANT_ID timeline_id=$TIMELINE_ID layer=000000000000000000000000000000000000-FFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFF__00000000020C8A71-00000000020CAF91}: Rebuilt layer map. Did 9 insertions to process a batch of 1 updates.

After:

  INFO compaction_loop{tenant_id=$TENANT_ID}:compact_timeline{timeline=$TIMELINE_ID}:download_remote_layer{layer=000000000000000000000000000000000000-FFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFF__00000000020C8A71-00000000020CAF91}: layer file download finished
  INFO compaction_loop{tenant_id=$TENANT_ID}:compact_timeline{timeline=$TIMELINE_ID}:download_remote_layer{layer=000000000000000000000000000000000000-FFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFF__00000000020C8A71-00000000020CAF91}: Rebuilt layer map. Did 9 insertions to process a batch of 1 updates.
  INFO compaction_loop{tenant_id=$TENANT_ID}:compact_timeline{timeline=$TIMELINE_ID}:download_remote_layer{layer=000000000000000000000000000000000000-FFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFF__00000000020C8A71-00000000020CAF91}: on-demand download successful

pageserver/src/tenant/timeline.rs

koivunej

Approving even with 2 => 3 expansion, but I wish that was still considered. Need to upgrade log analysis dashboards.

github-actions · 2023-04-14T14:05:21Z

Test results for `50d8430`:

debug build: 219 tests run: 209 passed, 0 failed, 10 (full report)

release build: 219 tests run: 209 passed, 0 failed, 10 (full report)

pageserver/src/bin/pageserver.rs

libs/utils/src/tracing_span_assert.rs

problame · 2023-04-21T12:57:14Z

Switch to tracing-error crate's SpanTrace https://docs.rs/tracing-error/latest/tracing_error/struct.SpanTrace.html#method.with_spans

problame · 2023-04-25T15:35:02Z

@arssher adding you / safekeepers to the review because the logging code is shared. The perf overhead of the tracing_error is non-zero, but, I'd like to have it enabled in release builds to see what the actual overhead is in prod. Are safekeepers ok with that?

- Remove repeated tenant & timeline from span - Demote logging of the path to debug level - Log completion at info level, in the same function where we log errors - distinguish between layer file download success & on-demand download succeeding as a whole in the log message wording - Assert that the span contains a tenant id and a timeline id The assert uncovered that walreceiver_connection uses TenantTimelineId in the span. I changed that to tenant_id and timeline_id. fixes #3945 Before: ``` INFO compaction_loop{tenant_id=$TENANT_ID}:compact_timeline{timeline=$TIMELINE_ID}:download_remote_layer{tenant_id=$TENANT_ID timeline_id=$TIMELINE_ID layer=000000000000000000000000000000000000-FFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFF__00000000020C8A71-00000000020CAF91}: download complete: /storage/pageserver/data/tenants/$TENANT_ID/timelines/$TIMELINE_ID/000000000000000000000000000000000000-FFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFF__00000000020C8A71-00000000020CAF91 INFO compaction_loop{tenant_id=$TENANT_ID}:compact_timeline{timeline=$TIMELINE_ID}:download_remote_layer{tenant_id=$TENANT_ID timeline_id=$TIMELINE_ID layer=000000000000000000000000000000000000-FFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFF__00000000020C8A71-00000000020CAF91}: Rebuilt layer map. Did 9 insertions to process a batch of 1 updates. ``` After: ``` INFO compaction_loop{tenant_id=$TENANT_ID}:compact_timeline{timeline=$TIMELINE_ID}:download_remote_layer{layer=000000000000000000000000000000000000-FFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFF__00000000020C8A71-00000000020CAF91}: layer file download finished INFO compaction_loop{tenant_id=$TENANT_ID}:compact_timeline{timeline=$TIMELINE_ID}:download_remote_layer{layer=000000000000000000000000000000000000-FFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFF__00000000020C8A71-00000000020CAF91}: Rebuilt layer map. Did 9 insertions to process a batch of 1 updates. INFO compaction_loop{tenant_id=$TENANT_ID}:compact_timeline{timeline=$TIMELINE_ID}:download_remote_layer{layer=000000000000000000000000000000000000-FFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFF__00000000020C8A71-00000000020CAF91}: on-demand download successful ```

problame · 2023-04-26T09:07:00Z

Rebased to get the fix for the failed test

commit bfd45dd6713a2e9038954cf0368b1a082937b045
Author: Joonas Koivunen <joonas@neon.tech>
Date:   Tue Apr 25 18:41:09 2023 +0300

    test_tenant_config: allow ERROR from eviction task (#4074)

arssher · 2023-04-26T10:07:15Z

Is the only reason for tracing_error inclusion is debug_assert_current_span_has_tenant_and_timeline_id? We try not to have many logs in perf sensitive places, so this shouldn't be an issue, but just to understand.

Also seems like tracing_error layer can be made optional, if needed.

problame · 2023-04-26T10:11:54Z

Is the only reason for tracing_error inclusion is debug_assert_current_span_has_tenant_and_timeline_id?

Yes.

We try not to have many logs in perf sensitive places, so this shouldn't be an issue, but just to understand.

I don't understand this sentence.
We're not logging anything in debug_assert_current_span_has_tenant_and_timeline_id.
What it does, essentially, is walk up the stack of tracing::Span and ensure that, along that walk, we see a tenant_id or tenant field, and a timeline_id or timeline field.

Also seems like tracing_error layer can be made optional, if needed.

True, since debug_assert_current_span_has_tenant_and_timeline_id is cfg(debug_assertion), we can make the tracing_error layer cfg(debug_assertion) as well.

But, as I said,

The perf overhead of the tracing_error is non-zero, but, I'd like to have it enabled in release builds to see what the actual overhead is in prod. Are safekeepers ok with that?

So, I read it's not Ok for you (SKs) to have it enabled always?

arssher · 2023-04-26T12:47:29Z

I don't understand this sentence.

I should have made it separate paragraph, not related to debug_assert_current_span_has_tenant_and_timeline_id.

So I think it is ok, I just ensured we can easily turn it off if needed.

problame · 2023-04-26T13:02:09Z

So I think it is ok, I just ensured we can easily turn it off if needed.

Ok, it can't be turned off currently, so, I take as an action item that it should be configurable and off by default?

arssher · 2023-04-26T13:09:35Z

I doubt this is important currently, my message that we try not to log a lot in perf sensitive places was supposed to be an argument why this shouldn't be important. I think we can return here only if we spot any problems.

But if the whole deal is a matter of adding single #[cfg(debug_assertions)] in logging.rs, why not.

arssher · 2023-04-26T13:11:37Z

but, I'd like to have it enabled in release builds to see what the actual overhead is in prod.

Ah, I missed that part. Then leaving as is is definitely ok.

problame · 2023-04-26T13:22:59Z

@arssher now I already put in the work :D
The latest commit constrains the enablement to just pageserver, and there only if cfg!(debug_assertions).

That takes out almost all the performance risk with this PR.

arssher · 2023-04-26T13:29:47Z

cool!

PR `build: run clippy for powerset of features (#4077)` brought us a `clippy --release` pass. It was merged after #4030, which fails under `clippy --release` with ``` error: static `TENANT_ID_EXTRACTOR` is never used --> pageserver/src/tenant/timeline.rs:4270:16 | 4270 | pub static TENANT_ID_EXTRACTOR: once_cell::sync::Lazy< | ^^^^^^^^^^^^^^^^^^^ | = note: `-D dead-code` implied by `-D warnings` error: static `TIMELINE_ID_EXTRACTOR` is never used --> pageserver/src/tenant/timeline.rs:4276:16 | 4276 | pub static TIMELINE_ID_EXTRACTOR: once_cell::sync::Lazy< | ^^^^^^^^^^^^^^^^^^^^^ ``` A merge queue would have prevented this.

problame requested a review from koivunej April 14, 2023 12:39

koivunej reviewed Apr 14, 2023

View reviewed changes

pageserver/src/tenant/timeline.rs Outdated Show resolved Hide resolved

koivunej reviewed Apr 14, 2023

View reviewed changes

pageserver/src/tenant/timeline.rs Outdated Show resolved Hide resolved

koivunej approved these changes Apr 14, 2023

View reviewed changes

problame commented Apr 14, 2023

View reviewed changes

pageserver/src/bin/pageserver.rs Outdated Show resolved Hide resolved

problame commented Apr 15, 2023

View reviewed changes

libs/utils/src/tracing_span_assert.rs Outdated Show resolved Hide resolved

problame force-pushed the problame/ondemand-log-cleanup branch from 3221e35 to f03a2d1 Compare April 25, 2023 15:32

problame marked this pull request as ready for review April 25, 2023 15:33

problame requested review from a team as code owners April 25, 2023 15:33

problame requested review from knizhnik, arssher and a team and removed request for a team and knizhnik April 25, 2023 15:33

problame force-pushed the problame/ondemand-log-cleanup branch from f03a2d1 to 6d5a7fc Compare April 26, 2023 09:06

arssher approved these changes Apr 26, 2023

View reviewed changes

make tracing_error enablement configurable, only do it in pageserver

e0ebe4b

fixups previous commit

50d8430

problame enabled auto-merge (squash) April 26, 2023 15:26

problame removed the request for review from a team April 27, 2023 09:54

problame merged commit 9ea7b5d into main Apr 27, 2023

problame deleted the problame/ondemand-log-cleanup branch April 27, 2023 09:54

problame mentioned this pull request Apr 27, 2023

fix clippy --release failure introduced in #4030 #4095

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

clean up logging around on-demand downloads #4030

clean up logging around on-demand downloads #4030

problame commented Apr 14, 2023 •

edited

Loading

koivunej left a comment

github-actions bot commented Apr 14, 2023 •

edited

Loading

problame commented Apr 21, 2023 •

edited

Loading

problame commented Apr 25, 2023

problame commented Apr 26, 2023

arssher commented Apr 26, 2023

problame commented Apr 26, 2023

arssher commented Apr 26, 2023

problame commented Apr 26, 2023

arssher commented Apr 26, 2023 •

edited

Loading

arssher commented Apr 26, 2023

problame commented Apr 26, 2023

arssher commented Apr 26, 2023

clean up logging around on-demand downloads #4030

clean up logging around on-demand downloads #4030

Conversation

problame commented Apr 14, 2023 • edited Loading

koivunej left a comment

Choose a reason for hiding this comment

github-actions bot commented Apr 14, 2023 • edited Loading

Test results for 50d8430:

debug build: 219 tests run: 209 passed, 0 failed, 10 (full report)

release build: 219 tests run: 209 passed, 0 failed, 10 (full report)

problame commented Apr 21, 2023 • edited Loading

problame commented Apr 25, 2023

problame commented Apr 26, 2023

arssher commented Apr 26, 2023

problame commented Apr 26, 2023

arssher commented Apr 26, 2023

problame commented Apr 26, 2023

arssher commented Apr 26, 2023 • edited Loading

arssher commented Apr 26, 2023

problame commented Apr 26, 2023

arssher commented Apr 26, 2023

problame commented Apr 14, 2023 •

edited

Loading

github-actions bot commented Apr 14, 2023 •

edited

Loading

Test results for `50d8430`:

problame commented Apr 21, 2023 •

edited

Loading

arssher commented Apr 26, 2023 •

edited

Loading