Django tests taking a long time to start

Refresh

April 2019

Views

79 time

1

I'm running tests on a django App called stats which uses a Postgre database. The project keeps all tests in a folder ./stats/tests/.

When I run a test i.e. python manage.py test stats.tests.test_dataGeneration, several minutes of nothing pass where the text cursor in my command line just blinks. At this early stage I cannot even use a keyboard interrupt to instantly stop the test (keyboard interrupt takes at least 30 seconds to register).

Eventually, after several minutes I see the
Creating test database for alias 'default' ('test_statsdb')...
message which creates the database for testing. From this point the tests always complete in less than 10 seconds (as in django outputs Ran XX tests in 5.00s).

I don't know or understand why the tests take so long to start, or what is exactly being executed in the first few minutes. A few days ago I had no issues testing the app. Using --keepdb to recycle the test database between test runs does not noticeably improve the time that running tests takes.

I was hoping someone could shed some light on what is happeneing.

Example output of test results when i run them with verbosity=2 for extra details:
>python manage.py test stats.tests.test_dataGeneration --verbosity=2

Creating test database for alias 'default' ('test_statsdb')...
Operations to perform:
  Synchronize unmigrated apps: messages, portfolio_web, staticfiles, updateDatabase
  Apply all migrations: auth, contenttypes, sessions, stats
Synchronizing apps without migrations:
  Creating tables...
    Running deferred SQL...
Running migrations:
  Applying contenttypes.0001_initial... OK
  Applying contenttypes.0002_remove_content_type_name... OK
  Applying auth.0001_initial... OK
  Applying auth.0002_alter_permission_name_max_length... OK
  Applying auth.0003_alter_user_email_max_length... OK
  Applying auth.0004_alter_user_username_opts... OK
  Applying auth.0005_alter_user_last_login_null... OK
  Applying auth.0006_require_contenttypes_0002... OK
  Applying auth.0007_alter_validators_add_error_messages... OK
  Applying auth.0008_alter_user_username_max_length... OK
  Applying sessions.0001_initial... OK
  Applying stats.0001_initial... OK
  Applying stats.0002_auto_20180312_1632... OK
  Applying stats.0003_auto_20180321_2336... OK
  Applying stats.0004_auto_20180321_2353... OK
  Applying stats.0005_auto_20180423_1700... OK
System check identified no issues (0 silenced).
test_create_method_calls_create_game_with_correct_fields (stats.tests.test_dataGeneration.TestGameManager) ... FAIL
test_finds_tournament_instance (stats.tests.test_dataGeneration.TestGameManager) ... ok
test_sets_match_length (stats.tests.test_dataGeneration.TestGameManager) ... FAIL
test_can_create_tournaments_given_api_input (stats.tests.test_dataGeneration.TestProcessor) ... ERROR
test_correct_game_mode_being_selected_by_create_game_fucntion (stats.tests.test_dataGeneration.TestProcessor) ... FAIL
test_get_heroes (stats.tests.test_dataGeneration.TestProcessor) ... 
ok
test_get_players (stats.tests.test_dataGeneration.TestProcessor) ... 
ok
test_pass_data_method_calls_model_manager_equivalent (stats.tests.test_dataGeneration.TestProcessor) ...
ok
test_returns_match_ids (stats.tests.test_dataGeneration.TestProcessor) ... 
ok
test_tournament_creation_also_returns_tournament_ids_of_created_objects (stats.tests.test_dataGeneration.TestProcessor) ... FAIL
test_tournament_filter (stats.tests.test_dataGeneration.TestProcessor) ...
ok

======================================================================
ERROR: test_can_create_tournaments_given_api_input (stats.tests.test_dataGeneration.TestProcessor)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "C:\dev\Django code\portfolio_web\stats\tests\timer.py", line 8, in wrapper
    f(*args,**kwargs)
  File "C:\dev\Django code\portfolio_web\stats\tests\test_dataGeneration.py", line 77, in test_can_create_tournaments_given_api_input
    num_tournaments_start = Tournaments.objects.all()
NameError: name 'Tournaments' is not defined

======================================================================
FAIL: test_create_method_calls_create_game_with_correct_fields (stats.tests.test_dataGeneration.TestGameManager)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "C:\dev\Django code\portfolio_web\stats\tests\test_dataGeneration.py", line 143, in test_create_method_calls_create_game_with_correct_fields
    self.fail("finish test")
AssertionError: finish test

======================================================================
FAIL: test_sets_match_length (stats.tests.test_dataGeneration.TestGameManager)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "C:\dev\Django code\portfolio_web\stats\tests\test_dataGeneration.py", line 158, in test_sets_match_length
    self.fail("finish test, implement functionality")
AssertionError: finish test, implement functionality

======================================================================
FAIL: test_correct_game_mode_being_selected_by_create_game_fucntion (stats.tests.test_dataGeneration.TestProcessor)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "C:\dev\Django code\portfolio_web\stats\tests\timer.py", line 8, in wrapper
    f(*args,**kwargs)
  File "C:\dev\Django code\portfolio_web\stats\tests\test_dataGeneration.py", line 136, in test_correct_game_mode_being_selected_by_create_game_fucntion
    self.fail("Make sure the game mode is the correct one!")
AssertionError: Make sure the game mode is the correct one!

======================================================================
FAIL: test_tournament_creation_also_returns_tournament_ids_of_created_objects (stats.tests.test_dataGeneration.TestProcessor)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "C:\dev\Django code\portfolio_web\stats\tests\timer.py", line 8, in wrapper
    f(*args,**kwargs)
  File "C:\dev\Django code\portfolio_web\stats\tests\test_dataGeneration.py", line 93, in test_tournament_creation_also_returns_tournament_ids_of_created_objects
    self.assertEqual(tournament_ids, [data[0]['leagueid'], data[2]['leagueid']])
AssertionError: Lists differ: [] != ['30', '37']

Second list contains 2 additional elements.
First extra element 0:
'30'

- []
+ ['30', '37']

----------------------------------------------------------------------
Ran 11 tests in 0.015s

1 answers

0

The classes I was testing were not stored in individual files, but in a single Controller.py file which also created an instance of a class called API. API takes about 5-10 minutes to initialize. Python classes (and functions) aren't declared; instead they are real live statements. Consequently the interpreter reads and executes all code in a file, as opposed to just picking out class definitions. This was being done in my test files when they imported classes from Controller.py

Hence, a line at the very end of my code which was
API_INSTANCE = API(*args)
intialized API during every test. API gathers tons of data during initialization, and this slowed down testing immensely while the imports in test files were being read.

The obvious solution to the problem is to wrap the above line of code as follows:

if __name__ == '__main__':
    API_INSTANCE = API(*args)

The fact that the program stalled before the Creating test database... message should have been an indication that the code was stalling before the execution of a django.test.TestCase class.