Garbage collector details

[jonathan]

Hi, I have been working on a simulator in javascript that creates and
destroys a lot of arrays and objects. When I run it in Chrome (current
developer build: 4.0.302.2 dev), after a couple of minutes of this
behaviour, the application stops and memory usage seems to increase
dramatically and then I get an "Aw, snap" page because it has failed
to allocate memory. (this is on Ubuntu Linux).

It is clear (to me at least) that this is a bug in Chrome, but at this
point I have no way of characterising the bug properly. I would like
to figure out exactly what I am doing that is causing this behaviour,
but it is hard to know where to start. Can someone give me some
pointers to the GC code, or is there a design document somewhere that
will get me started?

thanks
Jonathan

[Kevin Millikin]

Hi Jonathan,

You can tell V8 to print some simple GC stats by starting chromium with --js-flags="--trace-gc".  That will confirm what you're already observing, but I'd be interested in the output.

Even better is if you can come up with a self-contained test case that exhibits this behavior so we can look into it further.

There is no design document for the V8 garbage collector.  The code is in the chromium source tree in src/v8/src/heap.cc (for the copying collector) and src/v8/src/mark-compact.cc (for the mark-sweep(-compact) collector).

--

Chromium Developers mailing list: chromi...@chromium.org

View archives, change email options, or unsubscribe:

   http://groups.google.com/a/chromium.org/group/chromium-dev

[jonathan]

Hi Kevin, I am not sure at this point how to come up with a reduced
test-case. I am really not sure what the exact problem is at the
moment. I have a feeling that it is related to this bug:
http://code.google.com/p/v8/issues/detail?id=524 or this bug:
http://code.google.com/p/chromium/issues/detail?id=29428. But that
isn't based on anything but intuition at this point.

Below is the output of trace-gc. I am not clear on what the output
means. But I am pretty sure that I am not using close to 1 gig of
objects.

Any further pointers on where to go next would be really appreciated.

Mark-sweep 2.6 -> 2.0 MB, 2 ms.
Scavenge 3.6 -> 3.2 MB, 1 ms.
Mark-sweep 4.6 -> 3.7 MB, 5 ms.
Scavenge 4.7 -> 4.0 MB, 0 ms.
Mark-sweep 5.8 -> 4.2 MB, 5 ms.
Scavenge 6.4 -> 4.8 MB, 1 ms.
Scavenge 6.5 -> 4.8 MB, 0 ms.
Scavenge 6.8 -> 5.0 MB, 0 ms.
Scavenge 6.8 -> 5.0 MB, 0 ms.
Scavenge 7.0 -> 5.0 MB, 0 ms.
Scavenge 7.0 -> 5.0 MB, 0 ms.
Scavenge 7.0 -> 5.1 MB, 0 ms.
Scavenge 7.0 -> 5.2 MB, 0 ms.
Scavenge 7.1 -> 5.2 MB, 0 ms.
Scavenge 7.2 -> 5.2 MB, 0 ms.
Scavenge 9.2 -> 5.3 MB, 0 ms.
Scavenge 9.2 -> 5.4 MB, 0 ms.
Scavenge 9.3 -> 5.5 MB, 0 ms.
Scavenge 9.4 -> 5.7 MB, 0 ms.
Scavenge 9.5 -> 5.8 MB, 1 ms.
Scavenge 9.7 -> 5.9 MB, 0 ms.
Scavenge 9.8 -> 5.9 MB, 0 ms.
Mark-sweep 9.9 -> 5.4 MB, 10 ms.
Scavenge 9.3 -> 5.7 MB, 0 ms.
Scavenge 9.5 -> 5.9 MB, 0 ms.
Scavenge 9.6 -> 6.0 MB, 0 ms.
Scavenge 9.8 -> 6.3 MB, 0 ms.
Mark-sweep 12.9 -> 6.1 MB, 11 ms.
Mark-compact 19.1 -> 8.1 MB, 21 ms.
Mark-sweep 22.5 -> 9.4 MB, 9 ms.
Mark-sweep 18.9 -> 12.4 MB, 11 ms.
Mark-sweep 23.2 -> 16.0 MB, 15 ms.
Mark-sweep 35.3 -> 15.3 MB, 14 ms.
Mark-sweep 27.6 -> 19.3 MB, 15 ms.
Mark-sweep 37.7 -> 14.9 MB, 11 ms.
Mark-sweep 30.1 -> 19.9 MB, 16 ms.
Mark-sweep 44.0 -> 27.9 MB, 19 ms.
Mark-sweep 47.0 -> 34.2 MB, 15 ms.
Mark-sweep 59.5 -> 42.7 MB, 19 ms.
Mark-sweep 66.9 -> 27.5 MB, 18 ms.
Mark-sweep 61.7 -> 38.9 MB, 23 ms.
Mark-sweep 91.4 -> 56.4 MB, 32 ms.
Mark-sweep 85.5 -> 66.1 MB, 24 ms.
Mark-sweep 104.0 -> 78.7 MB, 30 ms.
Mark-sweep 167.9 -> 56.6 MB, 31 ms.
Mark-sweep 134.8 -> 82.2 MB, 56 ms.
Mark-sweep 126.5 -> 96.9 MB, 39 ms.
Mark-sweep 153.8 -> 115.9 MB, 42 ms.
Mark-sweep 245.1 -> 81.9 MB, 41 ms.
Mark-sweep 203.1 -> 121.1 MB, 65 ms.
Mark-sweep 295.5 -> 178.7 MB, 91 ms.
Mark-sweep 279.9 -> 212.4 MB, 67 ms.
Mark-sweep 340.3 -> 255.0 MB, 87 ms.
Mark-sweep 544.7 -> 178.6 MB, 83 ms.
Mark-sweep 443.5 -> 265.0 MB, 132 ms.
Mark-sweep 656.3 -> 395.3 MB, 195 ms.
Mark-sweep 624.5 -> 471.3 MB, 142 ms.
Mark-sweep 759.1 -> 567.2 MB, 185 ms.
Mark-sweep 826.2 -> 653.6 MB, 218 ms.
Mark-sweep 653.6 -> 653.6 MB, 153 ms.

