Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Test failure: Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NeedlessExceptionInMessage #87934

Closed
BruceForstall opened this issue Jun 22, 2023 · 30 comments · Fixed by #88266
Assignees
Labels
arch-x86 area-Extensions-Logging blocking-clean-ci-optional Blocking optional rolling runs Known Build Error Use this to report build issues in the .NET Helix tab os-windows source-generator Indicates an issue with a source generator feature
Milestone

Comments

@BruceForstall
Copy link
Member

BruceForstall commented Jun 22, 2023

Also, Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NotPartial and others also fail, depending on the run.

All on Windows/x86. JitStress is not required. It does seem to require a Checked runtime, and does not fail with a Release runtime.

E.g.,

https://dev.azure.com/dnceng-public/public/_build/results?buildId=317311&view=ms.vss-test-web.build-test-results-tab&runId=6505130&resultId=137246&paneView=debug

  Starting:    Microsoft.Extensions.Logging.Generators.Roslyn4.0.Tests (parallel test collections = on, max threads = 4)
    Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NotPartial [FAIL]
      System.OutOfMemoryException : Insufficient memory to continue the execution of the program.
      Stack Trace:
        /_/src/libraries/System.Private.CoreLib/src/System/Runtime/InteropServices/Marshal.cs(31,0): at System.Runtime.InteropServices.Marshal.AllocHGlobal(Int32 cb)
        /_/src/libraries/System.Reflection.Metadata/src/System/Reflection/Internal/MemoryBlocks/NativeHeapMemoryBlock.cs(32,0): at System.Reflection.Internal.NativeHeapMemoryBlock.DisposableData..ctor(Int32 size)
        /_/src/libraries/System.Reflection.Metadata/src/System/Reflection/Internal/MemoryBlocks/NativeHeapMemoryBlock.cs(62,0): at System.Reflection.Internal.NativeHeapMemoryBlock..ctor(Int32 size)
        /_/src/libraries/System.Reflection.Metadata/src/System/Reflection/Internal/MemoryBlocks/StreamMemoryBlockProvider.cs(71,0): at System.Reflection.Internal.StreamMemoryBlockProvider.ReadMemoryBlockNoLock(Stream stream, Int64 start, Int32 size)
        /_/src/libraries/System.Reflection.Metadata/src/System/Reflection/PortableExecutable/PEReader.cs(190,0): at System.Reflection.PortableExecutable.PEReader..ctor(Stream peStream, PEStreamOptions options, Int32 size)
        /_/src/libraries/System.Reflection.Metadata/src/System/Reflection/PortableExecutable/PEReader.cs(128,0): at System.Reflection.PortableExecutable.PEReader..ctor(Stream peStream, PEStreamOptions options)
           at Microsoft.CodeAnalysis.ModuleMetadata.CreateFromStream(Stream peStream, PEStreamOptions options)
        /_/src/libraries/Common/tests/SourceGenerators/RoslynTestUtils.cs(38,0): at SourceGenerators.Tests.RoslynTestUtils.CreateTestProject(IEnumerable`1 references, Boolean includeBaseReferences, LanguageVersion langVersion)
        /_/src/libraries/Common/tests/SourceGenerators/RoslynTestUtils.cs(159,0): at SourceGenerators.Tests.RoslynTestUtils.RunGenerator(IIncrementalGenerator generator, IEnumerable`1 references, IEnumerable`1 sources, Boolean includeBaseReferences, LanguageVersion langVersion, CancellationToken cancellationToken)
        /_/src/libraries/Microsoft.Extensions.Logging.Abstractions/tests/Microsoft.Extensions.Logging.Generators.Tests/LoggerMessageGeneratorParserTests.cs(947,0): at Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.RunGenerator(String code, Boolean wrap, Boolean inNamespace, Boolean includeBaseReferences, Boolean includeLoggingReferences, CancellationToken cancellationToken)
        /_/src/libraries/Microsoft.Extensions.Logging.Abstractions/tests/Microsoft.Extensions.Logging.Generators.Tests/LoggerMessageGeneratorParserTests.cs(609,0): at Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NotPartial()
        --- End of stack trace from previous location ---

It's not clear when this started happening. The last runtime-coreclr libraries-jitstress pipeline without this failure was https://dev.azure.com/dnceng-public/public/_build/results?buildId=316592&view=results. However, I can repro the failure locally even with this git hash.

{
  "ErrorMessage": "Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NeedlessExceptionInMessage [FAIL]",
  "BuildRetry": false,
  "ErrorPattern": "",
  "ExcludeConsoleLog": false
}

Known issue validation

Build: 🔎 https://dev.azure.com/dnceng-public/public/_build/results?buildId=317311
Result validation: ✅ Known issue matched with the provided build.

Report

Build Definition Test Pull Request
326048 dotnet/runtime Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NotPartial
326002 dotnet/runtime Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NeedlessExceptionInMessage
325506 dotnet/runtime Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NeedlessExceptionInMessage
325428 dotnet/runtime Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.Valid_AdditionalAttributes
324865 dotnet/runtime Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NotPartial
324820 dotnet/runtime Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NeedlessExceptionInMessage
323832 dotnet/runtime Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NeedlessExceptionInMessage #88130
324303 dotnet/runtime Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NeedlessExceptionInMessage
323471 dotnet/runtime Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NotPartial
323384 dotnet/runtime Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NotPartial
323067 dotnet/runtime Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NeedlessExceptionInMessage #88090
322854 dotnet/runtime Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NeedlessExceptionInMessage
321944 dotnet/runtime Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NotPartial
321895 dotnet/runtime Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NotPartial
321311 dotnet/runtime Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NeedlessExceptionInMessage
320380 dotnet/runtime Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NotPartial
320333 dotnet/runtime Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NeedlessExceptionInMessage
320129 dotnet/runtime Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NotPartial
320072 dotnet/runtime Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NeedlessExceptionInMessage
319899 dotnet/runtime Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NotPartial
319891 dotnet/runtime Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NotPartial
319730 dotnet/runtime Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NeedlessExceptionInMessage #87917
319710 dotnet/runtime Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.Valid_AdditionalAttributes
319629 dotnet/runtime Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NotPartial
319175 dotnet/runtime Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NotPartial #87967
319201 dotnet/runtime Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NeedlessExceptionInMessage #87917
318922 dotnet/runtime Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NeedlessExceptionInMessage
318763 dotnet/runtime Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NotPartial
318753 dotnet/runtime Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NeedlessExceptionInMessage
317311 dotnet/runtime Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NotPartial

Summary

24-Hour Hit Count 7-Day Hit Count 1-Month Count
4 29 30
@BruceForstall BruceForstall added JitStress CLR JIT issues involving JIT internal stress modes area-Extensions-Logging labels Jun 22, 2023
@ghost ghost added the untriaged New issue has not been triaged by the area owner label Jun 22, 2023
@ghost
Copy link

ghost commented Jun 22, 2023

Tagging subscribers to this area: @dotnet/area-extensions-logging
See info in area-owners.md if you want to be subscribed.

Issue Details

Also, Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NotPartial

All on Windows/x86 in the runtime-coreclr libraries-pgo pipeline. Seems unrelated to that pipeline, perhaps?

https://dev.azure.com/dnceng-public/public/_build/results?buildId=317311&view=ms.vss-test-web.build-test-results-tab&runId=6505130&resultId=137246&paneView=debug

  Starting:    Microsoft.Extensions.Logging.Generators.Roslyn4.0.Tests (parallel test collections = on, max threads = 4)
    Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NotPartial [FAIL]
      System.OutOfMemoryException : Insufficient memory to continue the execution of the program.
      Stack Trace:
        /_/src/libraries/System.Private.CoreLib/src/System/Runtime/InteropServices/Marshal.cs(31,0): at System.Runtime.InteropServices.Marshal.AllocHGlobal(Int32 cb)
        /_/src/libraries/System.Reflection.Metadata/src/System/Reflection/Internal/MemoryBlocks/NativeHeapMemoryBlock.cs(32,0): at System.Reflection.Internal.NativeHeapMemoryBlock.DisposableData..ctor(Int32 size)
        /_/src/libraries/System.Reflection.Metadata/src/System/Reflection/Internal/MemoryBlocks/NativeHeapMemoryBlock.cs(62,0): at System.Reflection.Internal.NativeHeapMemoryBlock..ctor(Int32 size)
        /_/src/libraries/System.Reflection.Metadata/src/System/Reflection/Internal/MemoryBlocks/StreamMemoryBlockProvider.cs(71,0): at System.Reflection.Internal.StreamMemoryBlockProvider.ReadMemoryBlockNoLock(Stream stream, Int64 start, Int32 size)
        /_/src/libraries/System.Reflection.Metadata/src/System/Reflection/PortableExecutable/PEReader.cs(190,0): at System.Reflection.PortableExecutable.PEReader..ctor(Stream peStream, PEStreamOptions options, Int32 size)
        /_/src/libraries/System.Reflection.Metadata/src/System/Reflection/PortableExecutable/PEReader.cs(128,0): at System.Reflection.PortableExecutable.PEReader..ctor(Stream peStream, PEStreamOptions options)
           at Microsoft.CodeAnalysis.ModuleMetadata.CreateFromStream(Stream peStream, PEStreamOptions options)
        /_/src/libraries/Common/tests/SourceGenerators/RoslynTestUtils.cs(38,0): at SourceGenerators.Tests.RoslynTestUtils.CreateTestProject(IEnumerable`1 references, Boolean includeBaseReferences, LanguageVersion langVersion)
        /_/src/libraries/Common/tests/SourceGenerators/RoslynTestUtils.cs(159,0): at SourceGenerators.Tests.RoslynTestUtils.RunGenerator(IIncrementalGenerator generator, IEnumerable`1 references, IEnumerable`1 sources, Boolean includeBaseReferences, LanguageVersion langVersion, CancellationToken cancellationToken)
        /_/src/libraries/Microsoft.Extensions.Logging.Abstractions/tests/Microsoft.Extensions.Logging.Generators.Tests/LoggerMessageGeneratorParserTests.cs(947,0): at Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.RunGenerator(String code, Boolean wrap, Boolean inNamespace, Boolean includeBaseReferences, Boolean includeLoggingReferences, CancellationToken cancellationToken)
        /_/src/libraries/Microsoft.Extensions.Logging.Abstractions/tests/Microsoft.Extensions.Logging.Generators.Tests/LoggerMessageGeneratorParserTests.cs(609,0): at Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NotPartial()
        --- End of stack trace from previous location ---
