search

dotnet / runtime

.NET is a cross-platform runtime for cloud, mobile, desktop, and IoT apps.
https://docs.microsoft.com/dotnet/core/
MIT License
15.07k stars 4.69k forks source link

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

Closed BruceForstall closed 1 year ago

BruceForstall commented 1 year ago

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: :mag_right: https://dev.azure.com/dnceng-public/public/_build/results?buildId=317311 Result validation: :white_check_mark: 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 dotnet/runtime#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 dotnet/runtime#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 dotnet/runtime#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 dotnet/runtime#87967
319201 dotnet/runtime Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NeedlessExceptionInMessage dotnet/runtime#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
ghost commented 1 year ago

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: -
tarekgh commented 1 year ago

@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.

ghost commented 1 year ago

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

BruceForstall commented 1 year ago

@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.

tarekgh commented 1 year ago

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 commented 1 year ago

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

ghost commented 1 year ago

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 commented 1 year ago

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 commented 1 year ago

Presumably these are the changes:

https://dev.azure.com/dnceng-public/public/_traceability/runview/changes?currentRunId=318154

@stephentoub Could https://github.com/dotnet/runtime/pull/87904 cause this?

stephentoub commented 1 year ago

@stephentoub Could https://github.com/dotnet/runtime/pull/87904 cause this?

I don't see how it could.

tarekgh commented 1 year ago

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 commented 1 year ago

Well, there is this: https://github.com/dotnet/runtime/pull/87522. I don't know how to read that w.r.t. your question about compiler changes.

@jaredpar Maybe Roslyn related?

jaredpar commented 1 year ago

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 commented 1 year ago

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).

tarekgh commented 1 year ago

I changed the label to the VM as looks the issue happen when switching to the checked runtime. @BruceForstall if your repo this reliably, it will be good to create a full dump when the issue happens. The other guess is there is something allocated a lot of native memory causing any other allocations to fail.

BruceForstall commented 1 year ago

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 commented 1 year ago

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

mangod9 commented 1 year ago

I notice that https://github.com/dotnet/runtime/pull/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 commented 1 year ago

@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 commented 1 year ago

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 commented 1 year ago

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 commented 1 year ago

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 commented 1 year ago

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 commented 1 year ago

@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 commented 1 year ago

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

ericstj commented 1 year ago

Disabling seems like the right quick fix. Probably we need to dispose this AdHocWorkspace:

https://github.com/dotnet/runtime/blob/2f208128f257b2390a8edefa0a19e0eaad6bd419/src/libraries/Common/tests/SourceGenerators/RoslynTestUtils.cs#L53C3-L53C3

