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

Add debug output for skin configuration lookups #24726

Merged
merged 6 commits into from
Sep 6, 2023

Conversation

peppy
Copy link
Member

@peppy peppy commented Sep 6, 2023

We've struggle with debugging these over the years so I think this was worth a couple of hours of work.

Example of osu! lookups:

[runtime] 2023-09-06 08:38:30 [verbose]: BeatmapSkinProvidingContainer.GetConfig(lookup: SpinnerFrequencyModulate)
[runtime] 2023-09-06 08:38:30 [verbose]: |-SkinProvidingContainer+DisableableSkinSource{ skin: SkinTransformer{ Skin: LegacyBeatmapSkin{ Name: Vickeblanka - Lucky Ending (TV Size) (tears_) [Normal] } } }.GetConfig(lookup: SpinnerFrequencyModulate)
[runtime] 2023-09-06 08:38:30 [verbose]: |-RulesetSkinProvidingContainer.GetConfig(lookup: SpinnerFrequencyModulate)
[runtime] 2023-09-06 08:38:30 [verbose]: |-|-SkinProvidingContainer+DisableableSkinSource{ skin: SkinTransformer{ Skin: LegacySkin{ Name: Test Skin [test-skin] } } }.GetConfig(lookup: SpinnerFrequencyModulate)
[runtime] 2023-09-06 08:38:30 [verbose]: |-|-|-SkinTransformer{ Skin: LegacySkin{ Name: Test Skin [test-skin] } }.GetConfig(lookup: SpinnerFrequencyModulate)
[runtime] 2023-09-06 08:38:30 [verbose]: |-|-|-|-LegacySkin{ Name: Test Skin [test-skin] }.GetConfig(lookup: SpinnerFrequencyModulate) 🟢
[runtime] 2023-09-06 08:38:30 [verbose]: |-|-SkinProvidingContainer+DisableableSkinSource{ skin: SkinTransformer{ Skin: DefaultLegacySkin{ Name: osu! "classic" (2013) } } }.GetConfig(lookup: SpinnerFrequencyModulate)
[runtime] 2023-09-06 08:38:30 [verbose]: |-|-|-SkinTransformer{ Skin: DefaultLegacySkin{ Name: osu! "classic" (2013) } }.GetConfig(lookup: SpinnerFrequencyModulate)
[runtime] 2023-09-06 08:38:30 [verbose]: |-|-|-|-DefaultLegacySkin{ Name: osu! "classic" (2013) }.GetConfig(lookup: SpinnerFrequencyModulate) 🟢
[runtime] 2023-09-06 08:38:30 [verbose]: |-|-SkinProvidingContainer+DisableableSkinSource{ skin: osu.Game.Skinning.ResourceStoreBackedSkin }.GetConfig(lookup: SpinnerFrequencyModulate)
[runtime] 2023-09-06 08:38:30 [verbose]: |-|-|-osu.Game.Skinning.ResourceStoreBackedSkin.GetConfig(lookup: SpinnerFrequencyModulate) 🔴
[runtime] 2023-09-06 08:38:30 [verbose]: |-|-SkinProvidingContainer+DisableableSkinSource{ skin: TrianglesSkin{ Name: osu! "triangles" (2017) } }.GetConfig(lookup: SpinnerFrequencyModulate)
[runtime] 2023-09-06 08:38:30 [verbose]: |-|-|-TrianglesSkin{ Name: osu! "triangles" (2017) }.GetConfig(lookup: SpinnerFrequencyModulate) 🔴
[runtime] 2023-09-06 08:38:30 [verbose]:
[runtime] 2023-09-06 08:38:30 [verbose]: BeatmapSkinProvidingContainer.GetConfig(lookup: ScorePrefix)
[runtime] 2023-09-06 08:38:30 [verbose]: |-SkinProvidingContainer+DisableableSkinSource{ skin: SkinTransformer{ Skin: LegacyBeatmapSkin{ Name: Vickeblanka - Lucky Ending (TV Size) (tears_) [Normal] } } }.GetConfig(lookup: ScorePrefix)
[runtime] 2023-09-06 08:38:30 [verbose]: |-RulesetSkinProvidingContainer.GetConfig(lookup: ScorePrefix)
[runtime] 2023-09-06 08:38:30 [verbose]: |-|-SkinProvidingContainer+DisableableSkinSource{ skin: SkinTransformer{ Skin: LegacySkin{ Name: Test Skin [test-skin] } } }.GetConfig(lookup: ScorePrefix)
[runtime] 2023-09-06 08:38:30 [verbose]: |-|-|-SkinTransformer{ Skin: LegacySkin{ Name: Test Skin [test-skin] } }.GetConfig(lookup: ScorePrefix)
[runtime] 2023-09-06 08:38:30 [verbose]: |-|-|-|-LegacySkin{ Name: Test Skin [test-skin] }.GetConfig(lookup: ScorePrefix) 🟢
[runtime] 2023-09-06 08:38:30 [verbose]: |-|-SkinProvidingContainer+DisableableSkinSource{ skin: SkinTransformer{ Skin: DefaultLegacySkin{ Name: osu! "classic" (2013) } } }.GetConfig(lookup: ScorePrefix)
[runtime] 2023-09-06 08:38:30 [verbose]: |-|-|-SkinTransformer{ Skin: DefaultLegacySkin{ Name: osu! "classic" (2013) } }.GetConfig(lookup: ScorePrefix)
[runtime] 2023-09-06 08:38:30 [verbose]: |-|-|-|-DefaultLegacySkin{ Name: osu! "classic" (2013) }.GetConfig(lookup: ScorePrefix) 🟢
[runtime] 2023-09-06 08:38:30 [verbose]: |-|-SkinProvidingContainer+DisableableSkinSource{ skin: osu.Game.Skinning.ResourceStoreBackedSkin }.GetConfig(lookup: ScorePrefix)
[runtime] 2023-09-06 08:38:30 [verbose]: |-|-|-osu.Game.Skinning.ResourceStoreBackedSkin.GetConfig(lookup: ScorePrefix) 🔴
[runtime] 2023-09-06 08:38:30 [verbose]: |-|-SkinProvidingContainer+DisableableSkinSource{ skin: TrianglesSkin{ Name: osu! "triangles" (2017) } }.GetConfig(lookup: ScorePrefix)
[runtime] 2023-09-06 08:38:30 [verbose]: |-|-|-TrianglesSkin{ Name: osu! "triangles" (2017) }.GetConfig(lookup: ScorePrefix) 🔴

