GC: full mark&sweep abused ?

[strk]

I'm profiling a node.js http server and facing a lot of time spent by stop-the-world garbage collector which doesn't seem to be succeeding in collecting much.
Here's the output from --trace-gc, "only" the portion within the same millisecond:

  111182 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 13 ms [external memory allocation limit reached] [GC in old space requested].
  111182 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 13 / 26 ms [external memory allocation limit reached] [GC in old space requested].
  111182 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 26 / 39 ms [external memory allocation limit reached] [GC in old space requested].
  111182 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 39 / 52 ms [external memory allocation limit reached] [GC in old space requested].
  111182 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 52 / 65 ms [external memory allocation limit reached] [GC in old space requested].
  111182 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 65 / 78 ms [external memory allocation limit reached] [GC in old space requested].
  111182 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 78 / 91 ms [external memory allocation limit reached] [GC in old space requested].
  111182 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 91 / 104 ms [external memory allocation limit reached] [GC in old space requested].
  111182 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 104 / 117 ms [external memory allocation limit reached] [GC in old space requested].
  111182 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 117 / 130 ms [external memory allocation limit reached] [GC in old space requested].
  111182 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 130 / 143 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 143 / 156 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 156 / 169 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 169 / 182 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 182 / 195 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 195 / 208 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 208 / 221 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 221 / 234 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 234 / 247 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 247 / 260 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 260 / 274 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 274 / 287 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 287 / 300 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 300 / 313 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 313 / 326 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 326 / 339 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 339 / 352 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 352 / 365 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 365 / 378 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 378 / 391 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 391 / 404 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 404 / 417 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 417 / 431 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 431 / 444 ms [external memory allocation limit reached] [GC in old space requested].
   111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 444 / 457 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 457 / 470 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 470 / 483 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 483 / 496 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 496 / 509 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 509 / 522 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 522 / 535 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 535 / 548 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 548 / 561 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 561 / 574 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 575 / 588 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 588 / 601 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 601 / 614 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 614 / 627 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 627 / 640 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 640 / 653 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 653 / 667 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 667 / 680 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 680 / 693 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 693 / 706 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 706 / 719 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 719 / 732 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 732 / 745 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 745 / 758 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 758 / 771 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 771 / 784 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 784 / 797 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 797 / 810 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 810 / 823 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 823 / 837 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 837 / 850 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 850 / 863 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 863 / 876 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 876 / 889 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 889 / 902 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 902 / 915 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 915 / 928 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 928 / 941 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 941 / 954 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 954 / 967 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 967 / 981 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 981 / 994 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 994 / 1007 ms [external memory allocation limit reached] [GC in old space requested].                  
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 1007 / 1020 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 1020 / 1034 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 1034 / 1047 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 1047 / 1061 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 1061 / 1074 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 1074 / 1087 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 1087 / 1101 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 1101 / 1114 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 1114 / 1127 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 1127 / 1140 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 1140 / 1153 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 1153 / 1166 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 1166 / 1179 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 1179 / 1192 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 1192 / 1205 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 1205 / 1218 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 1218 / 1231 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 1231 / 1244 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 1244 / 1258 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 1258 / 1271 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 1271 / 1284 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 1284 / 1297 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 1297 / 1310 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 1310 / 1323 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 1323 / 1336 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.2 (48.0) -> 11.2 (48.0) MB, 1336 / 1351 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.3 (48.0) -> 11.2 (48.0) MB, 1351 / 1364 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.3 (48.0) -> 11.2 (48.0) MB, 1364 / 1377 ms [external memory allocation limit reached] [GC in old space requested].
  111183 ms: Mark-sweep 11.3 (48.0) -> 11.2 (48.0) MB, 1377 / 1391 ms [external memory allocation limit reached] [GC in old space requested].

Do I read it correctly that it is failing to release anything ? Also, how can I find out _why_ it is triggered ?
I mean, isn't 48MB a low memory usage for triggering an "external memory allocation limit" ? Or what does "external memory allocation limit" mean ?

Thanks in advance.

[Vyacheslav Egorov]

[v8-dev mailing list is mostly used for code review and commit
messages by developers, I suggest using v8-users next time instead]

This GC is triggered by a heuristic that tries to track amount of
resources held by objects in V8 heap. V8's embedder notifies V8 about
such creating/destruction of such resources by calling
v8::V8::AdjustAmountOfExternalAllocatedMemory.

It can be that somebody misuses this API.

I suggest to place a breakpoint into
AdjustAmountOfExternalAllocatedMemory and check stack trace to see who
calls it.

--
Vyacheslav Egorov

> --
> v8-dev mailing list
> v8-...@googlegroups.com
> http://groups.google.com/group/v8-dev

[Sandro Santilli]

On Wed, Aug 01, 2012 at 12:31:53PM +0200, Vyacheslav Egorov wrote:
> [v8-dev mailing list is mostly used for code review and commit
> messages by developers, I suggest using v8-users next time instead]

Sorry, will do. I hope I can keep it hear for this time.

> This GC is triggered by a heuristic that tries to track amount of
> resources held by objects in V8 heap. V8's embedder notifies V8 about
> such creating/destruction of such resources by calling
> v8::V8::AdjustAmountOfExternalAllocatedMemory.
>
> It can be that somebody misuses this API.
>
> I suggest to place a breakpoint into
> AdjustAmountOfExternalAllocatedMemory and check stack trace to see who
> calls it.

Indeed commenting out _all_ calls to VM::AdjustAmountOfExternalAllocatedMemory
makes the GC much much lighter: no frequent full mark&swep runs and when they
happen they are effective and mainly _fast_ (2-digits ms vs. 4-digits ones).

Thanks for the pointer !

--strk;

,------o-.
| __/ | Delivering high quality PostGIS 2.1
| / 2.1 | http://strk.keybit.net - http://vizzuality.com
`-o------'

[st...@vizzuality.com]

For the record: it turned out a integer overflow resulted in calls to ::AdjustAmountOfExternalAllocatedMemory with a positive (and big) value rather than the expected negative value on objects deletion.

The object deletion was in turn triggered by a previous GC run every GC object disposal was triggering another scheduled run. Dunno how the GC did ever get out of the loop (but it eventually did).

More info: https://github.com/mapnik/node-mapnik/issues/116

--strk;