On Jan 28, 8:28 pm, Kevin Millikin <kmilli...@chromium.org> wrote:
> Hi Jonathan,
>
> You can tell V8 to print some simple GC stats by starting chromium with
> --js-flags="--trace-gc".  That will confirm what you're already observing,
> but I'd be interested in the output.
>
> Even better is if you can come up with a self-contained test case that
> exhibits this behavior so we can look into it further.
>
> There is no design document for the V8 garbage collector.  The code is in
> the chromium source tree in src/v8/src/heap.cc (for the copying collector)
> and src/v8/src/mark-compact.cc (for the mark-sweep(-compact) collector).
>

> On Thu, Jan 28, 2010 at 10:05 AM, jonathan <jricket...@gmail.com> wrote:
> > Hi, I have been working on a simulator in javascript that creates and
> > destroys a lot of arrays and objects. When I run it in Chrome (current
> > developer build: 4.0.302.2 dev), after a couple of minutes of this
> > behaviour, the application stops and memory usage seems to increase
> > dramatically and then I get an "Aw, snap" page because it has failed
> > to allocate memory. (this is on Ubuntu Linux).
>
> > It is clear (to me at least) that this is a bug in Chrome, but at this
> > point I have no way of characterising the bug properly. I would like
> > to figure out exactly what I am doing that is causing this behaviour,
> > but it is hard to know where to start. Can someone give me some
> > pointers to the GC code, or is there a design document somewhere that
> > will get me started?
>
> > thanks
> > Jonathan
>
> > --

> > Chromium Developers mailing list: chromium-...@chromium.org

[Anton Muhin]

Jonathan,

that all looks very suspicious.

What we can do:

1) you can run the same code in different browser---chances are your
code have memory leak and just doesn't release unnecessary memory;
2) if other browsers work for you, could you send us a snippet, or
ideally, file a bug at http://code.google.com/p/chromium/issues/list
with a reproducible test case? If you file a bug, you can just assign
it to me (ant...@chromium.org).

hth and let us know,
anton.

> Chromium Developers mailing list: chromi...@chromium.org

[Jonathan Ricketson]

Anton, I have been suspicious of memory leaks too, and have been trying to find if I have any, and indeed I did find some and fix them. Using the chrome memory profiler it seems to show that I have hundreds of megabytes of arrays on the heap... I am definitely using arrays, but I am having trouble tracking down where all those arrays are being created (and references being kept). Does the Chrome Heap Profiler also show arrays that have been created and no longer referenced, but that the GC hasn't collected yet?

jonathan

2010/1/28 Anton Muhin <ant...@chromium.org>

[Anton Muhin]