Example of osu!mania lookups:

[runtime] 2023-09-06 08:28:34 [verbose]: |-RulesetSkinProvidingContainer.GetConfig(lookup: [ManiaSkinConfigurationLookup lookup:ColumnWidth col:0])
[runtime] 2023-09-06 08:28:34 [verbose]: |-|-SkinProvidingContainer+DisableableSkinSource{ skin: SkinTransformer{ Skin: LegacySkin{ Name: Test Skin [test-skin] } } }.GetConfig(lookup: [ManiaSkinConfigurationLookup lookup:ColumnWidth col:0])
[runtime] 2023-09-06 08:28:34 [verbose]: |-|-|-SkinTransformer{ Skin: LegacySkin{ Name: Test Skin [test-skin] } }.GetConfig(lookup: [LegacyManiaSkinConfigurationLookup lookup:ColumnWidth col:0 totalcols:4])
[runtime] 2023-09-06 08:28:34 [verbose]: |-|-|-|-LegacySkin{ Name: Test Skin [test-skin] }.GetConfig(lookup: [LegacyManiaSkinConfigurationLookup lookup:ColumnWidth col:0 totalcols:4]) 🔴
[runtime] 2023-09-06 08:28:34 [verbose]: |-|-SkinProvidingContainer+DisableableSkinSource{ skin: SkinTransformer{ Skin: DefaultLegacySkin{ Name: osu! "classic" (2013) } } }.GetConfig(lookup: [ManiaSkinConfigurationLookup lookup:ColumnWidth col:0])
[runtime] 2023-09-06 08:28:34 [verbose]: |-|-|-SkinTransformer{ Skin: DefaultLegacySkin{ Name: osu! "classic" (2013) } }.GetConfig(lookup: [LegacyManiaSkinConfigurationLookup lookup:ColumnWidth col:0 totalcols:4])
[runtime] 2023-09-06 08:28:34 [verbose]: |-|-|-|-DefaultLegacySkin{ Name: osu! "classic" (2013) }.GetConfig(lookup: [LegacyManiaSkinConfigurationLookup lookup:ColumnWidth col:0 totalcols:4]) 🟢
[runtime] 2023-09-06 08:28:34 [verbose]:
[runtime] 2023-09-06 08:28:34 [verbose]: BeatmapSkinProvidingContainer.GetConfig(lookup: [ManiaSkinConfigurationLookup lookup:ColumnSpacing col:0])
[runtime] 2023-09-06 08:28:34 [verbose]: |-SkinProvidingContainer+DisableableSkinSource{ skin: SkinTransformer{ Skin: LegacyBeatmapSkin{ Name: antiPLUR - Runengon (Raveille) [Easy] } } }.GetConfig(lookup: [ManiaSkinConfigurationLookup lookup:ColumnSpacing col:0])
[runtime] 2023-09-06 08:28:34 [verbose]: |-RulesetSkinProvidingContainer.GetConfig(lookup: [ManiaSkinConfigurationLookup lookup:ColumnSpacing col:0])
[runtime] 2023-09-06 08:28:34 [verbose]: |-|-SkinProvidingContainer+DisableableSkinSource{ skin: SkinTransformer{ Skin: LegacySkin{ Name: Test Skin [test-skin] } } }.GetConfig(lookup: [ManiaSkinConfigurationLookup lookup:ColumnSpacing col:0])
[runtime] 2023-09-06 08:28:34 [verbose]: |-|-|-SkinTransformer{ Skin: LegacySkin{ Name: Test Skin [test-skin] } }.GetConfig(lookup: [LegacyManiaSkinConfigurationLookup lookup:ColumnSpacing col:0 totalcols:4])
[runtime] 2023-09-06 08:28:34 [verbose]: |-|-|-|-LegacySkin{ Name: Test Skin [test-skin] }.GetConfig(lookup: [LegacyManiaSkinConfigurationLookup lookup:ColumnSpacing col:0 totalcols:4]) 🔴
[runtime] 2023-09-06 08:28:34 [verbose]: |-|-SkinProvidingContainer+DisableableSkinSource{ skin: SkinTransformer{ Skin: DefaultLegacySkin{ Name: osu! "classic" (2013) } } }.GetConfig(lookup: [ManiaSkinConfigurationLookup lookup:ColumnSpacing col:0])
[runtime] 2023-09-06 08:28:34 [verbose]: |-|-|-SkinTransformer{ Skin: DefaultLegacySkin{ Name: osu! "classic" (2013) } }.GetConfig(lookup: [LegacyManiaSkinConfigurationLookup lookup:ColumnSpacing col:0 totalcols:4])
[runtime] 2023-09-06 08:28:34 [verbose]: |-|-|-|-DefaultLegacySkin{ Name: osu! "classic" (2013) }.GetConfig(lookup: [LegacyManiaSkinConfigurationLookup lookup:ColumnSpacing col:0 totalcols:4]) 🟢
[runtime] 2023-09-06 08:28:34 [verbose]:

