Skip to content

Add support for logging assembly loads logging#653

Merged
KirillOsenkov merged 1 commit intoKirillOsenkov:mainfrom
JanKrivanek:proto/assembly-loads-logging
Feb 7, 2023
Merged

Add support for logging assembly loads logging#653
KirillOsenkov merged 1 commit intoKirillOsenkov:mainfrom
JanKrivanek:proto/assembly-loads-logging

Conversation

@JanKrivanek
Copy link
Copy Markdown
Collaborator

@JanKrivanek JanKrivanek commented Feb 7, 2023

Related to: dotnet/msbuild#6303
Feature in MSBuild: dotnet/msbuild#8316

Context

Adding support for showing assembly load events, prduced by the MSBuild.
There is no special treating of the events - they get disaplayed as text message. For sample messages, see the MSBuild PR listed at top.
Sample viewer screenshot:

image

@KirillOsenkov KirillOsenkov merged commit 51c92b5 into KirillOsenkov:main Feb 7, 2023
@JanKrivanek JanKrivanek deleted the proto/assembly-loads-logging branch February 7, 2023 20:22
@JanKrivanek
Copy link
Copy Markdown
Collaborator Author

JanKrivanek commented Feb 8, 2023

@KirillOsenkov Do you have any quick thoughts why the same events are sometimes displayed as Message sometimes as Property?

image

The Property display happens for MSBuild tasks (indicated by BuildEventCotnext).

Unless this is expected or unless there might be some obvious reason for that I'll of cource investigate closer (I just wanted to see if I'm not missing anything)

@KirillOsenkov
Copy link
Copy Markdown
Owner

it looks for space, equals, space to guess whether it’s a property :) The Version = string sometimes contains spaces and sometimes doesn’t :) We can tune the heuristic to account for this case. It ‘s in MessageProcessor.cs somewhere.

@JanKrivanek
Copy link
Copy Markdown
Collaborator Author

Thank you @KirillOsenkov!
It got me into the right direction - the fix proposal: #654

Something that seems strange to me now is that those messages do not appear in the search results:

image

Do you have any idea for reason for that?

@KirillOsenkov
Copy link
Copy Markdown
Owner

yes you need to intern the strings in a special way to include them in search, look for Intern() methods used everywhere in Construction.cs and MessageProcessor.cs

@JanKrivanek
Copy link
Copy Markdown
Collaborator Author

Thank you!
Works like a charm now! ;-) (#654)

JaynieBai pushed a commit to dotnet/msbuild that referenced this pull request Feb 24, 2023
Fixes #6303
Related: KirillOsenkov/MSBuildStructuredLog#653

Context
Assembly loading logging for:
Task runs - including loads in separate app domain for AppDomainIsolatedTask
Except for tasks runs in OutOfProcessRaskHostNode - as neither LoggingService nor LoggingContext are available there - not sure if not supporting those is a problem.
Sdk resolving (explicitly skipping resolvers defined in Microsoft.Build assembly)
Loggers initialization (explicitly skipping resolvers defined in Microsoft.Build assembly orwithin Microsoft.Build.Logging namespace) - Note - loggers initialiation reordered - Binlog is the first one - as assembly load events are emited at the time of each logger initialization, currently LoggerService dispatches events immediately after construction, so as a result order of logger definitions matter (only the earlier initialized gets messages about latter ones initialization assembly loads). Alternative would be to change the LoggerService contract to start dispatching on explicit request (easy to implement and preserving current MSBuild behavior - however might be potentially breaking for API users?) or to cache those events and log them later (doable, but convoluted - probably not worth the efforts now)
Evaluation
Samples
task run:

Assembly loaded during TaskRun: System.Diagnostics.Debug, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a (location: C:\Windows\Microsoft.Net\assembly\GAC_MSIL\System.Diagnostics.Debug\v4.0_4.0.0.0__b03f5f7f11d50a3a\System.Diagnostics.Debug.dll, MVID: bc6b825d-5f99-464e-a06d-e3ae4b860a34, AppDomain: [Default])
evaluation:

Assembly loaded during Evaluation: System.Collections.Immutable, Version=7.0.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a (location: C:\Program Files\dotnet\shared\Microsoft.NETCore.App\7.0.2\System.Collections.Immutable.dll, MVID: 5a4c54a3-2092-428e-89cc-a391fd9d398a, AppDomain: [Default])
logger initialization:

Assembly loaded during LoggerInitialization (MyLoggers.BasicFileLogger): System.Reflection.Metadata, Version=7.0.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a (location: C:\Program Files\dotnet\shared\Microsoft.NETCore.App\7.0.2\System.Reflection.Metadata.dll, MVID: c602a8ce-3890-40fc-aa9b-fa3c23f81aab, AppDomain: [Default])
custom sdk resolver (no sample - similar to logger initialization)

Perf impact
No observable impact.

MSBUILDLOGALLASSEMBLYLOADS is used to turn on loggin of all assembly loads
build command: msbuild.exe <proj> /nodeReuse:false /bl
Scenario	Mean Duration
Orchard - MSBuild main	00:00:59.25
Orchard - curr branch	00:00:58.30
Orchard - curr branch, all loads	00:00:58.30
Console - MSBuild main	00:00:01.08
Console - curr branch	00:00:01.09
Console - curr branch, all loads	00:00:01.10
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants