687558 - long cycle collection pause times in realtime JS raytracing demo

Status: RESOLVED WORKSFORME

(Core :: XPCOM, defect)

Description

[Andrew McCreight [:mccr8]]

Billm found that the cycle collector has horrible pause times.  When he tried it, it was bad at startup, but then smoothed out.  For me, when I am trying it, it has horrible 10+ second pause times, then some shorter multi-second pause times, then it goes back to the long pause times.  I haven't investigated to see what exactly is the problem for me.

Comment 1

[Andrew McCreight [:mccr8]]

I tried this again, in a debug build.  GC pause times were 260ms, and CC pause times were very short, around 10ms.  I'm not sure what problem I was having before, but that has gone away.

Anyways, back to what Bill identified.  When I run the demo right at startup, it does 6 GCs of about 260ms, which is the normal steady state GC, then does this mega CC:

CC timestamp: 1316559049737356, collected: 769 (769 waiting for GC), suspected: 4969, duration: 4729 ms.

After that, behavior is normal (260ms JS pause times, then 4ms CC pause times).  It looked like the graphics driver re-initialized after the huge CC.  I don't know if that is related or just something weird.

I'll have to try out a non-debug optimized build and see if things are any different, and dump a CC log.

The fact that 100% of the items it collected are "waiting for GC" is weird.  I assume that means that they were all JS objects, so I'm not sure why the CC would care about them.

Comment 2

[Andrew McCreight [:mccr8]]

Most of the time is spent on MarkRoots, which is pretty standard for CCs:

cc: SelectPurple() took 1ms
cc: MarkRoots() took 4029ms
cc: ScanRoots() took 264ms
cc: CollectWhite() took 18ms

Comment 3

[Andrew McCreight [:mccr8]]

I tried this just now and I don't see any long CC or GC times.