[wasm] emscripten 2.0.21 introduces failure in System.Runtime.Caching.Tests.dll

[radekdoulik]

[23:13:27] info: console.info: Arguments: --run,WasmTestRunner.dll,System.Runtime.Caching.Tests.dll,-notrait,category=IgnoreForCI,-notrait,category=OuterLoop,-notrait,category=failing
[23:13:27] info: console.debug: MONO_WASM: Initializing mono runtime
[23:13:27] info: console.debug: MONO_WASM: ICU data archive(s) loaded, disabling invariant mode
[23:13:27] info: console.debug: mono_wasm_runtime_ready fe00e07a-5519-4dfe-b35a-f867dbaf2e28
[23:13:27] info: console.info: Initializing.....
[23:13:27] info: Discovering: System.Runtime.Caching.Tests.dll (method display = ClassAndMethod, method display options = None)
[23:13:27] info: Discovered:  System.Runtime.Caching.Tests.dll (found 26 of 37 test cases)
[23:13:27] info: Starting:    System.Runtime.Caching.Tests.dll
[23:13:27] fail: [FAIL] MonoTests.System.Runtime.Caching.MemoryCacheTestExpires4.TestCacheShrink
[23:13:27] info: Assert.Equal() Failure
[23:13:27] info: Expected: 6146
[23:13:27] info: Actual:   5326
[23:13:27] info:    at MonoTests.System.Runtime.Caching.MemoryCacheTestExpires4.TestCacheShrink()
[23:13:27] info: --- End of stack trace from previous location ---
[23:13:27] info: Finished:    System.Runtime.Caching.Tests.dll
[23:13:27] info: 
[23:13:27] info: === TEST EXECUTION SUMMARY ===
[23:13:27] info: Total: 26, Errors: 0, Failed: 1, Skipped: 1, Time: 7.480924s
[23:13:27] info: 
[23:13:27] info: Process v8 exited with 1

[ghost]

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

Issue Details

---

[23:13:27] info: console.info: Arguments: --run,WasmTestRunner.dll,System.Runtime.Caching.Tests.dll,-notrait,category=IgnoreForCI,-notrait,category=OuterLoop,-notrait,category=failing
[23:13:27] info: console.debug: MONO_WASM: Initializing mono runtime
[23:13:27] info: console.debug: MONO_WASM: ICU data archive(s) loaded, disabling invariant mode
[23:13:27] info: console.debug: mono_wasm_runtime_ready fe00e07a-5519-4dfe-b35a-f867dbaf2e28
[23:13:27] info: console.info: Initializing.....
[23:13:27] info: Discovering: System.Runtime.Caching.Tests.dll (method display = ClassAndMethod, method display options = None)
[23:13:27] info: Discovered:  System.Runtime.Caching.Tests.dll (found 26 of 37 test cases)
[23:13:27] info: Starting:    System.Runtime.Caching.Tests.dll
[23:13:27] fail: [FAIL] MonoTests.System.Runtime.Caching.MemoryCacheTestExpires4.TestCacheShrink
[23:13:27] info: Assert.Equal() Failure
[23:13:27] info: Expected: 6146
[23:13:27] info: Actual:   5326
[23:13:27] info:    at MonoTests.System.Runtime.Caching.MemoryCacheTestExpires4.TestCacheShrink()
[23:13:27] info: --- End of stack trace from previous location ---
[23:13:27] info: Finished:    System.Runtime.Caching.Tests.dll
[23:13:27] info: 
[23:13:27] info: === TEST EXECUTION SUMMARY ===
[23:13:27] info: Total: 26, Errors: 0, Failed: 1, Skipped: 1, Time: 7.480924s
[23:13:27] info: 
[23:13:27] info: Process v8 exited with 1

Author:	radekdoulik
Assignees:	-
Labels:	arch-wasm, area-Build-mono
Milestone:	-

[radekdoulik]

Looks like this issue was introduced between emscripten 2.0.15 and 2.0.16.

[radekdoulik]

The test fails, because the memory cache is removing cached entries earlier than planned.

It happens through this path:

  info:    at System.Runtime.Caching.MemoryCacheStore.RemoveFromCache(MemoryCacheEntry entry, CacheEntryRemovedReason reason, Boolean delayRelease) in System.Runtme.Caching.dll:token 0x6000155+0x0
  info:    at System.Runtime.Caching.MemoryCacheStore.Remove(MemoryCacheKey key, MemoryCacheEntry entryToRemove, CacheEntryRemovedReason reason) in System.RuntimeCaching.dll:token 0x600015f+0x0
  info:    at System.Runtime.Caching.UsageBucket.FlushUnderUsedItems(Int32 maxFlush, Boolean force) in System.Runtime.Caching.dll:token 0x60000bb+0x0
  info:    at System.Runtime.Caching.CacheUsage.FlushUnderUsedItems(Int32 toFlush) in System.Runtime.Caching.dll:token 0x60000c1+0x0
  info:    at System.Runtime.Caching.MemoryCacheStore.TrimInternal(Int32 percent) in System.Runtime.Caching.dll:token 0x6000161+0x0
  info:    at System.Runtime.Caching.MemoryCache.Trim(Int32 percent) in System.Runtime.Caching.dll:token 0x60000fb+0x0
  info:    at System.Runtime.Caching.MemoryCacheStatistics.CacheManagerThread(Int32 minPercent) in System.Runtime.Caching.dll:token 0x600014f+0x0
  info:    at System.Runtime.Caching.MemoryCacheStatistics.CacheManagerTimerCallback(Object state) in System.Runtime.Caching.dll:token 0x6000144+0x0
  info:    at System.Threading.TimerQueueTimer.CallCallback(Boolean isThreadPool) in System.Private.CoreLib.dll:token 0x6002c2b+0x0
  info:    at System.Threading.TimerQueueTimer.Fire(Boolean isThreadPool) in System.Private.CoreLib.dll:token 0x6002c29+0x0
  info:    at System.Threading.TimerQueueTimer.System.Threading.IThreadPoolWorkItem.Execute() in System.Private.CoreLib.dll:token 0x6002c28+0x0
  info:    at System.Threading.ThreadPoolWorkQueue.Dispatch() in System.Private.CoreLib.dll:token 0x6002bea+0x0
  info:    at System.Threading.ThreadPool.Callback() in System.Private.CoreLib.dll:token 0x600298d+0x0

The cache flushes the entries, because PhysicalMemoryMonitor is reporting high memory pressure. It looks like the GC is reporting wrong MemoryLoadBytes numbers. I am going to look at how do we calculate these on wasm architecture.

[radekdoulik]

We use sysconf to determine available memory size in mono. We call sysconf (_SC_AVPHYS_PAGES) and sysconf (_SC_PAGESIZE) to calculate it.

On wasm, this wasn't working well before (we are ignoring errno and return value of -1). Now emscripten just gives up and reports both JT_PHYS_PAGES and JT_AVPHYS_PAGES as max heap size.

It was changed here:

emscripten-core/emscripten@83d5a15#diff-8de4eb33b0d4bc184e48991bb7cd82dc816f683be8d8eda741561c02fc996f29L204-R211

I also think we have the MemoryLoadBytes calculated wrong in mono, so I opened #53364

That led to calculating the memory pressure as 100% in the PhysicalMemoryMonitor in our case and thus the cache started flushing the entries sooner than the test expected.

[lewing]

sounds like it entirely safe to treat this as an active issue rather than a true regression then.

[radekdoulik]

Yes. I am going to use the ActiveIssue here and also for the filesystem failures. That should make the bump PR complete.

[radekdoulik]

Fixed by #53364