Pathoschild / SMAPI

The modding API for Stardew Valley.
https://smapi.io/
GNU Lesser General Public License v3.0
1.87k stars 263 forks source link

Investigate tilesheet corruption #424

Closed Pathoschild closed 6 years ago

Pathoschild commented 6 years ago

Some players report intermittent tilesheet corruption:

Pathoschild commented 6 years ago

If you're affected, please reply with the following info. (Feel free to skip any questions you don't know.)

InsaneJ commented 6 years ago

I saw this happen on my farm yesterday the moment I got out of bed and went outside. It looked very much like the screenshot above. Unfortunately I don't have the log file for it. Reloading the safe game resolved the issue for me. I didn't venture outside of the farm so I don't know if this happens elsewhere as well.

This is the mod list I was using:

Pathoschild commented 6 years ago

@InsaneJ Can you attach a zip of your save files and Mods folder?

InsaneJ commented 6 years ago

I've started a new game and noticed corruption in town: stardew valley - tile corruption in town

Log up to the moment I walked into town: https://paste2.org/eGkODDKY Save up to the day I walked into town: Bman_175631855.zip Mods folder: Mods.zip

InsaneJ commented 6 years ago

Trying to figure out which mods trigger the tile corruption I've found that UI info suite and CarryChest both trigger the issue. Having either one of them in my mods folder results in the screenshot above.

Pathoschild commented 6 years ago

@InsaneJ Thanks! I can't reproduce the issue with your save and mods. Do you have any mods installed under Content?

Pathoschild commented 6 years ago

@InsaneJ I can reproduce tilesheet corruption on the farm with your save (though it's intermittent), thanks! I'll look into this for SMAPI 2.4.

Pathoschild commented 6 years ago

Observations:

Pathoschild commented 6 years ago

Further testing:

Pathoschild commented 6 years ago

The issue most likely happens sometime during the async SaveGame.GetLoadEnumerator method. Here's the stack trace when the asset is first loaded by SMAPI (identical with and without corruption):

   at StardewModdingAPI.Framework.SContentManager.<>c__DisplayClass41_0`1.<LoadImpl>b__0()
   at StardewModdingAPI.Framework.SContentManager.WithWriteLock[T](Func`1 action)
   at StardewModdingAPI.Framework.SContentManager.LoadImpl[T](String assetName, ContentManager instance)
   at StardewModdingAPI.Framework.SContentManager.LoadFor[T](String assetName, ContentManager instance)
   at StardewModdingAPI.Framework.ContentManagerShim.Load[T](String assetName)
   at xTile.Display.XnaDisplayDevice.LoadTileSheet(TileSheet tileSheet)
   at xTile.Map.LoadTileSheets(IDisplayDevice displayDevice)
   at StardewValley.Game1.setGraphicsForSeason()
   at StardewValley.Game1.loadForNewGame(Boolean loadedGame)
   at StardewValley.SaveGame.<>c.<getLoadEnumerator>b__51_1()
   at System.Threading.Tasks.Task.InnerInvoke()
   at System.Threading.Tasks.Task.Execute()
   at System.Threading.Tasks.Task.ExecutionContextCallback(Object obj)
   at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx)
   at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx)
   at System.Threading.Tasks.Task.ExecuteWithThreadLocal(Task& currentTaskSlot)
   at System.Threading.Tasks.Task.ExecuteEntry(Boolean bPreventDoubleExecution)
   at System.Threading.Tasks.Task.System.Threading.IThreadPoolWorkItem.ExecuteWorkItem()
   at System.Threading.ThreadPoolWorkQueue.Dispatch()
   at System.Threading._ThreadPoolWaitCallback.PerformWaitCallback()
Pathoschild commented 6 years ago

I ran some tests to track corruption of Maps\spring_outdoorsTileSheet while progressively reducing SMAPI's asset interception:

test case corruption in test loads
normal 00001 00100 00000 00001 ✖
SContentManager.LoadImpl<T> ignores loaders 00000 00111 10011 10010 ✖
SContentManager.LoadImpl<T> ignores loaders + editors 11100 10010 10001 10000 ✖
SContentManager.LoadImpl<T> defers to base.Load for loading 01010 01000 00000 01000 ✖
SContentManager.LoadImpl<T> just calls base.Load 10000 10011 10000 00000 ✖
SContentManager.LoadFor<T> just calls base.Load 00000 10011 11101 01000 ✖
IContentHelper.Load<T> does nothing 00000 00000 10011 10000 ✖
IContentHelper does nothing 01001 00100 10110 00000 ✖
SContentManager does nothing (except passthrough Load) 01001 01100 10110 11110 ✖
content interception feature removed entirely 00000 00000 00000 00000 ✓

So the issue is most likely caused by the content interception or something interacting with it, but the issue occurs even if that content interception does nothing.

In very rare cases (roughly 3 of those 200 tests), I saw errors like this. These suggest a race condition due to parallel code; but if that's the cause, it's unclear why it doesn't happen when content interception is removed.

[23:29:37 TRACE Console.Out] getLoadEnumerator('Bman_175631855')
[23:29:39 ERROR Extended Minecart] Could not patch the Beach due to a unknown error
System.ArgumentException: An item with the same key has already been added.
   at System.ThrowHelper.ThrowArgumentException(ExceptionResource resource)
   at System.Collections.Generic.Dictionary`2.Insert(TKey key, TValue value, Boolean add)
   at Microsoft.Xna.Framework.Content.ContentManager.Load[T](String assetName)
   at StardewValley.LocalizedContentManager.Load[T](String assetName)
   at StardewModdingAPI.Framework.SContentManager.LoadFor[T](String assetName, ContentManager instance) in C:\source\_Stardew\SMAPI\src\SMAPI\Framework\SContentManager.cs:line 206
   at StardewModdingAPI.Framework.ContentManagerShim.Load[T](String assetName) in C:\source\_Stardew\SMAPI\src\SMAPI\Framework\ContentManagerShim.cs:line 40
   at xTile.Display.XnaDisplayDevice.LoadTileSheet(TileSheet tileSheet)
   at xTile.Map.LoadTileSheets(IDisplayDevice displayDevice)
   at Entoarox.ExtendedMinecart.ExtendedMinecartMod.GameEvents_UpdateTick(Object s, EventArgs e)
[23:29:39 TRACE Console.Out] gameMode was 'loadingMode (6)', set to 'selectGameScreen (9)'.
[23:29:39 ERROR Console.Out] System.InvalidOperationException: Collection was modified; enumeration operation may not execute.
   at System.ThrowHelper.ThrowInvalidOperationException(ExceptionResource resource)
   at System.Collections.Generic.List`1.Enumerator.MoveNextRare()
   at System.Collections.Generic.List`1.Enumerator.MoveNext()
   at xTile.Map.LoadTileSheets(IDisplayDevice displayDevice)
   at StardewValley.Game1.setGraphicsForSeason()
   at StardewValley.Game1.loadForNewGame(Boolean loadedGame)
   at StardewValley.SaveGame.<>c.<getLoadEnumerator>b__51_1()
   at System.Threading.Tasks.Task.InnerInvoke()
   at System.Threading.Tasks.Task.Execute()
Pathoschild commented 6 years ago

Fixed in develop for the upcoming SMAPI 2.4.

The cause is pretty obvious in retrospect. SMAPI pauses mods when the game is running async code, but it doesn't pause mods while a save file is loading. Loading happens asynchronously, which means mods using update-tick events can run code while the save is loading on a separate thread. In rare cases, a mod will use the GPU just as a tilesheet file is being loaded, corrupting the tilesheet. The reason mods which use the content manager tend to trigger the corruption isn't because of the content manager directly, it's just because they're more likely to use the GPU while a tilesheet is being loaded.

As of SMAPI 2.4, SMAPI will no longer raise events while a load is in progress.