-
Notifications
You must be signed in to change notification settings - Fork 17.9k
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
runtime/pprof: give more useful profiling output for time.Now (and other vDSO functions) on Linux #24142
Comments
It is certainly possible to get the complete call stack for the call to |
Change https://golang.org/cl/97315 mentions this issue: |
OK, I discovered a slight wrinkle here: in production, we're running on virtual instances in EC2 and the default Xen clocksource doesn't support vDSO, so time.Now is very slow (~720ns, vs ~50ns on my local machine). This is why I'm seeing such a large _ExternalCode cost in my profiles. If I understand this correctly, we're going through the __vdso_gettimeofday_sym fallback which does a syscall under the hood. One option would be to do the cgo-style bookkeeping only in the fallback case where we know we're going to incur the syscall overhead anyway. |
It's more painful than I thought, as it turns out that the time functions can be called while we are nominally in system call, so simply reusing the fields breaks traceback also. |
Change https://golang.org/cl/99617 mentions this issue: |
This lets SIGPROF signals get a useful traceback. Without it we just see sysvicallN calling asmcgocall. Updates #24142 Change-Id: I5dfe3add51f0c3a4cb1c98acb7738be6396214bc Reviewed-on: https://go-review.googlesource.com/99617 Run-TryBot: Ian Lance Taylor <iant@golang.org> TryBot-Result: Gobot Gobot <gobot@golang.org> Reviewed-by: Austin Clements <austin@google.com>
(Moving this over from a discussion at https://groups.google.com/d/msg/golang-nuts/83xaAgzL2cU/OcLIOdi8CwAJ.)
These results are on Go 1.10 / Linux / amd64, but they're unchanged from previous versions.
On Linux, time.Now (and anything else which calls runtime.walltime and runtime.nanotime) are implemented using a vDSO. When a profiling signal arrives during the vDSO call, pprof attributes that time to the catch-all runtime._ExternalCode, unrelated to any Go function.
Here's a demonstration:
This is unhelpful for the user in several ways:
@ianlancetaylor kindly cooked up https://golang.org/cl/97315 to address (1), so that at least this will be marked as _VDSO instead of _ExternalCode.
Even with this change, it's still hard for users to know that the VDSO time is (likely, but not necessarily) due to time.Now calls, or where those calls originate.
By contrast, if I have a program which is slow because it's making many os.Stat calls, it will be clear from the profile graph that the cause is os.Stat (and what function is calling os.Stat), even though the big red box with all the self time is labeled syscall.Syscall.
I don't know how this would be implemented or even if it's feasible, but I hope that something better can be done for these vDSO calls as well.
This is not a hypothetical or benchmark-only problem. Here is a small part of a pprof graph from an important production service that I'm trying to debug:
(This is a CGO_ENABLED=0 build.)
The text was updated successfully, but these errors were encountered: