search

CenterForOpenScience / osf.io

Facilitating Open Science
https://osf.io
Apache License 2.0
674 stars 331 forks source link

optimize the test suite #4768

Closed chadwhitacre closed 8 years ago

chadwhitacre commented 8 years ago

The test suite takes a loooooooonnnnnggggg time to run. I strongly suspect that we could cut it by an order of magnitude without too much effort. Here's some argument from authority about why fast tests are good:

The tests are what give you confidence in your code, and the ability to refactor with impunity, not fearing that your changes are breaking existing features. They are the safety net for our daily tight-rope walk across our code base.

But if your test suite takes a quarter of an hour to run, that puts a severe damper on your willingness to run it often, or even at all. Those tests definitely don’t get run every few minutes. They might get run before you commit a change. More likely, they get run around the end of a development cycle, when the new work is preparing for deployment. Although they can still be marginally useful when run like that, they are a far cry from what they might be.

https://signalvnoise.com/posts/2742-the-road-to-faster-tests

chadwhitacre commented 8 years ago

~9 minutes on a SSD: https://github.com/CenterForOpenScience/osf.io/issues/4762#issuecomment-165256051.

chadwhitacre commented 8 years ago

17m 44s at Travis.

screen shot 2015-12-16 at 5 47 54 pm

chadwhitacre commented 8 years ago

Looking into this ...

chadwhitacre commented 8 years ago

I'm starting with getting a profiling framework in place.

[osf.io]$ python -m cProfile -o profile.dat env/bin/nosetests tests/test_app.py
[website.util.paths]  WARNING: Skipping load of "webpack-assets.json" in DEBUG_MODE.
[website.project.metadata.authorizers]  INFO: No local.json found to populate lists of DraftRegistrationApproval authorizers.
[website.addons.github.settings]  WARNING: No local.py settings file found
[website.addons.osfstorage.settings]  WARNING: No local.py settings file found
[website.addons.wiki.settings]  WARNING: No local.py settings file found
[root]  DEBUG: Setting storage backends
[root]  INFO: Sentry disabled; Flask's debug mode enabled
[root]  INFO: Sentry disabled; Flask's debug mode enabled
.
----------------------------------------------------------------------
Ran 1 test in 0.003s

OK
[osf.io]$
chadwhitacre commented 8 years ago

I'd like to look both at startup time for the entire test suite, and then obviously hotspots in tests themselves.

chadwhitacre commented 8 years ago

@erinspace reports that ... James? recently profiled and optimized the test suite over on SHARE.

chadwhitacre commented 8 years ago

Not seeing a PR for that in https://github.com/CenterForOpenScience/SHARE/pulls?q=is%3Apr+is%3Aclosed.

chadwhitacre commented 8 years ago

The following are some interesting calls to experiment with:

p.sort_stats('cumulative').print_stats(10)

This sorts the profile by cumulative time in a function, and then only prints the ten most significant lines. If you want to understand what algorithms are taking time, the above line is what you would use.

If you were looking to see what functions were looping a lot, and taking a lot of time, you would do:

p.sort_stats('time').print_stats(10)

to sort according to time spent within each function, and then print the statistics for the top ten functions.

https://docs.python.org/2/library/profile.html#instant-user-s-manual

erinspace commented 8 years ago

It was part of a much larger PR made in a hackathon on scrapi -- the real code behind SHARE: https://github.com/CenterForOpenScience/scrapi/pull/244/files I think he did a big overhaul including using tox for test running (which was possible because scrapi is very separate from the OSF)

chadwhitacre commented 8 years ago

Cool, thanks @erinspace. :-)

chadwhitacre commented 8 years ago

Invoked as a script, the pstats module is a statistics browser for reading and examining profile dumps. It has a simple line-oriented interface (implemented using cmd) and interactive help.

end of https://docs.python.org/2/library/profile.html#instant-user-s-manual

So ...

chadwhitacre commented 8 years ago

Yesssssssssssss ...

[osf.io]$ python -m pstats profile.dat 
Welcome to the profile statistics browser.
profile.dat% ?

Documented commands (type help <topic>):
========================================
EOF  add  callees  callers  help  quit  read  reverse  sort  stats  strip

profile.dat% sort cumulative
profile.dat% stats 10
Thu Dec 17 13:44:38 2015    profile.dat

         3136876 function calls (3093717 primitive calls) in 9.313 seconds

   Ordered by: cumulative time
   List reduced from 8626 to 10 due to restriction <10>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.032    0.032    9.319    9.319 env/bin/nosetests:3(<module>)
        1    0.000    0.000    8.703    8.703 /Users/whit537/workbench/cos/osf.io/env/lib/python2.7/site-packages/nose/core.py:102(__init__)
        1    0.000    0.000    8.702    8.702 /Users/whit537/lib/python2.7/unittest/main.py:72(__init__)
        1    0.000    0.000    8.699    8.699 /Users/whit537/workbench/cos/osf.io/env/lib/python2.7/site-packages/nose/core.py:142(parseArgs)
        1    0.000    0.000    8.584    8.584 /Users/whit537/workbench/cos/osf.io/env/lib/python2.7/site-packages/nose/core.py:181(createTests)
        1    0.000    0.000    8.584    8.584 /Users/whit537/workbench/cos/osf.io/env/lib/python2.7/site-packages/nose/loader.py:469(loadTestsFromNames)
        1    0.000    0.000    8.584    8.584 /Users/whit537/lib/python2.7/unittest/loader.py:126(loadTestsFromNames)
        1    0.000    0.000    8.584    8.584 /Users/whit537/workbench/cos/osf.io/env/lib/python2.7/site-packages/nose/loader.py:361(loadTestsFromName)
        1    0.000    0.000    8.582    8.582 /Users/whit537/workbench/cos/osf.io/env/lib/python2.7/site-packages/nose/importer.py:34(importFromPath)
        1    0.000    0.000    8.582    8.582 /Users/whit537/workbench/cos/osf.io/env/lib/python2.7/site-packages/nose/importer.py:49(importFromDir)

profile.dat%
chadwhitacre commented 8 years ago

Okay! I've kicked off a full test run, and then we should have some interesting profiling data to explore! :-)

chadwhitacre commented 8 years ago 
Thu Dec 17 14:02:06 2015    profile.dat

         156687425 function calls (152033491 primitive calls) in 682.988 seconds

   Ordered by: cumulative time
   List reduced from 16670 to 30 due to restriction <30>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.028    0.028  683.061  683.061 nosetests:3(<module>)
        1    0.000    0.000  682.527  682.527 core.py:102(__init__)
        1    0.000    0.000  682.526  682.526 main.py:72(__init__)
        1    0.000    0.000  672.944  672.944 core.py:195(runTests)
        1    0.000    0.000  672.944  672.944 core.py:46(run)
    382/1    0.005    0.000  672.943  672.943 suite.py:176(__call__)
    382/1    0.024    0.000  672.943  672.943 suite.py:197(run)
     1736    0.007    0.000  452.909    0.261 case.py:44(__call__)
     1736    0.020    0.000  452.901    0.261 case.py:115(run)
     1736    0.019    0.000  452.583    0.261 case.py:142(runTest)
     1736    0.007    0.000  452.558    0.261 case.py:392(__call__)
     1736    0.077    0.000  452.550    0.261 case.py:295(run)
   304728  326.892    0.001  326.892    0.001 {method 'recv' of '_socket.socket' objects}
