Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

log: avoid stack lookups when not needed/used #28069

Merged
merged 7 commits into from
Sep 7, 2023

Conversation

holiman
Copy link
Contributor

@holiman holiman commented Sep 6, 2023

We can avoid the somewhat expensive stack.Caller invocation by checking the atomic global.

name            old time/op    new time/op    delta
TraceLogging-8    2.84µs ± 8%    0.97µs ± 4%  -65.87%  (p=0.008 n=5+5)

name            old alloc/op   new alloc/op   delta
TraceLogging-8      511B ± 0%      263B ± 0%  -48.53%  (p=0.008 n=5+5)

name            old allocs/op  new allocs/op  delta
TraceLogging-8      4.00 ± 0%      2.00 ± 0%  -50.00%  (p=0.008 n=5+5)

Closes #28064

})
}
if locationEnabled.Load() {
record.Call = stack.Caller(skip)
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It's problematic. e.g. in the log/handler_glog.go, L188, we assume this is available.

But I agree it's a good optimization, but just need more checks.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Hm, interesting. I dug into this, it turns out that r.Call.String() == %!v(NOFUNC).
due to

// String implements fmt.Stinger. It is equivalent to fmt.Sprintf("%v", c).
func (c Call) String() string {
	return fmt.Sprint(c)
}

So there's no crash, just it won't print the backtrace.

Copy link
Contributor Author

@holiman holiman Sep 7, 2023

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Should be noted, though: the Call is stack.Call -- not a pointer. Nothing is nil here. And it goes on

type Call struct {
	frame runtime.Frame
}

(no pointers)

type Frame struct {
	// PC is the program counter for the location in this frame.
	// For a frame that calls another frame, this will be the
	// program counter of a call instruction. Because of inlining,
	// multiple frames may have the same PC value, but different
	// symbolic information.
	PC uintptr
...

This struct too is (nearly) pointer-free.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Ha I spent two hours yesterday trying to create a test to hit this, but couldn't because no pointer. So it looks good to me

Copy link
Member

@MariusVanDerWijden MariusVanDerWijden left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM

@karalabe
Copy link
Member

karalabe commented Sep 7, 2023

Sweet. On my machine it's 1000ns vs 98 with and without the call.

@karalabe karalabe added this to the 1.13.0 milestone Sep 7, 2023
// storeStackRecords is an atomic flag controlling whether the log handler needs
// to store the callsite stack. This is needed in case any handler wants to
// print locations (locationEnabled), use vmodule, or print full stacks (BacktraceAt).
var stackEnabled atomic.Bool
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

linter's gonna lint :P field and comment name don't match

log/format.go Outdated Show resolved Hide resolved
Copy link
Member

@karalabe karalabe left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

SGTM

@holiman holiman merged commit a8d7201 into ethereum:master Sep 7, 2023
1 of 2 checks passed
thaarok pushed a commit to thaarok/go-ethereum that referenced this pull request Sep 7, 2023
 Avoids the somewhat expensive stack.Caller invocation by checking if it is needed
@holiman holiman deleted the faster_log branch October 11, 2023 07:25
devopsbo3 pushed a commit to HorizenOfficial/go-ethereum that referenced this pull request Nov 10, 2023
 Avoids the somewhat expensive stack.Caller invocation by checking if it is needed
devopsbo3 added a commit to HorizenOfficial/go-ethereum that referenced this pull request Nov 10, 2023
devopsbo3 added a commit to HorizenOfficial/go-ethereum that referenced this pull request Nov 10, 2023
devopsbo3 added a commit to HorizenOfficial/go-ethereum that referenced this pull request Nov 10, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

Extensive trace logging is expensive even when disabled
4 participants