Test runner slowing to a crawl

Hi,

 

Since 2019.3 we've found that running unit tests slows to a crawl as more and more tests are run. For example in a typical run from the root by the time 640 tests have been run it's taking ten seconds or more per test. But if we run those tests as a single group they only take one or two seconds to run.

Those tests are outputting a lot of logging and it appears that commenting out some of our logging improves performance.

Our CI machine which runs the tests using NUnit completes them all in just under ten minutes whereas to be honest no-one knows how long R# test runner will take because even leaving the tests running over a lunch break didn't give them enough time to complete.

2 comments
Comment actions Permalink

Something else I've just noticed, looking at the stack trace for each test. If I run a smaller group of tests I can see that our database connection handler (created through Autofac, InstancePerLifetimeScope) is only instantiated once. But when a large number of tests are run the later ones shows dozens of connections being made:

Run as part of a small group:

6490 [NonParallelWorker] INFO xxxxx.Core.Server.Autofac.PostgresConnectionModule (null) - Creating NpgsqlConnection...
6546 [NonParallelWorker] INFO xxxxx.Core.Server.Autofac.AbstractElasticModule (null) - Automatically creating indices
6547 [NonParallelWorker] INFO xxxxx.Core.Server.Repository.Indexing.IndexManager (null) - Creating an index named mahon_filtering
6738 [NonParallelWorker] DEBUG xxxxx.Core.Server.Autofac.AbstractElasticModule (null) - Successful (200) low level call on HEAD: /mahon_filtering

Run as part of a large test:

146072 [NonParallelWorker] INFO xxxxx.Core.Server.Database.PostgresTestDbHook (null) - Creating DB with timestamp 05/03/2020 09:49:03
146072 [NonParallelWorker] INFO xxxxx.Core.Server.Database.PostgresTestDbHook (null) - Creating DB with timestamp 05/03/2020 09:49:03
146072 [NonParallelWorker] INFO xxxxx.Core.Server.Database.PostgresTestDbHook (null) - Creating DB with timestamp 05/03/2020 09:49:03
146072 [NonParallelWorker] INFO xxxxx.Core.Server.Database.PostgresTestDbHook (null) - Creating DB with timestamp 05/03/2020 09:49:03
146072 [NonParallelWorker] INFO xxxxx.Core.Server.Database.PostgresTestDbHook (null) - Creating DB with timestamp 05/03/2020 09:49:03
146072 [NonParallelWorker] INFO xxxxx.Core.Server.Database.PostgresTestDbHook (null) - Creating DB with timestamp 05/03/2020 09:49:03
146072 [NonParallelWorker] INFO xxxxx.Core.Server.Database.PostgresTestDbHook (null) - Creating DB with timestamp 05/03/2020 09:49:03
146072 [NonParallelWorker] INFO xxxxx.Core.Server.Database.PostgresTestDbHook (null) - Creating DB with timestamp 05/03/2020 09:49:03
146072 [NonParallelWorker] INFO xxxxx.Core.Server.Database.PostgresTestDbHook (null) - Creating DB with timestamp 05/03/2020 09:49:03
146072 [NonParallelWorker] INFO xxxxx.Core.Server.Database.PostgresTestDbHook (null) - Creating DB with timestamp 05/03/2020 09:49:03
146072 [NonParallelWorker] INFO xxxxx.Core.Server.Database.PostgresTestDbHook (null) - Creating DB with timestamp 05/03/2020 09:49:03
146072 [NonParallelWorker] INFO xxxxx.Core.Server.Database.PostgresTestDbHook (null) - Creating DB with timestamp 05/03/2020 09:49:03
146072 [NonParallelWorker] INFO xxxxx.Core.Server.Database.PostgresTestDbHook (null) - Creating DB with timestamp 05/03/2020 09:49:03
146072 [NonParallelWorker] INFO xxxxx.Core.Server.Database.PostgresTestDbHook (null) - Creating DB with timestamp 05/03/2020 09:49:03
146656 [NonParallelWorker] INFO xxxxx.Core.Server.Database.Migrations.MigrationExecutor (null) - Constructing MigrationExecutor for database 'DrFilterServiceIntegrationTest_2b4d058e20200305'...
146656 [NonParallelWorker] INFO xxxxx.Core.Server.Database.Migrations.MigrationExecutor (null) - Constructing MigrationExecutor for database 'DrFilterServiceIntegrationTest_2b4d058e20200305'...
146656 [NonParallelWorker] INFO xxxxx.Core.Server.Database.Migrations.MigrationExecutor (null) - Constructing MigrationExecutor for database 'DrFilterServiceIntegrationTest_2b4d058e20200305'...

Which seems odd. It looks like log entries are being duplicated.

Update:Yup, I think that's the issue. Each of the stack traces shows an additional repetition, so it looks like there's a logger that's not being disposed somewhere.

0
Comment actions Permalink

One of the recent updates to R# appears to have fixed this.

0

Please sign in to leave a comment.