[cc'ing Michail, who implemented a lot of memory profiler for Chromium/v8]

I don't know in which version it was fixed, but profiler used to show
deallocate objects as arrays, but as you're on the dev build chances
are slim (still Michail might know better).

I don't know if profiler is able to show objects which would be
collected by next GC. Just in case, please, note that there are
different GCs in V8 which collect different sets of objects. To
collect all the garbage you need to provoke some named major GC (in
logs they are marked as Mark-Compact and Mark-Sweep).

There might be some issues with retention due to various V8 caches.
Is your code heavily DOM dependent? Could it be turned into pure JS?
If it could, would mind building v8 proper (not a part of Chromium)
and run this script in there---it might reveal more details and if
you're no opposed to building we would have more tools at our disposal
to sort things out.

yours,
anton.

[Mikhail Naganov]

Hi Jonathan,

> find if I have any, and indeed I did find some and fix them. Using the
> chrome memory profiler it seems to show that I have hundreds of megabytes of
> arrays on the heap... I am definitely using arrays, but I am having trouble
> tracking down where all those arrays are being created

Currently this is under development. If you don't afraid running
Chrome with special flags and then using command-line scripts from V8,
I can provide instructions to you.

> tracking down where all those arrays are being created (and references being
> kept).

Aggregated objects that keep references are shown in a heap profile as
child nodes. The number of references is shown in the "count" column.
You can grab several heap snapshots and compare them to figure out the
dynamics of references count.

> Does the Chrome Heap Profiler also show arrays that have been created
> and no longer referenced, but that the GC hasn't collected yet?

Yes, such arrays are shown, but currently there is no way to
distinguish them from arrays that are referenced.

[jonathan]

Hmm,
@Anton: My code is largely non-dom, and the dom stuff is completely
separate. I do use setTimeout and setInterval though to allow the UI
to refresh. This is easily changed if it would be useful to run
directly in v8.

@Mikhail: I am not afraid!! Please tell me how to do the special
magic.
As for the profiler: I am having trouble making the information that
it shows useful, because I am creating and dereferencing many arrays
in a short period of time, and so if the array count shown also
includes dereferenced arrays, then I can't easily analyse whether I
have dereferenced them properly.
Can you please clarify a couple of things about the heap profiler (I
can't find much detail on the web, I understand that it is a very new
feature):
* The top level items in the profile are the objects that are
referenced, and the count of these is the number of objects of this
type on the heap.
* The second level items are the objects that hold the references to
the top level items, and the count is the number of references.
* What are the next (and next and next...) levels of expansion? are
they the next objects in the reference chain?

Thanks
Jonathan

> >> ideally, file a bug athttp://code.google.com/p/chromium/issues/list

> >> with a reproducible test case?  If you file a bug, you can just assign
> >> it to me (ant...@chromium.org).
>
> >> hth and let us know,
> >> anton.
>

> >> On Thu, Jan 28, 2010 at 1:21 PM, jonathan <jricket...@gmail.com> wrote:
> >> > Hi Kevin, I am not sure at this point how to come up with a reduced
> >> > test-case. I am really not sure what the exact problem is at the
> >> > moment. I have a feeling that it is related to this bug:

> >> >http://code.google.com/p/v8/issues/detail?id=524or this bug:

[Mikhail Naganov]

> @Mikhail: I am not afraid!! Please tell me how to do the special
> magic.

First step: collect a log file on disk. This can be done by running
Chrome with the following cmdline:

--no-sandbox --js-flags="--logfile=%t.log --log-producers
--noprof-lazy --log-code --log-gc --noinline-new --never-compact"

(note the quotes around 'js-flags' argument. See
http://code.google.com/p/v8/wiki/ProfilingChromiumWithV8 if you want
some explanations.)

Open your app, do what you need, then close Chrome. Not that as
'--never-compact' flag is passed to V8, garbage collector will not
perform compactions, so you can run out of heap memory even quicker,
but I hope you will still collect enough useful data.

Second step: process the log. You need to download and build the
bleeding_edge branch of V8 (this is fast and easy, see
http://code.google.com/apis/v8/build.html)

Then, among generated in step 1 log files files, choose the biggest
one, and run:

v8/tools/linux-tick-processor <filename.log>

I'm assuming you're on Linux, otherwise use windows-tick-processor or
mac-tick-processor.

And in output you should see something like this:

Generation N:
1262 70.4% (closure)
357 28.3% Script:
http://v8.googlecode.com/svn/data/benchmarks/v5/earley-boyer.js
162 12.8% LazyCompile: InstantiateFunction native apinatives.js:62
162 100.0% LazyCompile: Instantiate native apinatives.js:44
...

330 18.4% Object
204 61.8% LazyCompile: InstantiateFunction native apinatives.js:62
204 100.0% LazyCompile: Instantiate native apinatives.js:44
186 91.2% LazyCompile: ConfigureTemplateInstance native
apinatives.js:93
185 99.5% LazyCompile: Instantiate native apinatives.js:44
185 100.0% LazyCompile: InstantiateFunction native
apinatives.js:62
40 12.1% Script:
http://v8.googlecode.com/svn/data/benchmarks/v5/raytrace.js
13 3.9% Script:
http://v8.googlecode.com/svn/data/benchmarks/v5/earley-boyer.js
11 3.3% LazyCompile: Instantiate native apinatives.js:44
....

110 6.1% Function
99 90.0% Function: <anonymous>
99 100.0% Script: v8/DateExtension
3 2.7% Function: RunStep
3 100.0% LazyCompile: BenchmarkSuite.RunSuites
http://v8.googlecode.com/svn/data/benchmarks/v5/base.js:105
3 100.0% LazyCompile: Run
http://v8.googlecode.com/svn/data/benchmarks/v5/run.html:51

36 2.0% Array
6 16.7% Script:
http://v8.googlecode.com/svn/data/benchmarks/v5/raytrace.js
4 11.1% Script: native date.js
2 5.6% LazyCompile: BenchmarkSuite.RunSuites
http://v8.googlecode.com/svn/data/benchmarks/v5/base.js:105
2 100.0% LazyCompile: Run
http://v8.googlecode.com/svn/data/benchmarks/v5/run.html:51
2 5.6% LazyCompile: BenchmarkSuite.RunStep
http://v8.googlecode.com/svn/data/benchmarks/v5/base.js:217
2 100.0% Function: RunStep
2 100.0% LazyCompile: BenchmarkSuite.RunSuites
http://v8.googlecode.com/svn/data/benchmarks/v5/base.js:105
2 100.0% LazyCompile: Run
http://v8.googlecode.com/svn/data/benchmarks/v5/run.html:51
...

For every GC iteration, call paths that produced objects belonging to
the same constructor are listed.

> Can you please clarify a couple of things about the heap profiler (I
> can't find much detail on the web, I understand that it is a very new
> feature):
> * The top level items in the profile are the objects that are
> referenced, and the count of these is the number of objects of this
> type on the heap.

Right.

> * The second level items are the objects that hold the references to
> the top level items, and the count is the number of references.

Right.

> * What are the next (and next and next...) levels of expansion? are
> they the next objects in the reference chain?

The next levels are actually not very useful. I should remove them.

[Anton Muhin]

On Thu, Jan 28, 2010 at 4:47 PM, jonathan <jrick...@gmail.com> wrote:
> Hmm,
> @Anton: My code is largely non-dom, and the dom stuff is completely
> separate. I do use setTimeout and setInterval though to allow the UI
> to refresh. This is easily changed if it would be useful to run
> directly in v8.

I'd recommend to run in just v8 to see if the OOM is reproducible, but
it's completely up to you.

yours,
anton.

[jonathan]

Hi Mikhail, I have done as you suggested and am trying to make sense
of the output. Below is the output from the last generation before it
crashes. If you want to see the whole file I will send it to you.
Should I be able to somehow use this output to see where objects are
being created, but not dereferenced?

Generation 49:
2110 48.4% (closure)
227 10.8% LazyCompile: InstantiateFunction native
apinatives.js:62
227 100.0% LazyCompile: Instantiate native apinatives.js:44
194 85.5% LazyCompile: ConfigureTemplateInstance native
apinatives.js:93
188 96.9% LazyCompile: Instantiate native apinatives.js:
44
188 100.0% LazyCompile: InstantiateFunction native
apinatives.js:62
5 2.6% LazyCompile: <anonymous>
http://localhost:8000/media/4.0/jquery/jquery-1-3-2.js:12
6 2.6% LazyCompile: InstantiateFunction native
apinatives.js:62
6 100.0% LazyCompile: Instantiate native apinatives.js:
44
2 33.3% LazyCompile: InstantiateFunction native
apinatives.js:62
1 16.7% Function: <anonymous> {52}
1 16.7% Function: <anonymous> {29}
194 9.2% Script: native date.js
97 50.0% Function: <anonymous>
97 100.0% Script: v8/DateExtension
97 50.0% CallNormal: args_count: 1 {1}
189 9.0% Script: native v8natives.js
126 66.7% CallNormal: args_count: 1 {1}
168 8.0% Script: native messages.js
112 66.7% CallNormal: args_count: 1 {1}
158 7.5% LazyCompile: <anonymous>
http://localhost:8000/media/4.0/jquery/jquery-1-3-2.js:12
156 7.4% Script: native mirror.js
156 100.0% CallNormal: args_count: 1 {1}
153 7.3% Script: native string.js
102 66.7% CallNormal: args_count: 1 {1}
133 6.3% Script: native debug.js
133 100.0% CallNormal: args_count: 1 {1}
126 6.0% Script: native runtime.js
84 66.7% CallNormal: args_count: 1 {1}
112 5.3% CallNormal: args_count: 1 {1}
105 5.0% Script: native array.js
70 66.7% CallNormal: args_count: 1 {1}
60 2.8% Script: native uri.js
40 66.7% CallNormal: args_count: 1 {1}
60 2.8% Script: native math.js
40 66.7% CallNormal: args_count: 1 {1}

987 22.7% Array
201 20.4% LazyCompile: slice native array.js:529
186 92.5% RegExp: (compatible|webkit)
7 3.5% LazyCompile: CORE.environment._initialiseProcess
http://localhost:8000/media/4.0/evolve/environment.js:90
7 100.0% LazyCompile: CORE.environment._birthProcess
http://localhost:8000/media/4.0/evolve/environment.js:69
7 100.0% RegExp: (compatible|webkit)
1 14.3% LazyCompile: shift native array.js:489
6 3.0% LazyCompile: getSpeciesCallback
http://localhost:8000/media/4.0/evolve/environment.js:24
189 19.1% LazyCompile: getSpeciesCallback
http://localhost:8000/media/4.0/evolve/environment.js:24
188 19.0% Function: ShadowPrototypeElements
188 100.0% LazyCompile: CORE.Process
http://localhost:8000/media/4.0/evolve/process.js:1
184 97.9% RegExp: (compatible|webkit)
4 2.1% LazyCompile: getSpeciesCallback
http://localhost:8000/media/4.0/evolve/environment.js:24
187 18.9% RegExp: (compatible|webkit)
81 8.2% LazyCompile: CORE.environment._resizeGrid
http://localhost:8000/media/4.0/evolve/environment.js:152
81 100.0% RegExp: \[name=['"]*((?:[\\w\\u00c0-\\uFFFF_-]|\\\
\.)+)['"]*\\](?![^\\[]*\\])(?![^\\(]*\\))
81 100.0% Function: <anonymous> {40}
81 100.0% Stub: FastNewContextStub {1}
81 100.0% Function: <anonymous> {31}
23 2.3% Function: <anonymous> {35}
23 100.0% Function: <anonymous> {31}
22 95.7% Function: <anonymous> {44}
22 100.0% Function: <anonymous> {31}
22 100.0% Function: <anonymous> {38}
1 4.3% Function: <anonymous> {37}
1 100.0% Function: <anonymous> {31}
1 100.0% Function: <anonymous> {50}

640 14.7% Object
200 31.3% LazyCompile: InstantiateFunction native
apinatives.js:62
200 100.0% LazyCompile: Instantiate native apinatives.js:44
194 97.0% LazyCompile: ConfigureTemplateInstance native
apinatives.js:93
188 96.9% LazyCompile: Instantiate native apinatives.js:
44
188 100.0% LazyCompile: InstantiateFunction native
apinatives.js:62
5 2.6% LazyCompile: <anonymous>
http://localhost:8000/media/4.0/jquery/jquery-1-3-2.js:12
5 2.5% LazyCompile: Instantiate native apinatives.js:
44

5 100.0% LazyCompile: InstantiateFunction native
apinatives.js:62

5 100.0% LazyCompile: Instantiate native
apinatives.js:44
64 10.0% LazyCompile: <anonymous>
http://localhost:8000/media/4.0/jquery/jquery-1-3-2.js:12
38 5.9% CallNormal: args_count: 1 {1}
28 4.4% Function: <anonymous> {35}
28 100.0% Function: <anonymous> {31}
25 89.3% Function: <anonymous> {44}
25 100.0% Function: <anonymous> {31}
25 100.0% Function: <anonymous> {38}
2 7.1% Function: <anonymous> {37}
2 100.0% Function: <anonymous> {31}
2 100.0% Function: <anonymous> {50}
1 3.6% Function: <anonymous> {48}
1 100.0% Stub: RuntimeStub_NewContext
1 100.0% LazyCompile: <anonymous>
http://localhost:8000/media/4.0/jquery/jquery-1-3-2.js:12
27 4.2% LazyCompile: Instantiate native apinatives.js:44
27 100.0% LazyCompile: InstantiateFunction native
apinatives.js:62
27 100.0% LazyCompile: Instantiate native apinatives.js:
44
6 22.2% LazyCompile: InstantiateFunction native
apinatives.js:62
6 100.0% LazyCompile: Instantiate native
apinatives.js:44
4 14.8% Function: <anonymous> {49}
4 100.0% LazyCompile: <anonymous>
http://localhost:8000/media/4.0/jquery/jquery-1-3-2.js:12
2 7.4% LazyCompile: SimpleSlice native array.js:289
2 100.0% LazyCompile: slice native array.js:529
2 7.4% LazyCompile: <anonymous>
http://localhost:8000/media/4.0/jquery/jquery-1-3-2.js:12
2 7.4% Function: <anonymous> {52}
2 100.0% Function: <anonymous> {29}
2 7.4% Function: <anonymous> {29}
2 100.0% LazyCompile: <anonymous>
http://localhost:8000/media/4.0/jquery/jquery-1-3-2.js:12
1 3.7% Stub: RuntimeStub_NewContext
1 100.0% Stub: FastNewContextStub {1}
1 3.7% Stub: FastNewContextStub {2}
1 100.0% Function: <anonymous> {90}
1 3.7% Function: <anonymous> {87}
1 100.0% Stub: RuntimeStub_StringLastIndexOf
1 3.7% Function: <anonymous> {53}
1 100.0% Function: <anonymous> {29}
23 3.6% Function: <anonymous> {29}
23 100.0% LazyCompile: <anonymous>
http://localhost:8000/media/4.0/jquery/jquery-1-3-2.js:12
21 3.3% Function: <anonymous> {46}
17 81.0% Function: <anonymous> {44}
17 100.0% Function: <anonymous> {31}
17 100.0% Function: <anonymous> {38}
7 41.2% LazyCompile:
CORE.environment._initialiseProcess http://localhost:8000/media/4.0/evolve/environment.js:90
6 35.3% Function: <anonymous> {40}
2 11.8% Stub: FastNewContextStub {1}
2 11.8% Function: <anonymous> {45}
4 19.0% Function: <anonymous> {37}
4 100.0% Function: <anonymous> {31}
4 100.0% Function: <anonymous> {50}
4 100.0% LazyCompile: <anonymous>
http://localhost:8000/media/4.0/jquery/jquery-1-3-2.js:12

545 12.5% Function
99 18.2% Function: <anonymous>
99 100.0% Script: v8/DateExtension
17 3.1% Stub:
GenericBinaryOpStub_MUL_OverwriteRight_NoSmiInStub_StackArgs_SSE3
14 2.6% LazyCompile: <anonymous>
http://localhost:8000/media/4.0/jquery/jquery-1-3-2.js:12
13 2.4% LazyCompile: <anonymous>
http://localhost:8000/media/4.0/jquery/jquery-depends.js:2
12 2.2% LazyCompile: copy http://localhost:8000/media/4.0/evolve/vm.js:283

Statistical profiling result from /home/jon/.config/google-chrome/
1264811309728.log, (1756 ticks, 73476 unaccounted, 0 excluded).

On Jan 29, 3:09 am, Mikhail Naganov <mnaga...@chromium.org> wrote:
> > @Mikhail: I am not afraid!! Please tell me how to do the special
> > magic.
>
> First step: collect a log file on disk. This can be done by running
> Chrome with the following cmdline:
>
> --no-sandbox --js-flags="--logfile=%t.log --log-producers
> --noprof-lazy --log-code --log-gc --noinline-new --never-compact"
>

> (note the quotes around 'js-flags' argument. Seehttp://code.google.com/p/v8/wiki/ProfilingChromiumWithV8if you want

> some explanations.)
>
> Open your app, do what you need, then close Chrome. Not that as
> '--never-compact' flag is passed to V8, garbage collector will not
> perform compactions, so you can run out of heap memory even quicker,
> but I hope you will still collect enough useful data.
>
> Second step: process the log. You need to download and build the

> bleeding_edge branch of V8 (this is fast and easy, seehttp://code.google.com/apis/v8/build.html)

>       3  100.0%      LazyCompile: BenchmarkSuite.RunSuiteshttp://v8.googlecode.com/svn/data/benchmarks/v5/base.js:105
>       3  100.0%        LazyCompile: Runhttp://v8.googlecode.com/svn/data/benchmarks/v5/run.html:51

>
>      36    2.0%  Array
>       6   16.7%    Script:http://v8.googlecode.com/svn/data/benchmarks/v5/raytrace.js
>       4   11.1%    Script: native date.js

>       2    5.6%    LazyCompile: BenchmarkSuite.RunSuiteshttp://v8.googlecode.com/svn/data/benchmarks/v5/base.js:105
>       2  100.0%      LazyCompile: Runhttp://v8.googlecode.com/svn/data/benchmarks/v5/run.html:51
>       2    5.6%    LazyCompile: BenchmarkSuite.RunStephttp://v8.googlecode.com/svn/data/benchmarks/v5/base.js:217
>       2  100.0%      Function: RunStep
>       2  100.0%        LazyCompile: BenchmarkSuite.RunSuiteshttp://v8.googlecode.com/svn/data/benchmarks/v5/base.js:105
>       2  100.0%          LazyCompile: Runhttp://v8.googlecode.com/svn/data/benchmarks/v5/run.html:51

> ...
>
> For every GC iteration, call paths that produced objects belonging to
> the same constructor are listed.
>
> > Can you please clarify a couple of things about the heap profiler (I
> > can't find much detail on the web, I understand that it is a very new
> > feature):
> > * The top level items in the profile are the objects that are
> > referenced, and the count of these is the number of objects of this
> > type on the heap.
>
> Right.
>
> > * The second level items are the objects that hold the references to
> > the top level items, and the count is the number of references.
>
> Right.
>
> > * What are the next (and next and next...) levels of expansion? are
> > they the next objects in the reference chain?
>
> The next levels are actually not very useful. I should remove them.
>

> >> >> >http://code.google.com/p/v8/issues/detail?id=524orthis bug:

> ...
>
> read more »

[jonathan]

Also Mikhail: where are objects with no constructors shown in the heap
profiler GUI?

On Jan 29, 3:09 am, Mikhail Naganov <mnaga...@chromium.org> wrote:

> > @Mikhail: I am not afraid!! Please tell me how to do the special
> > magic.
>
> First step: collect a log file on disk. This can be done by running
> Chrome with the following cmdline:
>
> --no-sandbox --js-flags="--logfile=%t.log --log-producers
> --noprof-lazy --log-code --log-gc --noinline-new --never-compact"
>

> (note the quotes around 'js-flags' argument. Seehttp://code.google.com/p/v8/wiki/ProfilingChromiumWithV8if you want

> some explanations.)
>
> Open your app, do what you need, then close Chrome. Not that as
> '--never-compact' flag is passed to V8, garbage collector will not
> perform compactions, so you can run out of heap memory even quicker,
> but I hope you will still collect enough useful data.
>
> Second step: process the log. You need to download and build the

> bleeding_edge branch of V8 (this is fast and easy, seehttp://code.google.com/apis/v8/build.html)

>       3  100.0%      LazyCompile: BenchmarkSuite.RunSuiteshttp://v8.googlecode.com/svn/data/benchmarks/v5/base.js:105
>       3  100.0%        LazyCompile: Runhttp://v8.googlecode.com/svn/data/benchmarks/v5/run.html:51

>
>      36    2.0%  Array
>       6   16.7%    Script:http://v8.googlecode.com/svn/data/benchmarks/v5/raytrace.js
>       4   11.1%    Script: native date.js

>       2    5.6%    LazyCompile: BenchmarkSuite.RunSuiteshttp://v8.googlecode.com/svn/data/benchmarks/v5/base.js:105
>       2  100.0%      LazyCompile: Runhttp://v8.googlecode.com/svn/data/benchmarks/v5/run.html:51
>       2    5.6%    LazyCompile: BenchmarkSuite.RunStephttp://v8.googlecode.com/svn/data/benchmarks/v5/base.js:217
>       2  100.0%      Function: RunStep
>       2  100.0%        LazyCompile: BenchmarkSuite.RunSuiteshttp://v8.googlecode.com/svn/data/benchmarks/v5/base.js:105
>       2  100.0%          LazyCompile: Runhttp://v8.googlecode.com/svn/data/benchmarks/v5/run.html:51

> ...
>
> For every GC iteration, call paths that produced objects belonging to
> the same constructor are listed.
>
> > Can you please clarify a couple of things about the heap profiler (I
> > can't find much detail on the web, I understand that it is a very new
> > feature):
> > * The top level items in the profile are the objects that are
> > referenced, and the count of these is the number of objects of this
> > type on the heap.
>
> Right.
>
> > * The second level items are the objects that hold the references to
> > the top level items, and the count is the number of references.
>
> Right.
>
> > * What are the next (and next and next...) levels of expansion? are
> > they the next objects in the reference chain?
>
> The next levels are actually not very useful. I should remove them.
>

> >> >> >http://code.google.com/p/v8/issues/detail?id=524orthis bug:

> ...
>
> read more »

[Mikhail Naganov]

Hi Jonathan,

Some comments on the tree structure. The top producers for arrays are:

201 20.4% LazyCompile: slice native array.js:529

189 19.1% LazyCompile: getSpeciesCallback
http://localhost:8000/media/4.0/evolve/environment.js:24
188 19.0% Function: ShadowPrototypeElements

187 18.9% RegExp: (compatible|webkit)

23 2.3% Function: <anonymous> {35}

"slice" and "ShadowPrototypeElements" are built-in V8 functions.
"slice" creates new arrays according to spec, but it's surprising that
"ShadowPrototypeElements" does (however, it might be a wrong
reporting.)

"slice" was mostly called to create a result for RegExp execution:

186 92.5% RegExp: (compatible|webkit)
7 3.5% LazyCompile: CORE.environment._initialiseProcess
http://localhost:8000/media/4.0/evolve/environment.js:90

6 3.0% LazyCompile: getSpeciesCallback
http://localhost:8000/media/4.0/evolve/environment.js:24

It might be due to reporting results of regex matching.

To get an idea of what those "native" functions are, you can look at
V8 source code. As for "<anonymous>" functions: sorry, currently there
is no way of knowing what they are.

> Should I be able to somehow use this output to see where objects are
> being created, but not dereferenced?

I'm not sure I'm understanding you. All objects in the report are
referenced, otherwise, they would be collected. Although, it's
currently not possible to match "created" objects report with
"retained" objects report, sorry.

> Also Mikhail: where are objects with no constructors shown in the heap
> profiler GUI?

They are accounted on the "Object" entry.

[Jonathan Ricketson]

Hi Mikhail, I have refactored my code a bit to make a lot less use of "slice", to instead use "splice". This seemed to help, but I am again having OOM problems. But a further problem that I am having now is that when I run the tick processor I also get an out of memory error... Maybe it is just me :)

(I edited linux-tick-processor to remove the echo to dev/null)

bash ./tools/linux-tick-processor /home/jon/.config/google-chrome/1264934403864.log > /home/jon/data/Projects/evolveJsgoogle/chrome.linux-ticks.localhost.out

#
# Fatal error in CALL_AND_RETRY_2
# Allocation failed - process out of memory
#

./tools/linux-tick-processor: line 24:  9582 Aborted                 $d8_exec $tools_path/splaytree.js $tools_path/codemap.js $tools_path/csvparser.js $tools_path/consarray.js $tools_path/profile.js $tools_path/profile_view.js $tools_path/logreader.js $tools_path/tickprocessor.js $tools_path/tickprocessor-driver.js -- $@

Thanks,
Jonathan

[Mikhail Naganov]

Yes, that can happen if you have a really big log file. You can try to
increase maximum memory that can be allocated for V8 heap by
specifying --max_old_space_size in linux-tick-processor, like this:

$d8_exec --max_old_space_size 3221225472 $tools_path/splaytree.js ...

This will allow to use up to 3GB (the default is 512MB on 32-bit
system and 1GB on 64-bit.)

As an alternative, you can cut your log file. As you probably don't
need the very beginning of the log, you can safely remove blocks of
lines surrounded by "heap-sample-begin" and "heap-sample-end" with the
same names ("NewSpace" or "Heap".)

[Jonathan Ricketson]

I can't seem to increase my max_old_space_size past 1 000 000 000 (which from your description is the default on my 64 bit system). If I put a bigger number (such as your suggested 3221225472), it throws this error:
#
# Fatal error in v8::ObjectTemplate::New()
# Error initializing V8
#

[Kevin Millikin]

You have a 32-bit build of V8.

You should pass "arch=x64" (without the quotes) on the scons command line to build a 64-bit executable.

--
Chromium Developers mailing list: chromi...@chromium.org

[Mikhail Naganov]

Sorry, I forgot about this issue. You should execute 'scons arch=x64 d8' (or 'scons -j8 arch=x64 d8' to get a faster build) as Kevin suggests.

Remember that having a 64-bit system doesn't mean that all your applications are 64-bit.

[Jonathan Ricketson]

Hi, thanks for all your help so far.

I have found that any logs larger than about 200MB will cause a OOM exception for the linux-tick-processor. This is even with specifying 3gb for max old space.

As you say though, I am probably most interested in the last 200mb of any log file. I have tried to figure out how to cut a log file to leave only the last 1m lines, but the obvious ways (tail -1000000) doesn't work, (even accounting for ensuring the "heap-sample-begin" and "heap-sample-end" blocks are maintained). By "doesn't work", I mean that all of the ticks are empty of any detail, except for a whole bunch of "deleted code" markers.

Can you give me any tips on how to trim the log and still have something useful there to analyse?

thanks
jonathan

On 1 February 2010 23:52, Mikhail Naganov <mnag...@chromium.org> wrote:

[Mikhail Naganov]

I think I'll fix this from my side. Right now the tick processor script isn't very scalable, because it first loads the whole log (a historical limitation, because long ago the d8 shell didn't have line-by-line file loading), then it tries to process it, and only then prints results. For huge logs like yours this simply doesn't work. I always wanted to change this behavior in favor of "read log chunk, spit out current results" approach, which fits especially good for heap object generations you're dealing with. I will try to fix that soon.

--
Chromium Developers mailing list: chromi...@chromium.org

[Mikhail Naganov]

Hi Jonathan,

I've just landed a patch for the tick processor script (r3811, bleeding_edge branch, http://code.google.com/p/v8/source/detail?r=3811) which implements line-by-line log reading behavior previously discussed. In my testing environment, I was able to process a 300MB Chrome's log file, whereas with the previous version it was impossible. Please try it.

BTW, I noticed that I forgot one little flag in Chrome's jsflags arguments, which will reduce the speed of its growth: --noprof-auto. So, the full invocation line is as follows:

--no-sandbox --js-flags="--logfile=%t.log --log-producers --noprof-lazy --noprof-auto --log-code --log-gc --noinline-new --never-compact"

On Fri, Feb 5, 2010 at 14:17, Jonathan Ricketson <jrick...@gmail.com> wrote:

thanks. I look forward to being able to use it.

Jonathan