ghost commented 1 year ago

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. ```json { "ErrorMessage": "Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NeedlessExceptionInMessage [FAIL]", "BuildRetry": false, "ErrorPattern": "", "ExcludeConsoleLog": false } ``` ### Known issue validation **Build: :mag_right:** https://dev.azure.com/dnceng-public/public/_build/results?buildId=317311 **Result validation: :white_check_mark:** Known issue matched with the provided build. ### Report |Build|Definition|Test|Pull Request| |---|---|---|---| |[325506](https://dev.azure.com/dnceng-public/public/_build/results?buildId=325506)|dotnet/runtime|[Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NeedlessExceptionInMessage](https://dev.azure.com/dnceng-public/public/_build/results?buildId=325506&view=ms.vss-test-web.build-test-results-tab&runId=6694044&resultId=137040)|| |[325428](https://dev.azure.com/dnceng-public/public/_build/results?buildId=325428)|dotnet/runtime|[Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.Valid_AdditionalAttributes](https://dev.azure.com/dnceng-public/public/_build/results?buildId=325428&view=ms.vss-test-web.build-test-results-tab&runId=6691982&resultId=104225)|| |[324865](https://dev.azure.com/dnceng-public/public/_build/results?buildId=324865)|dotnet/runtime|[Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NotPartial](https://dev.azure.com/dnceng-public/public/_build/results?buildId=324865&view=ms.vss-test-web.build-test-results-tab&runId=6676924&resultId=114314)|| |[324820](https://dev.azure.com/dnceng-public/public/_build/results?buildId=324820)|dotnet/runtime|[Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NeedlessExceptionInMessage](https://dev.azure.com/dnceng-public/public/_build/results?buildId=324820&view=ms.vss-test-web.build-test-results-tab&runId=6676038&resultId=145732)|| |[323832](https://dev.azure.com/dnceng-public/public/_build/results?buildId=323832)|dotnet/runtime|[Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NeedlessExceptionInMessage](https://dev.azure.com/dnceng-public/public/_build/results?buildId=323832&view=ms.vss-test-web.build-test-results-tab&runId=6665066&resultId=137263)|dotnet/runtime#88130| |[324303](https://dev.azure.com/dnceng-public/public/_build/results?buildId=324303)|dotnet/runtime|[Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NeedlessExceptionInMessage](https://dev.azure.com/dnceng-public/public/_build/results?buildId=324303&view=ms.vss-test-web.build-test-results-tab&runId=6664838&resultId=104112)|| |[323471](https://dev.azure.com/dnceng-public/public/_build/results?buildId=323471)|dotnet/runtime|[Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NotPartial](https://dev.azure.com/dnceng-public/public/_build/results?buildId=323471&view=ms.vss-test-web.build-test-results-tab&runId=6645710&resultId=112488)|| |[323384](https://dev.azure.com/dnceng-public/public/_build/results?buildId=323384)|dotnet/runtime|[Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NotPartial](https://dev.azure.com/dnceng-public/public/_build/results?buildId=323384&view=ms.vss-test-web.build-test-results-tab&runId=6642970&resultId=143397)|| |[323067](https://dev.azure.com/dnceng-public/public/_build/results?buildId=323067)|dotnet/runtime|[Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NeedlessExceptionInMessage](https://dev.azure.com/dnceng-public/public/_build/results?buildId=323067&view=ms.vss-test-web.build-test-results-tab&runId=6640620&resultId=152646)|dotnet/runtime#88090| |[322854](https://dev.azure.com/dnceng-public/public/_build/results?buildId=322854)|dotnet/runtime|[Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NeedlessExceptionInMessage](https://dev.azure.com/dnceng-public/public/_build/results?buildId=322854&view=ms.vss-test-web.build-test-results-tab&runId=6629462&resultId=134448)|| |[321944](https://dev.azure.com/dnceng-public/public/_build/results?buildId=321944)|dotnet/runtime|[Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NotPartial](https://dev.azure.com/dnceng-public/public/_build/results?buildId=321944&view=ms.vss-test-web.build-test-results-tab&runId=6607788&resultId=124094)|| |[321895](https://dev.azure.com/dnceng-public/public/_build/results?buildId=321895)|dotnet/runtime|[Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NotPartial](https://dev.azure.com/dnceng-public/public/_build/results?buildId=321895&view=ms.vss-test-web.build-test-results-tab&runId=6606604&resultId=141656)|| |[321311](https://dev.azure.com/dnceng-public/public/_build/results?buildId=321311)|dotnet/runtime|[Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NeedlessExceptionInMessage](https://dev.azure.com/dnceng-public/public/_build/results?buildId=321311&view=ms.vss-test-web.build-test-results-tab&runId=6591890&resultId=137768)|| |[320380](https://dev.azure.com/dnceng-public/public/_build/results?buildId=320380)|dotnet/runtime|[Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NotPartial](https://dev.azure.com/dnceng-public/public/_build/results?buildId=320380&view=ms.vss-test-web.build-test-results-tab&runId=6571414&resultId=111936)|| |[320333](https://dev.azure.com/dnceng-public/public/_build/results?buildId=320333)|dotnet/runtime|[Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NeedlessExceptionInMessage](https://dev.azure.com/dnceng-public/public/_build/results?buildId=320333&view=ms.vss-test-web.build-test-results-tab&runId=6568500&resultId=144463)|| |[320129](https://dev.azure.com/dnceng-public/public/_build/results?buildId=320129)|dotnet/runtime|[Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NotPartial](https://dev.azure.com/dnceng-public/public/_build/results?buildId=320129&view=ms.vss-test-web.build-test-results-tab&runId=6563750&resultId=141365)|| |[320072](https://dev.azure.com/dnceng-public/public/_build/results?buildId=320072)|dotnet/runtime|[Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NeedlessExceptionInMessage](https://dev.azure.com/dnceng-public/public/_build/results?buildId=320072&view=ms.vss-test-web.build-test-results-tab&runId=6562656&resultId=144979)|| |[319899](https://dev.azure.com/dnceng-public/public/_build/results?buildId=319899)|dotnet/runtime|[Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NotPartial](https://dev.azure.com/dnceng-public/public/_build/results?buildId=319899&view=ms.vss-test-web.build-test-results-tab&runId=6558976&resultId=104214)|| |[319891](https://dev.azure.com/dnceng-public/public/_build/results?buildId=319891)|dotnet/runtime|[Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NotPartial](https://dev.azure.com/dnceng-public/public/_build/results?buildId=319891&view=ms.vss-test-web.build-test-results-tab&runId=6558604&resultId=142227)|| |[319730](https://dev.azure.com/dnceng-public/public/_build/results?buildId=319730)|dotnet/runtime|[Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NeedlessExceptionInMessage](https://dev.azure.com/dnceng-public/public/_build/results?buildId=319730&view=ms.vss-test-web.build-test-results-tab&runId=6554796&resultId=139822)|dotnet/runtime#87917| |[319710](https://dev.azure.com/dnceng-public/public/_build/results?buildId=319710)|dotnet/runtime|[Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.Valid_AdditionalAttributes](https://dev.azure.com/dnceng-public/public/_build/results?buildId=319710&view=ms.vss-test-web.build-test-results-tab&runId=6554150&resultId=113153)|| |[319629](https://dev.azure.com/dnceng-public/public/_build/results?buildId=319629)|dotnet/runtime|[Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NotPartial](https://dev.azure.com/dnceng-public/public/_build/results?buildId=319629&view=ms.vss-test-web.build-test-results-tab&runId=6552726&resultId=146315)|| |[319175](https://dev.azure.com/dnceng-public/public/_build/results?buildId=319175)|dotnet/runtime|[Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NotPartial](https://dev.azure.com/dnceng-public/public/_build/results?buildId=319175&view=ms.vss-test-web.build-test-results-tab&runId=6546688&resultId=138870)|dotnet/runtime#87967| |[319201](https://dev.azure.com/dnceng-public/public/_build/results?buildId=319201)|dotnet/runtime|[Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NeedlessExceptionInMessage](https://dev.azure.com/dnceng-public/public/_build/results?buildId=319201&view=ms.vss-test-web.build-test-results-tab&runId=6543112&resultId=142414)|dotnet/runtime#87917| |[318922](https://dev.azure.com/dnceng-public/public/_build/results?buildId=318922)|dotnet/runtime|[Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NeedlessExceptionInMessage](https://dev.azure.com/dnceng-public/public/_build/results?buildId=318922&view=ms.vss-test-web.build-test-results-tab&runId=6537060&resultId=120680)|| |[318763](https://dev.azure.com/dnceng-public/public/_build/results?buildId=318763)|dotnet/runtime|[Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NotPartial](https://dev.azure.com/dnceng-public/public/_build/results?buildId=318763&view=ms.vss-test-web.build-test-results-tab&runId=6533752&resultId=141473)|| |[318753](https://dev.azure.com/dnceng-public/public/_build/results?buildId=318753)|dotnet/runtime|[Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NeedlessExceptionInMessage](https://dev.azure.com/dnceng-public/public/_build/results?buildId=318753&view=ms.vss-test-web.build-test-results-tab&runId=6533718&resultId=140007)|| |[317311](https://dev.azure.com/dnceng-public/public/_build/results?buildId=317311)|dotnet/runtime|[Microsoft.Extensions.Logging.Generators.Tests.LoggerMessageGeneratorParserTests.NotPartial](https://dev.azure.com/dnceng-public/public/_build/results?buildId=317311&view=ms.vss-test-web.build-test-results-tab&runId=6505130&resultId=137245)|| #### 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 commented 1 year ago

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 commented 1 year ago

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 commented 1 year ago

I'll try to take a look later today.