Confirmed useful by using the output to debug the source of failure for #24693.

We've struggle with debugging these over the years so I think this was
worth a couple of hours of work.

Example of osu! lookups:

```log
[runtime] 2023-09-06 08:38:30 [verbose]: BeatmapSkinProvidingContainer.GetConfig(lookup: SpinnerFrequencyModulate)
[runtime] 2023-09-06 08:38:30 [verbose]: |-SkinProvidingContainer+DisableableSkinSource{ skin: SkinTransformer{ Skin: LegacyBeatmapSkin{ Name: Vickeblanka - Lucky Ending (TV Size) (tears_) [Normal] } } }.GetConfig(lookup: SpinnerFrequencyModulate)
[runtime] 2023-09-06 08:38:30 [verbose]: |-RulesetSkinProvidingContainer.GetConfig(lookup: SpinnerFrequencyModulate)
[runtime] 2023-09-06 08:38:30 [verbose]: |-|-SkinProvidingContainer+DisableableSkinSource{ skin: SkinTransformer{ Skin: LegacySkin{ Name: Test Skin [test-skin] } } }.GetConfig(lookup: SpinnerFrequencyModulate)
[runtime] 2023-09-06 08:38:30 [verbose]: |-|-|-SkinTransformer{ Skin: LegacySkin{ Name: Test Skin [test-skin] } }.GetConfig(lookup: SpinnerFrequencyModulate)
[runtime] 2023-09-06 08:38:30 [verbose]: |-|-|-|-LegacySkin{ Name: Test Skin [test-skin] }.GetConfig(lookup: SpinnerFrequencyModulate) 🟢
[runtime] 2023-09-06 08:38:30 [verbose]: |-|-SkinProvidingContainer+DisableableSkinSource{ skin: SkinTransformer{ Skin: DefaultLegacySkin{ Name: osu! "classic" (2013) } } }.GetConfig(lookup: SpinnerFrequencyModulate)
[runtime] 2023-09-06 08:38:30 [verbose]: |-|-|-SkinTransformer{ Skin: DefaultLegacySkin{ Name: osu! "classic" (2013) } }.GetConfig(lookup: SpinnerFrequencyModulate)
[runtime] 2023-09-06 08:38:30 [verbose]: |-|-|-|-DefaultLegacySkin{ Name: osu! "classic" (2013) }.GetConfig(lookup: SpinnerFrequencyModulate) 🟢
[runtime] 2023-09-06 08:38:30 [verbose]: |-|-SkinProvidingContainer+DisableableSkinSource{ skin: osu.Game.Skinning.ResourceStoreBackedSkin }.GetConfig(lookup: SpinnerFrequencyModulate)
[runtime] 2023-09-06 08:38:30 [verbose]: |-|-|-osu.Game.Skinning.ResourceStoreBackedSkin.GetConfig(lookup: SpinnerFrequencyModulate) 🔴
[runtime] 2023-09-06 08:38:30 [verbose]: |-|-SkinProvidingContainer+DisableableSkinSource{ skin: TrianglesSkin{ Name: osu! "triangles" (2017) } }.GetConfig(lookup: SpinnerFrequencyModulate)
[runtime] 2023-09-06 08:38:30 [verbose]: |-|-|-TrianglesSkin{ Name: osu! "triangles" (2017) }.GetConfig(lookup: SpinnerFrequencyModulate) 🔴
[runtime] 2023-09-06 08:38:30 [verbose]:
[runtime] 2023-09-06 08:38:30 [verbose]: BeatmapSkinProvidingContainer.GetConfig(lookup: ScorePrefix)
[runtime] 2023-09-06 08:38:30 [verbose]: |-SkinProvidingContainer+DisableableSkinSource{ skin: SkinTransformer{ Skin: LegacyBeatmapSkin{ Name: Vickeblanka - Lucky Ending (TV Size) (tears_) [Normal] } } }.GetConfig(lookup: ScorePrefix)
[runtime] 2023-09-06 08:38:30 [verbose]: |-RulesetSkinProvidingContainer.GetConfig(lookup: ScorePrefix)
[runtime] 2023-09-06 08:38:30 [verbose]: |-|-SkinProvidingContainer+DisableableSkinSource{ skin: SkinTransformer{ Skin: LegacySkin{ Name: Test Skin [test-skin] } } }.GetConfig(lookup: ScorePrefix)
[runtime] 2023-09-06 08:38:30 [verbose]: |-|-|-SkinTransformer{ Skin: LegacySkin{ Name: Test Skin [test-skin] } }.GetConfig(lookup: ScorePrefix)
[runtime] 2023-09-06 08:38:30 [verbose]: |-|-|-|-LegacySkin{ Name: Test Skin [test-skin] }.GetConfig(lookup: ScorePrefix) 🟢
[runtime] 2023-09-06 08:38:30 [verbose]: |-|-SkinProvidingContainer+DisableableSkinSource{ skin: SkinTransformer{ Skin: DefaultLegacySkin{ Name: osu! "classic" (2013) } } }.GetConfig(lookup: ScorePrefix)
[runtime] 2023-09-06 08:38:30 [verbose]: |-|-|-SkinTransformer{ Skin: DefaultLegacySkin{ Name: osu! "classic" (2013) } }.GetConfig(lookup: ScorePrefix)
[runtime] 2023-09-06 08:38:30 [verbose]: |-|-|-|-DefaultLegacySkin{ Name: osu! "classic" (2013) }.GetConfig(lookup: ScorePrefix) 🟢
[runtime] 2023-09-06 08:38:30 [verbose]: |-|-SkinProvidingContainer+DisableableSkinSource{ skin: osu.Game.Skinning.ResourceStoreBackedSkin }.GetConfig(lookup: ScorePrefix)
[runtime] 2023-09-06 08:38:30 [verbose]: |-|-|-osu.Game.Skinning.ResourceStoreBackedSkin.GetConfig(lookup: ScorePrefix) 🔴
[runtime] 2023-09-06 08:38:30 [verbose]: |-|-SkinProvidingContainer+DisableableSkinSource{ skin: TrianglesSkin{ Name: osu! "triangles" (2017) } }.GetConfig(lookup: ScorePrefix)
[runtime] 2023-09-06 08:38:30 [verbose]: |-|-|-TrianglesSkin{ Name: osu! "triangles" (2017) }.GetConfig(lookup: ScorePrefix) 🔴
```

