553682 - TM: GC Profiler

Status: RESOLVED FIXED

(Core :: JavaScript Engine, defect)

Description

[Gregor Wagner [:gwagner]]

Attachment: GCTimer

I used this patch to profile the js_GC function and count how many chunks are allocated and destroyed between GC calls. The results are written to a file and can be visualized with gnuplot.

Comment 1

[Gregor Wagner [:gwagner]]

Attachment: gnuplot file

and the gnuplot file to generate the graph.
You have to change the input filename in order to use it.

Comment 2

[Gregor Wagner [:gwagner]]

Attachment: sample output

Sample output

Comment 3

[Mike Moening]

Gregor,

Can you update the patch to include #ifdef so we can conditionally enabled this on trunk builds?

Mike M

Comment 4

[Gregor Wagner [:gwagner]]

Attachment: Profile of random webpages

I captured a random surf behavior: Opened a lot of tabs and visited random webpages. 
The graph shows again the two different webpage styles:
1) transition based with long living objects
2) recreation based with lots of short living objects.

Marking time dominates in 1) and sweeping time in 2).

Comment 5

[Gregor Wagner [:gwagner]]

Attachment: Facebook

Example for transition based webpage: Facebook.
Marking time kills here.

Comment 6

[Gregor Wagner [:gwagner]]

Attachment: 280 slides

example for recreation based webpage: 280 slides.
Sweeping time matters.

Comment 7

[Robert Sayre]

Gregor, this work is fantastic.

Comment 8

[Brendan Eich [:brendan]]

