Skip to content

WeakMap() usage results in permanently expanded RSS #14420

Closed
Closed
WeakMap() usage results in permanently expanded RSS#14420
Labels
invalidIssues and PRs that are invalid.v8 engineIssues and PRs related to the V8 dependency.

Description

@owenallenaz
owenallenaz
opened on Jul 21, 2017
  • Version:v8.2.1
  • Platform:Linux nodeServer 2.6.32-573.el6.x86_64 deps: update openssl to 1.0.1j #1 SMP Thu Jul 23 15:44:03 UTC 2015 x86_64 x86_64 x86_64 GNU/Linux
  • Subsystem:WeakMap

From my tests, using WeakMap() can cause the RSS to grow infinitely. As stated in other issues, this isn't necessarily a memory leak, as the RSS on linux doesn't truly indicate that memory isn't available, but as I understand it, as memory increases from one process it can force other processes into swap or give the appearance of a box running out of memory. In addition if the RSS grows above 5gigs we're seeing it result in ENOMEM errors.

I've tested this on Node 7.4.0, 7.10.0 and 8.2.1 and all of them appear to have the same problem.

I've created a gist with the recreation script and results https://gist.github.com/owenallenaz/9fa93cee775ac834c0fcf7f41477c6a5 .

If you look at the results, you'll see the RSS steadily increasing, up to 250mb. After 30s it halts allocations, a few gc's later it goes to a baseline of 100mb. Which is still quite high seeing as there is nothing in the WeakMap() at all. Then 30s later it fully resets the WeakMap but we're still left with 29mb RSS.

If you change settings.clearAfterAllocate = true then it will reset the map after each allocate() call. Now, in theory since the allocate() has fully finished, all of the objs should have gone out of scope. This should mean the WeakMap is effectively empty. Except, when you make that change the RSS expansion is halted. Once the allocations stop, the RSS drops down to 17mb.