Author: BruceForstall
Assignees: -
Labels:

JitStress, area-Extensions-Logging

Milestone: -

@BruceForstall BruceForstall added arch-x86 os-windows and removed untriaged New issue has not been triaged by the area owner labels Jun 22, 2023
@tarekgh
Copy link
Member

tarekgh commented Jun 22, 2023

@BruceForstall

This is an out of memory situation when running under stress environment. This easier infra issue to use a better machine configuration with more memory or the jit-stress serialize or exclude such tests. I don't think there is anything wrong with the test itself.

@tarekgh tarekgh added this to the Future milestone Jun 22, 2023
@tarekgh tarekgh added the needs-author-action An issue or pull request that requires more info or actions from the author. label Jun 22, 2023
@ghost
Copy link

ghost commented Jun 22, 2023

This issue has been marked needs-author-action and may be missing some important information.

@BruceForstall
Copy link
Member Author

@BruceForstall

This is an out of memory situation when running under stress environment. This easier infra issue to use a better machine configuration with more memory or the jit-stress serialize or exclude such tests. I don't think there is anything wrong with the test itself.

I don't recall seeing this before. I'm not sure if something changed in the machine environment, stress modes, CLR VM/librararies, or test itself. I wonder if the test uses significantly more memory under stress or not.

@ghost ghost added needs-further-triage Issue has been initially triaged, but needs deeper consideration or reconsideration and removed needs-author-action An issue or pull request that requires more info or actions from the author. labels Jun 22, 2023
@tarekgh tarekgh removed the needs-further-triage Issue has been initially triaged, but needs deeper consideration or reconsideration label Jun 22, 2023
@tarekgh
Copy link
Member