5069/4929    0.050    0.000  320.983    0.065 base.py:72(__call__)
6121/4929    0.057    0.000  320.935    0.065 base.py:511(create)
6159/5959    0.220    0.000  319.128    0.054 base.py:418(_generate)
853013/163197    2.413    0.000  271.321    0.002 storedobject.py:101(wrapped)
290683/162697    2.957    0.000  269.015    0.002 storedobject.py:76(wrapped)
6159/5975    0.183    0.000  250.883    0.042 base.py:390(_prepare)
   147874    1.824    0.000  244.552    0.002 mongo_client.py:949(__receive_message_on_socket)
   295748    1.922    0.000  242.287    0.001 mongo_client.py:934(__receive_data_on_socket)
79355/59779    5.301    0.000  224.279    0.004 storedobject.py:762(save)
      648    0.008    0.000  219.913    0.339 util.py:441(try_run)
   102117    1.804    0.000  195.512    0.002 mongo_client.py:888(_send_message)
36419/28546    0.276    0.000  191.935    0.007 model.py:92(save)
     5594    0.103    0.000  181.126    0.032 factories.py:84(_create)
16983/8546    0.696    0.000  169.357    0.020 model.py:1351(save)
      382    0.010    0.000  162.673    0.426 suite.py:268(setUp)
      310    0.004    0.000  162.650    0.525 suite.py:300(setupContext)
19273/19201    0.726    0.000  161.838    0.008 core.py:1046(save)
chadwhitacre commented 8 years ago

The recv call jumps out at me. I notice below that we've got several calls in mongo_client. Can we avoid calling to mongo so much?

chadwhitacre commented 8 years ago

With paths intact:

Thu Dec 17 14:02:06 2015    profile.dat

         156687425 function calls (152033491 primitive calls) in 682.988 seconds

   Ordered by: cumulative time
   List reduced from 17531 to 30 due to restriction <30>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.028    0.028  683.061  683.061 env/bin/nosetests:3(<module>)
        1    0.000    0.000  682.527  682.527 /Users/whit537/workbench/cos/osf.io/env/lib/python2.7/site-packages/nose/core.py:102(__init__)
        1    0.000    0.000  682.526  682.526 /Users/whit537/lib/python2.7/unittest/main.py:72(__init__)
        1    0.000    0.000  672.944  672.944 /Users/whit537/workbench/cos/osf.io/env/lib/python2.7/site-packages/nose/core.py:195(runTests)
        1    0.000    0.000  672.944  672.944 /Users/whit537/workbench/cos/osf.io/env/lib/python2.7/site-packages/nose/core.py:46(run)
    382/1    0.005    0.000  672.943  672.943 /Users/whit537/workbench/cos/osf.io/env/lib/python2.7/site-packages/nose/suite.py:176(__call__)
    382/1    0.024    0.000  672.943  672.943 /Users/whit537/workbench/cos/osf.io/env/lib/python2.7/site-packages/nose/suite.py:197(run)
     1736    0.007    0.000  452.909    0.261 /Users/whit537/workbench/cos/osf.io/env/lib/python2.7/site-packages/nose/case.py:44(__call__)
     1736    0.020    0.000  452.901    0.261 /Users/whit537/workbench/cos/osf.io/env/lib/python2.7/site-packages/nose/case.py:115(run)
     1736    0.019    0.000  452.583    0.261 /Users/whit537/workbench/cos/osf.io/env/lib/python2.7/site-packages/nose/case.py:142(runTest)
     1736    0.007    0.000  452.558    0.261 /Users/whit537/lib/python2.7/unittest/case.py:392(__call__)
     1736    0.077    0.000  452.550    0.261 /Users/whit537/lib/python2.7/unittest/case.py:295(run)
   304728  326.892    0.001  326.892    0.001 {method 'recv' of '_socket.socket' objects}
5069/4929    0.050    0.000  320.983    0.065 /Users/whit537/workbench/cos/osf.io/env/lib/python2.7/site-packages/factory/base.py:72(__call__)
6121/4929    0.057    0.000  320.935    0.065 /Users/whit537/workbench/cos/osf.io/env/lib/python2.7/site-packages/factory/base.py:511(create)
6159/5959    0.220    0.000  319.128    0.054 /Users/whit537/workbench/cos/osf.io/env/lib/python2.7/site-packages/factory/base.py:418(_generate)
853013/163197    2.413    0.000  271.321    0.002 /Users/whit537/workbench/cos/osf.io/env/lib/python2.7/site-packages/modularodm/storedobject.py:101(wrapped)
290683/162697    2.957    0.000  269.015    0.002 /Users/whit537/workbench/cos/osf.io/env/lib/python2.7/site-packages/modularodm/storedobject.py:76(wrapped)
6159/5975    0.183    0.000  250.883    0.042 /Users/whit537/workbench/cos/osf.io/env/lib/python2.7/site-packages/factory/base.py:390(_prepare)
   147874    1.824    0.000  244.552    0.002 /Users/whit537/workbench/cos/osf.io/env/lib/python2.7/site-packages/pymongo/mongo_client.py:949(__receive_message_on_socket)
   295748    1.922    0.000  242.287    0.001 /Users/whit537/workbench/cos/osf.io/env/lib/python2.7/site-packages/pymongo/mongo_client.py:934(__receive_data_on_socket)
79355/59779    5.301    0.000  224.279    0.004 /Users/whit537/workbench/cos/osf.io/env/lib/python2.7/site-packages/modularodm/storedobject.py:762(save)
      648    0.008    0.000  219.913    0.339 /Users/whit537/workbench/cos/osf.io/env/lib/python2.7/site-packages/nose/util.py:441(try_run)
   102117    1.804    0.000  195.512    0.002 /Users/whit537/workbench/cos/osf.io/env/lib/python2.7/site-packages/pymongo/mongo_client.py:888(_send_message)
36419/28546    0.276    0.000  191.935    0.007 /Users/whit537/workbench/cos/osf.io/framework/guid/model.py:92(save)
     5594    0.103    0.000  181.126    0.032 /Users/whit537/workbench/cos/osf.io/tests/factories.py:84(_create)
16983/8546    0.696    0.000  169.357    0.020 /Users/whit537/workbench/cos/osf.io/website/project/model.py:1351(save)
      382    0.010    0.000  162.673    0.426 /Users/whit537/workbench/cos/osf.io/env/lib/python2.7/site-packages/nose/suite.py:268(setUp)
      310    0.004    0.000  162.650    0.525 /Users/whit537/workbench/cos/osf.io/env/lib/python2.7/site-packages/nose/suite.py:300(setupContext)
19273/19201    0.726    0.000  161.838    0.008 /Users/whit537/workbench/cos/osf.io/framework/auth/core.py:1046(save)
chadwhitacre commented 8 years ago

