[browser][MT] test GC by pavelsavara · Pull Request #97970 · dotnet/runtime

pavelsavara · 2024-02-05T12:11:54Z

testing GC

ghost · 2024-02-05T12:11:59Z

Tagging subscribers to 'arch-wasm': @lewing
See info in area-owners.md if you want to be subscribed.

Issue Details

null

Author:	pavelsavara
Assignees:	pavelsavara
Labels:	`arch-wasm`, `area-VM-threading-mono`, `os-browser`
Milestone:	9.0.0

pavelsavara · 2024-02-05T13:45:00Z

Something about this leaks like crazy

[STRT] System.Runtime.InteropServices.JavaScript.Tests.WebWorkerTest.VeryLongRunningGC(executor: Main)
dotnet.runtime.js:1296 [MONO] GC_MAJOR_SWEEP: major size: 3456K in use: 713K empty reserved: 0K
dotnet.runtime.js:1296 [MONO] GC_MAJOR: (user request) time 8.26ms, stw 8.29ms los size: 0K in use: 0K
dotnet.native.js:993 GC.GetTotalMemory: 4625048
dotnet.runtime.js:1296 [MONO] GC_MAJOR_SWEEP: major size: 3456K in use: 293K empty reserved: 0K
dotnet.runtime.js:1296 [MONO] GC_MAJOR: (user request) time 6.43ms, stw 6.62ms los size: 262208K in use: 262144K
dotnet.runtime.js:1296 [MONO] GC_MAJOR_SWEEP: major size: 3456K in use: 293K empty reserved: 0K
dotnet.runtime.js:1296 [MONO] GC_MAJOR: (user request) time 3.91ms, stw 3.93ms los size: 262208K in use: 262144K
dotnet.native.js:993 GC.GetTotalMemory: 273061440

....

