-
-
Notifications
You must be signed in to change notification settings - Fork 5.5k
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
Count GC's time waiting for a safepoint as GC time #53441
base: master
Are you sure you want to change the base?
Conversation
base/timing.jl
Outdated
@@ -57,7 +57,7 @@ function GC_Diff(new::GC_Num, old::GC_Num) | |||
new.poolalloc - old.poolalloc, | |||
new.bigalloc - old.bigalloc, | |||
new.freecall - old.freecall, | |||
new.total_time - old.total_time, | |||
(new.total_time - old.total_time) + (new.total_time_to_safepoint - old.total_time_to_safepoint), |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I would prefer introducing a new field in GC_Diff that is the safepoint time, and break the top-level report into two sections. As an example when I run a scaling test, I want to see that total_time
stays constant (e.g. the work of GC scales well with the number of threads and GC workers). If gc time starts creeping up I might use that as a decision point to use more GC threads.
On the other hand if the latency to start GC is high (time to safepoint) I can use that as a decision point to look with a profiler if I spend to much time in certain ccalls.
Munging them together yields a simple: "GC is slow" but no actionable information.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Yeah, that's fair. In my view, "GC is slow" is very actionable information — and throwing more information at people isn't always helpful. How would you want this to appear? Perhaps we take inspiration from compilation time?
2.39% compilation time: 12% of which was recompilation
How many people that see this message will know what "waiting for safe point" means? It's quite a lot of text to add. |
So instead of "waiting for safe point", I would call it latency. Or we could just print it as Another way of thinking about TTSP is that it is like the GC lock. |
the information certainly seems useful and 👍 to the functionality, but I'm just noting that #52883 also recently lengthened the message in the parenthetical maybe at this point |
My only goal here is to match what "gc time" means to me (and I'd wager the vast majority of Julia users) — and that's the total time spent inside I really don't want yet another way of interpreting a particular category's breakdown. So in my view we only have two choices, and I'm happy with either:
It does only print out this extra info if more than 0.5% of the GC time was spent waiting to start. I could make the caveat shorter with just "waiting" but when I wrote "waiting for safepoint" I chose to do so because I figured it'd make for good googlefodder. |
Edit: ignore above, I just saw in the code that @mbauman already only shows this if it is > 50% Thanks for doing this, I learned something new reading this! |
One challenge with using So you could get a measurement where with two threads Right now GC % is a measurement of something automatic, but useful. Mixing in TTSP makes the time reported less useful for me. Which is why I likened it to the recently added lock measurement. Put another way, currently GC time is a measurement of work and how efficiently that work is being processed, whereas TTSP is a measurement of work not occuring. I should say that I am all in favor of surfacing this information since it I strongly believe that this is an issue we as a community are not aware of enough. |
The counterpoint to this is that we really do need to make it so that TTSP is always ~0. Right now |
Ok. But it's the combined number that is the measurement of time my work is not happening. That's why it's what's useful to me — and I'd wager most folks. |
But the action to take in either case is drastically different. In one case I might need to add some strategical Maybe we report TTSP in the lock section? The more I think about that the more I like the idea. GC is waiting on a lock to acquire exclusive access to the heap. |
Want to note that there seems to be some history in the interpretation "GC time = mark time + sweep time". Note that GCBenchmarks displays/interprets GC time like "mark time + sweep time" (doesn't count TTSP in it), and pretty much all dashboards we have internally at RAI do so. Having GC times being defined in two ways in GCBenchmarks (which is arguably our main open-source tools for GC performance analysis now) and |
I'm just confused how to concretely — and succinctly and understandably — say that this is due to the GC without saying it's GC time. I suppose it could be in its own section:
One additional challenge is in determining the "floor" for elision — this time is always nonzero. I did also think about using the locks section, but there are two issues there: the existing metric is different (time vs count), and even if we started counting counts, I'd still want to separate out GC locks vs. ReentrantLocks which means that we still need to add a new descriptor. |
At the core of the issue for me are units. Currently Take as an example the program below it uses 10 units of real-time and 20 units of cpu-time. If we look at the time
Now what about TTSP? In the ascii diagram above This problem gets even worse the more threads we are adding:
Still 10 units of real time, but 50 units of cpu time. GC takes 20%, but TTSP takes 40% in real time and 8% of cpu-time.
I don't disagree (besides being cute and stating that GC is still doing your work, but work you procrastinated on). But I wager that you actually care about the cpu-time ratio and not the real-time ratio, and phrasing a multi-core measurement in real-time is not useful. I don't think we currently track CPU-time accurately throughout the system, |
So what's your suggestion on how to present this information? In my mind, the overarching goal of I hear you on the units, but I must confess I don't have a solid understanding of what the percentages are supposed to mean in the context of multithreading. If you were to have pressed me (before I had looked at implementation yesterday) I might have guessed they're numerated by CPU time and denominated by wall time — but maybe that's just because compilation time sometimes reports >100%. I still haven't quite grokked how the GC tracks multiple threads waiting for a safepoint — but it seems that it only counts the time from the first/worst one? That is, this diagram:
The GC stats — as they currently exist — seem like they do the real-world timing, it's just the worst-case-thread one. (edit: I'm guessing that's because the other threads start waiting on behalf of the first thread's collection before they can even try to start their own, and then we end up with 4 synchronized collections back-to-back, but the effect is that this number is more real-time-like than I expected):
|
Yes we currently only track the time the thread requesting GC spends waiting for all the other threads to reach a safe point and it gains exclusive access to the heap and thus object graph. The real time vs cpu time is probably also the reason why compile time can exceed total time |
:) Under the assumption that folks are trying to get all threads evenly chuggingly along, I think this PR is capturing the situation quite well. It's that worst-case thread that you end up waiting for:
|
@@ -57,7 +58,8 @@ function GC_Diff(new::GC_Num, old::GC_Num) | |||
new.poolalloc - old.poolalloc, | |||
new.bigalloc - old.bigalloc, | |||
new.freecall - old.freecall, | |||
new.total_time - old.total_time, | |||
new.total_time - old.total_time, |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
new.total_time - old.total_time, | |
new.total_time - old.total_time, |
The code in this PR seems useful. Is the issue "only" the way the measurement is presented? If so, the place I'd look if I don't understand the output of |
What about |
Unfortunately that doesn't resolve Valentin's objection, which is the inclusion of waiting time in the overall GC percentage number. That's where this is at loggerheads. |
Ok. What about going back to gc_time being what it used to be and something like |
This is a very simple change that will hopefully help folks identify things like https://discourse.julialang.org/t/inconsistent-cpu-utilisation-in-threads-loops/110512 a little faster.
Before:
After: