Profiling memory allocation count

[joh...@grob.org]

Hi

I'm working on a large JavaScript application and would like to reduce the number of memory allocations/disposals to make the GC's life easier. I'm specifically worried that we have a few locations in inner loops that dominate the memory turnaround. Is there any way that the DevTools could help me identifying them?

Ideally, I think I would like to record the call stack every time a new object is created, and then create statistics about which function created how many objects within a given time frame. The size of the objects doesn't matter too much in this process, as I'm not trying to bring down the overall memory usage in this case.

Cheers,
Joe

[Yury Semikhatsky]

Hi Joe,

We have been doing some experiments with V8 that would allow us to get
a better picture of JS heap allocations over time. It is at the very
early stage though.

I'm wondering why you decided to optimize allocations to help GC. Did
you see long pauses on the DevTools Timeline? Do the application's
memory grows rapidly and kicks GC too often?

On Thu, Jul 4, 2013 at 12:02 PM, <joh...@grob.org> wrote:
> Hi
>
> I'm working on a large JavaScript application and would like to reduce the
> number of memory allocations/disposals to make the GC's life easier. I'm
> specifically worried that we have a few locations in inner loops that
> dominate the memory turnaround.

Do they allocate objects that persist in the memory or just some
short-living ones? In the latter case V8's GC should do pretty good
job and be really fast no matter how much garbage was created.

> Is there any way that the DevTools could help me identifying them?
>

Yes. You can run your application with Timeline recording on and see
how often GCs occur and how long it takes. You can also try "Record
Heap Allocations" on the Profiles panel that captures heap state 10
times per second and draws allocations graph which changes over time
when the old objects are collected. It forces GC though, so the graph
may be different from what actually happens in your app when it is not
being inspected.

> Ideally, I think I would like to record the call stack every time a new
> object is created, and then create statistics about which function created
> how many objects within a given time frame.

We don't have such tool at the moment.

> The size of the objects doesn't
> matter too much in this process, as I'm not trying to bring down the overall
> memory usage in this case.
>

Hmm, why do you want to optimize the number of allocations? If all
allocated objects are small and the heap doesn't grow much they
shouldn't trigger GCs too often. Also can you describe what kind of
application you work on and what you optimize for (e.g. are you trying
to achieve 60fps rendering speed and avoid dropped frames)?

> Cheers,
> Joe
>
> --
> You received this message because you are subscribed to the Google Groups
> "Google Chrome Developer Tools" group.
> To unsubscribe from this group and stop receiving emails from it, send an
> email to google-chrome-develo...@googlegroups.com.
> For more options, visit https://groups.google.com/groups/opt_out.
>
>


Yury

[joh...@grob.org]

Hi Yuri

Thanks for the quick answer!!

What really started our research is that, in Canary, the GC sometimes freezes the application for 5-10s. I presume that this is a problem with the GC though. In stable Chrome, there is no noticeable performance impact from the GC, even though it does kick in every 8 frames or so, as you can see from the attached timeline screenshot. Each run takes 3-4 ms and collects 7.5 MB of memory.

Combined, these observations made us believe that we should be more careful about memory allocation. The objects in question are on the one hand extremely volatile ones that don't outlive a single frame, and on the other hand objects which are trashed every couple of frames.

By now you might have guessed that I'm working on an interactive graphical application which renders tied to animation frames. As mentioned before, we currently do not have noticeable problems in stable Chrome, but due to the behavior of Canary the issue popped up on our radar. I suppose that if we started to turn around much more memory, we'd see the GC runs happen more often and start to noticeably impact performance, and we'd like to keep some safety distance from that point.

If the heap allocation profiler only takes a sample every 100ms, it's probably not good enough to give a meaningful answer about objects which are created on a frame-by-frame basis :-/

By the way, do you happen to know anything about GC events taking 10+ seconds in Canary?

Cheers,
Joe

[Ilya Tikhonovsky]

Hi Joe, looks like you forgot to attach the screenshot.

Actually you can save Timeline data and attach it. It might be more useful.

The file has plain json text format, so you can reduce the size by zip.

Regards,
Tim.

Cheers,
Joe

[joh...@grob.org]

D'oh, what an idiot...I had the attachment in the e-mail, but then I switched to the web interface and forgot. Sorry!

I've attached two timelines. First one is stable Chrome, showing the GC events every couple of frames. As I said, no noticeable performance impact, but starting to look worrisome tome. Second one is a long session in Canary where towards the end there is a couple of seconds of straight garbage collection.

Cheers,
Joe

[Yury Semikhatsky]

[+danno,ulan]

GC event taking 10+ seconds which reproduces only on Canary build
sounds like a problem in the garbage collector. Probably something has
changed in recently V8's GC algorithm that causes the long pause.
Hopefully Daniel or Ulan could comment on this.

On Thu, Jul 4, 2013 at 2:29 PM, <joh...@grob.org> wrote:

[Daniel Clifford]

Hi Joe,

You mention that the GC freezes for 5-10s, how do you know that it's the GC? Under normal circumstances, the V8 GC almost never needs more than a few dozen milliseconds, even under very high load. 

I rather suspect that this is a problem with Chrome erroneously triggering a low memory notification and V8 doing repeated "emergency" full collections as a result. These colletions are very expensive and could freeze Chrome for a few seconds, but if you are not really almost completely out of memory this situation should never happen, if it does it's a bug in Chrome or the bindings. What version of Chrome were you experiencing this with? There have been recent fixes to the Chrome bindings to mitigate problems that resulted in this situation (M29).