I'm poking around in the testing and mongo infrastructure, trying to formulate a question ...

chadwhitacre commented 8 years ago

save is implicated, but what about reads (recv)?

chadwhitacre commented 8 years ago

I want to understand the structure of the test suite and its setup/teardown. I also want to understand what the pathways to mongo are in the test suite and how frequently each is called.

chadwhitacre commented 8 years ago

For the latter I'm thinking of adding print statements in storedobject.py and rerunning the test suite. For the former I need to read code ...

chadwhitacre commented 8 years ago

I count 27 calls to StoredObject.save on test suite initialization, in order to run one test.

chadwhitacre commented 8 years ago

Alright, so I'm seeing OsfTestCase that subclasses DbTestCase in tests/base.py. I'm isolating this as a test which exercises DbTestCase:

[osf.io]$ nosetests tests/test_guids.py:TestGuidStoredObject -s
[website.util.paths]  WARNING: Skipping load of "webpack-assets.json" in DEBUG_MODE.
[website.project.metadata.authorizers]  INFO: No local.json found to populate lists of DraftRegistrationApproval authorizers.
[website.addons.github.settings]  WARNING: No local.py settings file found
[website.addons.osfstorage.settings]  WARNING: No local.py settings file found
[website.addons.wiki.settings]  WARNING: No local.py settings file found
[root]  DEBUG: Setting storage backends
[root]  INFO: Sentry disabled; Flask's debug mode enabled
[root]  INFO: Sentry disabled; Flask's debug mode enabled
.
----------------------------------------------------------------------
Ran 1 test in 0.657s

OK
[osf.io]$
chadwhitacre commented 8 years ago

Let's log some save calls ...

chadwhitacre commented 8 years ago

Okay! Here's a patch for env/lib/python2.7/site-packages/modularodm/storedobject.py:

--- storedobject.py.bak 2015-12-17 15:20:55.000000000 -0500
+++ storedobject.py 2015-12-17 15:21:02.000000000 -0500
@@ -19,6 +19,11 @@
 logger = logging.getLogger(__name__)

+import inspect
+OSF_IO_BASE = '/Users/whit537/workbench/cos/osf.io/'
+save_log = open('save.log', 'w+')
+
+
 class ContextLogger(object):

     @staticmethod
@@ -768,6 +773,21 @@
             back-references
         :returns: List of changed fields
         """
+        frames = inspect.stack()
+        entry = exit_ = prev = ''
+        for frame in frames:
+            loc = (frame[1][len(OSF_IO_BASE):], frame[2])
+            if loc[0].startswith('env/lib/python2.7/'):
+                continue
+            elif exit_ and loc[0].startswith('tests/'):
+                entry = prev
+                break
+            elif not exit_:
+                exit_ = loc
+            prev = loc
+        fmt = lambda loc: "{}:{}".format(*loc)
+        print >> save_log, "{:<50}{:<50}".format(fmt(entry), fmt(exit_))
+
         if self._detached:
             raise exceptions.DatabaseError('Cannot save detached object.')

And here's some sample output:

[osf.io]$ nosetests tests/test_guids.py:TestGuidStoredObject -s
[website.util.paths]  WARNING: Skipping load of "webpack-assets.json" in DEBUG_MODE.
[website.project.metadata.authorizers]  INFO: No local.json found to populate lists of DraftRegistrationApproval authorizers.
[website.addons.github.settings]  WARNING: No local.py settings file found
[website.addons.osfstorage.settings]  WARNING: No local.py settings file found
[website.addons.wiki.settings]  WARNING: No local.py settings file found
[root]  DEBUG: Setting storage backends
[root]  INFO: Sentry disabled; Flask's debug mode enabled
[root]  INFO: Sentry disabled; Flask's debug mode enabled
.
----------------------------------------------------------------------
Ran 1 test in 0.611s

OK
[osf.io]$ cat save.log 
api/base/wsgi.py:16                               website/project/model.py:136                      
api/base/wsgi.py:16                               website/project/model.py:136                      
api/base/wsgi.py:16                               website/project/model.py:136                      
api/base/wsgi.py:16                               website/project/model.py:136                      
api/base/wsgi.py:16                               website/project/model.py:136                      
api/base/wsgi.py:16                               website/project/model.py:136                      
api/base/wsgi.py:16                               website/project/model.py:136                      
api/base/wsgi.py:16                               website/project/model.py:136                      
api/base/wsgi.py:16                               website/project/model.py:136                      
api/base/wsgi.py:16                               website/project/model.py:136                      
api/base/wsgi.py:16                               website/project/model.py:136                      
api/base/wsgi.py:16                               website/project/licenses/__init__.py:112          
api/base/wsgi.py:16                               website/project/licenses/__init__.py:112          
api/base/wsgi.py:16                               website/project/licenses/__init__.py:112          
api/base/wsgi.py:16                               website/project/licenses/__init__.py:112          
api/base/wsgi.py:16                               website/project/licenses/__init__.py:112          
api/base/wsgi.py:16                               website/project/licenses/__init__.py:112          
api/base/wsgi.py:16                               website/project/licenses/__init__.py:112          
api/base/wsgi.py:16                               website/project/licenses/__init__.py:112          
api/base/wsgi.py:16                               website/project/licenses/__init__.py:112          
api/base/wsgi.py:16                               website/project/licenses/__init__.py:112          
api/base/wsgi.py:16                               website/project/licenses/__init__.py:112          
api/base/wsgi.py:16                               website/project/licenses/__init__.py:112          
api/base/wsgi.py:16                               website/project/licenses/__init__.py:112          
api/base/wsgi.py:16                               website/project/licenses/__init__.py:112          
api/base/wsgi.py:16                               website/project/licenses/__init__.py:112          
api/base/wsgi.py:16                               website/project/licenses/__init__.py:112          
framework/guid/model.py:94                        framework/guid/model.py:82                        
framework/guid/model.py:95                        framework/guid/model.py:95                        
[osf.io]$
chadwhitacre commented 8 years ago

Seeing a bunch of:

======================================================================
ERROR: test_no_warning_for_read_only_user_with_valid_link (tests.webtest_tests.TestPrivateLinkView)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/Users/whit537/workbench/cos/osf.io/tests/webtest_tests.py", line 363, in setUp
    self.link.save()
  File "/Users/whit537/workbench/cos/osf.io/env/lib/python2.7/site-packages/modularodm/storedobject.py", line 115, in wrapped
    return func(*args, **kwargs)
  File "/Users/whit537/workbench/cos/osf.io/env/lib/python2.7/site-packages/modularodm/storedobject.py", line 87, in wrapped
    return func(this, *args, **kwargs)
  File "/Users/whit537/workbench/cos/osf.io/env/lib/python2.7/site-packages/modularodm/storedobject.py", line 789, in save
    print >> save_log, "{:<50}{:<50}".format(fmt(entry), fmt(exit_))
  File "/Users/whit537/workbench/cos/osf.io/env/lib/python2.7/site-packages/modularodm/storedobject.py", line 788, in <lambda>
    fmt = lambda loc: "{}:{}".format(*loc)
IndexError: tuple index out of range
chadwhitacre commented 8 years ago

Fixed. New diff:

--- storedobject.py.bak 2015-12-17 15:20:55.000000000 -0500
+++ env/lib/python2.7/site-packages/modularodm/storedobject.py  2015-12-17 15:59:23.000000000 -0500
@@ -19,6 +19,11 @@
 logger = logging.getLogger(__name__)

+import inspect
+OSF_IO_BASE = '/Users/whit537/workbench/cos/osf.io/'
+save_log = open('save.log', 'w+')
+
+
 class ContextLogger(object):

     @staticmethod
@@ -768,6 +773,21 @@
             back-references
         :returns: List of changed fields
         """
