Search Unity

  1. Welcome to the Unity Forums! Please take the time to read our Code of Conduct to familiarize yourself with the forum rules and how to post constructively.
  2. Dismiss Notice

Unity testing broken

Discussion in '2018.1 Beta' started by snacktime, Mar 25, 2018.

  1. snacktime

    snacktime

    Joined:
    Apr 15, 2013
    Posts:
    3,356
    Unit tests take so long to run they are effectively unusable. Just opening the test runner window takes forever.

    I started a unit test while writing this message. It's still not finished.
     
  2. superpig

    superpig

    Drink more water! Unity Technologies

    Joined:
    Jan 16, 2011
    Posts:
    4,614
    We use the test framework a lot internally and nobody's reported this, so I suspect it's something specific to your project or your Unity install. Did you file a bug report already?
     
  3. snacktime

    snacktime

    Joined:
    Apr 15, 2013
    Posts:
    3,356
    Won't do any good I don't think filing a bug report if I can't repro it with a small enough project. Mine is too big to send in and I wouldn't even know where to start getting a repro. The problem is obviously in work being done not directly related to Nunit. It takes about 45 seconds just to get to where it runs the test, which itself completes in the expected time.

    I suspect it's doing things which cause multiple passes of the general reload phase or parts of it. The project is big enough where a code change results in 30 seconds of waiting until you can play. So connecting the dots there it seems to be connected.
     
  4. superpig

    superpig

    Drink more water! Unity Technologies

    Joined:
    Jan 16, 2011
    Posts:
    4,614
    Alright. Let's see if we can narrow it down on your machine then...

    Have you tried opening the Profiler, turning on the 'Profile Editor' switch, and then opening the Test Runner window? That should capture why just opening the window is taking so long.
     
  5. snacktime

    snacktime

    Joined:
    Apr 15, 2013
    Posts:
    3,356
    Hmm it actually just locks up the editor and profiler. Both when opening the window and when running the test. When running it locks up for around 20 seconds, shows the diallog 'running such and such test' then immediately locks up again for another 20 or so seconds then completes.

    Like it's literally trying to get a lock on something and eventually times out. The cpu at that time is just spinning at a steady 30% but no disk activity.
     
  6. SugoiDev

    SugoiDev

    Joined:
    Mar 27, 2013
    Posts:
    395
    Same here. I tried using the profiler with no success.
    Took over a minute to open.




    It's the same thing when changing from "EditMode" to "PlayMode". Over a minute to switch.
    Messages will be shown, this time

    Skipping profile frame. Receiver can not keep up with the amount of data sent
    UnityEditor.TestTools.TestRunner.TestRunnerWindow:ShowPlaymodeTestsRunnerWindowCodeBased()


    Skipping profile frame. Receiver can not keep up with the amount of data sent

    The profiler will have a "blank" frame (no data) in the hiccup spot.

    This has been happening for me in all 2018 builds, but I couldn't reproduce on a small project so never got around to submitting a bug report.
     
  7. SugoiDev

    SugoiDev

    Joined:
    Mar 27, 2013
    Posts:
    395
    Maybe relevant: using the filter dropdown to the right of the search field is just as slow as changing tabs or re-opening the window. Takes a long time. From 20s to over a minute.
     
  8. superpig

    superpig

    Drink more water! Unity Technologies

    Joined:
    Jan 16, 2011
    Posts:
    4,614
    Hmm, ok. This makes me think it's something to do with building the test list, which involves iterating over assemblies...

    If the in-Unity profiler is not being much help, we need to try external ones. Are either of you familiar with Windows Performance Recorder? If so, that's probably the best tool to use; if not, we can try a tool like Very Sleepy to capture the freeze and see if we can figure out where the threads are at.
     
  9. snacktime

    snacktime

    Joined:
    Apr 15, 2013
    Posts:
    3,356
    Not familiar but shouldn't be a problem. Getting late here so I probably won't get back with any info until tomorrow my time.
     
  10. superpig

    superpig

    Drink more water! Unity Technologies

    Joined:
    Jan 16, 2011
    Posts:
    4,614
    No worries, whenever works for you. Here's the WPR docs - I think we want the 'CPU Usage' profile. When looking at the trace in WPA we should be able to see Unity.exe and dig into the callstacks that were sampled during the freeze.
     
  11. bdovaz

    bdovaz

    Joined:
    Dec 10, 2011
    Posts:
    1,015
  12. SugoiDev

    SugoiDev

    Joined:
    Mar 27, 2013
    Posts:
    395
    I'm posting the relevant screenshots of the meaty part (29s delay).
    If you need the full dump, let me know how send I can send it privately. Those contain a lot of info.

    Here's the gallery: https://imgur.com/a/uwo4t
    I let the Performance Analyzer download symbols from Unity's symbol servers and use the local copies as well.


    Edit: I only have a few dozen tests in this project. They are isolated to two custom assemblies (one for runtime, and one for editor tests).
     
  13. superpig

    superpig

    Drink more water! Unity Technologies

    Joined:
    Jan 16, 2011
    Posts:
    4,614
    Ah! Thank you. Harald is off sick at the moment, but this may mean he's already fixed the problem. I'll point him at this thread when he's back.

    Thanks!

    Right, so, from those screenshots, I can see that the time is being spent mostly in C# code - I believe the OnEnable call on the TestRunnerWindow itself (MonoBehaviour::AwakeFromLoad + MonoBehaviour::CallMethodInactive frame pairs are invoking OnEnable). Unfortunately, as you can see, the frames are just identified as ?!? - WPR/WPA doesn't capture the dynamic symbol information emitted by the Mono JIT. I've googled around a little but I can't see any way to make it capture that info. So... we're a bit stuck without Unity's profiler.

    Best thing to do for now is just to wait for Harald I think.
     
  14. SugoiDev

    SugoiDev

    Joined:
    Mar 27, 2013
    Posts:
    395
    > So... we're a bit stuck without Unity's profiler.

    Yeah. I hope the profiler gets some love eventually. I used to be able to get a better view of assembly reloads and compilation, but in recent versions (with .NET 4.x) I can't get anything useful from it for assembly reloads. This was especially useful to find stuff with InitializeOnLoad causing slowdowns.


    Here's two mode examples of what the profiler shows when opening the test runner. It's pretty random what it can see.






    > Best thing to do for now is just to wait for Harald I think.

    I think so too.
     
  15. HaraldNielsen

    HaraldNielsen

    Unity Technologies

    Joined:
    Jun 8, 2016
    Posts:
    133
    Hi,

    So yeah I'm currently adding multiple performance optimizations to the Test Runner Window, that will hopefully also speed up what you are experiencing here. Hoping that it will be included in 2018.1 release. Will let you know If I can get it included.
    Initially, I thought it was not possible to get it included but now there is a chance.
     
  16. snacktime

    snacktime

    Joined:
    Apr 15, 2013
    Posts:
    3,356
    What would probably help and a feature request anyways, is that we be able to have some way of specifying the location of tests. Similar to how outside of Unity best practice is a separate project for tests.

    One potential issue with scanning an entire project is that I don't want third party asset tests running when I run my tests. I'm assuming right now that would happen. It's also not a real issue right now because hardly any asset creators create tests, but that's another issue:)
     
  17. HaraldNielsen

    HaraldNielsen

    Unity Technologies

    Joined:
    Jun 8, 2016
    Posts:
    133
    @snacktime I haven't thought about assets from the Asset Store.
    But for packages, that are a new feature, this will automatically be solved. There we enforce usage of assembly definitions, and won't compile test assemblies that are just imported for normal usage.
     
  18. SebastianHjorth

    SebastianHjorth

    Unity Technologies

    Joined:
    Feb 13, 2018
    Posts:
    6
    @SugoiDev Can you please try profile editor, open up the test runner window, store the profiling session and attach the file here with the version of Unity used? I'll have a look at why the profiler did not pick up the data correctly.
    Also, I am curious as to why you keep hitting Skipping profile frame. Receiver can not keep up with the amount of data sent. Does this only happen when profiling playmode? It means that you are generating profiling data faster than the profiler can send/process the data, which should not happen unless your PC is under really heavy load.
     
  19. SugoiDev

    SugoiDev

    Joined:
    Mar 27, 2013
    Posts:
    395
    @SebastianHjorth

    >Can you please try profile editor, open up the test runner window, store the profiling session and attach the file here with the version of Unity used?

    Sure, give me a few minutes.
    I'm curious about that, since it gets pretty hard to debug assembly reload issues.

    >Skipping profile frame. Receiver can not keep up with the amount of data sent. Does this only happen when profiling playmode?

    No. It's in edit mode and load is pretty normal (<50%). I find it pretty strange too, since I only ever saw when debugging a remote player with deep profiling enabled. It also only shows once or twice. When I saw this with a built player, it would usually be spamming like crazy.
     
  20. SugoiDev

    SugoiDev

    Joined:
    Mar 27, 2013
    Posts:
    395
  21. SebastianHjorth

    SebastianHjorth

    Unity Technologies

    Joined:
    Feb 13, 2018
    Posts:
    6
    That's interesting. Would you mind submitting a but report on that?
     
  22. SugoiDev

    SugoiDev

    Joined:
    Mar 27, 2013
    Posts:
    395
    I'll create a small repro later today and submit a report. Should I ping you back here with the number?
     
    LeonhardP likes this.
  23. LeonhardP

    LeonhardP

    Unity Technologies

    Joined:
    Jul 4, 2016
    Posts:
    3,106
    Always :)
     
  24. SugoiDev

    SugoiDev

    Joined:
    Mar 27, 2013
    Posts:
    395
    @LeonhardP

    Alright. Took a while to see it on fogbugz. Case #1019376
     
  25. SebastianHjorth

    SebastianHjorth

    Unity Technologies

    Joined:
    Feb 13, 2018
    Posts:
    6
    Thank you!
    Also that log you posted is profiled using Deep profiling and Editor profiling, correct?
    Did it print that discard frames error?
     
  26. SugoiDev

    SugoiDev

    Joined:
    Mar 27, 2013
    Posts:
    395
    > Also that log you posted is profiled using Deep profiling and Editor profiling, correct?

    Yes.


    > Did it print that discard frames error?

    Yes, once.