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: additional memory profiler report modes or similar #13463

Open
dvyukov opened this Issue Dec 3, 2015 · 20 comments

Comments

Projects
None yet
@dvyukov
Member

dvyukov commented Dec 3, 2015

Memory profiler reports heap contents at the end of one of the previous GCs. This makes profiles "stable" in the sense that it does not dependent on exact point in time it is queried (just after GC, just before GC, somewhere in the middle). It makes sense. However, we see periodic confusion caused by the fact that actual memory consumption is actually 2x of what's reported. The meaning of the reported numbers is not obvious, it is reasonable to assume that if a tool says X MB, then memory consumption should be ~X MB.

While what we report is a useful view of reality, it is not the only view possible and maybe it should not be the default view. I think that all of the following views are useful:

  • heap contents at the end of GC cycle (what we report now); shows more-of-less persistent data in heap and allows to understand why my heap is that large
  • heap contents at the beginning of GC cycle (total memory consumption should be GOGC times larger than the prvious one); allows to understand memory consumption of the program and shows kind of worst case view of heap; this view can also be appealing to developers with C/C++ background
  • difference between the previous two modes (what was collected during a GC cycle); allows to understand why GCs are happening so frequently and optimize performance (identify transient allocs)

Also, if you are presented with several options, it forces you to ask yourself a question regarding the difference between these options. If you understand the difference, you interpret the data correctly.

The proposal is to add these additional modes to memory profiler. Exact set of modes and the default mode is discussable. Degenerate case would be just to switch the default.

From implementation point of view, I think all proposed modes are easy to implement in the current phased design.

@dvyukov dvyukov added the Proposal label Dec 3, 2015

@dvyukov

This comment has been minimized.

Member

dvyukov commented Dec 3, 2015

@rsc rsc changed the title from runtime: additional memory profiler report modes to proposal: runtime: additional memory profiler report modes Dec 3, 2015

@rsc rsc added this to the Proposal milestone Dec 3, 2015

@aclements

This comment has been minimized.

Member

aclements commented Jan 4, 2016

I'm increasingly of the opinion that it's more important to have a mode that reports the current state of the heap than it is to have the "stable" mode that we have now (that is, I'm not necessarily opposed to having both, but the current state should be the default and if we only have one, it should be the current state).

Most often, people want to answer the question "what is consuming my process's memory"? The "stable" view does not answer that, but a "current" view would. This question comes in many related flavors, such as "why is my RSS x?" and "why was my process OOM-killed?" People try to answer this question using the "stable" heap profile and get confused and unhappy (rightfully so) when the answer doesn't make sense (and doesn't match MemStats) and they blame it on the Go memory manager.

The "stable" view is interesting and certainly well-defined, but I'm having trouble formulating exactly what question it answers, and that's a problem. It's something like "where is my retained memory going?", but that seems like clearly a secondary question to "where is my memory going?" ("Why is my memory being retained?" is a very useful question, but we don't have any tool that can answer that right now.)

The "stable" view can also be actively misleading. For example, if there are large allocations that quickly become garbage, they will almost never show up in the "stable" view, but they would be likely to show up in a "current" view. This makes the "current" view more useful for answering the question "why is my process garbage collecting as often as it is?" Strictly speaking, this does show up in the raw data exported by the runtime as large values of both allocated and freed memory at a site, but most analysis tools reveal only the difference between allocated and freed and I do not believe complicating the presentation of the data is the answer to this (even members of the Go team at Google I've spoken with who have dealt with this problem didn't realize this raw data was there).

The "stable" view is also currently slightly wrong, I think. I haven't checked this in detail, but I think it currently counts floating garbage; it would have to delay by yet one more GC cycle to eliminate this. This is only tangentially related to this issue, but it is related in that it seems clear to me we don't want to delay the data even more than we currently do, and that suggests that delaying the data by any significant amount is a mistake.

@rsc

This comment has been minimized.

Contributor

rsc commented Jan 5, 2016

What about pprof --alloc_space/--alloc_objects? It seems like that addresses this point almost exactly, but is still more well-defined.

@dvyukov

This comment has been minimized.

Member

dvyukov commented Jan 7, 2016

This question comes in many related flavors, such as "why is my RSS x?" and "why was my process OOM-killed?"

"Current" profile won't help to answer these questions (unless you capture the profile in kill handler, which is slightly separate topic). To answer these questions you need profile at the beginning of GC cycle (or "max" stable profile; for concurrent GC it probably should be samples between marking and sweeping). The maximum heap is what determines RSS. Consider that GC runs once per several minutes, if you just sample "current" heap, you almost never will see the maximum.