+        frames = inspect.stack()
+        entry = exit_ = prev = None
+        for frame in frames:
+            loc = (frame[1][len(OSF_IO_BASE):], frame[2])
+            if loc[0].startswith('env/lib/python2.7/'):
+                continue
+            elif exit_ and loc[0].startswith('tests/'):
+                entry = prev
+                break
+            elif not exit_:
+                exit_ = loc
+            prev = loc
+        fmt = lambda loc: "{}:{}".format(*loc) if loc else '-'
+        print >> save_log, "{:<50}{:<50}".format(fmt(entry), fmt(exit_))
+
         if self._detached:
             raise exceptions.DatabaseError('Cannot save detached object.')
chadwhitacre commented 8 years ago

Rerunning ...

chadwhitacre commented 8 years ago 
------ Entries (N=271) -----------------

17,827 framework/auth/core.py:1051
14,672 website/project/model.py:1377
12,992 website/project/model.py:1371
 6,522 website/project/model.py:1397
 3,132 website/project/model.py:2107
 2,311 framework/routing/__init__.py:111
 2,142 website/project/model.py:2118
 1,613 website/project/model.py:2128
 1,474 website/project/model.py:144
 1,447 website/project/model.py:3269
 1,422 website/project/model.py:2136
 1,242 website/project/model.py:1388
 1,202 scripts/parse_citation_styles.py:49
   867 website/project/model.py:3278
   684 -
   547 tests/factories.py:88
   447 framework/sessions/__init__.py:185
   445 framework/sessions/__init__.py:166
   373 website/project/model.py:2803
   346 website/project/model.py:2133
   336 website/project/model.py:3664
   324 tests/factories.py:251
   322 tests/factories.py:264
   322 tests/factories.py:262
   273 website/project/licenses/__init__.py:112
   217 website/project/model.py:3233
   214 website/project/model.py:2047
   200 framework/guid/model.py:95
   195 website/project/model.py:2806
   182 website/project/model.py:3176
   171 website/project/model.py:3010
   148 website/project/model.py:1583
   144 website/archiver/utils.py:141
   140 website/project/model.py:2050
   132 website/project/model.py:1518
   130 framework/addons/__init__.py:111
   126 website/project/model.py:2888
   123 website/project/model.py:3242
   123 website/project/model.py:2873
   118 framework/addons/__init__.py:98
   118 website/project/model.py:3031
   105 website/project/model.py:3183
   104 website/project/model.py:2437
   104 website/project/model.py:2251
   103 website/project/model.py:3953
    99 framework/guid/model.py:94
    98 website/project/model.py:1561
    96 website/project/model.py:4297
    94 website/project/model.py:2936
    91 website/project/model.py:1998
    88 website/project/model.py:2450
    81 website/addons/github/model.py:98
    81 website/project/model.py:2175
    77 website/project/model.py:4246
    72 website/project/model.py:1512
    62 tests/factories.py:325
    60 website/project/views/node.py:703
    59 website/archiver/model.py:185
    56 website/project/model.py:3029
    54 website/project/model.py:1490
    54 website/addons/github/model.py:97
    52 website/project/model.py:2248
    50 website/project/model.py:4140
    49 website/project/model.py:1578
    48 framework/auth/core.py:1317
    46 website/project/model.py:2933
    46 website/project/model.py:3814
    44 website/project/model.py:2448
    40 website/project/model.py:2886
    39 website/project/model.py:4060
    38 framework/tasks/handlers.py:29
    36 website/archiver/utils.py:135
    35 website/project/model.py:3187
    30 website/project/model.py:1753
    30 website/project/model.py:3565
    30 website/conferences/utils.py:63
    28 website/project/model.py:3831
    28 website/project/model.py:3507
    28 website/project/model.py:2161
    27 scripts/parse_citation_styles.py:14
    27 api/base/wsgi.py:16
    27 website/project/model.py:2172
    27 website/project/model.py:2572
    27 website/project/model.py:4057
    24 website/project/model.py:2044
    24 website/project/model.py:3245
    23 website/tokens/__init__.py:51
    22 website/files/models/base.py:168
    22 website/project/model.py:3555
    21 framework/auth/core.py:1286
    21 website/addons/wiki/model.py:219
    20 website/archiver/listeners.py:47
    20 website/project/model.py:1048
    20 website/addons/base/__init__.py:869
    20 website/project/model.py:1330
    20 website/archiver/listeners.py:24
    19 website/archiver/model.py:156
    19 website/files/models/base.py:356
    19 website/project/model.py:1521
    18 website/project/model.py:1952
    18 website/conferences/utils.py:76
    18 website/project/model.py:4046
    17 website/conferences/utils.py:82
    17 website/files/models/base.py:629
    16 website/project/model.py:4154
    16 website/project/model.py:1229
    15 website/archiver/model.py:186
    15 website/project/model.py:2938
    15 website/conferences/utils.py:83
    14 lib.py:17
    13 website/mails/queued_mails.py:90
    12 website/project/model.py:3114
    12 website/project/model.py:1942
    12 website/project/model.py:1896
    12 website/oauth/models/__init__.py:275
    12 framework/auth/core.py:1099
    12 website/files/models/osfstorage.py:153
    12 website/project/model.py:2154
    11 website/project/model.py:787
    10 website/project/model.py:3068
    10 website/project/model.py:1957
    10 website/project/model.py:3094
    10 website/addons/base/__init__.py:870
     9 website/project/model.py:2752
     9 framework/auth/core.py:1297
     9 website/project/model.py:2569
     9 website/project/model.py:4063
     9 website/project/model.py:1505
     9 website/project/model.py:3956
     8 website/identifiers/model.py:44
     8 website/project/model.py:3000
     8 framework/auth/__init__.py:47
     8 framework/auth/__init__.py:46
     8 website/project/model.py:1226
     8 website/project/model.py:4048
     8 website/project/model.py:1778
     8 tests/test_addons.py:532
     7 website/project/model.py:2882
     7 website/project/model.py:2852
     7 framework/auth/core.py:1292
     6 website/project/model.py:232
     6 website/project/model.py:1348
     6 website/project/model.py:3112
     6 website/project/model.py:3207
     6 tests/test_addons.py:188
     6 website/addons/base/__init__.py:377
     6 tests/test_addons.py:103
     6 website/project/model.py:2575
     6 website/archiver/utils.py:77
     6 tests/test_addons.py:179
     6 website/mails/queued_mails.py:47
     6 website/project/model.py:2808
     6 tests/test_addons.py:94
     5 website/addons/base/__init__.py:859
     5 framework/auth/core.py:858
     5 framework/auth/core.py:515
     5 website/project/model.py:1288
     5 website/addons/base/__init__.py:862
     5 website/project/model.py:3092
     5 website/project/model.py:1829
     4 website/project/model.py:1893
     4 website/archiver/model.py:175
     4 framework/auth/cas.py:227
     4 website/project/model.py:542
     4 website/archiver/tasks.py:342
     4 website/project/model.py:1920
     4 website/project/model.py:3254
     4 website/files/models/base.py:379
     4 framework/addons/__init__.py:128
     4 website/project/model.py:2476
     4 website/project/model.py:3156
     4 website/archiver/model.py:174
     4 website/conferences/utils.py:80
     4 website/project/model.py:2151
     4 website/project/model.py:2463
     4 website/project/model.py:4301
     3 website/project/model.py:3932
     3 website/notifications/utils.py:150
     3 website/project/views/contributor.py:270
     3 website/project/model.py:3213
     3 website/project/__init__.py:140
     3 tests/factories.py:541
     3 website/project/model.py:3212
     3 website/project/model.py:3209
     3 website/project/model.py:312
     3 website/project/views/contributor.py:257
     3 website/project/model.py:1296
     3 framework/auth/core.py:1113
     3 website/project/model.py:3825
     3 website/archiver/listeners.py:58
     3 website/project/model.py:1598
     3 website/conferences/utils.py:88
     3 website/files/models/base.py:529
     3 website/project/views/contributor.py:519
     3 website/archiver/utils.py:76
     3 framework/auth/core.py:1246
     3 website/project/views/contributor.py:268
     2 website/project/model.py:1773
     2 website/project/views/contributor.py:399
     2 website/project/model.py:538
     2 website/notifications/events/files.py:254
     2 website/project/model.py:1269
     2 website/project/model.py:3259
     2 website/project/model.py:3256
     2 website/project/model.py:2699
     2 website/profile/views.py:567
     2 framework/tasks/utils.py:41
     2 website/project/model.py:246
     2 website/project/model.py:3158
     2 website/project/model.py:1856
     2 website/oauth/models/__init__.py:431
     2 website/project/model.py:278
     2 website/project/model.py:3162
     2 website/project/views/contributor.py:419
     2 website/project/model.py:3161
     2 website/project/model.py:2474
     2 website/project/model.py:1782
     2 website/project/model.py:1832
     2 framework/auth/__init__.py:78
     2 website/project/model.py:1006
     2 website/project/views/contributor.py:464
     2 website/files/models/base.py:623
     2 website/project/model.py:3260
     1 website/project/model.py:1010
     1 website/project/model.py:2816
     1 website/project/model.py:262
     1 website/project/model.py:1959
     1 website/project/model.py:2011
     1 framework/auth/cas.py:226
     1 website/project/model.py:2838
     1 website/project/model.py:2690
     1 website/archiver/utils.py:108
     1 website/identifiers/model.py:49
     1 framework/auth/core.py:771
     1 website/project/model.py:1256
     1 website/project/model.py:1266
     1 website/project/model.py:243
     1 website/project/model.py:3827
     1 website/addons/base/__init__.py:888
     1 framework/auth/decorators.py:37
     1 website/util/__init__.py:162
     1 website/project/model.py:4165
     1 website/project/model.py:2730
     1 framework/auth/core.py:783
     1 website/project/model.py:2908
     1 website/project/model.py:2105
     1 website/project/model.py:2513
     1 website/oauth/models/__init__.py:506
     1 website/files/models/base.py:620
     1 website/mails/queued_mails.py:38
     1 website/project/model.py:1290
     1 website/archiver/decorators.py:20
     1 website/project/model.py:1614
     1 website/project/model.py:4159
     1 website/project/views/contributor.py:453
     1 website/project/model.py:1475
     1 website/files/models/osfstorage.py:149
     1 framework/auth/core.py:1272
     1 framework/auth/core.py:989
     1 website/files/models/base.py:624
     1 website/files/models/base.py:494
     1 website/project/model.py:294
     1 framework/auth/core.py:1247
     1 website/project/model.py:2653
     1 website/project/licenses/__init__.py:73
     1 website/project/model.py:327
     1 website/files/models/base.py:380
     1 website/files/models/base.py:78
     1 website/project/model.py:4288
     1 website/project/model.py:4285
     1 website/project/model.py:2647
79,355 Σ

------ Exits (N=293) -------------------

41,220 framework/guid/model.py:95
 6,059 framework/guid/model.py:40
 6,047 framework/guid/model.py:88
 4,472 framework/addons/__init__.py:98
 3,647 website/project/model.py:2248
 2,674 website/files/models/base.py:356
 2,590 website/addons/osfstorage/model.py:36
 2,590 website/addons/osfstorage/model.py:41
 1,496 website/project/model.py:136
 1,202 scripts/parse_citation_styles.py:49
   736 website/project/model.py:3664
   580 website/archiver/model.py:156
   547 tests/factories.py:88
   485 website/archiver/model.py:175
   447 framework/sessions/__init__.py:185
   406 website/addons/osfstorage/model.py:59
   406 website/addons/wiki/model.py:84
   324 tests/factories.py:251
   322 tests/factories.py:264
   322 tests/factories.py:262
   305 website/project/licenses/__init__.py:112
   297 website/project/model.py:3260
   297 website/project/model.py:3254
   116 website/addons/github/model.py:98
    78 website/project/model.py:4246
    68 website/mails/queued_mails.py:90
    64 website/project/model.py:2161
    63 website/project/model.py:1561
    62 tests/factories.py:325
    60 website/archiver/model.py:185
    55 website/addons/github/model.py:97
    54 tests/test_conferences.py:423
    51 website/project/model.py:3207
    51 website/project/model.py:3213
    45 website/project/model.py:3156
    44 website/project/model.py:3162
    33 website/addons/base/__init__.py:661
    33 website/addons/osfstorage/model.py:51
    33 website/addons/osfstorage/model.py:46
    24 tests/test_notifications.py:367
    24 tests/test_notifications.py:386
    24 tests/test_notifications.py:384
    24 tests/test_notifications.py:365
    24 tests/test_notifications.py:377
    24 tests/test_notifications.py:375
    20 tests/test_models.py:3497
    20 website/archiver/listeners.py:47
    18 tests/test_notifications.py:983
    18 tests/test_notifications.py:981
    18 tests/test_notifications.py:991
    17 framework/auth/core.py:1099
    16 tests/test_rubeus.py:46
    15 website/archiver/model.py:144
    15 tests/test_citations.py:35
    14 website/project/model.py:3507
    14 website/project/views/drafts.py:169
    14 tests/utils.py:116
    13 tests/test_addons.py:522
    13 tests/test_addons.py:514
    12 tests/test_views.py:94
    12 website/identifiers/model.py:44
    12 framework/guid/model.py:46
    12 website/project/model.py:4063
    12 tests/models/test_addon_settings.py:40
    11 website/addons/base/__init__.py:377
    11 website/project/model.py:3827
    10 website/addons/base/__init__.py:870
    10 framework/sessions/__init__.py:101
     9 tests/test_views.py:2524
     9 website/project/model.py:538
     9 framework/auth/core.py:515
     9 tests/test_notifications.py:767
     9 tests/test_notifications.py:761
     9 tests/test_addons.py:752
     9 tests/test_notifications.py:755
     9 tests/test_notifications.py:870
     9 tests/test_notifications.py:876
     9 tests/test_addons.py:532
     8 website/tokens/handlers.py:89
     7 website/files/models/base.py:424
     7 website/conferences/views.py:249
     7 tests/models/test_addon_settings.py:41
     7 website/notifications/model.py:59
     7 website/project/model.py:4215
     6 tests/test_alternative_citations.py:19
     6 tests/test_addons.py:188
     6 tests/test_addons.py:103
     6 tests/test_addons.py:171
     6 tests/test_addons.py:179
     6 website/mails/queued_mails.py:47
     6 tests/test_addons.py:85
     6 website/project/model.py:4301
     6 tests/test_websitefiles.py:63
     6 tests/test_addons.py:94
     5 website/project/model.py:3945
     5 tests/test_registrations/test_archiver.py:1048
     5 tests/test_events.py:359
     5 website/addons/base/__init__.py:862
     5 tests/test_events.py:349
     5 tests/test_events.py:342
     5 tests/test_registrations/test_archiver.py:1056
     4 tests/test_notifications.py:221
     4 tests/test_notifications.py:224
     4 tests/test_models.py:517
     4 tests/test_events.py:288
     4 tests/test_notifications.py:212
     4 tests/test_registrations/test_models.py:137
     4 tests/test_events.py:297
     4 tests/test_events.py:519
     4 tests/webtest_tests.py:363
     4 tests/test_events.py:536
     4 tests/test_notifications.py:209
     4 website/project/licenses/__init__.py:73
     4 tests/test_registrations/test_models.py:143
     4 website/archiver/utils.py:76
     4 tests/test_events.py:526
     3 tests/test_tokens.py:119
     3 tests/test_events.py:223
     3 tests/factories.py:541
     3 website/addons/base/__init__.py:888
     3 website/files/models/base.py:430
     3 website/addons/github/model.py:491
     3 tests/test_events.py:444
     3 tests/test_tokens.py:133
     3 website/notifications/views.py:106
     3 website/addons/base/__init__.py:213
     3 website/notifications/model.py:42
     3 tests/test_events.py:454
     3 website/oauth/models/__init__.py:310
     3 tests/test_events.py:437
     3 website/oauth/models/__init__.py:285
     2 website/archiver/listeners.py:69
     2 tests/test_events.py:196
     2 tests/test_events.py:170
     2 website/oauth/models/__init__.py:431
     2 tests/test_events.py:258
     2 tests/test_auth.py:155
     2 website/project/model.py:4288
     2 website/project/model.py:4285
     1 tests/test_notifications.py:1189
     1 tests/test_registrations/test_retractions.py:579
     1 tests/test_notifications.py:836
     1 tests/test_websitefiles.py:198
     1 tests/test_views.py:862
     1 tests/test_events.py:547
     1 tests/test_views.py:1251
     1 tests/test_oauth.py:268
     1 tests/test_events.py:549
     1 tests/test_elastic.py:285
     1 tests/test_websitefiles.py:518
     1 tests/test_notifications.py:788
     1 website/addons/base/__init__.py:399
     1 tests/test_events.py:380
     1 tests/test_notifications.py:1248
     1 tests/test_notifications.py:1030
     1 tests/test_notifications.py:1240
     1 tests/test_elastic.py:850
     1 tests/test_oauth.py:475
     1 tests/test_notifications.py:802
     1 website/project/views/node.py:1135
     1 website/project/__init__.py:140
     1 tests/test_views.py:166
     1 tests/test_elastic.py:859
     1 website/project/views/node.py:662
     1 tests/test_models.py:2524
     1 tests/test_websitefiles.py:163
     1 tests/test_events.py:372
     1 tests/test_models.py:1441
     1 tests/test_notifications.py:1256
     1 tests/test_websitefiles.py:366
     1 tests/test_notifications.py:795
     1 tests/test_models.py:2529
     1 tests/test_websitefiles.py:365
     1 tests/test_registrations/test_sanctions.py:246
     1 website/project/model.py:1256
     1 website/conferences/utils.py:24
     1 website/mails/presends.py:56
     1 tests/test_conferences.py:375
     1 website/addons/github/model.py:199
     1 website/identifiers/model.py:49
     1 website/project/model.py:4159
     1 tests/test_oauth.py:443
     1 tests/test_notifications.py:845
     1 tests/test_notifications.py:847
     1 tests/test_registrations/test_models.py:85
     1 tests/webtest_tests.py:378
     1 tests/test_registrations/test_archiver.py:1155
     1 tests/test_events.py:579
     1 tests/test_notifications.py:1205
     1 tests/test_events.py:476
     1 tests/test_conferences.py:515
     1 tests/test_notifications.py:1007
     1 tests/test_notifications.py:918
     1 tests/test_notifications.py:925
     1 tests/test_notifications.py:681
     1 tests/test_registrations/test_sanctions.py:93
     1 tests/test_addons.py:727
     1 tests/test_notifications.py:588
     1 tests/test_models.py:4242
     1 tests/test_registrations/test_retractions.py:529
     1 tests/test_models.py:4252
     1 tests/test_notifications.py:260
     1 tests/test_registrations/test_models.py:106
     1 tests/test_notifications.py:559
     1 website/project/model.py:4165
     1 tests/test_websitefiles.py:389
     1 tests/test_views.py:183
     1 website/project/model.py:2908
     1 tests/test_notifications.py:460
     1 tests/test_events.py:567
     1 tests/test_models.py:3437
     1 tests/test_notifications.py:1197
     1 tests/test_prereg.py:74
     1 tests/test_elastic.py:343
     1 framework/guid/model.py:82
     1 tests/test_notifications.py:939
     1 tests/test_notifications.py:262
     1 tests/test_notifications.py:781
     1 tests/test_registrations/test_models.py:118
     1 tests/test_registrations/test_views.py:490
     1 tests/test_websitefiles.py:74
     1 tests/test_auth_basic_auth.py:56
     1 website/oauth/models/__init__.py:506
     1 tests/test_models.py:848
     1 tests/test_conferences.py:187
     1 tests/test_views.py:1640
     1 tests/test_models.py:2518
     1 tests/test_alternative_citations.py:31
     1 tests/test_notifications.py:820
     1 tests/test_notifications.py:826
     1 tests/test_events.py:408
     1 tests/test_views.py:1255
     1 tests/test_notifications.py:953
     1 tests/test_addons.py:660
     1 tests/test_registrations/test_models.py:166
     1 tests/test_rubeus.py:250
     1 tests/test_notifications.py:899
     1 website/project/views/drafts.py:300
     1 tests/test_oauth.py:520
     1 tests/test_registrations/test_models.py:168
     1 tests/test_notifications.py:890
     1 tests/test_notifications.py:446
     1 tests/test_websitefiles.py:154
     1 tests/test_registrations/test_archiver.py:908
     1 tests/test_registrations/test_sanctions.py:86
     1 tests/test_project_decorators.py:70
     1 tests/test_notifications.py:448
     1 tests/test_notifications.py:1292
     1 tests/test_alternative_citations.py:24
     1 tests/test_notifications.py:813
     1 tests/test_views.py:111
     1 tests/test_notifications.py:811
     1 tests/test_alternative_citations.py:38
     1 tests/test_events.py:480
     1 tests/test_models.py:4263
     1 tests/test_views.py:120
     1 tests/test_events.py:489
     1 tests/test_notifications.py:966
     1 tests/test_views.py:1276
     1 tests/test_guids.py:50
     1 tests/test_views.py:1272
     1 tests/test_registrations/test_archiver.py:896
     1 tests/test_events.py:565
     1 tests/test_notifications.py:432
     1 tests/test_notifications.py:434
     1 website/addons/base/__init__.py:467
     1 website/files/models/base.py:717
     1 tests/test_registrations/test_archiver.py:932
     1 tests/test_websitefiles.py:530
     1 tests/test_notifications.py:804
     1 tests/test_alternative_citations.py:52
     1 tests/test_views.py:101
     1 framework/auth/core.py:1247
     1 tests/test_alternative_citations.py:59
     1 tests/test_registrations/test_sanctions.py:234
     1 tests/test_auth_basic_auth.py:78
     1 tests/test_websitefiles.py:183
     1 tests/test_views.py:877
     1 website/files/models/base.py:555
     1 tests/test_oauth.py:310
     1 tests/test_oauth.py:413
     1 tests/test_notifications.py:1087
     1 tests/test_events.py:398
     1 tests/test_events.py:394
     1 tests/test_models.py:1076
     1 tests/test_auth_basic_auth.py:67
     1 website/addons/base/__init__.py:482
     1 website/addons/base/__init__.py:480
     1 tests/test_models.py:2665
     1 tests/test_notifications.py:1028
     1 tests/test_alternative_citations.py:45
     1 tests/test_models.py:810
     1 tests/test_views.py:3853