tarekgh commented Jun 22, 2023

We have had a recent trivial change in this area but shouldn't' cause any more memory allocations in general. I am not sure if something updated in the reflection or interop layer that cause more allocations.

CC @steveharter @jkoritzinsky

@jkoritzinsky
Copy link
Member

We haven't changed anything in interop that would use significantly more memory, especially only in JitStress.

@ghost
Copy link

ghost commented Jun 22, 2023

Tagging subscribers to this area: @dotnet/area-extensions-logging
See info in area-owners.md if you want to be subscribed.

Issue Details

Also, Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NotPartial

All on Windows/x86 in the runtime-coreclr libraries-pgo pipeline. Seems unrelated to that pipeline, perhaps?

https://dev.azure.com/dnceng-public/public/_build/results?buildId=317311&view=ms.vss-test-web.build-test-results-tab&runId=6505130&resultId=137246&paneView=debug

  Starting:    Microsoft.Extensions.Logging.Generators.Roslyn4.0.Tests (parallel test collections = on, max threads = 4)
    Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NotPartial [FAIL]
      System.OutOfMemoryException : Insufficient memory to continue the execution of the program.
      Stack Trace:
        /_/src/libraries/System.Private.CoreLib/src/System/Runtime/InteropServices/Marshal.cs(31,0): at System.Runtime.InteropServices.Marshal.AllocHGlobal(Int32 cb)
        /_/src/libraries/System.Reflection.Metadata/src/System/Reflection/Internal/MemoryBlocks/NativeHeapMemoryBlock.cs(32,0): at System.Reflection.Internal.NativeHeapMemoryBlock.DisposableData..ctor(Int32 size)
        /_/src/libraries/System.Reflection.Metadata/src/System/Reflection/Internal/MemoryBlocks/NativeHeapMemoryBlock.cs(62,0): at System.Reflection.Internal.NativeHeapMemoryBlock..ctor(Int32 size)
        /_/src/libraries/System.Reflection.Metadata/src/System/Reflection/Internal/MemoryBlocks/StreamMemoryBlockProvider.cs(71,0): at System.Reflection.Internal.StreamMemoryBlockProvider.ReadMemoryBlockNoLock(Stream stream, Int64 start, Int32 size)
        /_/src/libraries/System.Reflection.Metadata/src/System/Reflection/PortableExecutable/PEReader.cs(190,0): at System.Reflection.PortableExecutable.PEReader..ctor(Stream peStream, PEStreamOptions options, Int32 size)
        /_/src/libraries/System.Reflection.Metadata/src/System/Reflection/PortableExecutable/PEReader.cs(128,0): at System.Reflection.PortableExecutable.PEReader..ctor(Stream peStream, PEStreamOptions options)
           at Microsoft.CodeAnalysis.ModuleMetadata.CreateFromStream(Stream peStream, PEStreamOptions options)
        /_/src/libraries/Common/tests/SourceGenerators/RoslynTestUtils.cs(38,0): at SourceGenerators.Tests.RoslynTestUtils.CreateTestProject(IEnumerable`1 references, Boolean includeBaseReferences, LanguageVersion langVersion)
        /_/src/libraries/Common/tests/SourceGenerators/RoslynTestUtils.cs(159,0): at SourceGenerators.Tests.RoslynTestUtils.RunGenerator(IIncrementalGenerator generator, IEnumerable`1 references, IEnumerable`1 sources, Boolean includeBaseReferences, LanguageVersion langVersion, CancellationToken cancellationToken)
        /_/src/libraries/Microsoft.Extensions.Logging.Abstractions/tests/Microsoft.Extensions.Logging.Generators.Tests/LoggerMessageGeneratorParserTests.cs(947,0): at Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.RunGenerator(String code, Boolean wrap, Boolean inNamespace, Boolean includeBaseReferences, Boolean includeLoggingReferences, CancellationToken cancellationToken)
        /_/src/libraries/Microsoft.Extensions.Logging.Abstractions/tests/Microsoft.Extensions.Logging.Generators.Tests/LoggerMessageGeneratorParserTests.cs(609,0): at Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NotPartial()
        --- End of stack trace from previous location ---
Author: BruceForstall
Assignees: -
Labels:

arch-x86, os-windows, JitStress, area-Extensions-Logging

Milestone: Future

@BruceForstall
Copy link
Member Author

These tests have failed in multiple runs in the "runtime-coreclr libraries-jitstress" pipeline as well:

https://dev.azure.com/dnceng-public/public/_build/results?buildId=318763&view=ms.vss-test-web.build-test-results-tab

including in the "jitminopts" which disables JIT optimization.

They also have failed in multiple runs of the runtime-coreclr libraries-pgo pipeline:

https://dev.azure.com/dnceng-public/public/_build?definitionId=145&_a=summary

Failures started in the last 2 days.

@BruceForstall
Copy link
Member Author

@stephentoub
Copy link
Member

@stephentoub Could #87904 cause this?

I don't see how it could.

@tarekgh
Copy link
Member

tarekgh commented Jun 23, 2023

The out of memory is happening during creating and building the project for the source generation SourceGenerators.Tests.RoslynTestUtils.CreateTestProject which not really exercising any logging code at that time. Did we have any changes recently on the compiler version we are using in the runtime repo?

@BruceForstall BruceForstall added the blocking-clean-ci-optional Blocking optional rolling runs label Jun 23, 2023
@BruceForstall
Copy link
Member Author

Well, there is this: #87522. I don't know how to read that w.r.t. your question about compiler changes.

@jaredpar Maybe Roslyn related?

@jaredpar
Copy link
Member

This is the SRM layer allocating in response to items in the PE file. That code comes from runtime 😄

This code really hasn't changed recently to my knowledge. It's fairly stable. That particular code path is getting it's size parameters from code within SRM so it's not a place where we're passing incorrect sizes down from Roslyn. My expectation is that if you get a dump here we would see a fairly expected size being passed to AllocHGlobal

@BruceForstall
Copy link
Member Author

This test (5 tests in the assembly, actually) reliably fails for me with out of memory with NO JitStress or tiering configuration variables set with a Release libraries and Checked runtime. With a Release runtime, it passes (and quickly).

@BruceForstall BruceForstall removed the JitStress CLR JIT issues involving JIT internal stress modes label Jun 23, 2023
@BruceForstall BruceForstall added this to the 8.0.0 milestone Jun 24, 2023
@BruceForstall BruceForstall added the untriaged New issue has not been triaged by the area owner label Jun 24, 2023
@jakobbotsch jakobbotsch added the Known Build Error Use this to report build issues in the .NET Helix tab label Jun 24, 2023
@BruceForstall
Copy link
Member Author

The other guess is there is something allocated a lot of native memory causing any other allocations to fail.

It looks like each test (?) allocates about 17MB (loading a PE file from a stream?) and AFAICT, the memory doesn't get deallocated.

It would be good for someone who knows how to debug this managed test to investigate.

@BruceForstall
Copy link
Member Author

@mangod9 This is assigned to area-VM-coreclr. It's creating a lot of noise in the CI.

@mangod9
Copy link
Member

mangod9 commented Jun 29, 2023

I notice that #85738 updated the SRM version in runtime last month. Perhaps the test should be disabled till this can be investigated? Dont believe this belongs in the VM area.

@BruceForstall
Copy link
Member Author

@jaredpar It smells to me like this is a memory leak in the Roslyn source generators tests, or related / called components.

The test doesn't fail with a Release runtime, but it does eat up memory until about 1.1GB before the test completes. With a Checked runtime, it eats up memory until about 1.5GB before tests start to fail. It's certainly possible that Checked Runtimes starting using more memory, changed fragmentation, etc.

This stack trace allocates a lot of memory:

>	System.Reflection.Metadata.dll!System.Reflection.PortableExecutable.PEReader.PEReader(System.IO.Stream peStream, System.Reflection.PortableExecutable.PEStreamOptions options, int size) Line 191	C#
 	System.Reflection.Metadata.dll!System.Reflection.PortableExecutable.PEReader.PEReader(System.IO.Stream peStream, System.Reflection.PortableExecutable.PEStreamOptions options) Line 130	C#
 	Microsoft.CodeAnalysis.dll!Microsoft.CodeAnalysis.ModuleMetadata.CreateFromStream(System.IO.Stream peStream, System.Reflection.PortableExecutable.PEStreamOptions options) Line 133	C#
 	Microsoft.CodeAnalysis.dll!Microsoft.CodeAnalysis.MetadataReference.CreateFromFile(System.IO.Stream peStream, string path, Microsoft.CodeAnalysis.MetadataReferenceProperties properties, Microsoft.CodeAnalysis.DocumentationProvider documentation) Line 76	C#
 	Microsoft.CodeAnalysis.dll!Microsoft.CodeAnalysis.MetadataReference.CreateFromFile(string path, Microsoft.CodeAnalysis.MetadataReferenceProperties properties, Microsoft.CodeAnalysis.DocumentationProvider documentation) Line 71	C#
 	Microsoft.Extensions.Logging.Generators.Roslyn4.0.Tests.dll!SourceGenerators.Tests.RoslynTestUtils.CreateTestProject(System.Collections.Generic.IEnumerable<System.Reflection.Assembly> references, bool includeBaseReferences, Microsoft.CodeAnalysis.CSharp.LanguageVersion langVersion) Line 41	C#
 	Microsoft.Extensions.Logging.Generators.Roslyn4.0.Tests.dll!SourceGenerators.Tests.RoslynTestUtils.RunGenerator(Microsoft.CodeAnalysis.IIncrementalGenerator generator, System.Collections.Generic.IEnumerable<System.Reflection.Assembly> references, System.Collections.Generic.IEnumerable<string> sources, bool includeBaseReferences, Microsoft.CodeAnalysis.CSharp.LanguageVersion langVersion, System.Threading.CancellationToken cancellationToken) Line 159	C#
 	Microsoft.Extensions.Logging.Generators.Roslyn4.0.Tests.dll!Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.RunGenerator(string code, bool wrap, bool inNamespace, bool includeBaseReferences, bool includeLoggingReferences, System.Threading.CancellationToken cancellationToken) Line 947	C#
 	Microsoft.Extensions.Logging.Generators.Roslyn4.0.Tests.dll!Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.DoubleLogLevel_FirstOneSetAsMethodParameter_SecondOneInMessageTemplate_Supported() Line 317	C#

In particular, it frequently allocates 17MB. I never saw the Dispose method called.

Can the Microsoft.CodeAnalysis.dll or Microsoft.Extensions.Logging.Generators.Roslyn4.0.Tests.dll owner please investigate?

cc @jkotas

@jaredpar
Copy link
Member

Can the Microsoft.CodeAnalysis.dll or Microsoft.Extensions.Logging.Generators.Roslyn4.0.Tests.dll owner please investigate?

Believe the Tests owner should investigate here as they're driving the Roslyn behavior here.

@BruceForstall
Copy link
Member Author

Believe the Tests owner should investigate here as they're driving the Roslyn behavior here.

@tarekgh Based on recent changes to src\libraries\Microsoft.Extensions.Logging.Abstractions\tests\Microsoft.Extensions.Logging.Generators.Tests, that would be you?

@tarekgh
Copy link
Member

tarekgh commented Jun 29, 2023

I'll try to take a look but will not be able to do so soon as I am looking at some higher priority stuff and I am off this week. If it is blocking, I suggest disabling the test in the failing scenario for now till we have a chance to look more.

@BruceForstall
Copy link
Member Author

The only way I can think of to disable the test is disable it completely for x86. The number of tests that fail varies, which makes sense as we'll run out of memory at different times.

@BruceForstall
Copy link
Member Author

BruceForstall commented Jun 30, 2023

@ericstj Can you please get someone to disable this test on x86, ASAP?

(btw, I should point out that by "this test" I mean the entire Microsoft.Extensions.Logging.Generators.Roslyn4.0.Tests assembly -- all the tests in this assembly. Because it's not just one or two, but up to 9 or so that I've seen fail)

@tarekgh
Copy link
Member

tarekgh commented Jun 30, 2023

@BruceForstall will try to disable them tomorrow if this can wait to tomorrow.

@ericstj
Copy link
Member

ericstj commented Jun 30, 2023

@ghost
Copy link

ghost commented Jun 30, 2023

Tagging subscribers to this area: @dotnet/area-extensions-logging
See info in area-owners.md if you want to be subscribed.

Issue Details

Also, Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NotPartial and others also fail, depending on the run.

All on Windows/x86. JitStress is not required. It does seem to require a Checked runtime, and does not fail with a Release runtime.

E.g.,

https://dev.azure.com/dnceng-public/public/_build/results?buildId=317311&view=ms.vss-test-web.build-test-results-tab&runId=6505130&resultId=137246&paneView=debug

  Starting:    Microsoft.Extensions.Logging.Generators.Roslyn4.0.Tests (parallel test collections = on, max threads = 4)
    Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NotPartial [FAIL]
      System.OutOfMemoryException : Insufficient memory to continue the execution of the program.
      Stack Trace:
        /_/src/libraries/System.Private.CoreLib/src/System/Runtime/InteropServices/Marshal.cs(31,0): at System.Runtime.InteropServices.Marshal.AllocHGlobal(Int32 cb)
        /_/src/libraries/System.Reflection.Metadata/src/System/Reflection/Internal/MemoryBlocks/NativeHeapMemoryBlock.cs(32,0): at System.Reflection.Internal.NativeHeapMemoryBlock.DisposableData..ctor(Int32 size)
        /_/src/libraries/System.Reflection.Metadata/src/System/Reflection/Internal/MemoryBlocks/NativeHeapMemoryBlock.cs(62,0): at System.Reflection.Internal.NativeHeapMemoryBlock..ctor(Int32 size)
        /_/src/libraries/System.Reflection.Metadata/src/System/Reflection/Internal/MemoryBlocks/StreamMemoryBlockProvider.cs(71,0): at System.Reflection.Internal.StreamMemoryBlockProvider.ReadMemoryBlockNoLock(Stream stream, Int64 start, Int32 size)
        /_/src/libraries/System.Reflection.Metadata/src/System/Reflection/PortableExecutable/PEReader.cs(190,0): at System.Reflection.PortableExecutable.PEReader..ctor(Stream peStream, PEStreamOptions options, Int32 size)
        /_/src/libraries/System.Reflection.Metadata/src/System/Reflection/PortableExecutable/PEReader.cs(128,0): at System.Reflection.PortableExecutable.PEReader..ctor(Stream peStream, PEStreamOptions options)
           at Microsoft.CodeAnalysis.ModuleMetadata.CreateFromStream(Stream peStream, PEStreamOptions options)
        /_/src/libraries/Common/tests/SourceGenerators/RoslynTestUtils.cs(38,0): at SourceGenerators.Tests.RoslynTestUtils.CreateTestProject(IEnumerable`1 references, Boolean includeBaseReferences, LanguageVersion langVersion)
        /_/src/libraries/Common/tests/SourceGenerators/RoslynTestUtils.cs(159,0): at SourceGenerators.Tests.RoslynTestUtils.RunGenerator(IIncrementalGenerator generator, IEnumerable`1 references, IEnumerable`1 sources, Boolean includeBaseReferences, LanguageVersion langVersion, CancellationToken cancellationToken)
        /_/src/libraries/Microsoft.Extensions.Logging.Abstractions/tests/Microsoft.Extensions.Logging.Generators.Tests/LoggerMessageGeneratorParserTests.cs(947,0): at Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.RunGenerator(String code, Boolean wrap, Boolean inNamespace, Boolean includeBaseReferences, Boolean includeLoggingReferences, CancellationToken cancellationToken)
        /_/src/libraries/Microsoft.Extensions.Logging.Abstractions/tests/Microsoft.Extensions.Logging.Generators.Tests/LoggerMessageGeneratorParserTests.cs(609,0): at Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NotPartial()
        --- End of stack trace from previous location ---