I suspect that "current' profile will lead even to more confusion, because you can observe profile closer to min, or to max, or somewhere in between and see radically different numbers. And even if you understand that you are sampling "current", it is difficult to understand where are you between min and max and how to interpret these numbers.

What about pprof --alloc_space/--alloc_objects? It seems like that addresses this point almost exactly, but is still more well-defined.

How can they help to understand RSS?
I see only how to use them for performance optimization: alloc_space helps to reduce frequency of GCs, alloc_objects helps to reduce malloc overhead.

@neild

This comment has been minimized.

Contributor

neild commented Mar 4, 2016

As an example of how current memory profiles are confusing: I wrote a program that allocates 500 1M slices and retains them all. pprof reports that it is using 225M. If I call runtime.GC, the heap profile catches up and pprof reports on the full 500M.

The program uses 500M of memory, it has no garbage, and yet pprof reports a figure half its total memory consumption. Results are the same with --alloc_space/--inuse_space.

@neild

This comment has been minimized.

Contributor

neild commented Mar 4, 2016

One thought: I think the most useful information that we do not currently provide would be heap contents at the last time memory was requested from the system. This directly addresses the question of what determined the current RSS, especially when the RSS is determined by a transient spike in memory usage.

@aclements

This comment has been minimized.

Member

aclements commented Jul 23, 2016

I've been thinking about this more in response to an internal bug. I think there are several confusions around the heap profile, but underpinning many of them is the subtle but crucial difference between a heap profile and a memory profile. People are confused because they're trying to account for their process' RSS, but the memory reported by the OS and the memory reported by the heap profile are off by, well, about a factor of 2. If you don't understand how the Go memory manager works, it's natural to think that that memory must be going somewhere else, or that the heap profile is wrong.

I proposed in #15848 that the heap profile should also report totals for non-GC'd runtime allocation pools (stack memory, etc), mainly for debugging. But we could take that a step further and also report the amount of "unused heap" memory (there's probably a clearer term), so that the total reported by the heap profile actually matches the amount of memory the OS is reporting. I believe this information is already in the raw heap profile, it just isn't shown in any way. This wouldn't allay all confusion or solve all problems with the heap profile, but it would at least point people at why the allocation total doesn't match the process' RSS.

(For another common situation, figuring out why your process OOM'ed, I think switching to core files for the heap dump would put us on a path to being able to write a separate tool for answering this question.)

@hyangah

This comment has been minimized.

Contributor

hyangah commented Jul 25, 2016

Do we know how pprof handles garbages in Java?

@Sajmani

This comment has been minimized.

Contributor

Sajmani commented Jul 25, 2016

  • Michael Matloob

On Mon, Jul 25, 2016 at 11:13 AM Hyang-Ah Hana Kim notifications@github.com
wrote:

Do we know how pprof handles garbages in Java?


You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub
#13463 (comment), or mute
the thread
https://github.com/notifications/unsubscribe-auth/AJSK3dVzD3NfecBqzpN_gHIz8jiketXuks5qZNKogaJpZM4Gt55r
.

@aclements

This comment has been minimized.

Member

aclements commented Jul 25, 2016

I'm warming to Dmitry's original proposal, though I believe I think about it somewhat differently: rather than having several new modes (people already don't know about/are confused by the existing modes), the heap profiler should understand not just the "live" allocations as of the last GC, but also the allocations that became "dead", and it should show both simultaneously (in a visually distinguishable way). I'm also assuming the new profile information should represent the heap at the beginning of mark termination, not the beginning of GC (maybe that's really what Dmitry meant).

Unlike a "current heap profile", this "dead" heap profile is reasonably stable, since it captures the last heap peak, just like the existing profile captures the last heap trough. It's not as stable as the existing profile, since invoking runtime.GC() is idempotent against the existing profile, but not against the peak profile; however, it is stable in the steady state. I think it's also reasonably easy to explain.

If we can have pprof show a unified profile indicating both live and dead allocation samples as of the last GC, it would be significantly easier to profile transient garbage. I think this would be generally more useful than --alloc_* for two reasons: 1) it shows instantaneous garbage rather than cumulative garbage, which is more useful in multi-phase or long-running applications and in tracking down transient heap growth, and 2) it extends the current default in-use view, so people could get a lot more information from the default view without having to know about or dive in to the other modes.

@bcmills

This comment has been minimized.

Member

bcmills commented Jul 25, 2016

I like the idea of showing the dead allocations as of the last mark termination. It fits in nicely with the existing "snapshot of heap usage" model but would also be useful for troubleshooting high allocation rates (not just large allocations), and it would clear up a lot of the "RSS vs. heap profile" confusion for folks who aren't used to thinking in terms of garbage collection.

@neild

This comment has been minimized.

Contributor

neild commented Jul 25, 2016

One that I think would be very useful is live allocations as of the last
time memory was requested from the OS--i.e., what allocations caused the
actual process size to increase? This would aid in diagnosing growth caused
by transient spikes in allocations.

On Mon, Jul 25, 2016 at 12:16 PM, Bryan C. Mills notifications@github.com
wrote:

I like the idea of showing the dead allocations as of the last mark
termination. It fits in nicely with the existing "snapshot of heap usage"
model but would also be useful for troubleshooting high allocation rates
(not just large allocations), and it would clear up a lot of the "RSS vs.
heap profile" confusion for folks who aren't used to thinking in terms of
garbage collection.


You are receiving this because you commented.
Reply to this email directly, view it on GitHub
#13463 (comment), or mute
the thread
https://github.com/notifications/unsubscribe-auth/AADNQLJLM5RsjO01o9k86a4NXmPGBPZCks5qZQufgaJpZM4Gt55r
.

@minux

This comment has been minimized.

Member

minux commented Jul 26, 2016

@aclements

This comment has been minimized.

Member

aclements commented Jul 26, 2016

I think @neild is proposing snapshotting the whole heap profile as of process growth (and perhaps reporting all allocations, not just "live" ones?), not just sampling the allocation that caused process growth.

I believe that's technically feasible, though I worry about the performance cost of it, since there's some cost to taking that snapshot and when the process grows it tends to grow several times in quick succession. I also worry a bit about the cognitive cost of having another profiling mode, though perhaps it would make sense to expose it as a distinct class of profile, since the semantics are fairly different from the existing heap profile. Also, in the worst case of process growth, when you get an OOM, it's too late to get any useful profile out of the runtime, so I think the answer has to be a tool that can extract a profile out of a core file (which we're working towards).