Example of osu!mania lookups:

```log
[runtime] 2023-09-06 08:28:34 [verbose]: |-RulesetSkinProvidingContainer.GetConfig(lookup: [ManiaSkinConfigurationLookup lookup:ColumnWidth col:0])
[runtime] 2023-09-06 08:28:34 [verbose]: |-|-SkinProvidingContainer+DisableableSkinSource{ skin: SkinTransformer{ Skin: LegacySkin{ Name: Test Skin [test-skin] } } }.GetConfig(lookup: [ManiaSkinConfigurationLookup lookup:ColumnWidth col:0])
[runtime] 2023-09-06 08:28:34 [verbose]: |-|-|-SkinTransformer{ Skin: LegacySkin{ Name: Test Skin [test-skin] } }.GetConfig(lookup: [LegacyManiaSkinConfigurationLookup lookup:ColumnWidth col:0 totalcols:4])
[runtime] 2023-09-06 08:28:34 [verbose]: |-|-|-|-LegacySkin{ Name: Test Skin [test-skin] }.GetConfig(lookup: [LegacyManiaSkinConfigurationLookup lookup:ColumnWidth col:0 totalcols:4]) 🔴
[runtime] 2023-09-06 08:28:34 [verbose]: |-|-SkinProvidingContainer+DisableableSkinSource{ skin: SkinTransformer{ Skin: DefaultLegacySkin{ Name: osu! "classic" (2013) } } }.GetConfig(lookup: [ManiaSkinConfigurationLookup lookup:ColumnWidth col:0])
[runtime] 2023-09-06 08:28:34 [verbose]: |-|-|-SkinTransformer{ Skin: DefaultLegacySkin{ Name: osu! "classic" (2013) } }.GetConfig(lookup: [LegacyManiaSkinConfigurationLookup lookup:ColumnWidth col:0 totalcols:4])
[runtime] 2023-09-06 08:28:34 [verbose]: |-|-|-|-DefaultLegacySkin{ Name: osu! "classic" (2013) }.GetConfig(lookup: [LegacyManiaSkinConfigurationLookup lookup:ColumnWidth col:0 totalcols:4]) 🟢
[runtime] 2023-09-06 08:28:34 [verbose]:
[runtime] 2023-09-06 08:28:34 [verbose]: BeatmapSkinProvidingContainer.GetConfig(lookup: [ManiaSkinConfigurationLookup lookup:ColumnSpacing col:0])
[runtime] 2023-09-06 08:28:34 [verbose]: |-SkinProvidingContainer+DisableableSkinSource{ skin: SkinTransformer{ Skin: LegacyBeatmapSkin{ Name: antiPLUR - Runengon (Raveille) [Easy] } } }.GetConfig(lookup: [ManiaSkinConfigurationLookup lookup:ColumnSpacing col:0])
[runtime] 2023-09-06 08:28:34 [verbose]: |-RulesetSkinProvidingContainer.GetConfig(lookup: [ManiaSkinConfigurationLookup lookup:ColumnSpacing col:0])
[runtime] 2023-09-06 08:28:34 [verbose]: |-|-SkinProvidingContainer+DisableableSkinSource{ skin: SkinTransformer{ Skin: LegacySkin{ Name: Test Skin [test-skin] } } }.GetConfig(lookup: [ManiaSkinConfigurationLookup lookup:ColumnSpacing col:0])
[runtime] 2023-09-06 08:28:34 [verbose]: |-|-|-SkinTransformer{ Skin: LegacySkin{ Name: Test Skin [test-skin] } }.GetConfig(lookup: [LegacyManiaSkinConfigurationLookup lookup:ColumnSpacing col:0 totalcols:4])
[runtime] 2023-09-06 08:28:34 [verbose]: |-|-|-|-LegacySkin{ Name: Test Skin [test-skin] }.GetConfig(lookup: [LegacyManiaSkinConfigurationLookup lookup:ColumnSpacing col:0 totalcols:4]) 🔴
[runtime] 2023-09-06 08:28:34 [verbose]: |-|-SkinProvidingContainer+DisableableSkinSource{ skin: SkinTransformer{ Skin: DefaultLegacySkin{ Name: osu! "classic" (2013) } } }.GetConfig(lookup: [ManiaSkinConfigurationLookup lookup:ColumnSpacing col:0])
[runtime] 2023-09-06 08:28:34 [verbose]: |-|-|-SkinTransformer{ Skin: DefaultLegacySkin{ Name: osu! "classic" (2013) } }.GetConfig(lookup: [LegacyManiaSkinConfigurationLookup lookup:ColumnSpacing col:0 totalcols:4])
[runtime] 2023-09-06 08:28:34 [verbose]: |-|-|-|-DefaultLegacySkin{ Name: osu! "classic" (2013) }.GetConfig(lookup: [LegacyManiaSkinConfigurationLookup lookup:ColumnSpacing col:0 totalcols:4]) 🟢
[runtime] 2023-09-06 08:28:34 [verbose]:

```
@peppy peppy force-pushed the skin-lookup-debug branch from 4770fbc to 1493667 Compare September 6, 2023 09:03
@bdach bdach self-requested a review September 6, 2023 15:43
@bdach
Copy link
Collaborator