It's not clear when this started happening. The last runtime-coreclr libraries-jitstress pipeline without this failure was https://dev.azure.com/dnceng-public/public/_build/results?buildId=316592&view=results. However, I can repro the failure locally even with this git hash.

{
  "ErrorMessage": "Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NeedlessExceptionInMessage [FAIL]",
  "BuildRetry": false,
  "ErrorPattern": "",
  "ExcludeConsoleLog": false
}

Known issue validation

Build: 🔎 https://dev.azure.com/dnceng-public/public/_build/results?buildId=317311
Result validation: ✅ Known issue matched with the provided build.

Report

Build Definition Test Pull Request
325506 dotnet/runtime Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NeedlessExceptionInMessage
325428 dotnet/runtime Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.Valid_AdditionalAttributes
324865 dotnet/runtime Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NotPartial
324820 dotnet/runtime Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NeedlessExceptionInMessage
323832 dotnet/runtime Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NeedlessExceptionInMessage #88130
324303 dotnet/runtime Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NeedlessExceptionInMessage
323471 dotnet/runtime Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NotPartial
323384 dotnet/runtime Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NotPartial
323067 dotnet/runtime Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NeedlessExceptionInMessage #88090
322854 dotnet/runtime Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NeedlessExceptionInMessage
321944 dotnet/runtime Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NotPartial
321895 dotnet/runtime Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NotPartial
321311 dotnet/runtime Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NeedlessExceptionInMessage
320380 dotnet/runtime Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NotPartial
320333 dotnet/runtime Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NeedlessExceptionInMessage
320129 dotnet/runtime Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NotPartial
320072 dotnet/runtime Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NeedlessExceptionInMessage
319899 dotnet/runtime Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NotPartial
319891 dotnet/runtime Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NotPartial
319730 dotnet/runtime Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NeedlessExceptionInMessage #87917
319710 dotnet/runtime Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.Valid_AdditionalAttributes
319629 dotnet/runtime Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NotPartial
319175 dotnet/runtime Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NotPartial #87967
319201 dotnet/runtime Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NeedlessExceptionInMessage #87917
318922 dotnet/runtime Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NeedlessExceptionInMessage
318763 dotnet/runtime Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NotPartial
318753 dotnet/runtime Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NeedlessExceptionInMessage
317311 dotnet/runtime Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NotPartial

