problems with GC memory reclamation on wpe 2.38

[tomasz-karczewski-red]

Hello,

On our platform (LGI boxes, ARM / Broadcom soc, e,g BCM72180, and other Broadcom platforms we have) we are experiencing the issue where sometimes wpe GC seems to not able to reclaim the memory after exiting some of the heavier web apps. Some example are Sky apps:

https://stv.prd.sky.ch/store/
https://stv.prd.sky.ch/show/

but similar effect could be observed e.g. with Apple TV+ (https://atve.tv.apple.com/94819831-5404-4438-810e-afb648d6a826/tvw_0e7f0489b969451a9f79941a0d18fad1/). These apps normally needs more than 200MB to work, and we have a container cgroup limit of 550MB, so when the memory is not reclaimed quickly enough, wpe gets killed.

Often when these applications exit, I can see that even after GC Full Collection (seen with JSC_logGC=1) the memory is still not reclaimed. Like here - GC was run, spent quite a lot of time, visited a lot of memory, but still wasn't able to release much ('Full sweep: 142348kb => 141164kb')

Jul 09 10:00:19 E0B7B1-APLSTB-300037462300 wpe.sh[13290]: [GC<0x8aff5050>: START M 142134kb => FullCollection, v=0kb (C:0 M:0 P1:0) o=0 b=15866 i#1:N<CsMsrShDMsm(0)> 1+0 v=109974kb (C:55860 M:0 P1:54113) o=11 b=15866 i#2:N 366+0 v=109990kb (C:55872 M:0 P1:54118) o=13 b=15866 i#3:P 0+0 v=109990kb (C:55872 M:0 P1:54118) o=13 b=15866 i#4:P<WsOJwMsrShCsMsm(0)DDomoCb> => 120237kb, p=2353.949000ms (max 2353.949000), cycle 2353.843000ms END]
Jul 09 10:00:19 E0B7B1-APLSTB-300037462300 wpe.sh[13290]: GC END!
Jul 09 10:00:19 E0B7B1-APLSTB-300037462300 wpe.sh[13290]: [GC<0x8aff5050>: finalize 49.610000ms]
1720512019 209
Jul 09 10:00:19 E0B7B1-APLSTB-300037462300 wpe.sh[13290]: [GC<0x8aff5050>: Full sweep: 142348kb => 141164kb, 78.841000ms]

In our setup, each time we leave any app, we return to metro '#boot' (https://widgets.metrological.com/lightning/liberty/2e3c4fc22f0d35e3eb7fdb47eb7d4658#boot). This 'application' is pretty small, and normally uses maybe 20MB of ram. But even when we wait for some time and then browse to some other webapp - the memory often is not released, keeps on piling up, and so we run OOM after several iterations.

I've tried with some upstream changes, like this one:

#1285

Also tried some additional modifications to GC process, like here:

LibertyGlobal@ab127e3

(for example I've modified Source/bmalloc/bmalloc/AvailableMemory.cpp to check for WPE_RAM_SIZE when determining available memory; we are running wpe in lxc container, so there are different limits that what sysinfo returns I believe. but this doesn't seem to fix the problem by itself; also - I've enabled some bmalloc verbose flags & from what I've seen it doesn't seem that bmalloc is to be blamed here)

I was also checking out many JSC options, like:

JSC_forceRAMSize=576716800
JSC_mediumHeapGrowthFactor=1.1
JSC_smallHeapGrowthFactor=1.1
JSC_largeHeapGrowthFactor=1.1
JSC_smallHeapRAMFraction=0.25
JSC_mediumHeapRAMFraction=0.5
JSC_customFullGCCallbackBailThreshold=1.0
JSC_maximumMutatorUtilization=0.6
JSC_minimumGCPauseMS=1
JSC_useStochasticMutatorScheduler=false
JSC_gcIncrementScale=1
JSC_criticalGCMemoryThreshold=0.5
JSC_forceDidDeferGCWork=true
JSC_useGlobalGC=true

Some of these sometimes seem to help for a while, but then - the app runs into the same problem.

I've also added some logic (on thunder plugin side) to force GC in regular intervals after the application returns to #boot app (via webkit_web_context_garbage_collect_javascript_objects that ends up calling WebProcess::garbageCollectJavaScriptObjects); this generally helps, but even this is not 100% reliable. Even if this sometimes makes the situation better, at times I still run into the scenario when the app memory is not reclaimed, even when GC is invoked manually from the inspector (via $vm.gc(), if enabled via JSC_enableDollarVM=true). This behavior seems a bit random - for example it might start working fine after the reboot. I've checked wpe 2.22, and didn't observe these issues; memory is reclaimed pretty quickly when I leave the app.

Looking into web inspector / Timelines / memory tab, I see that most of this 'unreclaimable' memory is still counted as 'JavaScript' - in line with what I can see in the GC run results.

So for example, on our platform, the memory graph for 2.22 versus 2.38 compares like this:

for 2.22: see attached wpe-2.22-graph.png

for 2.38: see attached wpe-2.38-graph,png

So while 2.22 was running the test scenario just fine, 2.38 OOMed pretty quickly.

I've tried similar test on wpe 2.38 with different platform, the 'Video Accelerator' (https://rdkcentral.com/rdk-video-accelerator). Here, there are no containers, but when I check the WPEWebProcess Rss memory after exiting these apps, I see something like this: (checked after each iteration of 'enter the app - exit to #boot')

RssAnon: 14580 kB
RssAnon: 14580 kB
RssAnon: 211136 kB
RssAnon: 215216 kB
RssAnon: 67124 kB
RssAnon: 228000 kB
RssAnon: 228052 kB
RssAnon: 236304 kB
RssAnon: 381584 kB
RssAnon: 234400 kB
RssAnon: 234400 kB
RssAnon: 235620 kB

So sometimes the memory gets cleaned up, sometimes - keeps on piling up. With our 550MB memory limit, 381584 kB in idle state might be enough to run into OOM when we try to start eg. Sky Store app.

Do you have some clues what could cause the difference in GC behaviour in 2.38, maybe there are some other config options we are not aware of?

[justinmichaud]

Hi Tomasz,

Sorry for the delay. I have been struggling to get a WPE build working on a rpi remotely all last week, but my pi finally arrived in the mail today so I should be able to reproduce this tomorrow.

I have tried unsuccessfully to reproduce this on desktop with PSON (process swap on navigation) disabled, but I will try a few more configurations.

I am curious though; why does wpe navigate in the same process? This is not an area that I am at all familiar with. My intuition is that this would be faster, and also reduce memory fragmentation, without too much memory overhead.

[tomasz-karczewski-red]

hello @justinmichaud,
Sorry for the late update, I was on the vacation. Regarding PSON - yes, we do not seem to be using that; I'll investigate why & if that is possible to test in our setup.

[tomasz-karczewski-red]

I was able to get a heap snapshot ('gcdebugging') type, it's here:

snapshot-leak-gddebugging.json.z01.txt

snapshot-leak-gddebugging.json.zip.txt

(Had to split the zip file - too big for github - and add '.txt' suffixes to upload - github doesn't accept 'z01' files)

Once unzipped, it is possible to open that file in web inspector; it is visible that the heap still contains the objects referencing both pages that I've visited ('https://stv.prd.sky.ch/store/' and 'https://widgets.metrological.com/lightning/liberty/2e3c4fc22f0d35e3eb7fdb47eb7d4658#boot).

Also, curiously, web inspector shows the Window objects that seem to be connected to both these pages (and 3 more):

I've reformatted the GC roots information from this heap, it is here:

snapshot-leak-gddebugging.rootsinfo.json

Again, the heap seems to contain GC roots that reference both old & new pages.

[tomasz-karczewski-red]

also, regarding PSON - this seems to be disabled by default on wpe:

WPEWebKit/Source/WebKit/UIProcess/API/glib/WebKitWebContext.cpp

Line 427 in 59d63a5

configuration.setProcessSwapsOnNavigation(false);

[tomasz-karczewski-red]

One more update, regarding our platform - it might not be obvious from the description, but this is 32 bit arm (armv7l)

cat /proc/cpuinfo
processor : 0
model name : ARMv7 Processor rev 0 (v7l)
BogoMIPS : 54.00
Features : half thumb fastmult vfp edsp neon vfpv3 tls vfpv4 idiva idivt vfpd32 lpae evtstrm aes pmull sha1 sha2 crc32
CPU implementer : 0x42
CPU architecture: 7
CPU variant : 0x0
CPU part : 0x100
CPU revision : 0

processor : 1
model name : ARMv7 Processor rev 0 (v7l)
BogoMIPS : 54.00
Features : half thumb fastmult vfp edsp neon vfpv3 tls vfpv4 idiva idivt vfpd32 lpae evtstrm aes pmull sha1 sha2 crc32
CPU implementer : 0x42
CPU architecture: 7
CPU variant : 0x0
CPU part : 0x100
CPU revision : 0

processor : 2
model name : ARMv7 Processor rev 0 (v7l)
BogoMIPS : 54.00
Features : half thumb fastmult vfp edsp neon vfpv3 tls vfpv4 idiva idivt vfpd32 lpae evtstrm aes pmull sha1 sha2 crc32
CPU implementer : 0x42
CPU architecture: 7
CPU variant : 0x0
CPU part : 0x100
CPU revision : 0

processor : 3
model name : ARMv7 Processor rev 0 (v7l)
BogoMIPS : 54.00
Features : half thumb fastmult vfp edsp neon vfpv3 tls vfpv4 idiva idivt vfpd32 lpae evtstrm aes pmull sha1 sha2 crc32
CPU implementer : 0x42
CPU architecture: 7
CPU variant : 0x0
CPU part : 0x100
CPU revision : 0

Hardware : Broadcom STB (Flattened Device Tree)
Revision : 0000
Serial : 0000000000000000

[justinmichaud]

Hey! No worries, I just got back from vacation myself. I am still working on this, but getting an armv7 setup working is proving to be challenging.

In the meantime, I have been trying to do some investigation on the desktop port. I would like to be able to log where the roots are coming from without WebInspector, because it can keep some things alive. I am also trying to find a way to manually trigger the memory pressure handler.

Does this issue reproduce on 64-bit builds for you?

[tomasz-karczewski-red]

hello,

to log where the roots are coming from without WebInspector

fwiw, I achieved something like this by directly calling GCController::singleton().dumpHeap() via WebProcess::garbageCollectJavaScriptObjects, which can be invoked from wpe thunder plugin in our integration. I also needed to modify HeapSnapshotBuilder.cpp to dump directly to the file, otherwise it will quickly require a lot of memory (json StringBuffer resizes exponentially)

Does this issue reproduce on 64-bit builds

I haven't tested that on 64 bit builds. I could probably try on my desktop with x86_64, but what exact setup would you suggest? wpe 2.38 with the cog (https://github.com/Igalia/cog) application?

[justinmichaud]

Don't worry, I thought maybe you may have had a 64-bit device handy running the same WPE build and software stack handy, since that would reduce a number of variables. I'll try to reproduce this on desktop too.

[tomasz-karczewski-red]

Hello,

I've been doing some investigation of this issue in parallel, and though I'd share what I've seen so far. Since the web inspector is rather underwhelming when it comes to analysing the heap dumps, I've prepared a small tool myself (see nodereader-networkx.py attached). And did following test, typical of our application flow:

1. start wpe
2. navigate to https://widgets.metrological.com/lightning/liberty/2e3c4fc22f0d35e3eb7fdb47eb7d4658#boot
3. navigate to https://tv.playsuisse.ch/, finish page loading
4. navigate back to https://widgets.metrological.com/lightning/liberty/2e3c4fc22f0d35e3eb7fdb47eb7d4658#boot
5. full GC forced (4 times)
6. navigate to https://stv.prd.sky.ch/store/, finish page loading
7. navigate back to https://widgets.metrological.com/lightning/liberty/2e3c4fc22f0d35e3eb7fdb47eb7d4658#boot
8. full GC forced (4 times)

And after that, I took a heap (gcdebugging type) snapshot.

With the help of this python tool (using 'node_by_class Window command') I can see that there are multiple Window objects; the most recent one still has proper 'Label' with the latest url; the old ones have 'about:blank' labels (but still exist, and via some links, they can be connected to these previously visited apps). Something like this:

Enter node id: node_by_class Window
NodeID: 4524649 Size: 2377 ClassName: 'Window' Flags: 0 Label: 'about:blank' Cell: 0x77184000 Wrapped: 0x0 ROOT: None Reason: None Reachibility: None
NodeID: 2509240 Size: 2377 ClassName: 'Window' Flags: 0 Label: 'https://widgets.metrological.com/lightning/liberty/2e3c4fc22f0d35e3eb7fdb47eb7d4658#boot' Cell: 0x771862c0 Wrapped: 0x0 ROOT: None Reason: None Reachibility: None
NodeID: 2460729 Size: 2428 ClassName: 'Window' Flags: 0 Label: 'https://widgets.metrological.com/lightning/liberty/2e3c4fc22f0d35e3eb7fdb47eb7d4658#boot' Cell: 0x77186b70 Wrapped: 0x0 ROOT: None Reason: None Reachibility: None
NodeID: 2514486 Size: 2377 ClassName: 'Window' Flags: 0 Label: 'https://widgets.metrological.com/lightning/liberty/2e3c4fc22f0d35e3eb7fdb47eb7d4658#boot' Cell: 0x77187420 Wrapped: 0x0 ROOT: None Reason: None Reachibility: None
NodeID: 2645150 Size: 2387 ClassName: 'Window' Flags: 0 Label: 'about:blank' Cell: 0x78e1f238 Wrapped: 0x0 ROOT: None Reason: None Reachibility: None
NodeID: 4526513 Size: 2377 ClassName: 'Window' Flags: 0 Label: 'about:blank' Cell: 0x78e5d038 Wrapped: 0x0 ROOT: None Reason: None Reachibility: None
NodeID: 2642737 Size: 2442 ClassName: 'Window' Flags: 0 Label: 'about:blank' Cell: 0x78ec3038 Wrapped: 0x0 ROOT: None Reason: None Reachibility: None
NodeID: 2575714 Size: 2387 ClassName: 'Window' Flags: 0 Label: 'about:blank' Cell: 0x7e812038 Wrapped: 0x0 ROOT: None Reason: None Reachibility: None
NodeID: 2474901 Size: 35 ClassName: 'Window' Flags: 0 Label: '' Cell: 0x822b7280 Wrapped: 0x0 ROOT: None Reason: None Reachibility: None
NodeID: 4526306 Size: 17 ClassName: 'Window' Flags: 0 Label: '' Cell: 0x84bc1f60 Wrapped: 0x0 ROOT: None Reason: None Reachibility: None
NodeID: 4497882 Size: 17 ClassName: 'Window' Flags: 0 Label: '' Cell: 0x84bc2120 Wrapped: 0x0 ROOT: None Reason: None Reachibility: None
NodeID: 4527500 Size: 17 ClassName: 'Window' Flags: 0 Label: '' Cell: 0x84bc22e0 Wrapped: 0x0 ROOT: None Reason: None Reachibility: None
NodeID: 2514187 Size: 17 ClassName: 'Window' Flags: 0 Label: '' Cell: 0x84bc2990 Wrapped: 0x0 ROOT: None Reason: None Reachibility: None
NodeID: 2474910 Size: 17 ClassName: 'Window' Flags: 0 Label: '' Cell: 0x84bc2b50 Wrapped: 0x0 ROOT: None Reason: None Reachibility: None
NodeID: 2518349 Size: 17 ClassName: 'Window' Flags: 0 Label: '' Cell: 0x84bc2d10 Wrapped: 0x0 ROOT: None Reason: None Reachibility: None
NodeID: 2655961 Size: 17 ClassName: 'Window' Flags: 0 Label: '' Cell: 0x84bc33c0 Wrapped: 0x0 ROOT: None Reason: None Reachibility: None
NodeID: 2584279 Size: 17 ClassName: 'Window' Flags: 0 Label: '' Cell: 0x84bc38c0 Wrapped: 0x0 ROOT: None Reason: None Reachibility: None
NodeID: 2640999 Size: 17 ClassName: 'Window' Flags: 0 Label: '' Cell: 0x84bc3ed0 Wrapped: 0x0 ROOT: None Reason: None Reachibility: None
NodeID: 2461886 Size: 2467 ClassName: 'Window' Flags: 0 Label: 'about:blank' Cell: 0xab878938 Wrapped: 0x0 ROOT: None Reason: None Reachibility: None
Enter node id: 2645150
NodeID: 2645150 Size: 2387 ClassName: 'Window' Flags: 0 Label: 'about:blank' Cell: 0x78e1f238 Wrapped: 0x0 ROOT: None Reason: None Reachibility: None
Enter node id: 2460729
NodeID: 2460729 Size: 2428 ClassName: 'Window' Flags: 0 Label: 'https://widgets.metrological.com/lightning/liberty/2e3c4fc22f0d35e3eb7fdb47eb7d4658#boot' Cell: 0x77186b70 Wrapped: 0x0 ROOT: None Reason: None Reachibility: None

Taking a look at the root objects that are holding these Window objects ('closest_root_paths $window_object_node_id' command), it seems that these old (not the latest) Window object are mostly held by root paths that look like this:

(4523988 class 'TextTrack' label 'url https://tv.playsuisse.ch/Landing' cell 0x79675c98(0xab95d3f8) ROOT) -> [0/na] -> (4523988 class 'Structure' label 'TextTrack' cell 0x7a0b62b0(0x0)) -> [0/na] -> (4523988 class 'Window' label 'about:blank' cell 0x7e812038(0x0))

(4523988 class 'CSSStyleDeclaration' label 'url https://tv.playsuisse.ch/Landing' cell 0x7a0d45e0(0xab938294) ROOT) -> [0/na] -> (4523988 class 'Structure' label 'CSSStyleDeclaration' cell 0x7a0d8c30(0x0)) -> [0/na] -> (4523988 class 'Window' label 'about:blank' cell 0x7e812038(0x0))

• so generally 'class X -> Structure of class X -> Window' path. This Window objects seem to correspond to 'global object' (eg. looking at the code in JSWindowProxy::setWindow - 'JSDOMGlobalObject *window = JSDOMWindow::create ... ASSERT(window->globalObject() == window') )

I've looked into Source/JavaScriptCore/runtime/Structure.cpp / Structure::visitChildrenImpl; during GC it is indeed visiting m_globalObject, guess that's where the GC link comes from. I've actually tried to comment this part out, like:

template
void Structure::visitChildrenImpl(JSCell* cell, Visitor& visitor)
...
#if 0
visitor.append(thisObject->m_globalObject);
#endif

• and then these 'class X -> structure X -> Window' paths disappear, but the Window objects are still not GC'd and instead I get longer paths via Function object, generally similar to:

(3793819 class 'CSSStyleDeclaration' label 'url https://stv.prd.sky.ch/store/' cell 0x764c7520(0xab9144c4) ROOT) -> [0/na] -> (1934867 class 'Structure' label 'CSSStyleDeclaration' cell 0x82263520(0x0)) -> [0/na] -> (1922666 class 'CSSStyleDeclaration' label '' cell 0x84bc3c30(0x0)) -> [1/setProperty] -> (1926559 class 'Function' label 'setProperty' cell 0x7e2b4be0(0x0)) -> [0/na] -> (1913906 class 'Window' label 'about:blank' cell 0xab8d8038(0x0))

so, now it's like 'class X -> structure of class X -> class X again (but some different cell/object now?) -> some Function (like, 'setProperty' here) -> Window'

Don't know how to get rid of this 'Function' link. It seems that this global object / Window instances are held locally, while this global object actually changes when you navigate (right?)

Attaching this new gc debugging snapshot (5-snapshot-then-exited-sstore.json), it should be possible to look into it with this helper tool I've attached.
5-snapshot-then-exited-sstore.json.zip.txt
5-snapshot-then-exited-sstore.json.z01.txt
5-snapshot-then-exited-sstore.json.z02.txt
nodereader-networkx.py.txt

[justinmichaud]

(4523988 class 'TextTrack' label 'url https://tv.playsuisse.ch/Landing' cell 0x79675c98(0xab95d3f8) ROOT)

That looks suspicious! Why is this a root? I'll investigate, but this seems like the culprit.

Just an update: I fixed a bug in WebInspector so linux users can actually load heap dumps now. This python tool is super helpful, thanks!

Separately, I created a way to manually trigger the memory pressure handler, which does free up some of the memory. I think this might be related to a different issue we were experiencing with MotionMark.

[justinmichaud]

Weak references now display the correct root marking reason. Weak references shouldn't be marked unless they are still reachable, so I am trying to see why these weak references are reachable. It is unfortunate that they make it harder to see where the "true" root is coming from.

I have made a little script that exports the heap snapshot to graphml, and I am opening it in Gephi. I will see if I can see any interesting structure