Danno

[PhistucK]

According to his posted ZIPs, he is using Chrome 30.0.1554.0 canary.

☆PhistucK

[Johannes Schmid]

Hey Danno

I've attached a saved timeline exposing the problem earlier in the
thread. The memory usage when it happens is substantial (442 MB?) but
not critical as far as I can tell...there would have been a few spare
gigs in the system when it happened, but I guess it depends on when
Chrome thinks it's low on memory. The problem was observed in
"30.0.1557.0 (Official Build 210174) canary" and I've never seen it
happening in "27.0.1453.116 (Official Build 206485) m".

Cheers,
Joe

> > email togoogle-chrome-devel...@googlegroups.com
> <mailto:google-chrome-developer-tools%2Bunsu...@googlegroups.com>.
> > For more options, visithttps://groups.google.com/groups/opt_out.
> >
> >
>
>

[ul...@chromium.org]

Hi Joe,

Could you run Chrome Canary with the --js-flags="--trace_gc" flag and attach the output here?

Is there a way to reproduce your test?

Cheers,

Ulan.

>     > email togoogle-chrome-developer-tools+unsubscribe@googlegroups.com
>     <mailto:google-chrome-developer-tools%2Bunsubscribe@googlegroups.com>.

[Daniel Clifford]

Ah, sorry, my bad. I didn't see the full context from the forwarded email. Now looking into the thread on groups, I see the json files. Let me take a look at those, but please also try "trace_gc" as Ulan suggested.

Danno

----------------------------------------------
Daniel Clifford
V8 Technical Lead and Manager
Google Germany GmbH

Dienerstr. 12

80331 München

----------------------------------------------

Registergericht und -nummer: Hamburg, HRB 86891

Sitz der Gesellschaft: Hamburg
Geschäftsführer: Graham Law, Katherine Stephens
----------------------------------------------

[joh...@grob.org]

No worries! Thanks to all of you for looking into this.

Is the "trace_gc" supposed to output on the console? Under Windows, the only output I get is "[8204:9276:0705/103057:ERROR:textfield.h(173)] NOT IMPLEMENTED". I'm working on getting a Linux up, but who knows how it'll behave there.

Right now I don't have an isolated test that reproduces the problem, and it might be difficult to create one. If it turns out to be an important issue to you I'll see what I can do.

Cheers,
Joe

[Ulan Degenbaev]

Yes, chrome on windows doesn't show stdout. You can get the output by changing the chrome binary type from GUI to CUI as described in http://mrale.ph/blog/2012/06/21/v8s-flags-and-chrome-on-windows.html

Cheers,

Ulan.

[joh...@grob.org]

Hi Ulan

I was redirecting stdout to get the error message mentioned before ("[8204:9276:0705/103057:ERROR:textfield.h(173)] NOT IMPLEMENTED"). I've patched the executable to CUI, but it shows exactly the same. To clarify:
----
C:\Users\joha7294\AppData\Local\Google\Chrome SxS\Application>chrome --js-flags="--trace_gc"
[7048:456:0705/120039:ERROR:textfield.h(173)] NOT IMPLEMENTED
----
and nothing after that. And I found out that Canary isn't available on Linux :-/ Is there another way to get the trace output? Should I switch to a different version?

Cheers,
Joe

[Ulan Degenbaev]

Could you try 'chrome --js-flags="--trace_gc" --no-sandbox' on windows?

> And I found out that Canary isn't available on Linux

Yes, there is no canary, but you can try chrome dev which is at version 29.

Cheers,

Ulan.

[joh...@grob.org]

That works! See the attachment for the debug output and the corresponding timeline.

Cheers,
Joe

[PhistucK]

Just do not forget to remove the insecure --no-sandbox when you are done debugging.

☆PhistucK

--

You received this message because you are subscribed to the Google Groups "Google Chrome Developer Tools" group.

To unsubscribe from this group and stop receiving emails from it, send an email to google-chrome-develo...@googlegroups.com.

[Ulan Degenbaev]

Thank you, Joe!

The trace confirms Danno's hypothesis about emergency GC:

[3652]    99796 ms: Mark-sweep 354.9 (390.9) -> 336.2 (389.9) MB, 31 / 819.0 ms (+ 696.0 ms in 1478 steps since start of marking, biggest step 2.0 ms) [low memory notification].
[3652]   100846 ms: Mark-sweep 336.2 (389.9) -> 304.5 (387.9) MB, 8 / 1050.0 ms [low memory notification].
[3652]   101893 ms: Mark-sweep 304.5 (387.9) -> 304.5 (370.9) MB, 9 / 1047.0 ms [low memory notification].
[3652]   102935 ms: Mark-sweep 304.5 (370.9) -> 304.5 (368.9) MB, 8 / 1042.0 ms [low memory notification].
[3652]   103975 ms: Mark-sweep 304.5 (368.9) -> 304.5 (368.9) MB, 8 / 1040.0 ms [low memory notification].
[3652]   105012 ms: Mark-sweep 304.5 (368.9) -> 304.5 (368.9) MB, 10 / 1037.0 ms [low memory notification].
[3652]   106050 ms: Mark-sweep 304.5 (368.9) -> 304.5 (368.9) MB, 8 / 1038.0 ms [low memory notification].

Do you mind posting the trace from the stable version of Chrome, which doesn't have these pauses?

Cheers,

Ulan.

[Ulan Degenbaev]

Joe, could you run also with --js-flags="--trace_gc_verbose" ? There one counter we would like to check.

Thank you,

Ulan.