Summary

24-Hour Hit Count 7-Day Hit Count 1-Month Count
4 27 28
Author: BruceForstall
Assignees: -
Labels:

arch-x86, os-windows, area-VM-coreclr, untriaged, blocking-clean-ci-optional, area-Extensions-Logging, Known Build Error

Milestone: 8.0.0

@jkotas
Copy link
Member

jkotas commented Jun 30, 2023

In particular, it frequently allocates 17MB. I never saw the Dispose method called.

Missing Dispose is not unusual perf issue with Roslyn and System.Reflection.Metadata APIs. The documentation at https://learn.microsoft.com/en-us/dotnet/api/microsoft.codeanalysis.metadatareference.createfromfile highlights that disposing is important for managing memory footprint.

This needs to be fixed in the test.

@jkoritzinsky
Copy link
Member

Honestly these tests should move to the Roslyn testing SDK instead of setting things up manually. That will solve these sorts of problems and help make these tests easier to maintain.

@tarekgh
Copy link
Member

tarekgh commented Jun 30, 2023

I'll try to take a look later today.

@tarekgh tarekgh removed the untriaged New issue has not been triaged by the area owner label Jun 30, 2023
@ghost ghost added the in-pr There is an active PR which will close this issue when it is merged label Jun 30, 2023
@tarekgh tarekgh added the source-generator Indicates an issue with a source generator feature label Jun 30, 2023
@ghost ghost removed the in-pr There is an active PR which will close this issue when it is merged label Jul 1, 2023
@ghost ghost locked as resolved and limited conversation to collaborators Jul 31, 2023
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
arch-x86 area-Extensions-Logging blocking-clean-ci-optional Blocking optional rolling runs Known Build Error Use this to report build issues in the .NET Helix tab os-windows source-generator Indicates an issue with a source generator feature
Projects
None yet
Development

Successfully merging a pull request may close this issue.

9 participants