Welcome Guest! To enable all features please Login or Register.

Notification

Icon
Error

Use Roslyn build
mattyboy
#1 Posted : Thursday, February 22, 2018 3:15:13 PM(UTC)
Rank: Newbie

Groups: Registered
Joined: 7/2/2015(UTC)
Posts: 6
Location: United Kingdom

Thanks: 2 times
Hi, I've been using NCrunch off and on for a few years. Have been using it happily for the last few months on a greenfield solution, which has grown as our team has added code.

As of the couple of weeks or so, NCrunch has slowed right down. As an example, I just changed some code in one of my tests:
VS build (Ctrl-Shift-B): 7 secs
NCrunch build (i.e. B icon with circle): 1min 51sec
NCrunch test (349 tests): 54 secs

The slow execution time is our fault - our tests still have some HTTP calls which need to be mocked. But the slow NCrunch build time is agony. And why the NCrunch build takes longer than Visual Studio is also a mystery. It never used to take this long. As a reference, a Rebuild Solution in VS takes 40secs. It's not only my machine, the rest of team have this pain too.

I wonder why does NCrunch have its own build process? Could or should it use the exes which are built by VS?

I'm not too sure how Roslyn works, but for example if I type bad code in VS, I immediately get an error appear in the Error List in VS. If I correct it it disappears. I guess this is Roslyn compiling the code for me and checking it? Can NCrunch use that?
Remco
#2 Posted : Thursday, February 22, 2018 11:00:43 PM(UTC)
Rank: NCrunch Developer

Groups: Administrators
Joined: 4/16/2011(UTC)
Posts: 5,144

Thanks: 680 times
Was thanked: 818 time(s) in 778 post(s)
Hi, thanks for posting.

To know more about how where the bottleneck is here, we'll need to take a look at some of the performance analysis results from one of your NCrunch builds.

The easiest way to do this is to turn on the Track engine performance setting. This will enable a new tab in the Tests Window allowing you to see where the time was spent in the pursuit of a test result. When you select one of your tests after a full test/run cycle (reset the engine with the 'Run all tests automatically' engine mode), this tab should give detailed information about both the test run and the build chain before it.

If you can export the results from this tab and copy/paste them here, or otherwise share details on which task appears to be the bottleneck, I may be able to help further.
mattyboy
#3 Posted : Friday, February 23, 2018 9:24:56 AM(UTC)
Rank: Newbie

Groups: Registered
Joined: 7/2/2015(UTC)
Posts: 6
Location: United Kingdom

Thanks: 2 times
Hi Remco,

Your help is appreciated!

Here's the results.

csv results here: https://www.dropbox.com/s/h59i6u47kldx2z3/ncrunch.csv?dl=0

It seems to be the "\Discover tests\Augment test discovery results with NCrunch metadata" step that is taking the bulk of the time.

Edit: a quick google leads me to Grendil's post. We are also using Autofixture and attributes, perhaps that is the problem too.

Matt
Remco
#4 Posted : Friday, February 23, 2018 11:03:39 PM(UTC)
Rank: NCrunch Developer

Groups: Administrators
Joined: 4/16/2011(UTC)
Posts: 5,144

Thanks: 680 times
Was thanked: 818 time(s) in 778 post(s)
Hi Matt,

Thanks for the CSV! This helps a great deal.

So the bottleneck in this case is in NCrunch's code. The first thing I would recommend checking is that you're running the latest version of NCrunch (v3.12). This version contained a fix targeting this area of code, which in earlier versions had a performance issue on some codebases.

Assuming you are already on v3.12, we'll need to try and figure out what is special about your code that is surfacing the performance issue so that we can recreate it. The code involved essentially takes a list of discovered tests (methods) and enumerates over all attributes attached to these methods. It also enumerates upwards through inheritance, so if you have a deep inheritance structure with a ton of attributes, this will greatly increase the work required. As you've mentioned that NCrunch was previously working OK on this codebase and the problem just started happening on its own, there must have been some kind of structural change to your test suite that has triggered the problem. If you can find what that is, we stand a good chance of reproducing it here.
mattyboy
#5 Posted : Saturday, February 24, 2018 10:54:14 AM(UTC)
Rank: Newbie