Huzzah^2, and props for using dear old gnuplot (don't make Andreas program it ;-).

/be

Comment 9

[Gregor Wagner [:gwagner]]

Attachment: new version

It covers now everything with the GCTIMER option.

Comment 10

[Mike Moening]

Gregor, Can you land the GCTIMER patch on the TIP?

Comment 11

[Gregor Wagner [:gwagner]]

(In reply to comment #10)
> Gregor, Can you land the GCTIMER patch on the TIP?

I still have problems with rdtsc on different platforms. It's defined in avmplus.h but it seems that not all platforms include this header.

Comment 12

[Gregor Wagner [:gwagner]]

Attachment: patch

added compiler flag

Comment 13

[Gregor Wagner [:gwagner]]

Attachment: patch update

refresh

Comment 14

[Gregor Wagner [:gwagner]]

Attachment: patch update

and now the right version.

Comment 15

[Igor Bukanov]

Comment on attachment 434637 [details] [diff] [review]
patch update

>diff -r f909e6aacc87 js/src/jsgc.cpp
>--- a/js/src/jsgc.cpp	Tue Mar 23 21:23:40 2010 -0700
>+++ b/js/src/jsgc.cpp	Wed Mar 24 13:07:46 2010 -0700
>@@ -562,21 +562,28 @@ MakeNewArenaFreeList(JSGCArena *a, size_
> #else
> # define METER(x)               ((void) 0)
> # define METER_IF(condition, x) ((void) 0)
> #endif
> 
> #define METER_UPDATE_MAX(maxLval, rval)                                       \
>     METER_IF((maxLval) < (rval), (maxLval) = (rval))
> 
>+#ifdef MOZ_GCTIMER
>+static int newChunkCount = 0;
>+static int destroyChunkCount = 0;

Use jsrefcount for the type here and JS_ATOMIC_INCREMENT to increase the counter.

>+#ifdef MOZ_GCTIMER
>+typedef struct GCTimer {

Nit: no need for typedef.

>+static uint64 firstEnter = 0;

Nit: use more descriptive name here. Something like firstGCStart. Alternatively move the static into js_GC and pass it into dumpGCTimer.

>+
>+void dumpGCTimer(GCTimer *gcT, bool lastGC)
>+{
>+    static FILE *gcFile;
>+
>+    if (!gcFile) {
>+        gcFile = fopen("gcTimer.dat", "w");
>+        JS_ASSERT(gcFile);

I suggest to always open file in the dump function and append the data using the "a" mode. This way the data file would not be overwritten if one starts browser again. 

>+#define TIMESTAMP(x) x = rdtsc();
>+#else
>+#define TIMESTAMP(x)
>+#endif

Nit: move the define into js_GC to emphasis its locality. Also use ((void) 0) for the empty timestamp and wrap the definition of the first one into parenthesis. 

>@@ -3199,16 +3263,17 @@ js_GC(JSContext *cx, JSGCInvocationKind 

>     FinalizeArenaList<JSString, FinalizeString>
>         (cx, FINALIZE_STRING, &emptyArenas);

It would be nice to add a separated counter for the string finalization timing.

Assume r+ with that fixed.

Comment 16

[Gregor Wagner [:gwagner]]

(In reply to comment #15)
> >+
> >+void dumpGCTimer(GCTimer *gcT, bool lastGC)
> >+{
> >+    static FILE *gcFile;
> >+
> >+    if (!gcFile) {
> >+        gcFile = fopen("gcTimer.dat", "w");
> >+        JS_ASSERT(gcFile);
> 
> I suggest to always open file in the dump function and append the data using
> the "a" mode. This way the data file would not be overwritten if one starts
> browser again. 
> 

I don't like if the file just grows and I have to manually delete it or copy some parts for plotting. I want to leave it like that if there is no other reason.

> 
> >@@ -3199,16 +3263,17 @@ js_GC(JSContext *cx, JSGCInvocationKind 
> 
> >     FinalizeArenaList<JSString, FinalizeString>
> >         (cx, FINALIZE_STRING, &emptyArenas);
> 
> It would be nice to add a separated counter for the string finalization timing.

Added

> 
> Assume r+ with that fixed.

Thx!

Comment 17

[Gregor Wagner [:gwagner]]

Attachment: patch

Addressed Igors comments.

Comment 18

[Gregor Wagner [:gwagner]]

Attachment: patch

fix output

Comment 19

[Gregor Wagner [:gwagner]]

Attachment: patch: gnuplot script

I added another folder for it. utils->gcTimer
Other script files don't have the copyright header so I didn't add one.

Comment 20

[Andreas Gal :gal]

Comment on attachment 434999 [details] [diff] [review]
patch: gnuplot script

Looks good. Please get consensus from #jsapi on the directory name.

Comment 21

[Gregor Wagner [:gwagner]]

Attachment: patch: gnuplot script

moved to js/src/gnuplot

Comment 22

[Gregor Wagner [:gwagner]]

Part 1: Gnuplot file:
http://hg.mozilla.org/tracemonkey/rev/f896af789657

Comment 23

[Gregor Wagner [:gwagner]]

Attachment: patch: minor fixes

Comment 24

[Gregor Wagner [:gwagner]]

http://hg.mozilla.org/tracemonkey/rev/b2daab8b12af

Comment 25

[Igor Bukanov]

Attachment: enable timestamping in debug builds

To make sure that the timestamping code does not rot the patch enables it (but not the stats printout) in debug builds unconditionally.

Comment 26

[Gregor Wagner [:gwagner]]

(In reply to comment #25)
> Created an attachment (id=435289) [details]
> enable timestamping in debug builds
> 
> To make sure that the timestamping code does not rot the patch enables it (but
> not the stats printout) in debug builds unconditionally.

I wanted to do the same but I always got a compile error with rdtsc on Maemo on try-server. I asked dmandelin because he uses it for traceviz and he said that rdtsc might not be implemented on Maemo.

Comment 27

[Igor Bukanov]

(In reply to comment #26)
> try-server. I asked dmandelin because he uses it for traceviz and he said that
> rdtsc might not be implemented on Maemo.

Then we should only enable it if rdtsc is available.

Comment 28

[Igor Bukanov]

I filed bug 555338 to get a preprocessor define that tells when rdtsc is available.

Comment 29

[Igor Bukanov]

Attachment: enable timestamping in debug builds v2

Here is an updated patch that checks for rdtsc availability using AVMPLUS_HAS_RDTSC from the bug 555338.

On a releated note I have found that it would be very useful to expose the timing stats for shell scripts. This way a performance benchmark can run a test repetitively and process the statistics on its own.

Comment 30

[Igor Bukanov]

(In reply to comment #29)
> On a releated note I have found that it would be very useful to expose the
> timing stats for shell scripts. This way a performance benchmark can run a test
> repetitively and process the statistics on its own.

Gregor, what do you think about this?

Comment 31

[Gregor Wagner [:gwagner]]

Comment on attachment 435666 [details] [diff] [review]
enable timestamping in debug builds v2


>+
>+#if !AVMPLUS_HAS_RDTSC
>+#error "MOZ_GCTIMER can only be enabled if the rdtsc() is available."
>+#endif
>+

nit: "if rdtsc() is available" or "if the rdtsc() instruction is available" sounds better to me.

Comment 32

[Gregor Wagner [:gwagner]]

> On a releated note I have found that it would be very useful to expose the
> timing stats for shell scripts. This way a performance benchmark can run a test
> repetitively and process the statistics on its own.

You mean like the sunspider comparison? 
Yeah the timing output was just the first step and we should really use these numbers.
I also want to use the relative application time that is already in the output file and do some GC frequency graphs.

Comment 33

[Robert Sayre]

http://hg.mozilla.org/mozilla-central/rev/f896af789657