bdach commented Sep 6, 2023

What's the intended way to use / enable this? Is it this?

diff --git a/Directory.Build.props b/Directory.Build.props
index 734374c840..015f402bcc 100644
--- a/Directory.Build.props
+++ b/Directory.Build.props
@@ -38,4 +38,7 @@
     <Copyright>Copyright (c) 2022 ppy Pty Ltd</Copyright>
     <PackageTags>osu game</PackageTags>
   </PropertyGroup>
+  <PropertyGroup>
+    <DefineConstants>SKIN_LOOKUP_DEBUG</DefineConstants>
+  </PropertyGroup>
 </Project>

osu.Game/Skinning/Skin.cs Show resolved Hide resolved
osu.Game/Skinning/Skin.cs Outdated Show resolved Hide resolved
osu.Game/Skinning/Skin.cs Outdated Show resolved Hide resolved
Co-authored-by: Bartłomiej Dach <[email protected]>
@peppy
Copy link
Member Author

peppy commented Sep 6, 2023

What's the intended way to use / enable this? Is it this?

Either what you have, or you can just #define at the top of the single file it's used in.

Rationale for not using envvar is to avoid the overhead in normal execution. But I'm not against using envvar + #if DEBUG or something similar if that's seen as easier to access.

@bdach
Copy link
Collaborator

bdach commented Sep 6, 2023

Eh I think it's fine. Was just curious how you did it, mostly.

@bdach bdach enabled auto-merge September 6, 2023 16:46
@bdach bdach disabled auto-merge September 6, 2023 17:28
@bdach bdach merged commit 9b202b5 into ppy:master Sep 6, 2023
@peppy peppy deleted the skin-lookup-debug branch September 14, 2023 07:24
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging this pull request may close these issues.

2 participants