Unity Startup IO analysis - slow to hit Play in editor - Resources/ loading

I have been looking at optimizing our startup time - from hitting ‘Play’ to starting any of our actual script loads was taking about 12 seconds. After digging through procmon calls on startup, I can see Unity is doing a lot of IO calls on startup. Let’s break them down a bit.

startup load system DLLs
scan full folder tree
load plugin DLLs (A)
scan full folder tree (B)
load system/DX dlls, etc
load dynamic resources from files directly (C) (interleaved)
load static resources from library cache (D) (interleaved)

A) plugin DLLs are loaded in 2b or 4b chunks per IO call
B) seems to be multiple full redundant folder scans
C) files are loaded mostly in 2048b or 7168b chunks, usually full but occasionally sparse
D) files are loaded mostly in 2048b or 7168b chunks, but larger files / faster than dynamic loads

Loading all the system DLLs, Unity DLLs, and plugin DLLs takes about 1-2 seconds. The rest is simply the full resource loading. The dynamic resources load is much slower, and seems to load more full files than sparse loads. A lot of the files are generally quite large, and reading with chunk sizes of 2048b or 7168b means a lot of IO calls per item. The majority of these files are unchanged from run to run, so some caching and timestamp checks could conceivably reduce startup time to almost nothing. There doesn’t really seem to be any actual work that needs doing on two subsequent runs.

(note: tautvydas-zilys mentioned the dynamic resources are loaded as an asset bundle, so it’s probably a pain to change loading there)

Some simple performance improvements might be:

a) increase load chunk size significantly (1-2mb buffer)
b) keep files in memory and file timestamp compare (instant load)
c) read in DLLs in one read instead of 2b/4b chunks (why?)

So the dynamic Resources/ load is much slower, moving most of our assets out of there into static folders reduced startup time to about 2s. I think it might be worth putting a warning on the Resources documentation (ie. this does not scale + loads all for any scene).

I’ve attached procmon logs, just a reminder that editor.log writes is not present because I run with -nolog since log file writes are two calls per BYTE. (Unity Script Compilation - IO analyis - Editor.log does two IO calls per byte written - Unity Engine - Unity Discussions)

Feel free to send me unity source so I can test and compare and write up findings. X)

TL;DR: Avoid using Resources/, it slows down hitting ‘play’ significantly.




1 Like

Added procmon analysis file.

2886439–212081–unity-startup-analysis-procmon.7z (2.59 MB)

Hi

I’ve had a look in our code and I do not see any of our file reads only reading the .dlls with 2-4 bytes at a time.

Our internal profiling of big projects have shown that the enter play mode and recompilation times are often slowed down by user scripts that invoked during these events.

I’m guessing that you have script / asset store package that reads the .dlls 2-4 bytes at a time when entering play mode. For instance the Panic Button package reads and modifies the .dlls and will slow down enter play mode times.

You can confirm what’s reading that data by using Windows Performance Analyzer. You should be able to see whether it’s asset store packages, your code or Unity itself doing it. Use “Unity+CPU+FileIO+DXGI.wprp” profile for that:

http://files.unity3d.com/zilys/ETWPerfGuide/data/CustomETWProfiles.html

Hi Zilys, sorry for the delay but I’m taking a look at this now and the wrwp doesn’t seem to be valid:

2932088--216839--upload_2017-1-23_11-42-34.png

I experimented a bit with WPA and got some results. It looks like FMOD file loads are taking up an unusually high amount of load time. It seems largely split into 4 categories.

  1. scanning project / mono / startup (lots of strlen and unusual number of calls to FindMonoBinaryToUse?)
  2. dense IO loading presumably assets (seems fairly solid block loads of large assets)
  3. Resources_CUSTOM_LoadAll (taking lots of time here)
  4. dense IO chunk #2 (not sure really)

#1, #3

can see preamble up to 4s, then a block of file loads from 4-6s; and a block at the end 10.5-12s~


We can see that Resources_CUSTOM_LoadAll() is where the bulk of time is going on CPU/IO:

Which is then further broken down into two main sections, the first being IntegrateAllThreadedObjects():

And the other bulk turns out to be something rather unexpected - a huge block of FMOD loads:

So in summary, it looks like most of the load is not super out of order – the YAML loads, strlen and general scanning seems mostly reasonable given the amount of work it’s doing; swapping YAML for binary loads would probably help but I’m sure it’s complicated for Reasons™.

FMOD load looks like something out of order on our setup, import settings or something, still investigating.

Removing the audio assets and digging into what else takes time, I’m curious why so many of these assets are being loaded from disk during startup - I would imagine they’re mostly already in memory when running from the editor?

In general it looks like the loads are not doing any weird 2b or 4b load chunks, if I am reading this correctly. Presumably the IO call tracking in the other tool I was using was maybe not profiling the reads in the right way (or confusing interleaved IO or something).