Test failure System.Runtime.InteropServices.HandleCollectorTests.TestHandleCollector #66571

Activity

1. VincentBu

   added

   arch-arm64

   area-System.Runtime.InteropServices

   os-windows

   arch-x64

   on Mar 14, 2022
2. ghost added

   untriagedNew issue has not been triaged by the area ownerNew issue has not been triaged by the area owner

   on Mar 14, 2022
4. jkoritzinsky

   added

   JitStressCLR JIT issues involving JIT internal stress modesCLR JIT issues involving JIT internal stress modes

   on Mar 14, 2022
5. jkoritzinsky commented on Mar 15, 2022

   

   jkoritzinsky

   on Mar 15, 2022

   Member

   More actions

   This might not be only JitStress (I'm seeing intermittent repros in some PR failures in the runtime pipeline), but JitStress might be the best way to repro it
6. VincentBu commented on Mar 23, 2022

   

   VincentBu

   on Mar 23, 2022

   ContributorAuthor

   More actions

   Failed again in: runtime-coreclr libraries-jitstress 20220322.1

   Failed test:

   net7.0-windows-Release-x64-CoreCLR_checked-jitstress1_tiered-Windows.10.Amd64.Open
   
   - System.Runtime.InteropServices.HandleCollectorTests.TestHandleCollector
   
   

   Error message:

   High limit handle did not trigger a GC
   Expected: True
   Actual:   False
   
   
   Stack trace
      at System.Runtime.InteropServices.HandleCollectorTests.TestHandleCollector() in /_/src/libraries/System.Runtime.InteropServices/tests/System.Runtime.InteropServices.UnitTests/System/Runtime/InteropServices/HandleCollectorTests.cs:line 144
   
7. adamsitnik commented on Mar 28, 2022

   

   adamsitnik

   on Mar 28, 2022

   Member

   More actions

   Hit again in https://helixre8s23ayyeko0k025g8.blob.core.windows.net/dotnet-runtime-refs-heads-main-d38cf73ba255498fa4/System.Runtime.InteropServices.Tests/1/console.1e36f4c8.log?sv=2019-07-07&se=2022-04-14T09%3A06%3A23Z&sr=c&sp=rl&sig=uDZFbVyRZK5cDOI9bm1CaZmEqIOWIiXmDLL1ex3Ac9M%3D
8. adamsitnik

   added

   blocking-clean-ciBlocking PR or rolling runs of 'runtime' or 'runtime-extra-platforms'Blocking PR or rolling runs of 'runtime' or 'runtime-extra-platforms'

   on Mar 28, 2022
9. lewing commented on Mar 29, 2022

   

   lewing

   on Mar 29, 2022

   Last edited by lewing

   Member

   More actions

   hit again in #67289 https://helixre8s23ayyeko0k025g8.blob.core.windows.net/dotnet-runtime-refs-pull-67289-merge-a849d3ef657e41ec85/System.Runtime.InteropServices.Tests/1/console.ca03e5cf.log?sv=2019-07-07&se=2022-04-18T13%3A35%3A45Z&sr=c&sp=rl&sig=YwnVzH2lC%2Bc4k6tulsxVOwo8M%2FewKh53GBQgbOvLWfc%3D
10. VincentBu commented on Apr 6, 2022

    

    VincentBu

    on Apr 6, 2022

    ContributorAuthor

    More actions

    Failed again in: runtime-coreclr libraries-jitstress 20220405.1

    Failed test:

    net7.0-windows-Release-arm64-CoreCLR_checked-jitstress2-Windows.10.Arm64v8.Open
    
    - System.Runtime.InteropServices.HandleCollectorTests.TestHandleCollector
    
    

    Error message:

    High limit handle did not trigger a GC
    Expected: True
    Actual:   False
    
    
    Stack trace
    
11. kouvel commented on Apr 7, 2022

    

    kouvel

    on Apr 7, 2022

    Contributor

    More actions

    Hit again in https://helixre8s23ayyeko0k025g8.blob.core.windows.net/dotnet-runtime-refs-pull-67160-merge-fce57385286b4acdbd/System.Runtime.InteropServices.Tests/1/console.51df3830.log?sv=2019-07-07&se=2022-04-27T01%3A23%3A31Z&sr=c&sp=rl&sig=HGoNjqy5wdwOJiN%2B4k9dooAvVHHVn7myC2nYC5cshT4%3D
12. VincentBu commented on Apr 14, 2022

    

    VincentBu

    on Apr 14, 2022

    ContributorAuthor

    More actions

    Failed again in: runtime-coreclr libraries-jitstress 20220413.1

    Failed test:

    net7.0-windows-Release-arm64-CoreCLR_checked-zapdisable-Windows.10.Arm64v8.Open
    
    - System.Runtime.InteropServices.HandleCollectorTests.TestHandleCollector
    
    

    Error message:

    High limit handle did not trigger a GC
    Expected: True
    Actual:   False
    
    
    Stack trace
       at System.RuntimeMethodHandle.InvokeMethod(Object target, Void** arguments, Signature sig, Boolean isConstructor)
       at System.Reflection.RuntimeMethodInfo.InvokeNonEmitUnsafe(Object obj, IntPtr* arguments, Span`1 argsForTemporaryMonoSupport, BindingFlags invokeAttr)
    
13. 2 remaining items

    Load more
14. ghost added

    in-prThere is an active PR which will close this issue when it is mergedThere is an active PR which will close this issue when it is merged

    on Apr 20, 2022
15. AaronRobinsonMSFT

    closed this as completedin #68285on Apr 20, 2022
16. ghost removed

    in-prThere is an active PR which will close this issue when it is mergedThere is an active PR which will close this issue when it is merged

    on Apr 20, 2022
17. elinor-fung commented on Apr 26, 2022

    

    elinor-fung

    on Apr 26, 2022

    Member

    More actions

    @AaronRobinsonMSFT it looks like this is still happening

    System.Runtime.InteropServices.HandleCollectorTests.TestHandleCollector [FAIL]
          High limit handle did not trigger a GC: 21 < 21
          Expected: True
          Actual:   False
          Stack Trace:
    

    Console log

    13 hits in the past five days after #68285 went in: https://runfo.azurewebsites.net/search/tests/?q=started%3A%7E5+definition%3Aruntime+name%3ATestHandleCollector
18. AaronRobinsonMSFT commented on Apr 26, 2022

    

    AaronRobinsonMSFT

    on Apr 26, 2022

    Member

    More actions

    @elinor-fung Thanks for keeping an eye on this. The new logging is very interesting. Based on the above log output there is something odd going on here. The HighLimitSize is hardcoded to 100000 so I would expect there to always be at least 1 additional collected object, but clearly that is not occurring under some scenario. I can think of three possible scenarios, others are welcome.

    1. The "High limit" loop wasn't run. The JIT elided it entirely or some other optimization caused it to not execute any iterations.

    runtime/src/libraries/System.Runtime.InteropServices/tests/System.Runtime.InteropServices.UnitTests/System/Runtime/InteropServices/HandleCollectorTests.cs

    Lines 141 to 145 in 2ea67f1

    	HandleCollector highLimitCollector = new HandleCollector("HighLimit.Collector", HighLimitSize);
    	for (int i = 0; i < HighLimitSize + 10; ++i)
    	{
    	HandleLimitTester hlt = new HandleLimitTester(highLimitCollector);
    	}

    2. The GC didn't allocate new memory for each iteration for some reason and reused existing object instances. This could mean the "collected" count didn't change - I don't know if that is possible.

    3. Some combination of (1) and (2) around a JIT optimization and the GC doing what it is told that changes how this is expected to run.

    The ctor for HandleLimitTester is doing all the right things in my mind:

    runtime/src/libraries/System.Runtime.InteropServices/tests/System.Runtime.InteropServices.UnitTests/System/Runtime/InteropServices/HandleCollectorTests.cs

    Lines 160 to 165 in 2ea67f1

    	internal HandleLimitTester(HandleCollector collector)
    	{
    	_collector = collector;
    	_collector.Add();
    	GC.KeepAlive(this);
    	}

    I'm not really sure what is occurring, and I've been unable to reproduce this locally under any DOTNET_ variable combination. Perhaps @jkotas or @Maoni0 could help educate me on what could be happening here.
19. AaronRobinsonMSFT

    reopened this on Apr 26, 2022
20. jkotas commented on Apr 26, 2022

    

    jkotas

    on Apr 26, 2022

    Member

    More actions

    This test can be running together with all other System.Runtime.InteropServices tests. Those other tests can be allocating and triggering GCs (ie altering the global state that this test asserts are based on). Is the logic of the test robust against that?
21. AaronRobinsonMSFT commented on Apr 26, 2022

    

    AaronRobinsonMSFT

    on Apr 26, 2022

    Member

    More actions

    Yes, I believe so. All we are attempting to validate is that the sum of GC.CollectionCount(0) + GC.CollectionCount(1) + GC.CollectionCount(2) after the above loop is greater than the same computed sum before the loop. The test is arguably not that useful in a situation where multiple tests are running so it is odd that it fails at all since we simply need 1 additional object to be collected for the test to pass.

    Let me confirm again the logic in HandleCollector.Add() and confirm that GC.Collect() will be called more than once.
22. VincentBu commented on Apr 28, 2022

    

    VincentBu

    on Apr 28, 2022

    ContributorAuthor

    More actions

    Failed again in: runtime-coreclr libraries-jitstress 20220427.1

    Failed test:

    net7.0-windows-Release-arm64-CoreCLR_checked-jitminopts-Windows.10.Arm64v8.Open
    
    - System.Runtime.InteropServices.HandleCollectorTests.TestHandleCollector
    
    

    Error message:

    High limit handle did not trigger a GC: 41 < 41
    Expected: True
    Actual:   False
    
    
    Stack trace
       at System.Runtime.InteropServices.HandleCollectorTests.TestHandleCollector() in /_/src/libraries/System.Runtime.InteropServices/tests/System.Runtime.InteropServices.UnitTests/System/Runtime/InteropServices/HandleCollectorTests.cs:line 153
       at System.RuntimeMethodHandle.InvokeMethod(Object target, Void** arguments, Signature sig, Boolean isConstructor)
       at System.Reflection.RuntimeMethodInfo.InvokeNonEmitUnsafe(Object obj, IntPtr* arguments, Span`1 argsForTemporaryMonoSupport, BindingFlags invokeAttr) in /_/src/coreclr/System.Private.CoreLib/src/System/Reflection/RuntimeMethodInfo.CoreCLR.cs:line 383
    
23. AaronRobinsonMSFT commented on Apr 28, 2022

    

    AaronRobinsonMSFT

    on Apr 28, 2022

    Member

    More actions

    I finally see what is going on here. This is a classic lack of memory pressure and the GC is making the right call and saying: "leave me alone". I am working on a fix to provide the needed pressure.
24. ghost added

    in-prThere is an active PR which will close this issue when it is mergedThere is an active PR which will close this issue when it is merged

    on Apr 28, 2022
25. AaronRobinsonMSFT

    closed this as completedin #68652on Apr 29, 2022
26. ghost removed

    in-prThere is an active PR which will close this issue when it is mergedThere is an active PR which will close this issue when it is merged

    on Apr 29, 2022
27. jeffhandley

    removed

    untriagedNew issue has not been triaged by the area ownerNew issue has not been triaged by the area owner

    on May 6, 2022
28. ghost locked as resolved and limited conversation to collaborators on Jun 5, 2022