@adg

This comment has been minimized.

Contributor

adg commented Aug 29, 2016

How can we make forward progress here? @aclements @dvyukov

@adg adg closed this Aug 29, 2016

@adg adg reopened this Aug 29, 2016

@aclements

This comment has been minimized.

Member

aclements commented Aug 30, 2016

How can we make forward progress here? @aclements @dvyukov

I'm opposed to adding new modes to the heap profile, and would much rather enhance the existing modes to provide a differentiated profile of some form (I proposed one possibility, but there may be others). However, if we do want to have a differentiated profile, I believe the right way to do that is with labels, in which case this depends on #16093. That's fine, but it means this will have to sit for a while.

@bradfitz

This comment has been minimized.

Member

bradfitz commented Aug 30, 2016

I'll take this out of the proposal process then and just track it as normal.

@bradfitz bradfitz modified the milestones: Unplanned, Proposal Aug 30, 2016

@bradfitz bradfitz removed the Proposal label Aug 30, 2016

@bradfitz bradfitz changed the title from proposal: runtime: additional memory profiler report modes to runtime: additional memory profiler report modes or similar Aug 30, 2016

@hyangah

This comment has been minimized.

Contributor

hyangah commented Jan 27, 2017

#16093 was accepted and included in go1.8.
Can some of the ideas discussed here be implemented in go1.9 cycle?

--
I'd still argue that 'current' view is more useful than 'stable' view even though the 'current' view is in between min/max. By capturing profiles multiple times, users may be lucky to capture the moment close to max, which is more useful in practice.

If the heap profile includes any allocations since the last GC as well. (@aclements mentioned reporting of 'dead' allocations above, but what I mean here are rather 'new' allocations. Some of them may be dead or some may be still alive).

With the new feature introduced by #16093, we can label the new allocations specially. pprof works as before, but with a special flag, it can report the sum of 'live' and 'new' which approximates 'current'.

The OOM killer we are currently dealing with captures heap profile before killing a process in a container. In that case, this information is useful in debugging the OOM situation.

--
Answering to my previous question... In Java, its heap dump or inspector is so powerful (it supports both 'after gc' and 'current' mode), users use heap dump instead of heap profile.

@neild

This comment has been minimized.

Contributor

neild commented Jan 27, 2017

As a specific case: I've got a process with a HeapIdle of ~5GB and a HeapInUse of ~300MB. Memory profile shows about 100MB.

Clearly at some point in the past this program had at least 2.5GB of live data, which has since become garbage and been collected. I want to know what that data was.

How do I find this out, other than by time travelling or figuring out how to replicate the spike?

@gopherbot

This comment has been minimized.

gopherbot commented Feb 22, 2017

CL https://golang.org/cl/37335 mentions this issue.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment