proposal: runtime/pprof: add SetMaxDumpGoroutine to limit the number of goroutines dumped in a profile

[doujiang24]

We are using pprof for online profiling and we found goroutine dumping may take too much time when there are many goroutines.

In this case, it will take ~300ms when there are 100k goroutines on my side.
https://gist.github.com/doujiang24/9d066bce3a2bdd0f1b9fe1ef49699e4e

It's a too long time since there are almost 10k-100k goroutines in our system.

I think the easier way is to introduce a new API SetMaxDumpGoroutineNum.
I have implemented it in this PR: #50771

But, the SetMaxDumpGoroutineNum API introduced a new global variable.
This may not be a good idea.

Any feedback would be greatly appreciated. Thank you!

[aclements]

Could you explain your use case more? Usually "online profiling" is done using a CPU profile, not a goroutine profile.

[rsc]

This proposal has been added to the active column of the proposals project
and will now be reviewed at the weekly proposal review meetings.
— rsc for the proposal review group

[rhysh]

Goroutine profiles stop the world, iterate over the entire list of live goroutines, and then restart the world. That whole-app pause can be hundreds of milliseconds when there are hundreds of thousands of goroutines.

@doujiang24 , is the problem for your apps the length of time that the app cannot do any other useful work? If so, it sounds similar to what's described in #33250.

Or is it the length of time that specific goroutine calling runtime/pprof.Lookup("goroutine").WriteTo needs to wait before it gets results?

---

@aclements , I've found regular collection of goroutine profiles to be one of the best tools (combination of effectiveness and ease-of-use) for tracking down problems of "why did my app get slow", including ones like the net/http deadlock in issue 32388. When I encountered that one, it affected a single service instance and self-resolved after about 15 minutes, so we were only able to understand it thanks to regular and automated collection of goroutine profiles. See also fgprof. Though @doujiang24 likely has other uses.

[doujiang24]

Could you explain your use case more? Usually "online profiling" is done using a CPU profile, not a goroutine profile.

@aclements Sorry for the delay.
We want to know what are the goroutines doing or waiting for when there are too many goroutines.
thus, we may get a chance to reduce the number of goroutines.
Sampling is good enough for us since we don't need to know every goroutine.

[doujiang24]

@rhysh Yeah, it's similar to #33250.
We use go for building a network proxy platform(MOSN), it's mostly used as a service mesh data plane.
So, latency is very important for us.

[doujiang24]

I came out with a new idea about the API.
We can introduce the WithMaxGoroutine instead of SetMaxDumpGoroutine to avoid introducing a global variable.

usage:

pprof.Lookup("heap").WithMaxGoroutine(1024).WriteTo(...)

[rsc]

The big question is whether the stop-the-world is the problem versus the size of the profile. If the former, then writing less data won't take appreciably less time.

[doujiang24]

The big question is whether the stop-the-world is the problem versus the size of the profile. If the former, then writing less data won't take appreciably less time.

@rsc Thanks for your point. I did more testing and I'm sharing the test results.