GC.GetTotalMemory: 1346809184
dotnet.runtime.js:1296 [MONO] GC_MAJOR_SWEEP: major size: 3456K in use: 295K empty reserved: 0K
dotnet.runtime.js:1296 [MONO] GC_MAJOR: (user request) time 3.11ms, stw 3.15ms los size: 1573248K in use: 1572864K
dotnet.runtime.js:1296 [MONO] GC_MAJOR_SWEEP: major size: 3456K in use: 295K empty reserved: 0K
dotnet.runtime.js:1296 [MONO] GC_MAJOR: (user request) time 4.04ms, stw 4.07ms los size: 1573248K in use: 1572864K
dotnet.native.js:993 GC.GetTotalMemory: 1615244656
dotnet.native.js:993 [FAIL] System.Runtime.InteropServices.JavaScript.Tests.WebWorkerTest.VeryLongRunningGC(executor: ThreadPool)
dotnet.native.js:993 System.OutOfMemoryException : Out of memory
dotnet.native.js:993    at System.Runtime.InteropServices.JavaScript.Tests.WebWorkerTest.<>c.<VeryLongRunningGC>b__18_0() in C:\Dev\runtime\src\libraries\System.Runtime.InteropServices.JavaScript\tests\System.Runtime.InteropServices.JavaScript.UnitTests\System\Runtime\InteropServices\JavaScript\WebWorkerTest.cs:line 501
dotnet.native.js:993    at System.Runtime.InteropServices.JavaScript.Tests.Executor.<>c__DisplayClass7_0.<Execute>g__wrapExecute|0() in C:\Dev\runtime\src\libraries\System.Runtime.InteropServices.JavaScript\tests\System.Runtime.InteropServices.JavaScript.UnitTests\System\Runtime\InteropServices\JavaScript\WebWorkerTestHelper.cs:line 161
dotnet.native.js:993    at System.Threading.Tasks.Task`1[[System.Threading.Tasks.Task, System.Private.CoreLib, Version=9.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e]].InnerInvoke() in C:\Dev\runtime\src\libraries\System.Private.CoreLib\src\System\Threading\Tasks\Future.cs:line 501
dotnet.native.js:993    at System.Threading.Tasks.Task.<>c.<.cctor>b__281_0(Object obj) in C:\Dev\runtime\src\libraries\System.Private.CoreLib\src\System\Threading\Tasks\Task.cs:line 2383
dotnet.native.js:993    at System.Threading.ExecutionContext.RunFromThreadPoolDispatchLoop(Thread , ExecutionContext , ContextCallback , Object ) in C:\Dev\runtime\src\libraries\System.Private.CoreLib\src\System\Threading\ExecutionContext.cs:line 264
dotnet.native.js:993 --- End of stack trace from previous location ---
dotnet.native.js:993    at System.Threading.ExecutionContext.RunFromThreadPoolDispatchLoop(Thread , ExecutionContext , ContextCallback , Object ) in C:\Dev\runtime\src\libraries\System.Private.CoreLib\src\System\Threading\ExecutionContext.cs:line 289
dotnet.native.js:993    at System.Threading.Tasks.Task.ExecuteWithThreadLocal(Task& , Thread ) in C:\Dev\runtime\src\libraries\System.Private.CoreLib\src\System\Threading\Tasks\Task.cs:line 2345
dotnet.native.js:993 --- End of stack trace from previous location ---
dotnet.native.js:993    at System.Runtime.InteropServices.JavaScript.Tests.WebWorkerTest.VeryLongRunningGC(Executor executor) in C:\Dev\runtime\src\libraries\System.Runtime.InteropServices.JavaScript\tests\System.Runtime.InteropServices.JavaScript.UnitTests\System\Runtime\InteropServices\JavaScript\WebWorkerTest.cs:line 484
dotnet.native.js:993 --- End of stack trace from previous location ---

lambdageek · 2024-02-05T16:17:07Z

@BrzVlad There's something going on with large object allocations on multi-threaded wasm (and possibly elsewhere).

Two cases:

if size > SGEN_MAX_SMALL_OBJ_SIZE && size <= LOS_SECTION_OBJECT_LIMIT, in this case (for example if we allocate new long[100*1024] the LOS memory management seems to be working properly. We see log messages about collections and the los size stays roughly constant.

if size > LOS_SECTION_OBJECT_LIMIT it looks like we never return the memory to the OS properly or we keep asking for more memory.

on the freeing side, I think we're supposed to end up here

runtime/src/mono/mono/utils/mono-mmap-wasm.c

Lines 168 to 190 in 4eadfbe

    
           mono_vfree (void *addr, size_t length, MonoMemAccountType type) 
        
           { 
        
           	VallocInfo *info = (VallocInfo*)(valloc_hash ? g_hash_table_lookup (valloc_hash, addr) : NULL); 
        
           	if (info) { 
        
           		/* 
        
           		 * We are passed the aligned address in the middle of the mapping allocated by 
        
           		 * mono_valloc_align (), free the original mapping. 
        
           		 */ 
        
           		BEGIN_CRITICAL_SECTION; 
        
           		munmap (info->addr, info->size); 
        
           		END_CRITICAL_SECTION; 
        
           		g_free (info); 
        
           		g_hash_table_remove (valloc_hash, addr); 
        
           	} else { 
        
           		BEGIN_CRITICAL_SECTION; 
        
           		munmap (addr, length); 
        
           		END_CRITICAL_SECTION; 
        
           	} 
        
           	mono_account_mem (type, -(ssize_t)length); 
        
           	return 0;

and then in emscripten's munmap:

https://github.com/emscripten-core/emscripten/blob/aef81424cdd99be99e62f995cbb37248434b8df5/system/lib/libc/emscripten_mmap.c#L52-L93

but what we see is the LOS grows bigger and bigger.
Maybe it's because we do this:

runtime/src/mono/mono/sgen/sgen-los.c

Lines 442 to 459 in 4eadfbe

    
           	sgen_ensure_free_space (size, GENERATION_OLD); 
        
           #ifdef USE_MALLOC 
        
           	obj = g_malloc (size + sizeof (LOSObject)); 
        
           	memset (obj, 0, size + sizeof (LOSObject)); 
        
           #else 
        
           	if (size > LOS_SECTION_OBJECT_LIMIT) { 
        
           		size_t obj_size = size + sizeof (LOSObject); 
        
           		int pagesize = mono_pagesize (); 
        
           		size_t alloc_size = SGEN_ALIGN_UP_TO (obj_size, pagesize); 
        
           		if (sgen_memgov_try_alloc_space (alloc_size, SPACE_LOS)) { 
        
           			obj = (LOSObject *)sgen_alloc_os_memory (alloc_size, (SgenAllocFlags)(SGEN_ALLOC_HEAP | SGEN_ALLOC_ACTIVATE), NULL, MONO_MEM_ACCOUNT_SGEN_LOS); 
        
           			if (obj) { 
        
           				sgen_los_memory_usage_total += alloc_size; 
        
           				obj = randomize_los_object_start (obj, obj_size, alloc_size, pagesize); 
        
           			} 
        
           		} 
        
           	} else {

as far as I can tell this is all fine - I think we pass addr and size of the huge object aligned back to the page sizes so we should be passing exactly the same values that we passed to mono_valloc.

On the allocation side, I think things might be a bit wrong:

does sgen_ensure_free_space always try to reserve some space from the OS even if size is too big? We never end up using the LOS space if the object is bigger than the LOS section size.

https://github.com/dotnet/runtime/blob/main/src/mono/mono/sgen/sgen-los.c#L442-L459

It looks like maybe sgen_ensure_free_space always ends up taking some memory, even if size > LOS_SECTION_OBJECT_LIMIT and we never even use the LOS memory. Is that possible?

pavelsavara · 2024-02-05T16:30:23Z

I pushed simpler repro as src/mono/sample/wasm/browser/Program.cs in this PR

ghost · 2024-02-05T16:34:55Z

Tagging subscribers to this area: @BrzVlad
See info in area-owners.md if you want to be subscribed.

Issue Details

testing GC

Author:	pavelsavara
Assignees:	pavelsavara
Labels:	`arch-wasm`, `area-GC-mono`, `area-VM-threading-mono`, `os-browser`
Milestone:	9.0.0

BrzVlad · 2024-02-05T16:59:34Z

Do I need to do something to test MT ? Or just pass a flag to build and then run the sample normally ?

lambdageek · 2024-02-05T17:25:02Z

@BrzVlad I usually do /build.sh --os browser -c Release /p:MonoWasmBuildVariant=multithread /p:KeepNativeSymbols=true /p:WasmNativeDebugSymbols=true /p:MonoEnableAssertMessages=true

I'm going to try to see if I can repro the problem with the single-threaded runtime or in a osx-arm64 console app, too.

lambdageek · 2024-02-05T18:42:24Z

@BrzVlad I can repro in a console app. I made a new issue #97991

pavelsavara · 2024-02-06T10:46:50Z

@BrzVlad @lambdageek

/p:MonoWasmBuildVariant is no longer a thing. We refactored it and now it's /p:WasmEnableThreads=true

pavelsavara · 2024-02-20T11:33:41Z

Looks OK now, thanks @BrzVlad

info: [STRT] System.Runtime.InteropServices.JavaScript.Tests.WebWorkerTest.VeryLongRunningGC
  info: VeryLongRunningGC 0
  info: GC.GetTotalMemory: 105297488
  info: GC.GetTotalMemory: 105297512
  info: GC.GetTotalMemory: 105297512
  info: GC.GetTotalMemory: 71743064
  info: GC.GetTotalMemory: 71743064
  info: GC.GetTotalMemory: 71743064
  info: GC.GetTotalMemory: 105297512
  info: GC.GetTotalMemory: 105297512
  info: VeryLongRunningGC 1
  info: GC.GetTotalMemory: 172406920
  info: GC.GetTotalMemory: 105298024
  info: GC.GetTotalMemory: 105298024
  info: GC.GetTotalMemory: 105298024
  info: GC.GetTotalMemory: 105298024
  info: GC.GetTotalMemory: 105298024
  info: GC.GetTotalMemory: 105298024
  info: GC.GetTotalMemory: 71743576
  info: VeryLongRunningGC 2
  info: GC.GetTotalMemory: 71743592
  info: GC.GetTotalMemory: 138852488
  info: GC.GetTotalMemory: 138852488
  info: GC.GetTotalMemory: 172406936
  info: GC.GetTotalMemory: 105298040
  info: GC.GetTotalMemory: 71743592
  info: GC.GetTotalMemory: 105298040
  info: VeryLongRunningGC 3
  info: GC.GetTotalMemory: 105297256
  info: GC.GetTotalMemory: 105297256
  info: GC.GetTotalMemory: 71742808
  info: GC.GetTotalMemory: 105297256
  info: GC.GetTotalMemory: 71742808
  info: GC.GetTotalMemory: 71742808
  info: GC.GetTotalMemory: 71742808
  info: VeryLongRunningGC 4
  info: GC.GetTotalMemory: 71742824
  info: GC.GetTotalMemory: 71742824
  info: GC.GetTotalMemory: 71742824
  info: GC.GetTotalMemory: 71742824
  info: GC.GetTotalMemory: 71742824
  info: GC.GetTotalMemory: 71742824
  info: GC.GetTotalMemory: 71742824
  info: VeryLongRunningGC 5
  info: GC.GetTotalMemory: 105297360
  info: GC.GetTotalMemory: 105297360
  info: GC.GetTotalMemory: 71742912
  info: GC.GetTotalMemory: 138851808
  info: GC.GetTotalMemory: 105297360
  info: GC.GetTotalMemory: 105297360
  info: GC.GetTotalMemory: 71742912
  info: VeryLongRunningGC 6

pavelsavara added arch-wasm WebAssembly architecture area-VM-threading-mono os-browser Browser variant of arch-wasm labels Feb 5, 2024

pavelsavara added this to the 9.0.0 milestone Feb 5, 2024

pavelsavara self-assigned this Feb 5, 2024

pavelsavara requested review from lambdageek and maraf February 5, 2024 13:46

This comment was marked as off-topic.

Sign in to view

pavelsavara added area-GC-mono and removed area-VM-threading-mono labels Feb 5, 2024

lambdageek mentioned this pull request Feb 5, 2024

[mono][gc] Objects larger than LOS section size call the LOS heap to grow without bound #97991

Closed

build-analysis bot mentioned this pull request Feb 5, 2024

superpmi replay jobs are failing #97985

Closed

This was referenced Feb 6, 2024

Intermittent build failure in AfterSourceBuild: "Could not write state file" #76488

Open

Tests crashing in CI with no dump: exit code 137 means SIGKILL Killed #97049

Closed

pavelsavara force-pushed the browser_mt_gc_test branch from f60ae69 to 7578f64 Compare February 7, 2024 11:47

build-analysis bot mentioned this pull request Feb 7, 2024

[mt][browser] HttpClient_CancelInDifferentThread failing with operation cancelled #98101

Open

test

5a4e4c9

pavelsavara force-pushed the browser_mt_gc_test branch from 7578f64 to 5a4e4c9 Compare February 20, 2024 11:22

pavelsavara closed this Feb 20, 2024

build-analysis bot mentioned this pull request Feb 20, 2024

[browser][MT] Assert failed: Cannot find Promise for JSHandle -2 #98406

Closed

github-actions bot locked and limited conversation to collaborators Mar 22, 2024

pavelsavara deleted the browser_mt_gc_test branch September 2, 2024 15:34

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[browser][MT] test GC#97970

[browser][MT] test GC#97970
pavelsavara wants to merge 1 commit intodotnet:mainfrom
pavelsavara:browser_mt_gc_test

pavelsavara commented Feb 5, 2024 •

edited

Loading

Uh oh!

ghost commented Feb 5, 2024

Uh oh!

pavelsavara commented Feb 5, 2024

Uh oh!

This comment was marked as off-topic.

lambdageek commented Feb 5, 2024

Uh oh!

pavelsavara commented Feb 5, 2024

Uh oh!

ghost commented Feb 5, 2024

Uh oh!

BrzVlad commented Feb 5, 2024

Uh oh!

lambdageek commented Feb 5, 2024

Uh oh!

lambdageek commented Feb 5, 2024

Uh oh!

pavelsavara commented Feb 6, 2024

Uh oh!

pavelsavara commented Feb 20, 2024

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

3 participants

Conversation

pavelsavara commented Feb 5, 2024 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

ghost commented Feb 5, 2024

Uh oh!

pavelsavara commented Feb 5, 2024

Uh oh!

This comment was marked as off-topic.

lambdageek commented Feb 5, 2024

Uh oh!

pavelsavara commented Feb 5, 2024

Uh oh!

ghost commented Feb 5, 2024

Uh oh!

BrzVlad commented Feb 5, 2024

Uh oh!

lambdageek commented Feb 5, 2024

Uh oh!

lambdageek commented Feb 5, 2024

Uh oh!

pavelsavara commented Feb 6, 2024

Uh oh!

pavelsavara commented Feb 20, 2024

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

3 participants

pavelsavara commented Feb 5, 2024 •

edited

Loading