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.

Sign up for GitHub

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

Jump to bottom

[mono][ios] Eventpipe gcdump test failing on apple mobile platforms #90012

Closed
kotlarmilos opened this issue Aug 4, 2023 · 4 comments · Fixed by #91785
Closed

[mono][ios] Eventpipe gcdump test failing on apple mobile platforms #90012

kotlarmilos opened this issue Aug 4, 2023 · 4 comments · Fixed by #91785
Assignees
@lateralusX
Labels
area-VM-meta-mono disabled-test The test is disabled in source code against the issue Known Build Error Use this to report build issues in the .NET Helix tab
Milestone
9.0.0

Comments

@kotlarmilos
Copy link
Member

kotlarmilos commented Aug 4, 2023 •
edited by build-analysis bot
Loading

Build Information

Build: https://dev.azure.com/dnceng-public/cbb18261-c48f-4abb-8651-8cdcb5474649/_build/results?buildId=363106
Build error leg or test failing: tracing/eventpipe/gcdump.dll
Pull request: #89726

Error Message

Fill the error message using step by step known issues guidance.

{
  "ErrorMessage": "Application has finished with exit code 255 but 100 was expected",
  "ErrorPattern": "",
  "BuildRetry": false,
  "ExcludeConsoleLog": false
}

Test log:

[03:12:26.0256760] Launched application 'net.dot.tracing_eventpipe' on 'DNCENGOSX117' with pid 14378
[03:12:26.1444880] 2023-08-04 03:12:26.185 tracing_eventpipe[14378:13727264]   0.0s: ==TEST STARTING==
[03:12:26.1548200] 2023-08-04 03:12:26.198 tracing_eventpipe[14378:13727274]   0.0s: Started sending sentinel events...
[03:12:26.1581380] 2023-08-04 03:12:26.201 tracing_eventpipe[14378:13727276]   0.0s: Connecting to EventPipe...
[03:12:26.2010550] 2023-08-04 03:12:26.244 tracing_eventpipe[14378:13727276]   0.1s: Creating EventPipeEventSource...
[03:12:26.2053600] 2023-08-04 03:12:26.248 tracing_eventpipe[14378:13727276]   0.1s: EventPipeEventSource created
[03:12:26.2137250] 2023-08-04 03:12:26.257 tracing_eventpipe[14378:13727276]   0.1s: Dynamic.All callback registered
[03:12:26.2137700] 2023-08-04 03:12:26.257 tracing_eventpipe[14378:13727276]   0.1s: Running optional trace validator
[03:12:26.2221300] 2023-08-04 03:12:26.264 tracing_eventpipe[14378:13727276]   0.1s: Finished running optional trace validator
[03:12:26.2221690] 2023-08-04 03:12:26.265 tracing_eventpipe[14378:13727276]   0.1s: Starting stream processing...
[03:12:26.3359410] 2023-08-04 03:12:26.379 tracing_eventpipe[14378:13727276]   0.2s: Saw sentinel event
[03:12:26.3359870] 2023-08-04 03:12:26.379 tracing_eventpipe[14378:13727274]   0.2s: Stopped sending sentinel events
[03:12:26.3371410] 2023-08-04 03:12:26.380 tracing_eventpipe[14378:13727264]   0.2s: Starting event generating action...
[03:12:36.3443740] 2023-08-04 03:12:36.387 tracing_eventpipe[14378:13727264]  10.2s: Stopping event generating action
[03:12:36.3456970] 2023-08-04 03:12:36.389 tracing_eventpipe[14378:13727274]  10.2s: Sending StopTracing command...
[03:12:36.4805540] 2023-08-04 03:12:36.524 tracing_eventpipe[14378:13727276]  10.4s: Saw new provider 'Microsoft-DotNETCore-EventPipe'
[03:12:36.4967410] 2023-08-04 03:12:36.540 tracing_eventpipe[14378:13727276]  10.4s: Saw new provider 'Microsoft-Windows-DotNETRuntimeRundown'
[03:12:36.5134950] 2023-08-04 03:12:36.557 tracing_eventpipe[14378:13727274]  10.4s: Finished StopTracing command
[03:12:36.5411160] 2023-08-04 03:12:36.584 tracing_eventpipe[14378:13727276]  10.4s: Stopping stream processing
[03:12:36.5412890] 2023-08-04 03:12:36.585 tracing_eventpipe[14378:13727276]  10.4s: Dropped 0 events
[03:12:36.5414080] 2023-08-04 03:12:36.585 tracing_eventpipe[14378:13727264]  10.4s: Reader task finished
[03:12:36.5415490] 2023-08-04 03:12:36.585 tracing_eventpipe[14378:13727264]  10.4s: Validating optional callback...
[03:12:36.5416170] 2023-08-04 03:12:36.585 tracing_eventpipe[14378:13727264] Test failed due to missing GC heap events.
[03:12:36.5417250] 2023-08-04 03:12:36.585 tracing_eventpipe[14378:13727264] _seenGCStart =            False
[03:12:36.5417550] 2023-08-04 03:12:36.586 tracing_eventpipe[14378:13727264] _seenGCStop =             False
[03:12:36.5417610] 2023-08-04 03:12:36.586 tracing_eventpipe[14378:13727264] _bulkTypeCount =          0
[03:12:36.5419840] 2023-08-04 03:12:36.586 tracing_eventpipe[14378:13727264] _bulkNodeCount =          0
[03:12:36.5420020] 2023-08-04 03:12:36.586 tracing_eventpipe[14378:13727264] _bulkEdgeCount =          0
[03:12:36.5420080] 2023-08-04 03:12:36.586 tracing_eventpipe[14378:13727264] _bulkRootEdgeCount =      0
[03:12:36.5420130] 2023-08-04 03:12:36.586 tracing_eventpipe[14378:13727264] _bulkRootStaticVarCount = 0
[03:12:36.5420220] 2023-08-04 03:12:36.586 tracing_eventpipe[14378:13727264]  10.4s: ==TEST FINISHED: FAILED!==
[03:12:36.5473960] Xamarin.Hosting: Process '14378' exited with exit code 255 or crashing signal .
[03:12:36.5478560] Application 'net.dot.tracing_eventpipe' terminated (with exit code '255' and/or crashing signal ').

Repro steps

  1. Build the runtime
./build.sh -ci -arch x64 -os tvossimulator  -s mono+libs -c Release
  1. Build and AOT compile the tests
./src/tests/build.sh  ci os tvossimulator x64 Release -mono tree tracing/eventpipe /p:ArchiveTests=true /p:DevTeamProvisioning=- /p:RunAOTCompilation=true /p:MonoForceInterpreter=true /p:LibrariesConfiguration=Release
  1. Run the app bundle using Xcode using the following environment variables
MONO_APPLE_APP_ENTRY_POINT_LIB_NAME = 'testdir-gcdump/gcdump.dll'
MONO_APPLE_APP_ASSEMBLY_LOAD_PREFIX = 'testdir-gcdump'

Note: You may need to provide a correct path to the cross compiler in the AppleBuild.targets.

Known issue validation

Build: 🔎 https://dev.azure.com/dnceng-public/public/_build/results?buildId=363106
Error message validated: Application has finished with exit code 255 but 100 was expected
Result validation: ✅ Known issue matched with the provided build.
Validation performed at: 8/4/2023 11:24:17 AM UTC

Report

Summary

24-Hour Hit Count 7-Day Hit Count 1-Month Count
0 0 0
@kotlarmilos kotlarmilos added area-VM-meta-mono Known Build Error Use this to report build issues in the .NET Helix tab labels Aug 4, 2023
@kotlarmilos kotlarmilos added this to the 9.0.0 milestone Aug 4, 2023
@kotlarmilos kotlarmilos added the disabled-test The test is disabled in source code against the issue label Aug 4, 2023
@lateralusX
Copy link
Member

lateralusX commented Aug 4, 2023 •
edited
Loading

Just following the steps above will leave the diagnostic tracing component disabled as well as not setting the needed env variable to startup the diagnostic server.

Making sure we link libmono-component-diagnostics_tracing-static.a as well as setting env DOTNET_DiagnosticPorts=127.0.0.1:9000,nosuspend,listen made the test at least pass on tvossimulator arm64.

@kotlarmilos could you retry your repro making sure we got the needed pre-reqs in place (linking to the none stub version of the diagnostics_tracing component as well as setting up the diagnostic server) and see if it still repros.

@lateralusX
Copy link
Member

@kotlarmilos, did you have a chance to try this test with the above?

@kotlarmilos
Copy link
Member Author

kotlarmilos commented Sep 4, 2023 •
edited
Loading

Thanks for the heads up, I didn't have capacity before the RC1 snap, but I will follow-up this week. I think the components are not properly initialized locally. I will try to reproduce it without stubs.

@kotlarmilos
Copy link
Member Author

I managed to reproduce it on a device.

Try to add snippet below to the target in /src/tests/build.proj.

runtime/src/tests/build.proj

Lines 348 to 351 in a3a0f5c

<UpdateRunScriptToHandleMultipleEntryPoints EntryPoints="@(EntryPoints)" RunScriptCommand="$(RunScriptCommand)" AppName="$(Category)" Condition="'$(BuildTestsOnHelix)' == 'true'">
<Output TaskParameter="OutputScript" PropertyName="RunScriptCommand" />
</UpdateRunScriptToHandleMultipleEntryPoints>
</Target> 

    <PropertyGroup>
      <RuntimeComponents>diagnostics_tracing;marshal-ilgen</RuntimeComponents>
      <DiagnosticPorts>127.0.0.1:9000,nosuspend,listen</DiagnosticPorts>
    </PropertyGroup>

The app fails with the following log:

023-09-06 19:30:51.588443+0200 tracing_eventpipe[13232:2222710]   0.0s: ==TEST STARTING==
2023-09-06 19:30:51.588581+0200 tracing_eventpipe[13232:2222710] assembly_preload_hook: System.Collections.Concurrent  /private/var/containers/Bundle/Application/760C8B04-003C-4102-982F-EE8ACFFD6718/tracing_eventpipe.app
2023-09-06 19:30:51.589748+0200 tracing_eventpipe[13232:2222710] assembly_preload_hook: System.Diagnostics.Process  /private/var/containers/Bundle/Application/760C8B04-003C-4102-982F-EE8ACFFD6718/tracing_eventpipe.app
2023-09-06 19:30:51.590791+0200 tracing_eventpipe[13232:2222710] assembly_preload_hook: System.ComponentModel.Primitives  /private/var/containers/Bundle/Application/760C8B04-003C-4102-982F-EE8ACFFD6718/tracing_eventpipe.app
2023-09-06 19:30:51.591279+0200 tracing_eventpipe[13232:2222710] assembly_preload_hook: System.ComponentModel  /private/var/containers/Bundle/Application/760C8B04-003C-4102-982F-EE8ACFFD6718/tracing_eventpipe.app
2023-09-06 19:30:51.591735+0200 tracing_eventpipe[13232:2222710] assembly_preload_hook: System.Collections.NonGeneric  /private/var/containers/Bundle/Application/760C8B04-003C-4102-982F-EE8ACFFD6718/tracing_eventpipe.app
2023-09-06 19:30:51.592449+0200 tracing_eventpipe[13232:2222710] assembly_preload_hook: System.Threading.ThreadPool  /private/var/containers/Bundle/Application/760C8B04-003C-4102-982F-EE8ACFFD6718/tracing_eventpipe.app
2023-09-06 19:30:51.595890+0200 tracing_eventpipe[13232:2222710] assembly_preload_hook: System.Linq  /private/var/containers/Bundle/Application/760C8B04-003C-4102-982F-EE8ACFFD6718/tracing_eventpipe.app
2023-09-06 19:30:51.602684+0200 tracing_eventpipe[13232:2222716]   0.0s: Started sending sentinel events...
2023-09-06 19:30:51.604979+0200 tracing_eventpipe[13232:2222718]   0.0s: Connecting to EventPipe...
2023-09-06 19:30:51.607233+0200 tracing_eventpipe[13232:2222718] assembly_preload_hook: System.IO.Pipes  /private/var/containers/Bundle/Application/760C8B04-003C-4102-982F-EE8ACFFD6718/tracing_eventpipe.app
2023-09-06 19:30:51.608137+0200 tracing_eventpipe[13232:2222718] assembly_preload_hook: System.Net.Sockets  /private/var/containers/Bundle/Application/760C8B04-003C-4102-982F-EE8ACFFD6718/tracing_eventpipe.app
2023-09-06 19:30:51.609637+0200 tracing_eventpipe[13232:2222718] assembly_preload_hook: System.Net.Primitives  /private/var/containers/Bundle/Application/760C8B04-003C-4102-982F-EE8ACFFD6718/tracing_eventpipe.app
2023-09-06 19:30:51.614050+0200 tracing_eventpipe[13232:2222718] assembly_preload_hook: System.Runtime.Intrinsics  /private/var/containers/Bundle/Application/760C8B04-003C-4102-982F-EE8ACFFD6718/tracing_eventpipe.app
2023-09-06 19:30:51.615104+0200 tracing_eventpipe[13232:2222718] assembly_preload_hook: Microsoft.Win32.Primitives  /private/var/containers/Bundle/Application/760C8B04-003C-4102-982F-EE8ACFFD6718/tracing_eventpipe.app
2023-09-06 19:30:51.616050+0200 tracing_eventpipe[13232:2222718] assembly_preload_hook: System.Threading.Thread  /private/var/containers/Bundle/Application/760C8B04-003C-4102-982F-EE8ACFFD6718/tracing_eventpipe.app
2023-09-06 19:30:51.617431+0200 tracing_eventpipe[13232:2222718] assembly_preload_hook: System.Private.Uri  /private/var/containers/Bundle/Application/760C8B04-003C-4102-982F-EE8ACFFD6718/tracing_eventpipe.app
2023-09-06 19:30:51.622956+0200 tracing_eventpipe[13232:2222718] assembly_preload_hook: System.Net.NameResolution  /private/var/containers/Bundle/Application/760C8B04-003C-4102-982F-EE8ACFFD6718/tracing_eventpipe.app
2023-09-06 19:30:51.649999+0200 tracing_eventpipe[13232:2222718]   0.1s: Creating EventPipeEventSource...
2023-09-06 19:30:51.650751+0200 tracing_eventpipe[13232:2222718] assembly_preload_hook: System.IO  /private/var/containers/Bundle/Application/760C8B04-003C-4102-982F-EE8ACFFD6718/tracing_eventpipe.app
2023-09-06 19:30:51.654388+0200 tracing_eventpipe[13232:2222718]   0.1s: EventPipeEventSource created
2023-09-06 19:30:51.657134+0200 tracing_eventpipe[13232:2222718] assembly_preload_hook: System.Xml.ReaderWriter  /private/var/containers/Bundle/Application/760C8B04-003C-4102-982F-EE8ACFFD6718/tracing_eventpipe.app
2023-09-06 19:30:51.657663+0200 tracing_eventpipe[13232:2222718] assembly_preload_hook: System.Private.Xml  /private/var/containers/Bundle/Application/760C8B04-003C-4102-982F-EE8ACFFD6718/tracing_eventpipe.app
2023-09-06 19:30:51.661600+0200 tracing_eventpipe[13232:2222718] assembly_preload_hook: System.Text.RegularExpressions  /private/var/containers/Bundle/Application/760C8B04-003C-4102-982F-EE8ACFFD6718/tracing_eventpipe.app
2023-09-06 19:30:51.663418+0200 tracing_eventpipe[13232:2222718]   0.1s: Dynamic.All callback registered
2023-09-06 19:30:51.663515+0200 tracing_eventpipe[13232:2222718]   0.1s: Running optional trace validator
2023-09-06 19:30:51.672573+0200 tracing_eventpipe[13232:2222718]   0.1s: Finished running optional trace validator
2023-09-06 19:30:51.672673+0200 tracing_eventpipe[13232:2222718]   0.1s: Starting stream processing...
2023-09-06 19:30:51.672896+0200 tracing_eventpipe[13232:2222718] assembly_preload_hook: System.Runtime.Extensions  /private/var/containers/Bundle/Application/760C8B04-003C-4102-982F-EE8ACFFD6718/tracing_eventpipe.app
2023-09-06 19:30:51.757710+0200 tracing_eventpipe[13232:2222718] assembly_preload_hook: System.Security.Cryptography  /private/var/containers/Bundle/Application/760C8B04-003C-4102-982F-EE8ACFFD6718/tracing_eventpipe.app
2023-09-06 19:30:51.784283+0200 tracing_eventpipe[13232:2222718]   0.2s: Saw sentinel event
2023-09-06 19:30:51.784642+0200 tracing_eventpipe[13232:2222716]   0.2s: Stopped sending sentinel events
2023-09-06 19:30:51.786039+0200 tracing_eventpipe[13232:2222710]   0.2s: Starting event generating action...
2023-09-06 19:31:01.792366+0200 tracing_eventpipe[13232:2222710]  10.2s: Stopping event generating action
2023-09-06 19:31:01.794321+0200 tracing_eventpipe[13232:2222716]  10.2s: Sending StopTracing command...
2023-09-06 19:31:01.929064+0200 tracing_eventpipe[13232:2222718]  10.4s: Saw new provider 'Microsoft-DotNETCore-EventPipe'
2023-09-06 19:31:01.947496+0200 tracing_eventpipe[13232:2222718]  10.4s: Saw new provider 'Microsoft-Windows-DotNETRuntimeRundown'
2023-09-06 19:31:01.964881+0200 tracing_eventpipe[13232:2222716]  10.4s: Finished StopTracing command
2023-09-06 19:31:01.992815+0200 tracing_eventpipe[13232:2222718]  10.4s: Stopping stream processing
2023-09-06 19:31:01.992999+0200 tracing_eventpipe[13232:2222718]  10.4s: Dropped 0 events
2023-09-06 19:31:01.993395+0200 tracing_eventpipe[13232:2222710]  10.4s: Reader task finished
2023-09-06 19:31:01.993593+0200 tracing_eventpipe[13232:2222710]  10.4s: Validating optional callback...
2023-09-06 19:31:01.993767+0200 tracing_eventpipe[13232:2222710] Test failed due to missing GC heap events.
2023-09-06 19:31:01.993969+0200 tracing_eventpipe[13232:2222710] _seenGCStart =            False
2023-09-06 19:31:01.994015+0200 tracing_eventpipe[13232:2222710] _seenGCStop =             False
2023-09-06 19:31:01.994053+0200 tracing_eventpipe[13232:2222710] _bulkTypeCount =          0
2023-09-06 19:31:01.994091+0200 tracing_eventpipe[13232:2222710] _bulkNodeCount =          0
2023-09-06 19:31:01.994127+0200 tracing_eventpipe[13232:2222710] _bulkEdgeCount =          0
2023-09-06 19:31:01.994164+0200 tracing_eventpipe[13232:2222710] _bulkRootEdgeCount =      0
2023-09-06 19:31:01.994201+0200 tracing_eventpipe[13232:2222710] _bulkRootStaticVarCount = 0
2023-09-06 19:31:01.994263+0200 tracing_eventpipe[13232:2222710]  10.4s: ==TEST FINISHED: FAILED!==

@kotlarmilos kotlarmilos mentioned this issue Sep 8, 2023
Merged
@ghost ghost added the in-pr There is an active PR which will close this issue when it is merged label Sep 8, 2023
@ghost ghost removed the in-pr There is an active PR which will close this issue when it is merged label Sep 8, 2023
@ghost ghost locked as resolved and limited conversation to collaborators Oct 8, 2023
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees

@lateralusX lateralusX

Labels
area-VM-meta-mono disabled-test The test is disabled in source code against the issue Known Build Error Use this to report build issues in the .NET Helix tab
Projects
None yet
Milestone
9.0.0
Development

Successfully merging a pull request may close this issue.

[mono][ios] Call mono_gc_init_finalizer_thread to allow gc thread creation kotlarmilos/runtime
2 participants
@kotlarmilos @lateralusX