79,355 Σ
#!/usr/bin/env python
# encoding: utf-8
from __future__ import absolute_import, division, print_function, unicode_literals
from collections import defaultdict

entries = defaultdict(int)
exits = defaultdict(int)
for line in open('save.log'):
    if not line:
        continue
    entry, exit_ = line.split()
    entries[entry] += 1
    exits[exit_] += 1

for name, d in (("Entries", entries), ("Exits", exits)):
    title = "------ {} (N={:,}) ".format(name, len(d))
    total = 0
    print(title.ljust(40, '-'))
    print()
    for k,v in reversed(sorted(d.items(), key=lambda o: o[1])):
        print("{:>6,} {}".format(v, k))
        total += v
    print('{:>6,} {}'.format(total, 'Σ').encode('utf8'))
    print()
    print()
chadwhitacre commented 8 years ago

"Entries" means the first frame outside of the test suite, and "Exits" are the last frame before descending into storedobject.py.

chadwhitacre commented 8 years ago

With the following patch, the test suite runs in ~37% of the time it runs without it. However, errors+failures are up to 82%. ;-)

diff --git a/framework/auth/core.py b/framework/auth/core.py
index a738882..2518e78 100644
--- a/framework/auth/core.py
+++ b/framework/auth/core.py
@@ -1046,6 +1046,7 @@ class User(GuidStoredObject, AddonModelMixin):
     def save(self, *args, **kwargs):
         # TODO: Update mailchimp subscription on username change
         # Avoid circular import