less data works for the previous case that takes ~300ms total (https://gist.github.com/doujiang24/9d066bce3a2bdd0f1b9fe1ef49699e4e)

Also, I have got more testing results by adding more log in pprof.go.
It shows 10x faster by writing less data.

100k goroutines, without the max goroutine limitation, means the standard behavior.

1. fetch profile(runtime_goroutineProfileWithLabels, including the STW) takes ~130ms.
2. the total pprof goroutine dump takes ~300ms (including printCountProfile).

100k goroutines, with the max 1k goroutine limitation, by using the PR #50771

1. fetch profile(runtime_goroutineProfileWithLabelsAndLimit) takes ~15ms.
2. the total pprof goroutine dump takes ~18ms.

Maybe STW may take more time in some other cases, but I think this shows less data will really take appreciably less time.

[rsc]

PR 50771 seems to be doing a random sample of the goroutines. Is that helpful in your use case, not to see all of them?
Then there's the question of the API.

/cc @aclements @mknyszek @prattmic for thoughts

[aclements]

I suspect we could eliminate the STW here at the cost of losing "snapshot consistency" across the goroutine stacks.

Just looking over the current implementation, we could certainly improve the performance of this, though I doubt we can squeeze 10x out of it short of substantially redesigning how traceback works (e.g., using frame pointers).

[mknyszek]

I think it's still not clear to me where exactly the problem lies for your use-case, @doujiang24. Is the 300 ms delay between when you request the profile and when you get it the problem, or is the 130 ms (or however long the world is actually stopped) the problem, because it's a global latency hit.

If it's the latter, one thing we could do instead of limiting the number of goroutines is relax the consistency of the goroutine dump. Depending on how strict we want to be on backwards compatibility with this, this might not require a new API. If the goal is statistical goroutine sampling anyway, then I think that's fine. If a major use-case is getting a consistent snapshot that always 100% makes sense, then either this isn't really an option or it needs a knob.

I imagine that the global latency impact of this approach would be the same latency impact as stack scanning by the GC, which is definitely much, much less than 130 ms even for 100,000 goroutines. However, this would not help the end-to-end latency of the operation; it would still take 300 ms for that many goroutines, limiting how often you can sample.

[prattmic]

Here are some of my initial thoughts, I haven't thought too deeply about this.

Currently, the goroutine profile is a complete instantaneous (one-off) view of what every goroutine is doing. Since it involves a stop-the-world (STW), we even get a consistent view of where every goroutine is at a single point in time [1] [2].

On the other hand, this proposal effectively turns this profile into an instantaneous (one-off) sampled view of what goroutines are doing, since we don't capture every goroutine. It would still maintain the consistent view due to STW.

My question for brainstorming is whether this is the best interface for use-cases of this profile? Is sampling OK, or do we typically need all goroutines? Is a consistent snapshot time needed? If so, maybe this API is best.

But I could also imagine perhaps we could provide a continuous sampling goroutine profile. Rather than a single instantaneous profile point, we sample goroutine state over time, eventually capturing all of them but never all at the same time. Would such a profile be useful, I'm not sure.

[1] As opposed to collecting traces while goroutines are running, which would result in each goroutine getting traced at a slightly different time of execution. In this case it would be possible to observe what appear to be "impossible" states between 2 goroutines.

[2] Modulo that some small bits of code not not preemptible and thus cannot be observed in the profile, but I don't think this matters much.

[ianlancetaylor]

It's worth asking what the purpose of the goroutine profile is. It's not particularly helpful for analyzing performance or memory usage. Presumably it is helpful for finding leaked goroutines: goroutines that are waiting for something to happen that is never going to happen. Are there other uses for this profile?

If that is the main use can we have a more targeted goroutine profile? Such as, only list goroutines that have been blocked for some period of time?

[prattmic]

I've found regular collection of goroutine profiles to be one of the best tools (combination of effectiveness and ease-of-use) for tracking down problems of "why did my app get slow"

@rhysh Could you expand more on this comment? How was this helpful? I'm imagining noticing some goroutines that, while not deadlocked, tend to be blocked or temporarily stopped somewhere we don't expect to be hot, but I'd like to hear if that is what you did.

[rhysh]

A common workflow is to collect hundreds or thousands of goroutine profiles (from every instance of an app, every few minutes, for some time range), to get a count in each profile of the number of goroutines with a function matching ServeHTTP on their stack, and to look at what's different in the profiles that score the highest.

Goroutine profiles were important in tracking down #33747, where a large number of waiters on a single lock would lead to performance collapse.

A team I work with encountered the effects of #32388 last October. We used goroutine profiles to figure out what was going on there, and then discovered that someone had already reported the issue (and they had used goroutine profiles too).

Sometimes the reason an app slows down is that its log collection daemon is running behind, and (with a blocking log library) its calls to log end up waiting on the logger's sync.Mutex for a little while.

None of those are exactly leaks, because the thing those goroutines are waiting for does eventually happen. In the first and third cases, if load on the application decreases then the goroutines will each get a turn with the sync.Mutex. In the second case the OS closes the TCP connection after 15 minutes or so (sometimes faster).

We also used them to debug the problem that led to aws/aws-sdk-go#3127, where a sync.Mutex protected a cache that was only populated on success, so consistent failures led to 100% cache misses which were then serialized.

Around Go 1.13, an app I support with a typical response time of 1ms had occasional delays of 100ms. I used goroutine profiles to learn that those requests were delayed in particular functions by calls to runtime.morestack{,_noctxt}. A very close look with the CPU profiler (with request id added as a profile label, filtering to request IDs that showed up more than once) showed contention in runtime.(*mcentral).cacheSpan, which was fixed by then in CL 221182 (thanks @mknyszek !).

It's a very general tool, very easy to deploy (vs the opt-in of block/mutex profiles), very easy to use (vs execution trace).

[doujiang24]

Thanks for @rhysh 's use cases.
In our system, we monitor the goroutine number online regularly and will dump a goroutine profile when:

1. the number increased too much suddenly(may decrease after some time),
2. or increased to a very large number.
   (we haven't enabled regular dump since we want to reduce the overhead of dumping).

in the 1st case, it may be caused by some unexpected issue, eg. network block or unexpected lock in some corner case.
for the second case, it usually means leaking and we can figure out it before online, but there may still have some corner cases that only happen online.

Actually, we care about two-part overhead:

1. fetch profile(means the STW time mostly), ~130ms in the test case.
2. other pure formatting or dumping working(means the printCountProfile), the ~170ms left.

the 1st STW time is more important for us.
but we also want to reduce the second time since ~170ms pure CPU time is also a bit heavy for an online network proxy system, and it's not so meaningful for us. We hope less overhead for profiling.

---

@rsc Yeah, we want to what does the goroutines are doing or waiting(mostly wanted). I think random sampling is a good choice, just like sampling in CPU or memory profile.

---

I suspect we could eliminate the STW here at the cost of losing "snapshot consistency" across the goroutine stacks.

@aclements @mknyszek I think this is a good choice for our use case. Glad to see this can be implemented, but there is another question we just break backward compatibility or introduce another new API to control it.
But I think it doesn't conflict with sampling, we can reduce the total overhead even it doesn't have STW.

---

If the goal is statistical goroutine sampling anyway, then I think that's fine.

@mknyszek yes, that's it.
In our previous cases, there are a large number of unexpected goroutines waiting on the same backtrace, and we don't need to know the exact number, the ratio is good enough for us.

---

Is sampling OK, or do we typically need all goroutines? Is a consistent snapshot time needed?

@prattmic sampling is OK for me usually. But I'm not sure if it is a good idea for others.

---

If that is the main use can we have a more targeted goroutine profile? Such as, only list goroutines that have been blocked for some period of time?

@ianlancetaylor yeah, in general, we are interested in the blocked goroutines while doing goroutine profile.
But I think the goroutine profile could give us a high level and brief view to know what the goroutines are doing/waiting of a system, make us know the system better, or find know to optimize it in a global view(it's a bit like the CPU profile, but not the same thing).

Thank you, everyone!

[gopherbot]

Change https://go.dev/cl/387415 mentions this issue: runtime: decrease STW pause for goroutine profile

[rsc]

Assuming CL 387415 lands, do we need SetMaxDumpGoroutine at all? Or should this proposal be closed? Thanks.

[doujiang24]

@rsc I think it's still better to have the SetMaxDumpGoroutine on my side, since it will reduce the total CPU cost.
One case on my side:
There are 40k goroutines in total, and most of them(about 30k) are unexpected and they are in the same backtrace.
I think SetMaxDumpGoroutine(sample with limit) is the better choice for this case.

@rhysh Glad to see CL 387415 started. Do you think sample with limit conflicts with CL 387415?

[felixge]

❤️ the discussion and proposed improvements, especially CL 387415 from @rhysh.

Before deciding on a SetMaxDumpGoroutine() API, I'd like to mention a related idea for extending the goroutine profiling API: If we could manage low STW overhead AND targeted goroutine profiling, it would be possible to build a goroutine tracer similar to the JavaScript wall-clock profiler in Chrome, showing stack traces on a per-goroutine timeline (flame chart) view rather than a FlameGraph.

I'm planning to submit a separate proposal and a working proof of concept (see this video for a teaser) for this soon, but the general idea would be to use pprof labels to allow users to mark a small subset of their goroutines (e.g. every Nth goroutine handling incoming user request) as "tracer goroutines" and then sample their stack traces at 100 Hz and record timestamps + goroutine ids + stacks. The output format could be the trace event format or protobuf format used by perfetto.

Perhaps this is entirely orthogonal to SetMaxDumpGoroutine, my only direct comment for this would be that a NewGoroutineProfile + GoroutineProfile.SetMaxGoroutines + GoroutineProfile.Write API similar to what's proposed for the CPU profiler in #42502 might provide a better path for future API additions.

[rhysh]

Collecting the profile concurrently would complicate the sampling algorithm, but otherwise I think the two changes would be able to work together, @doujiang24 . (I don't have an algorithm off the top of my head for how to do that without O(samples) light work to prepare, but at least it's less than O(goroutines) of heavy work.)

I want to be clear that as far as I know, CL 387415 (at PS 3) does not compromise on the consistency of the goroutine profile (based on the test infrastructure in CL 387416). The key information that goroutine profiles provide is sometimes the presence/absence/state of a single goroutine. In #32388 it's a single goroutine holding up the http connection pool because of a slow network write (and 10k goroutines waiting). In #33747 it's the mysterious absence of any goroutine actually holding the lock (and 10k goroutines waiting). So I'm not convinced that sampling the goroutines is going to give good results for its users. An additional field on an extensible API like @felixge mentioned seems like a decent middleground.

As for the CPU overhead, I'm not sure how to tell how much is too much. Here's a possible framework: The machines I use often provide CPU and Memory allocations in a particular ratio, such as 2 GB of memory per 1 CPU thread. Filling the memory with 2kB goroutine stacks allows 1e6 goroutines. Collecting a goroutine profile for all of those takes about 2µs each, for a total of 2 seconds of CPU time. How often does an app need to collect a goroutine profile before the collection takes an unacceptable fraction of the compute resources, when a goroutine profile every five minutes leads to a CPU overhead of less than 1%? Faster is nice, but maybe it's already fast enough. @doujiang24 , what framework and target do you have in mind for "We hope less overhead for profiling."?

[rsc]

It sounds like there are enough available performance improvements (some of which are already being implemented) that we should hold off on adding any new API right now, which we would be stuck with forever. Do I have that right?

[rhysh]

we should hold off on adding any new API right now

That's my view, yes.

[doujiang24]

@rhysh Sorry for the delay.
Yeah, using a global variable is not a good idea. WithMaxGoroutine should be better:
#50794 (comment)

Also, sampling is not a good idea for all cases but really useful in some cases.
We just want an option not force sampling always.

1. we implemented a continuous profiling library based on pprof, to capture the CPU/memory/goroutine spikes(at seconds levels), we don't want itself introduce spike.
2. 1% CPU time in five minutes, should be okay in our case, also I think is okay for most cases.
3. but, we care about the CPU spike since we(MOSN) are a network proxy software, CPU spike always leads to latency spike that's more important to us.

Yeah, CL 387415 reduced the STW really helps, STW could introduce larger latency.
But, 100+ms CPU block for one P is not friendly to us.

[rsc]

Based on the discussion above, this proposal seems like a likely decline.
— rsc for the proposal review group

[doujiang24]

okay, just confirm it clearly, is WithMaxGoroutine also not acceptable?

[ianlancetaylor]

@doujiang24 As @rsc says above, our current opinion is "we should hold off on adding any new API right now, which we would be stuck with forever." Let's try the new changes out for a while and see to what extent there is still a real problem here to solve. Thanks.

[doujiang24]

Okay, got it. Thank you all.

[rsc]

No change in consensus, so declined.
— rsc for the proposal review group