[v4 Upgrade question]
I’ve got a ServiceStack project we are trying to upgrade from 3.9.71 to 4.0.11.
I’ve been following Cam Tucker’s excellent blog post as a guideline, and had the project building under 4.0.11 in about an afternoon.
I know I still have a few OrmLite breaking changes to correct, where some of the converted APIs that deal with single rows no longer throw an exception, but return null. That’s fine. I can work through the 2 dozen cases where that affects my code.
Unit test project has slowed down
My problem is my unit test project. I had about 430 test cases, and under SS v3, it took about 20-30 seconds to run through the whole suite. Now, under SS v4, it takes over 4 hours to run the whole suite. The first few tests run quickly, and then it slows more and more for each subsequent test.
Some tests are failing (those 2 dozen places where the OrmLite API is now returning a null when it used to throw), but most are passing. But even the tests that pass are slowing down.
I’ve enabled logging and captured the console output from the NUnit test runner, and seen that SS is reporting longer and longer application init times.
Here are the first ten tests running:
INFO: Initializing Application took 358.5717ms
INFO: Initializing Application took 63.0126ms
INFO: Initializing Application took 55.5111ms
INFO: Initializing Application took 55.011ms
INFO: Initializing Application took 224.0448ms
INFO: Initializing Application took 110.5221ms
INFO: Initializing Application took 112.0224ms
INFO: Initializing Application took 103.5207ms
INFO: Initializing Application took 113.0226ms
INFO: Initializing Application took 116.0232ms
By test 7, the init times start growing for each subsequent test. Here are tests 30-40 running:
INFO: Initializing Application took 523.6047ms
INFO: Initializing Application took 557.1114ms
INFO: Initializing Application took 584.1168ms
INFO: Initializing Application took 610.6221ms
INFO: Initializing Application took 682.1364ms
INFO: Initializing Application took 728.1456ms
INFO: Initializing Application took 741.1482ms
INFO: Initializing Application took 784.1568ms
INFO: Initializing Application took 823.6647ms
INFO: Initializing Application took 925.6851ms
INFO: Initializing Application took 1012.7025ms
And by tests 170-180, each test spends over a minute inside ServiceStack performing its initialization:
INFO: Initializing Application took 59993.4963ms
INFO: Initializing Application took 62644.0263ms
INFO: Initializing Application took 62009.3994ms
INFO: Initializing Application took 56106.219ms
INFO: Initializing Application took 59171.832ms
INFO: Initializing Application took 66881.8737ms
INFO: Initializing Application took 65739.6453ms
INFO: Initializing Application took 67384.9743ms
INFO: Initializing Application took 68630.2233ms
INFO: Initializing Application took 69208.3389ms
INFO: Initializing Application took 70019.5011ms
With DEBUG level logging, I can see many of the “Registering service” messages pausing for second before the next message is output (I should have enabled timestamps in the log). Here is just a snippet of the services registered by my assembly for one unit test:
DEBUG: Registering OneWay service ‘MeasurementContainerService’ with request 'PutMeasurementContainer’
DEBUG: Registering OneWay service ‘MeasurementContainerService’ with request 'DeleteMeasurementContainer’
DEBUG: Registering Reply service ‘MeasurementContainerService’ with request 'PostMeasurementContainer’
DEBUG: Registering Reply service ‘DatasetService’ with request 'GetDatasets’
DEBUG: Registering Reply service ‘DatasetService’ with request 'GetLocationDatasets’
DEBUG: Registering Reply service ‘DatasetService’ with request 'GetLocationsFromDatasets’
DEBUG: Registering Reply service ‘DatasetService’ with request 'GetDatasetViewModes’
DEBUG: Registering Reply service ‘DatasetService’ with request 'GetDatasetsByViewMode’
DEBUG: Registering Reply service ‘ParameterSetService’ with request 'GetParameterSets’
DEBUG: Registering OneWay service ‘VersionService’ with request 'GetVersion’
DEBUG: Registering Reply service ‘VisitService’ with request 'GetVisit’
DEBUG: Registering OneWay service ‘VisitService’ with request 'PutVisit’
DEBUG: Registering OneWay service ‘VisitService’ with request 'DeleteVisit’
DEBUG: Registering Reply service ‘VisitService’ with request 'PostVisit’
DEBUG: Registering Reply service ‘VisitService’ with request 'GetLocationVisits’
DEBUG: Registering Reply service ‘VolumetricDischargeService’ with request 'GetVolumetricDischarge’
DEBUG: Registering OneWay service ‘VolumetricDischargeService’ with request 'DeleteVolumetricDischarge’
DEBUG: Registering Reply service ‘VolumetricDischargeService’ with request 'PostVolumetricDischarge’
DEBUG: Registering Reply service ‘VolumetricDischargeService’ with request 'PutVolumetricDischarge’
DEBUG: Registering Reply service ‘AuthenticatedTestService’ with request 'AuthenticatedRequest’
DEBUG: Registering Reply service ‘UnauthenticatedTestService’ with request 'UnauthenticatedRequest’
DEBUG: Registering Reply service ‘DummyService’ with request 'GetDummyRequest’
If I select just one test to run, rather than the whole suite, that test will run quickly again (so if I rerun test 180, which had a 70 second init time as part of the whole suite, that test will take half a second to run, just like it used to under SS v3).
So this new eventually-slow-down-during-init behavior seems to be unrelated to the actual test being run, and is instead a function of the number of times the application init logic (DI configuration perhaps?) is called.
Things I’ve investigated so far:
1) Licensing overhead
I had first thought the slowdown might be to the new Licensing.RegisterLicense() method call, but I’ve put that method under a [SetUpFixture] attribute and confirmed that the licensing is only being configured once per test suite run.
So that’s not it.
2) AppHost resource leaks
My unit test AppHost (which subclasses AppHostHttpListenerBase) is being created/disposed for every test.
[Setup]
…
AppHost = new TestAppHost();
AppHost.Init();
AppHost.Start(ListeningOnApi);
…
[Teardown]
…
if (AppHost != null)
{
AppHost.Stop();
AppHost.Dispose();
AppHost = null;
}
So I think that’s right.
I’m out of ideas now. I won’t be surprised if my v3 unit test project was already constructed under some bad pattern, but worked despite itself, while SS v4 makes the bad pattern more painful/obvious.
Any ideas? My team can’t move forward with our paid SS v4 offering until I can get the unit tests (which run as part of our build) to complete in a reasonable amount of time.
Cheers,
Doug Schmidt
Hi Doug, is it possible I can see some examples of a typical test?
Nicklas Laine Overgaard:
A way to try and narrow down the problem cloud be running the unit tests via some profiling software. I know that redgates performance profiler supports timing nunit projects : http://documentation.red-gate.com/display/APP8/Profiling+unit+tests+using+Nunit
If you don’t have a license for it, they provide a fully functional version for 14 days. Please note that I’m not affiliated with redgate, I just use their product 
Doug Schmidt:
OK, I’ve finally got some bandwidth on this conversion again.
+Nicklas Overgaard Thanks for the profiling tip. I’ve used JetBrain’s dotTrace product, and found that the two hotspots are:
ServiceStack.Text/ReflectionExtensions.cs: ServiceStack.PlatformExtensions.AllAttributes(Type)
ServiceStack.Interfaces/AttributeBase.cs: ServiceStack.AttributeBase.get_TypeId()
I haven’t been able to pinpoint it further than that, but both of those methods had accumulated nearly an hour of CPU time each during my test suite run.
+Demis Bellot I’ll post the standard test pattern we use in a separate comment.
hmm, interesting thanks for the pointers. Will investigate to see if I can see anything weird there.
Doug Schmidt:
+Demis Bellot Here’s the standard test pattern we use:
[SetUp]
public void OnTestSetup()
{
Acquire();
AppHost = new TestAppHost();
AppHost.Init();
AppHost.Start(ListeningOnApi);
DbConnection = AppHost.Container.TryResolve<IDbConnectionFactory>().Open();
MockSiteVisitDatabase.DropAndCreateDummyDatabaseSchema(DbConnection);
IdGenerator = AppHost.Container.TryResolve<IDatabaseIdGenerator>();
TestData = new DbHelper(DbConnection, IdGenerator);
LocationHelper = new LocationHelper(DbConnection, IdGenerator);
TimeSeriesHelper = new TimeSeriesHelper(DbConnection, IdGenerator);
ServiceClient = new JsonServiceClient(ListeningOnApi);
}
[TearDown]
public void OnTestFixtureTearDown()
{
if (AppHost != null)
{
AppHost.Stop();
AppHost.Dispose();
AppHost = null;
}
if (DbConnection != null)
{
DbConnection.Close();
DbConnection.Dispose();
DbConnection = null;
}
Release();
}
Each test ends up with this common preamble:
1) creating its own AppHost
2) creating an in-memory SQLite DB
3) listening on a fixed HTTP port
4) creating a Json service client talking to that fixed port.
When each test ends:
1) The AppHost and DB connection are disposed off
Here’s is a sample test:
[Test]
public void GetEnumValues_KnownType_ReturnsLocalizedPicklist()
{
var knownType = typeof(ActivityType);
var knownTypeName = knownType.Name;
InsertPartiallyLocalizedEnum(knownType);
var request = new GetEnumValues { Type = knownTypeName };
var response = ServiceClient.Get(request);
AssertThatEnumPicklistIsValid(knownType, response);
}
Each test follows the pattern:
1) Insert any required test data into the empty DB
2) Call the REST API via the JsonServiceClient.
3) Make assertions on the received response.
We’ve got 400+ tests like this, and they run super-fast on V3, but when run under v4, the time spent inside AppHost.Init() grows exponentially.
thx for the details Doug, will look to see if I can repro the issue on my side.
Hey Doug,
I’m having trouble trying to repro the slow downs. I’ve created a new Test project with Multiple Test fixtures, each with 100 tests that closely matches the description of your test framework, i.e. performs a client call to a web services that returns a result from the database you can see at:
https://github.com/ServiceStack/ServiceStack/blob/master/tests/CheckHttpListener/AnalyzeTestSideEffects.cs
I’ve then created 10 test fixtures you can run at the same time at: https://github.com/ServiceStack/ServiceStack/blob/master/tests/CheckHttpListener/ManyTestFixtures.cs
and so far I’m not able to see any slowdown, i.e. the last test in the last test fixture (i.e Test #1000) essentially takes about the same time.
I’m hoping you can could add something to these tests that can show the issues.
Doug Schmidt:
Yeah, I’ve been trying to rebuild something reproducible from the ground up as well. No luck here either. Every project except my production one runs just fine. 
I’ll see if I can extend the projects you listed and reproduce it.
If not, is there a way we might be able to do a pair debug session (via Skype screenshare or whatever?) I might need to strip everything down into a standalone private repo and send it over to you that way.
I’ll do a bit more investigation a bit more on my side but basically I need to be able to repro it on myside to be sure I’ve identified and correctly resolved what the issue is.
Other than that if there’s a profiler snapshot I could look at locally, that might also help.
Doug Schmidt:
+Demis Bellot I’ve made a bit of progress narrowing down the culprit for slow unit test initialization.
I still can only reproduce it in my repo, not in the test projects you added to the SS repo yesterday. I will create a private GitHub repo this afternoon that house enough of my project so that you can build it, reproduce the scenario, and dig deeper.
While I’m getting that repo ready, here’s more info for you to inspect: I configured log4net logging, so I could get some precise timing info on the slow init. When I ran the test project under the NUnit test runner, I could see that the exponentially-growing “stall” happens:
- DURING the call to AppHost.Init()
- AFTER registering the last service of my ServiceInterface.dll
- BEFORE registering the default authentication & roles services from ServiceStack.Auth
Here is a reduced log snippet that shows a 26 second duration of AppHost.Init(). Almost all of that 26 seconds is between ‘DummyService’ (my code) and ‘AuthenticateService’ (ServiceStack.Auth):
2014-02-25 11:52:13,662 [TestRunnerThread] INFO WebApps.ServiceInterface.Tests.TestBase - Before AppHost.Init()
…
2014-02-25 11:52:13,665 [TestRunnerThread] DEBUG ServiceStack.Host.ServiceController - Registering Reply service ‘ActivityService’ with request 'GetActivity’
2014-02-25 11:52:13,682 [TestRunnerThread] DEBUG ServiceStack.Host.ServiceController - Registering Reply service ‘DummyService’ with request 'GetDummyRequest’
2014-02-25 11:52:38,952 [TestRunnerThread] DEBUG ServiceStack.Host.ServiceController - Registering Reply service ‘AuthenticateService’ with request 'Authenticate’
2014-02-25 11:52:39,480 [TestRunnerThread] DEBUG ServiceStack.Host.ServiceController - Registering Reply service ‘AssignRolesService’ with request 'AssignRoles’
2014-02-25 11:52:39,885 [TestRunnerThread] DEBUG ServiceStack.Host.ServiceController - Registering Reply service ‘UnAssignRolesService’ with request 'UnAssignRoles’
2014-02-25 11:52:39,889 [TestRunnerThread] INFO ServiceStack.ServiceStackHost - Initializing Application took 26226.2442ms
2014-02-25 11:52:39,889 [TestRunnerThread] INFO WebApps.ServiceInterface.Tests.TestBase - After AppHost.Init()
Further, when I clicked “Stop” on the NUnit GUI to kill the test, NUnit was now wired into log4net and thankfully logged the call stack of the aborted thread, which confirms my earlier findings. Hopefully this call stack below, plus the ServiceStack.Auth hint above, will point to the culprit:
2014-02-25 11:28:24,581 [TestRunnerThread] DEBUG ServiceStack.Host.ServiceController - Registering Reply service ‘DummyService’ with request 'GetDummyRequest’
2014-02-25 11:28:25,115 [TestRunnerThread] ERROR ServiceStack.DtoUtils - ServiceBase<TRequest>::Service Exception
System.Threading.ThreadAbortException: Thread was being aborted.
at System.Array.Copy(Array sourceArray, Int32 sourceIndex, Array destinationArray, Int32 destinationIndex, Int32 length, Boolean reliable)
at System.ComponentModel.AttributeCollection.CopyTo(Array array, Int32 index)
at System.ComponentModel.TypeDescriptor.AttributeProvider.AttributeTypeDescriptor.GetAttributes()
at System.ComponentModel.TypeDescriptor.TypeDescriptionNode.DefaultTypeDescriptor.System.ComponentModel.ICustomTypeDescriptor.GetAttributes()
at System.ComponentModel.CustomTypeDescriptor.GetAttributes()
at System.ComponentModel.TypeDescriptor.AttributeProvider.AttributeTypeDescriptor.GetAttributes()
at System.ComponentModel.TypeDescriptor.TypeDescriptionNode.DefaultTypeDescriptor.System.ComponentModel.ICustomTypeDescriptor.GetAttributes()
at System.ComponentModel.CustomTypeDescriptor.GetAttributes()
at System.ComponentModel.TypeDescriptor.AttributeProvider.AttributeTypeDescriptor.GetAttributes()
at System.ComponentModel.TypeDescriptor.TypeDescriptionNode.DefaultTypeDescriptor.System.ComponentModel.ICustomTypeDescriptor.GetAttributes()
at System.ComponentModel.CustomTypeDescriptor.GetAttributes()
at System.ComponentModel.TypeDescriptor.AttributeProvider.AttributeTypeDescriptor.GetAttributes()
at System.ComponentModel.TypeDescriptor.TypeDescriptionNode.DefaultTypeDescriptor.System.ComponentModel.ICustomTypeDescriptor.GetAttributes()
at System.ComponentModel.CustomTypeDescriptor.GetAttributes()
at System.ComponentModel.TypeDescriptor.AttributeProvider.AttributeTypeDescriptor.GetAttributes()
at System.ComponentModel.TypeDescriptor.TypeDescriptionNode.DefaultTypeDescriptor.System.ComponentModel.ICustomTypeDescriptor.GetAttributes()
at System.ComponentModel.CustomTypeDescriptor.GetAttributes()
at System.ComponentModel.TypeDescriptor.AttributeProvider.AttributeTypeDescriptor.GetAttributes()
at System.ComponentModel.TypeDescriptor.TypeDescriptionNode.DefaultTypeDescriptor.System.ComponentModel.ICustomTypeDescriptor.GetAttributes()
at System.ComponentModel.CustomTypeDescriptor.GetAttributes()
at System.ComponentModel.TypeDescriptor.AttributeProvider.AttributeTypeDescriptor.GetAttributes()
at System.ComponentModel.TypeDescriptor.TypeDescriptionNode.DefaultTypeDescriptor.System.ComponentModel.ICustomTypeDescriptor.GetAttributes()
at System.ComponentModel.CustomTypeDescriptor.GetAttributes()
at System.ComponentModel.TypeDescriptor.AttributeProvider.AttributeTypeDescriptor.GetAttributes()
at System.ComponentModel.TypeDescriptor.TypeDescriptionNode.DefaultTypeDescriptor.System.ComponentModel.ICustomTypeDescriptor.GetAttributes()
at System.ComponentModel.CustomTypeDescriptor.GetAttributes()
at System.ComponentModel.TypeDescriptor.AttributeProvider.AttributeTypeDescriptor.GetAttributes()
at System.ComponentModel.TypeDescriptor.TypeDescriptionNode.DefaultTypeDescriptor.System.ComponentModel.ICustomTypeDescriptor.GetAttributes()
at System.ComponentModel.CustomTypeDescriptor.GetAttributes()
at System.ComponentModel.TypeDescriptor.AttributeProvider.AttributeTypeDescriptor.GetAttributes()
at System.ComponentModel.TypeDescriptor.TypeDescriptionNode.DefaultTypeDescriptor.System.ComponentModel.ICustomTypeDescriptor.GetAttributes()
at System.ComponentModel.TypeDescriptor.GetAttributes(Type componentType)
at ServiceStack.PlatformExtensions.AllAttributes(Type type)
at ServiceStack.PlatformExtensions.HasAttribute[T](Type type)
at ServiceStack.PlatformExtensions.IsDto(Type type)
at ServiceStack.ReflectionExtensions.GetSerializableProperties(Type type)
at ServiceStack.Serialization.StringMapTypeDeserializer…ctor(Type type)
at ServiceStack.Host.RestPath…ctor(Type requestType, String path, String verbs, String summary, String notes)
at ServiceStack.Host.ServiceController.RegisterRestPaths(Type requestType)
at ServiceStack.Host.ServiceController.RegisterService(ITypeFactory serviceFactoryFn, Type serviceType)
at ServiceStack.Host.ServiceController.RegisterService(Type serviceType)
2014-02-25 11:28:25,123 [TestRunnerThread] ERROR ServiceStack.Host.ServiceController - Thread was being aborted.
System.Threading.ThreadAbortException: Thread was being aborted.
at System.Array.Copy(Array sourceArray, Int32 sourceIndex, Array destinationArray, Int32 destinationIndex, Int32 length, Boolean reliable)
at System.ComponentModel.AttributeCollection.CopyTo(Array array, Int32 index)
at System.ComponentModel.TypeDescriptor.AttributeProvider.AttributeTypeDescriptor.GetAttributes()
at System.ComponentModel.TypeDescriptor.TypeDescriptionNode.DefaultTypeDescriptor.System.ComponentModel.ICustomTypeDescriptor.GetAttributes()
at System.ComponentModel.CustomTypeDescriptor.GetAttributes()
at System.ComponentModel.TypeDescriptor.AttributeProvider.AttributeTypeDescriptor.GetAttributes()
at System.ComponentModel.TypeDescriptor.TypeDescriptionNode.DefaultTypeDescriptor.System.ComponentModel.ICustomTypeDescriptor.GetAttributes()
at System.ComponentModel.CustomTypeDescriptor.GetAttributes()
at System.ComponentModel.TypeDescriptor.AttributeProvider.AttributeTypeDescriptor.GetAttributes()
at System.ComponentModel.TypeDescriptor.TypeDescriptionNode.DefaultTypeDescriptor.System.ComponentModel.ICustomTypeDescriptor.GetAttributes()
at System.ComponentModel.CustomTypeDescriptor.GetAttributes()
at System.ComponentModel.TypeDescriptor.AttributeProvider.AttributeTypeDescriptor.GetAttributes()
at System.ComponentModel.TypeDescriptor.TypeDescriptionNode.DefaultTypeDescriptor.System.ComponentModel.ICustomTypeDescriptor.GetAttributes()
at System.ComponentModel.CustomTypeDescriptor.GetAttributes()
at System.ComponentModel.TypeDescriptor.AttributeProvider.AttributeTypeDescriptor.GetAttributes()
at System.ComponentModel.TypeDescriptor.TypeDescriptionNode.DefaultTypeDescriptor.System.ComponentModel.ICustomTypeDescriptor.GetAttributes()
at System.ComponentModel.CustomTypeDescriptor.GetAttributes()
at System.ComponentModel.TypeDescriptor.AttributeProvider.AttributeTypeDescriptor.GetAttributes()
at System.ComponentModel.TypeDescriptor.TypeDescriptionNode.DefaultTypeDescriptor.System.ComponentModel.ICustomTypeDescriptor.GetAttributes()
at System.ComponentModel.CustomTypeDescriptor.GetAttributes()
at System.ComponentModel.TypeDescriptor.AttributeProvider.AttributeTypeDescriptor.GetAttributes()
at System.ComponentModel.TypeDescriptor.TypeDescriptionNode.DefaultTypeDescriptor.System.ComponentModel.ICustomTypeDescriptor.GetAttributes()
at System.ComponentModel.CustomTypeDescriptor.GetAttributes()
at System.ComponentModel.TypeDescriptor.AttributeProvider.AttributeTypeDescriptor.GetAttributes()
at System.ComponentModel.TypeDescriptor.TypeDescriptionNode.DefaultTypeDescriptor.System.ComponentModel.ICustomTypeDescriptor.GetAttributes()
at System.ComponentModel.CustomTypeDescriptor.GetAttributes()
at System.ComponentModel.TypeDescriptor.AttributeProvider.AttributeTypeDescriptor.GetAttributes()
at System.ComponentModel.TypeDescriptor.TypeDescriptionNode.DefaultTypeDescriptor.System.ComponentModel.ICustomTypeDescriptor.GetAttributes()
at System.ComponentModel.CustomTypeDescriptor.GetAttributes()
at System.ComponentModel.TypeDescriptor.AttributeProvider.AttributeTypeDescriptor.GetAttributes()
at System.ComponentModel.TypeDescriptor.TypeDescriptionNode.DefaultTypeDescriptor.System.ComponentModel.ICustomTypeDescriptor.GetAttributes()
at System.ComponentModel.TypeDescriptor.GetAttributes(Type componentType)
at ServiceStack.PlatformExtensions.AllAttributes(Type type)
at ServiceStack.PlatformExtensions.HasAttribute[T](Type type)
at ServiceStack.PlatformExtensions.IsDto(Type type)
at ServiceStack.ReflectionExtensions.GetSerializableProperties(Type type)
at ServiceStack.Serialization.StringMapTypeDeserializer…ctor(Type type)
at ServiceStack.Host.RestPath…ctor(Type requestType, String path, String verbs, String summary, String notes)
at ServiceStack.Host.ServiceController.RegisterRestPaths(Type requestType)
at ServiceStack.Host.ServiceController.RegisterService(ITypeFactory serviceFactoryFn, Type serviceType)
at ServiceStack.Host.ServiceController.RegisterService(Type serviceType)
2014-02-25 11:28:25,125 [TestRunnerThread] ERROR ServiceStack.DtoUtils - ServiceBase<TRequest>::Service Exception
System.Threading.ThreadAbortException: Thread was being aborted.
at ServiceStack.Host.ServiceController.RegisterService(Type serviceType)
at ServiceStack.ServiceStackHost.RegisterService(Type serviceType, String[] atRestPaths)
at ServiceStack.AuthFeature.Register(IAppHost appHost)
at ServiceStack.ServiceStackHost.LoadPlugin(IPlugin[] plugins)
Hopefully this info helps you while I try to construct my test repo this afternoon.
PS: Is there a better way to communicate these long log file dumps other than Google+? Typing all this crap in a small textbox is madness!
Yes there is the issues website is a better place for submitting issues:
https://github.com/ServiceStack/Issues
I’ve just created a new ticket for this issue using your last comment:
https://github.com/ServiceStack/Issues/issues/40
Lets continue on from there, yeah a private repo would be helpful thx.