+        return
         from framework.analytics import tasks as piwik_tasks
         self.username = self.username.lower().strip() if self.username else None
         ret = super(User, self).save(*args, **kwargs)
chadwhitacre commented 8 years ago 
------ Entries (N=14) ------------------

 1,202 scripts/parse_citation_styles.py:49
   418 website/project/model.py:144
    27 scripts/parse_citation_styles.py:14
    27 api/base/wsgi.py:16
    24 tests/factories.py:88
    11 -
    10 website/project/model.py:3664
     8 framework/auth/__init__.py:47
     6 website/oauth/models/__init__.py:275
     3 tests/factories.py:541
     2 framework/auth/core.py:515
     2 website/oauth/models/__init__.py:431
     1 framework/guid/model.py:95
     1 framework/guid/model.py:94
 1,742 Σ

------ Exits (N=24) --------------------

 1,202 scripts/parse_citation_styles.py:49
   440 website/project/model.py:136
    32 website/project/licenses/__init__.py:112
    24 tests/factories.py:88
    10 website/project/model.py:3664
     8 framework/sessions/__init__.py:101
     3 website/oauth/models/__init__.py:310
     3 website/oauth/models/__init__.py:285
     3 tests/factories.py:541
     2 website/oauth/models/__init__.py:431
     2 framework/auth/core.py:515
     1 tests/test_oauth.py:443
     1 framework/guid/model.py:95
     1 tests/test_registrations/test_archiver.py:1155
     1 tests/test_oauth.py:268
     1 tests/test_conferences.py:515
     1 tests/test_models.py:848
     1 tests/test_oauth.py:475
     1 tests/test_oauth.py:310
     1 tests/test_oauth.py:413
     1 tests/test_oauth.py:520
     1 framework/guid/model.py:82
     1 tests/test_models.py:810
     1 tests/test_conferences.py:375
 1,742 Σ
chadwhitacre commented 8 years ago

How about startup time? What does it cost to test the null hypothesis?

[osf.io]$ time nosetests tests/test_null.py 
[website.util.paths]  WARNING: Skipping load of "webpack-assets.json" in DEBUG_MODE.
[website.project.metadata.authorizers]  INFO: No local.json found to populate lists of DraftRegistrationApproval authorizers.
[website.addons.github.settings]  WARNING: No local.py settings file found
[website.addons.osfstorage.settings]  WARNING: No local.py settings file found
[website.addons.wiki.settings]  WARNING: No local.py settings file found
[root]  DEBUG: Setting storage backends
[root]  INFO: Sentry disabled; Flask's debug mode enabled
[root]  INFO: Sentry disabled; Flask's debug mode enabled
E
======================================================================
ERROR: test (tests.test_null.TestNull)
----------------------------------------------------------------------
TypeError: test() takes no arguments (1 given)
-------------------- >> begin captured logging << --------------------
website.util.paths: WARNING: Skipping load of "webpack-assets.json" in DEBUG_MODE.
website.project.metadata.authorizers: INFO: No local.json found to populate lists of DraftRegistrationApproval authorizers.
website.addons.github.settings: WARNING: No local.py settings file found
website.addons.osfstorage.settings: WARNING: No local.py settings file found
website.addons.wiki.settings: WARNING: No local.py settings file found
root: DEBUG: Setting storage backends
root: INFO: Sentry disabled; Flask's debug mode enabled
root: INFO: Sentry disabled; Flask's debug mode enabled
--------------------- >> end captured logging << ---------------------

