Track PostingsForMatchers cached promise completion timestamp in trace

[pracucci]

In #822 @charleskorn suggested to log the PostingsForMatchers cache promise completion timestamp in the trace. I'm doing it in this PR. However, there's a small performance regression introduced by the extra span event (using epoch timestamp to reduce the regression):

goos: darwin
goarch: arm64
pkg: github.com/prometheus/prometheus/tsdb
cpu: Apple M3 Pro
                                                          │ before.txt  │             after.txt              │
                                                          │   sec/op    │   sec/op     vs base               │
PostingsForMatchersCache/no_evictions-11                    637.3n ± 6%   705.8n ± 1%  +10.74% (p=0.002 n=6)
PostingsForMatchersCache/high_eviction_rate-11              10.67µ ± 1%   10.78µ ± 0%   +1.02% (p=0.002 n=6)
PostingsForMatchersCache_ConcurrencyOnHighEvictionRate-11   327.2n ± 2%   361.6n ± 5%  +10.51% (p=0.002 n=6)
geomean                                                     1.306µ        1.401µ        +7.33%

                                                          │  before.txt  │              after.txt              │
                                                          │     B/op     │     B/op      vs base               │
PostingsForMatchersCache/no_evictions-11                      974.0 ± 0%    1078.0 ± 0%  +10.68% (p=0.002 n=6)
PostingsForMatchersCache/high_eviction_rate-11              26.32Ki ± 0%   26.42Ki ± 0%   +0.39% (p=0.002 n=6)
PostingsForMatchersCache_ConcurrencyOnHighEvictionRate-11    1023.5 ± 0%    1131.5 ± 0%  +10.55% (p=0.002 n=6)
geomean                                                     2.925Ki        3.132Ki        +7.09%

                                                          │ before.txt │             after.txt             │
                                                          │ allocs/op  │ allocs/op   vs base               │
PostingsForMatchersCache/no_evictions-11                    20.00 ± 0%   23.00 ± 0%  +15.00% (p=0.002 n=6)
PostingsForMatchersCache/high_eviction_rate-11              46.00 ± 0%   49.00 ± 0%   +6.52% (p=0.002 n=6)
PostingsForMatchersCache_ConcurrencyOnHighEvictionRate-11   20.00 ± 0%   24.00 ± 4%  +20.00% (p=0.002 n=6)
geomean

[charleskorn]

LGTM - feedback below is not blocking if you're happy with this as-is.

However, there's a small performance regression because attribute.Stringer() is not lazily evaluated, so the timestamp get stringified for every single call, even if that call is not traced.

What if we passed the timestamp as an integer (in seconds / milliseconds / whatever since the epoch), and used 0 to indicate "not completed"? Then we'd avoid the string conversion.

[charleskorn]

It'd be really nice if we were able to always include the timestamp somewhere, as that will make it much easier to confirm exactly which cache entry is being used.

Perhaps we could log evaluationCompletedAt in postingsForMatchersPromise.result()?

[pracucci]

Moved to result(). There's still a regression using epoch, but a smaller one (I've updated the benchmark in the PR description).

[pracucci]

@charleskorn I'm merging this after having addressed your comment. If you have any other (post-merge) comment, I will promptly address it.