Groups: Registered
Joined: 7/2/2015(UTC)
Posts: 6
Location: United Kingdom

Thanks: 2 times
Just a quick note to say that I'm already running 3.12, so I will continue the investigation into the underlying cause.
mattyboy
#6 Posted : Tuesday, February 27, 2018 12:28:37 PM(UTC)
Rank: Newbie

Groups: Registered
Joined: 7/2/2015(UTC)
Posts: 6
Location: United Kingdom

Thanks: 2 times
OK so I've spent a day in order to fix this.

The problem is we use a custom Autofixture [AutoData] attribute on every test.

Our attribute's constructor creates a TestServer for running the web tests against. https://docs.microsoft.c...ing/integration-testing
We then inject the test server into each test, i.e.

[Scenario]
[RepairsWebHostAutoData]
public void CreateRepair(
WebApiClientFixture apiFixture

I've created a minimal repo with reproduction for you here: https://github.com/mattfrear/SlowNCrunch
If you add whitespace to my Test1(), then remove the whitespace, you'll see NCrunch's spinning B for like 60 seconds.

The bug IMO is that NCrunch is executing the constructor of the attribute during the Build step, instead of only when running the test.

In my case, I fixed this by introducing a base class for all of my tests which creates the TestServer (during test run), and dropped our custom [AutoData] attribute.

Matt
Remco
#7 Posted : Tuesday, February 27, 2018 10:34:02 PM(UTC)
Rank: NCrunch Developer

Groups: Administrators
Joined: 4/16/2011(UTC)
Posts: 5,144

Thanks: 680 times
Was thanked: 818 time(s) in 778 post(s)
Hi Matt,

Outstanding work in figuring this one out. Complex code in an attribute constructor will definitely cause this problem. Attribute constructors get called every time the attributes get enumerated using reflection, which can often result in accidental execution simply through meta-analysis. This is a limitation of the design of the CLR, since attributes themselves are usually considered to be metadata rather than runtime code.

We'll take a look at this one to see if there's anything we can do from the NCrunch side, but I'm not optimistic. It isn't possible for us to fully discover the tests without enumerating attributes, which would incidentally result in attribute constructor calls. Thanks for taking the time to produce a sample that can reproduce the problem.
mattyboy
#8 Posted : Wednesday, March 14, 2018 10:56:41 AM(UTC)
Rank: Newbie

Groups: Registered
Joined: 7/2/2015(UTC)
Posts: 6
Location: United Kingdom

Thanks: 2 times
Hi again,

Just to add to this, it did seem like the amount of time NCrunch took to analyze was a lot longer than the Sleep time in my attribute. E.g. the sleep time was set to 10 seconds, but NCrunch's build step would take around 60 seconds. So the attribute must be enumerated multiple times... I wonder if that could be improved?

Matt
Remco
#9 Posted : Wednesday, March 14, 2018 10:17:03 PM(UTC)
Rank: NCrunch Developer

Groups: Administrators
Joined: 4/16/2011(UTC)
Posts: 5,144

Thanks: 680 times
Was thanked: 818 time(s) in 778 post(s)
mattyboy;11919 wrote:

Just to add to this, it did seem like the amount of time NCrunch took to analyze was a lot longer than the Sleep time in my attribute. E.g. the sleep time was set to 10 seconds, but NCrunch's build step would take around 60 seconds. So the attribute must be enumerated multiple times... I wonder if that could be improved?


Yes, quite possibly, I will look into this.
Users browsing this topic
Guest (3)
Forum Jump  
You cannot post new topics in this forum.
You cannot reply to topics in this forum.
You cannot delete your posts in this forum.
You cannot edit your posts in this forum.
You cannot create polls in this forum.
You cannot vote in polls in this forum.

YAF | YAF © 2003-2011, Yet Another Forum.NET
This page was generated in 0.050 seconds.