----------------------------------------------------------------------
Ran 1 test in 0.617s

FAILED (errors=1)

real    0m5.957s
user    0m4.685s
sys     0m0.547s
[osf.io]$
from tests.base import OsfTestCase

class TestNull(OsfTestCase):
    def test():
        pass
chadwhitacre commented 8 years ago

I just double-checked the Gratipay test suite as a benchmark. Over there, I'm seeing ~70 seconds for ~500 tests. Here I'm seeing ~650 seconds for ~1,750 tests. If our test suite ran as fast as Gratipay's, we would expect to see ~250 seconds, roughly four minutes—a 2x to 3x improvement.

It's a normal workflow is to only run one or a few tests during active local development, running the full test suite only before pushing up changes. I'm seeing a similar profile for that case: 2.3 seconds on Gratipay to test the null hypothesis (def test(): pass) vs. 6.2 seconds here.

I'm going to focus on this latter case first, because I think it will have the greatest impact on developer productivity. Perhaps that'll have a follow-on effect for per-test setup and therefore on overall test suite time, but if not, I propose that our effort is better spent elsewhere than seeking a mere 2-3x improvement in overall test suite time. @JeffSpies mentioned that server restart time is also an issue during development, so I may look at that as well.

JeffSpies commented 8 years ago

We may find that there are optimizations in common between restart time and test suite start time.

On Dec 18, 2015, at 9:29 AM, Chad Whitacre notifications@github.com wrote:

I just double-checked the Gratipay test suite as a benchmark. Over there, I'm seeing ~70 seconds for ~500 tests. Here I'm seeing ~650 seconds for ~1,750 tests. If our test suite ran as fast as Gratipay's, we would expect to see ~250 seconds, roughly four minutes—a 2x to 3x improvement.

It's a normal workflow is to only run one or a few tests during active local development, running the full test suite only before pushing up changes. I'm seeing a similar profile for that case: 2.3 seconds on Gratipay to test the null hypothesis (def test(): pass) vs. 6.2 seconds here.

I'm going to focus on this latter case first, because I think it will have the greatest impact on developer productivity. Perhaps that'll have a follow-on effect for per-test setup and therefore on overall test suite time, but if not, I propose that our effort is better spent elsewhere than seeking a mere 2-3x improvement in overall test suite time. @JeffSpies https://github.com/JeffSpies mentioned that server restart time is also an issue during development, so I may look at that as well.

— Reply to this email directly or view it on GitHub https://github.com/CenterForOpenScience/osf.io/issues/4768#issuecomment-165790496.

chadwhitacre commented 8 years ago

If we're lucky. :)

chadwhitacre commented 8 years ago

Alright! Let's do this. :-)

tests/test_null.py .

========================================== 1 passed in 7.71 seconds ==========================================
[osf.io]$ cat save.log 
api/base/wsgi.py:16                               website/project/model.py:136                      
api/base/wsgi.py:16                               website/project/model.py:136                      
api/base/wsgi.py:16                               website/project/model.py:136                      
api/base/wsgi.py:16                               website/project/model.py:136                      
api/base/wsgi.py:16                               website/project/model.py:136                      
api/base/wsgi.py:16                               website/project/model.py:136                      
api/base/wsgi.py:16                               website/project/model.py:136                      
api/base/wsgi.py:16                               website/project/model.py:136                      
api/base/wsgi.py:16                               website/project/model.py:136                      
api/base/wsgi.py:16                               website/project/model.py:136                      
api/base/wsgi.py:16                               website/project/model.py:136                      
api/base/wsgi.py:16                               website/project/licenses/__init__.py:112          
api/base/wsgi.py:16                               website/project/licenses/__init__.py:112          
api/base/wsgi.py:16                               website/project/licenses/__init__.py:112          
api/base/wsgi.py:16                               website/project/licenses/__init__.py:112          
api/base/wsgi.py:16                               website/project/licenses/__init__.py:112          
api/base/wsgi.py:16                               website/project/licenses/__init__.py:112          
api/base/wsgi.py:16                               website/project/licenses/__init__.py:112          
api/base/wsgi.py:16                               website/project/licenses/__init__.py:112          
api/base/wsgi.py:16                               website/project/licenses/__init__.py:112          
api/base/wsgi.py:16                               website/project/licenses/__init__.py:112          
api/base/wsgi.py:16                               website/project/licenses/__init__.py:112          
api/base/wsgi.py:16                               website/project/licenses/__init__.py:112          
api/base/wsgi.py:16                               website/project/licenses/__init__.py:112          
api/base/wsgi.py:16                               website/project/licenses/__init__.py:112          
api/base/wsgi.py:16                               website/project/licenses/__init__.py:112          
api/base/wsgi.py:16                               website/project/licenses/__init__.py:112
cwisecarver commented 8 years ago

I added a blinker signal to GuidStoredObject.save() in a PR that's not been merged yet, for cache invalidation. While I was debugging, it had a log statement in it. For every call to save we were actually saving at least twice, sometimes more than four times. That could explain part of the mongo chatter.

chadwhitacre commented 8 years ago

Thanks @cwisecarver. That could certainly help the overall test suite time.

chadwhitacre commented 8 years ago

In the cProfile output for the null test, I'm seeing two calls to init_app, each taking 1.3 seconds:

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        2    0.000    0.000    2.543    1.271 /Users/whit537/workbench/cos/osf.io/website/app.py:104(init_app)

Surely we can remove one of those ...

cwisecarver commented 8 years ago

website.project.licenses is looping through a json file and doing individual queries by id instead of doing a 'in' in mongo. Depending on the length of that file I could see 1.3 seconds being saved there.

chadwhitacre commented 8 years ago

@cwisecarver Yeah, there's another loop in ensure_schemas for which we may be able to consolidate the db calls as well.

chadwhitacre commented 8 years ago

Importing api.base.wsgi triggers a call to init_app, and then importing from tests.base makes a second call. Can we avoid the first during testing?

chadwhitacre commented 8 years ago

Ftr it sounds like there is some template logfile writing(?) that doesn't need to happen as well.

sloria commented 8 years ago

Yeah, init_app does a lot. When we call it in tests or scripts, we usually only need the storage backends to be set on the models.

chadwhitacre commented 8 years ago

What happens if we use the test_app in the ApiAppTestCase?

chadwhitacre commented 8 years ago

Ooooh!

/me discovers api_tests

chadwhitacre commented 8 years ago

First run ...

screen shot 2015-12-18 at 10 41 47 am

chadwhitacre commented 8 years ago

/me learns about test_travis_$TEST_BUILD

chadwhitacre commented 8 years ago

Maybe we can at least lazily init_app the API app in setUpClass?

chadwhitacre commented 8 years ago

1291 passed, 1 skipped in 353.19 seconds