Activity

  1. mscdex commented on Jul 22, 2017

    @mscdex
    mscdex
    on Jul 22, 2017
    Contributor

    It's probably best to include the code and results in the first post instead of a gist (in case the gist gets deleted). For the long console output, just wrap it in a details html tag.

  2. mscdex
    added
    v8 engineIssues and PRs related to the V8 dependency.
    on Jul 22, 2017

  3. bnoordhuis commented on Jul 22, 2017

    @bnoordhuis
    bnoordhuis
    on Jul 22, 2017
    Member

    I don't see anything out of the ordinary. What would you say is the expected behavior and why?

    Keep in mind that the garbage collector uses numerous input signals to decide whether to grow or shrink the heap. RSS not shrinking right away1 or not shrinking to the lowest possible value doesn't necessarily indicate a bug.

    1 Weak collections are processed over the course of one or more major GC cycles (mark-sweep, mark-compact) so there would be a delay even with a shrink-immediately policy.

  4. owenallenaz commented on Jul 24, 2017

    @owenallenaz
    owenallenaz
    on Jul 24, 2017
    Author

    If the RSS eventually shrinked, that would be fine. We're seeing permanent, unbounded growth in the RSS. In the test case I posted, after 60s, we fully reset the WeakMap(), and yet, the RSS for it is never reclaimed even if you let the test case continue to run for minutes. Now, if instead of storing obj via map.set(obj, true), we store it in a plain array arr.push(obj), and then after 60 seconds, we wipe that array, after that wipe occurs, then the RSS resets back down to baseline. Obviously this change will cause the working set of memory to push to much higher limits (1.2gb) since we're storing every obj from every iteration in a single array, so none of them are available to GC until the full clear. Yet, even in this case, once the full clear happens and the array is reset, the memory returns down to baseline (18mb).

    So if I push to an array for 30s, stop pushing, and then 30 seconds later wipe the array = Memory back to normal.

    Pushing to array, and clearing array after 120s

    process { http_parser: '2.7.0',
    node: '7.10.0',
    v8: '5.5.372.43',
    uv: '1.11.0',
    zlib: '1.2.11',
    ares: '1.10.1-DEV',
    modules: '51',
    openssl: '1.0.2k',
    icu: '58.2',
    unicode: '9.0',
    cldr: '30.0.3',
    tz: '2016j' }
    settings { haltAfter: 30000,
    clearAfterAllocate: false,
    numObjects: 10000,
    gcInterval: 5000,
    logInterval: 1000,
    clearInterval: 5000,
    allocateInterval: 10,
    resetAfter: 120000 }
    rss 73043968 51253520
    rss 138858496 107147424
    rss 192929792 160636104
    rss 259137536 226260440
    rss 273469440 195742192
    rss 313798656 278217336
    rss 350752768 314251896
    rss 457154560 420104952
    rss 493768704 456106352
    rss 481378304 410003080
    rss 484339712 445206168
    rss 626851840 587185184
    rss 663064576 622786584
    rss 700489728 659587984
    rss 663240704 621729040
    rss 700252160 658132128
    rss 895307776 852700080
    rss 932327424 889101480
    rss 969748480 925902880
    rss 895913984 851103616
    rss 932114432 886706704
    rss 968318976 922308104
    rss 1005735936 959109504
    rss 1042350080 995110912
    rss 1150652416 1102969160
    rss 1187266560 1138972256
    rss 1224683520 1175773664
    done!
    rss 1225097216 1176184104
    rss 1225097216 1176185512
    rss 1225097216 1176146928
    rss 1225093120 1176150024
    rss 1225093120 1176151432
    rss 1225093120 1176152800
    rss 1225093120 1176154168
    rss 1225093120 1176147144
    rss 1225093120 1176150240
    rss 1225093120 1176151608
    rss 1225093120 1176152976
    rss 1225093120 1176154344
    rss 1225166848 1176147144
    rss 1225170944 1176150240
    rss 1225170944 1176151648
    rss 1225175040 1176153016
    rss 1225175040 1176154424
    rss 1225199616 1176143024
    rss 1225203712 1176146120
    rss 1225203712 1176147528
    rss 1225207808 1176148896
    rss 1225207808 1176150304
    rss 1225232384 1176142624
    rss 1225236480 1176145720
    rss 1225236480 1176147128
    rss 1225240576 1176148496
    rss 1225240576 1176149904
    rss 1225265152 1176142624
    rss 1225269248 1176145720
    rss 1225269248 1176147128
    rss 1225273344 1176148496
    rss 1225273344 1176149904
    rss 1225297920 1176142624
    rss 1225302016 1176145720
    rss 1225302016 1176147128
    rss 1225306112 1176148496
    rss 1225306112 1176149904
    rss 1225330688 1176142624
    rss 1225334784 1176145720
    rss 1225334784 1176147128
    rss 1225338880 1176148496
    rss 1225338880 1176149904
    rss 1225363456 1176142624
    rss 1225367552 1176145720
    rss 1225367552 1176147128
    rss 1225371648 1176148496
    rss 1225371648 1176149904
    rss 1225396224 1176142624
    rss 1225400320 1176145720
    rss 1225400320 1176147128
    rss 1225404416 1176148496
    rss 1225404416 1176149904
    rss 1225428992 1176142624
    rss 1225433088 1176145720
    rss 1225433088 1176147128
    rss 1225437184 1176148496
    rss 1225437184 1176149904
    rss 1225461760 1176142624
    rss 1225465856 1176145720
    rss 1225465856 1176147128
    rss 1225469952 1176148496
    rss 1225469952 1176149904
    rss 1225494528 1176142624
    rss 1225498624 1176145720
    rss 1225498624 1176147128
    rss 1225502720 1176148496
    rss 1225502720 1176149904
    rss 1225527296 1176142624
    rss 1225531392 1176145720
    rss 1225531392 1176147128
    rss 1225535488 1176148496
    rss 1225535488 1176149904
    rss 1225560064 1176142624
    full reset
    rss 1225564160 1176148248
    rss 1225568256 1176149656
    rss 1225568256 1176151064
    rss 1225568256 1176152432
    rss 1185751040 3292464
    rss 27856896 3295536
    rss 27856896 3296912
    rss 27860992 3298256
    rss 27860992 3299632
    rss 20168704 3288896
    rss 20172800 3291960
    rss 20172800 3293336
    rss 20176896 3294680
    rss 20176896 3296056
    rss 18595840 3288816
    rss 18599936 3291880
    rss 18599936 3293256
    rss 18604032 3294600

    If I set to a WeakMap() for 30s, stop settings, and then 30 seconds later wipe the WeakMap = RSS still high.

    WeakMap full clear after 60sprocess { http_parser: '2.7.0',
    node: '7.10.0',
    v8: '5.5.372.43',
    uv: '1.11.0',
    zlib: '1.2.11',
    ares: '1.10.1-DEV',
    modules: '51',
    openssl: '1.0.2k',
    icu: '58.2',
    unicode: '9.0',
    cldr: '30.0.3',
    tz: '2016j' }
    settings { haltAfter: 30000,
    clearAfterAllocate: false,
    numObjects: 10000,
    gcInterval: 5000,
    logInterval: 1000,
    clearInterval: 5000,
    allocateInterval: 10,
    resetAfter: 60000 }
    rss 106364928 57707992
    rss 150855680 90247304
    rss 197070848 136654928
    rss 243937280 183849320
    rss 152068096 71620984
    rss 184860672 116423136
    rss 223195136 158823776
    rss 279179264 202843480
    rss 318734336 247644168
    rss 153214976 71636136
    rss 183705600 114038216
    rss 221630464 155638856
    rss 260374528 198839520
    rss 313450496 237239296
    rss 153214976 71221840
    rss 183623680 113623920
    rss 223993856 160024656
    rss 279113728 202424552
    rss 318664704 247225240
    rss 153382912 71203976
    rss 184901632 116806152
    rss 225673216 164006888
    rss 279973888 204806736
    rss 320344064 251207472
    rss 152862720 71203976
    rss 185716736 118406176
    rss 226492416 165606936
    done!
    rss 260767744 200017440
    rss 260767744 200018848
    rss 219873280 70393632
    rss 152764416 70396712
    rss 152764416 70398104
    rss 152764416 70399456
    rss 152764416 70400808
    rss 112496640 70393824
    rss 112496640 70396904
    rss 112496640 70398256
    rss 112496640 70399608
    rss 112496640 70400960
    rss 111472640 70393824
    rss 111476736 70396904
    rss 111476736 70398296
    rss 111480832 70399648
    rss 111480832 70401040
    rss 111472640 70389704
    rss 111476736 70392784
    rss 111476736 70394176
    rss 111480832 70395528
    rss 111480832 70396920
    rss 111472640 70389304
    rss 111476736 70392384
    rss 111476736 70393776
    rss 111480832 70395128
    rss 111480832 70396520
    rss 111472640 70389304
    rss 111476736 70392384
    full reset
    rss 111480832 70396336
    rss 111480832 70397728
    rss 111480832 70399080
    rss 97398784 3280112
    rss 30244864 3283176
    rss 30244864 3284552
    rss 30248960 3285896
    rss 30248960 3287272
    rss 30240768 3277392
    rss 30244864 3280456
    rss 30244864 3281832
    rss 30248960 3283176
    rss 30248960 3284552
    rss 30240768 3277312
    rss 30244864 3280376
    rss 30244864 3281752
    rss 30248960 3283096

    As I understand, the intent of WeakMap is a storage so that when references go out of scope naturally, they should be garbage collected. So, then in that case there should be no reason to every wipe a WeakMap() manually. If I remove the full clear of the map, then it means my RSS stays at 111mb, when baseline should be 18mb. This is 5x RSS usage compared, and as I can tell it will never contract.

    Without full clear, logging every second

    process { http_parser: '2.7.0',
    node: '7.10.0',
    v8: '5.5.372.43',
    uv: '1.11.0',
    zlib: '1.2.11',
    ares: '1.10.1-DEV',
    modules: '51',
    openssl: '1.0.2k',
    icu: '58.2',
    unicode: '9.0',
    cldr: '30.0.3',
    tz: '2016j' }
    settings { haltAfter: 30000,
    clearAfterAllocate: false,
    numObjects: 10000,
    gcInterval: 5000,
    logInterval: 1000,
    clearInterval: 5000,
    allocateInterval: 10,
    resetAfter: 120000 }
    rss 89894912 57026512
    rss 151384064 90251632
    rss 195432448 134229368
    rss 241168384 179048088
    rss 152297472 71620136
    rss 182915072 113222216
    rss 222875648 158822928
    rss 278843392 202842632
    rss 318803968 248443344
    rss 153403392 71635288
    rss 184995840 117237464
    rss 224546816 162038152
    rss 278847488 202838000
    rss 318808064 248438712
    rss 153403392 71221112
    rss 184922112 116823288
    rss 225292288 163224024
    rss 279584768 204023848
    rss 317521920 245624464
    rss 153927680 71203248
    rss 185323520 117605424
    rss 226099200 164806184
    rss 280403968 205606032
    rss 318738432 248006672
    rss 153403392 71203248
    rss 185733120 118405448
    rss 226099200 164806184
    done!
    rss 257523712 193616568
    rss 257523712 193617976
    rss 222924800 70392904
    rss 153194496 70395984
    rss 153194496 70397376
    rss 153194496 70398728
    rss 153194496 70400080
    rss 112508928 70393096
    rss 112508928 70396176
    rss 112508928 70397528
    rss 112508928 70398880
    rss 112508928 70400232
    rss 111484928 70393096
    rss 111489024 70396176
    rss 111489024 70397568
    rss 111493120 70398920
    rss 111493120 70400312
    rss 111484928 70388976
    rss 111489024 70392056
    rss 111489024 70393448
    rss 111493120 70394800
    rss 111493120 70396192
    rss 111484928 70388576
    rss 111489024 70391656
    rss 111489024 70393048
    rss 111493120 70394400
    rss 111493120 70395792
    rss 111484928 70388576
    rss 111489024 70391656
    rss 111489024 70393048
    rss 111493120 70394400
    rss 111493120 70395792
    rss 111484928 70388576
    rss 111489024 70391656
    rss 111489024 70393048
    rss 111493120 70394400
    rss 111493120 70395792
    rss 111484928 70388576
    rss 111489024 70391656
    rss 111489024 70393048
    rss 111493120 70394400
    rss 111493120 70395792
    rss 111484928 70388576
    rss 111489024 70391656
    rss 111489024 70393048
    rss 111493120 70394400
    rss 111493120 70395792
    rss 111484928 70388576
    rss 111489024 70391656
    rss 111489024 70393048
    rss 111493120 70394400
    rss 111493120 70395792
    rss 111484928 70388576
    rss 111489024 70391656
    rss 111489024 70393048
    rss 111493120 70394400
    rss 111493120 70395792
    rss 111484928 70388576
    rss 111489024 70391656
    rss 111489024 70393048
    rss 111493120 70394400
    rss 111493120 70395792
    rss 111484928 70388576
    rss 111489024 70391656
    rss 111489024 70393048
    rss 111493120 70394400
    rss 111493120 70395792
    rss 111484928 70388576
    rss 111489024 70391656
    rss 111489024 70393048
    rss 111493120 70394400
    rss 111493120 70395792
    rss 111484928 70388576
    rss 111489024 70391656
    rss 111489024 70393048
    rss 111493120 70394400
    rss 111493120 70395792
    rss 111484928 70388576
    rss 111489024 70391656
    rss 111489024 70393048
    rss 111493120 70394400
    rss 111493120 70395792
    rss 111484928 70388576
    rss 111489024 70391656
    rss 111489024 70393048
    rss 111493120 70394400
    rss 111493120 70395792
    rss 111484928 70388576
    rss 111489024 70391656
    rss 111489024 70393048
    rss 111493120 70394400

    In the array test the RSS balloons to 1.1gb, and clears to baseline. With the WeakMap() test the RSS balloons to 300mb, and only goes down to 100mb. This tells me it's not just RSS eccentricities, since the RSS grows higher in the array test but still contracts fine.

    The reason we hit this was, upon introduction of code which used WeakMap(), processes which used 100mb, started using 2gb+. A process which used 800mb of memory started using 5gb+. When we run 100 processes per server, the difference between 100mb per process and 2gb per process is very, very important. On the 5gb process we are starting to get ENOMEM errors and are forced to reboot it every few days.

    I'm unable to put a line break after my details tags, no matter how many line breaks I put in my comment, it smashes it to the next line, so sorry for the formatting.

  5. owenallenaz
    added a commit that references this issue on Jul 24, 2017

    Removes usage of WeakMap() to get believed RSS growth issue nodejs/no…

    dd651b1

  6. bnoordhuis commented on Jul 26, 2017

    @bnoordhuis
    bnoordhuis
    on Jul 26, 2017
    Member

    Thanks, I understand what you mean but I don't think it's a bug but a misunderstanding. In particular, this...

    As I understand, the intent of WeakMap is a storage so that when references go out of scope naturally, they should be garbage collected.

    ...does not necessarily follow. WeakMaps are collected when there is pressure to do so but there is no such pressure in your test case; on my machine it doesn't even use 50% of the max JS heap size.

    If you restrict the heap with --max_old_space_size=256 (256 MB), you see that the GC works much harder and the heap (and RSS) stay much smaller as a result.

    I'm going to close this because it's working as expected. The 5 GB+ you report seeing suggests you may have been storing native objects that neglect to report their real size with v8::Isolate::AdjustAmountOfExternalAllocatedMemory(); e.g., objects created by the mongodb module.

  7. bnoordhuis
    closed this as completedon Jul 26, 2017
  8. bnoordhuis
    added
    invalidIssues and PRs that are invalid.
    on Jul 26, 2017

  9. owenallenaz commented on Jul 26, 2017

    @owenallenaz
    owenallenaz
    on Jul 26, 2017
    Author

    When you say "WeakMaps are collected when there is pressure to do so", is that a feature specific to WeakMaps or is that just how the V8 garbage collector system works for all entities? If it's how it works in general, then that would not explain why my RSS goes down neatly when I use an array instead of a WeakMap(). If it is specific to WeakMap(), then what I would infer from your statement is it's not really wise to use WeakMap() unless also using --max-old-space-size in order to give the gc a better guide of how much memory to use. Is that a valid assumption?

  10. bnoordhuis commented on Jul 26, 2017

    @bnoordhuis
    bnoordhuis
    on Jul 26, 2017
    Member

    It's specific to WeakMaps (and other weak entities), the GC deals with them in a separate post-processing step.

    --max-old-space-size is always a good idea if you have specific ideas about what memory usage should look like. Unless told otherwise, the GC will prefer to grow the heap if it has to vacuum too often. That isn't specific to WeakMaps but maybe it's a little more pronounced with them.

  11. owenallenaz commented on Aug 15, 2017

    @owenallenaz
    owenallenaz
    on Aug 15, 2017
    Author

    This ticket is closed but I wanted to leave this here for posterity sake. We recently deployed a fix to our live environment that did nothing other than remove the WeakMap usage, and our memory growth has dramatically calmed down.

    In the graph below we started the server (running 100 apps) at July 20th which included the WeakMap code. We rebooted it August 1st and 3rd in order to reclaim memory. We deployed the hotfix August 9th that removed WeakMap and we're basically flat since then. Even when the memory was spiked it was only the RSS that was expanded, not the heap, not the old space, just the RSS.

    https://www.screencast.com/t/ZSywpzaom

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    invalidIssues and PRs that are invalid.v8 engineIssues and PRs related to the V8 dependency.

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions