Create a gist now

Instantly share code, notes, and snippets.

@dmakhno /run_log
Last active Aug 29, 2015

What would you like to do?
Download ZIP
Paralleling tests
Raw
run_log
$ nosetests --processes 5 test_debug_parallel.py
INFO - heavy operation is beginning... 1 FirstTest
INFO - heavy operation is beginning... 1 SecondTest
INFO - heavy operation is beginning... 1 ThirdTest
INFO - heavy operation has ended 1 FirstTest
DEBUG - 47620 140735328031504 1396607234.95 setUpClass 1 FirstTest
INFO - heavy operation has ended 1 SecondTest
DEBUG - 47621 140735328031504 1396607234.96 setUpClass 1 SecondTest
INFO - heavy operation has ended 1 ThirdTest
DEBUG - 47622 140735328031504 1396607234.98 setUpClass 1 ThirdTest
DEBUG - 47620 140735328031504 1396607235.13 5 FirstTest
DEBUG - 47621 140735328031504 1396607235.15 5 SecondTest
DEBUG - 47622 140735328031504 1396607235.17 5 ThirdTest
DEBUG - 47620 140735328031504 1396607235.25 4 FirstTest
DEBUG - 47621 140735328031504 1396607235.27 4 SecondTest
DEBUG - 47622 140735328031504 1396607235.29 4 ThirdTest
DEBUG - 47620 140735328031504 1396607235.34 1 FirstTest
DEBUG - 47621 140735328031504 1396607235.36 1 SecondTest
DEBUG - 47622 140735328031504 1396607235.38 1 ThirdTest
DEBUG - 47622 140735328031504 1396607235.44 _3rd ThirdTest
DEBUG - 47621 140735328031504 1396607235.57 _2nd SecondTest
DEBUG - 47620 140735328031504 1396607235.58 3 FirstTest
DEBUG - 47622 140735328031504 1396607235.68 3 ThirdTest
DEBUG - 47620 140735328031504 1396607235.73 2 FirstTest
DEBUG - 47620 140735328031504 1396607235.73 tearDownClass FirstTest
.....DEBUG - 47621 140735328031504 1396607235.81 3 SecondTest
DEBUG - 47622 140735328031504 1396607235.83 2 ThirdTest
DEBUG - 47622 140735328031504 1396607235.83 tearDownClass ThirdTest
......DEBUG - 47621 140735328031504 1396607235.96 2 SecondTest
DEBUG - 47621 140735328031504 1396607235.96 tearDownClass SecondTest
......
----------------------------------------------------------------------
Ran 17 tests in 4.101s
OK
$ SHARE=True nosetests --processes 5 test_debug_parallel.py
INFO - Shared: True
INFO - heavy operation is beginning... 1 FirstTest
INFO - heavy operation has ended 1 FirstTest
DEBUG - 47651 140735328031504 1396607263.19 setUpClass 1 FirstTest
DEBUG - 47660 140735328031504 1396607263.37 1 FirstTest
DEBUG - 47659 140735328031504 1396607263.37 4 FirstTest
..DEBUG - 47658 140735328031504 1396607263.41 5 FirstTest
.DEBUG - 47662 140735328031504 1396607263.46 2 FirstTest
.DEBUG - 47659 140735328031504 1396607263.49 4 SecondTest
.DEBUG - 47658 140735328031504 1396607263.5 1 SecondTest
.DEBUG - 47661 140735328031504 1396607263.54 3 FirstTest
.DEBUG - 47660 140735328031504 1396607263.55 5 SecondTest
.DEBUG - 47658 140735328031504 1396607263.66 2 SecondTest
DEBUG - 47660 140735328031504 1396607263.67 4 ThirdTest
DEBUG - 47662 140735328031504 1396607263.68 _2nd SecondTest
...DEBUG - 47661 140735328031504 1396607263.72 5 ThirdTest
DEBUG - 47660 140735328031504 1396607263.73 _3rd ThirdTest
DEBUG - 47659 140735328031504 1396607263.74 3 SecondTest
...DEBUG - 47658 140735328031504 1396607263.75 1 ThirdTest
.DEBUG - 47661 140735328031504 1396607263.87 2 ThirdTest
.DEBUG - 47662 140735328031504 1396607263.92 3 ThirdTest
.DEBUG - 47651 140735328031504 1396607263.92 tearDownClass FirstTest
----------------------------------------------------------------------
Ran 17 tests in 3.737s
OK
$ SPLIT=True nosetests --processes 5 test_debug_parallel.py
INFO - Can Split: True
INFO - heavy operation is beginning... 1 FirstTest
INFO - heavy operation is beginning... 1 FirstTest
INFO - heavy operation is beginning... 1 FirstTest
INFO - heavy operation is beginning... 1 FirstTest
INFO - heavy operation is beginning... 1 FirstTest
INFO - heavy operation has ended 1 FirstTest
DEBUG - 47678 140735328031504 1396607281.78 setUpClass 1 FirstTest
INFO - heavy operation has ended 1 FirstTest
DEBUG - 47679 140735328031504 1396607281.8 setUpClass 1 FirstTest
INFO - heavy operation has ended 1 FirstTest
DEBUG - 47680 140735328031504 1396607281.82 setUpClass 1 FirstTest
INFO - heavy operation has ended 1 FirstTest
DEBUG - 47681 140735328031504 1396607281.84 setUpClass 1 FirstTest
INFO - heavy operation has ended 1 FirstTest
DEBUG - 47682 140735328031504 1396607281.85 setUpClass 1 FirstTest
DEBUG - 47680 140735328031504 1396607281.91 1 FirstTest
DEBUG - 47680 140735328031504 1396607281.91 tearDownClass FirstTest
INFO - heavy operation is beginning... 2 SecondTest
DEBUG - 47679 140735328031504 1396607281.93 4 FirstTest
DEBUG - 47679 140735328031504 1396607281.93 tearDownClass FirstTest
INFO - heavy operation is beginning... 2 SecondTest
..DEBUG - 47678 140735328031504 1396607281.97 5 FirstTest
DEBUG - 47678 140735328031504 1396607281.97 tearDownClass FirstTest
.INFO - heavy operation is beginning... 2 SecondTest
DEBUG - 47682 140735328031504 1396607282.01 2 FirstTest
DEBUG - 47682 140735328031504 1396607282.01 tearDownClass FirstTest
INFO - heavy operation is beginning... 2 SecondTest
.DEBUG - 47681 140735328031504 1396607282.08 3 FirstTest
DEBUG - 47681 140735328031504 1396607282.08 tearDownClass FirstTest
INFO - heavy operation is beginning... 2 SecondTest
.INFO - heavy operation has ended 2 SecondTest
DEBUG - 47680 140735328031504 1396607284.91 setUpClass 2 SecondTest
INFO - heavy operation has ended 2 SecondTest
DEBUG - 47679 140735328031504 1396607284.93 setUpClass 2 SecondTest
INFO - heavy operation has ended 2 SecondTest
DEBUG - 47678 140735328031504 1396607284.97 setUpClass 2 SecondTest
INFO - heavy operation has ended 2 SecondTest
DEBUG - 47682 140735328031504 1396607285.01 setUpClass 2 SecondTest
DEBUG - 47679 140735328031504 1396607285.05 4 SecondTest
DEBUG - 47679 140735328031504 1396607285.05 tearDownClass SecondTest
DEBUG - 47678 140735328031504 1396607285.06 1 SecondTest
DEBUG - 47678 140735328031504 1396607285.06 tearDownClass SecondTest
INFO - heavy operation is beginning... 3 ThirdTest
..INFO - heavy operation has ended 2 SecondTest
DEBUG - 47681 140735328031504 1396607285.08 setUpClass 2 SecondTest
DEBUG - 47680 140735328031504 1396607285.1 5 SecondTest
DEBUG - 47680 140735328031504 1396607285.1 tearDownClass SecondTest
INFO - heavy operation is beginning... 3 ThirdTest
.DEBUG - 47679 140735328031504 1396607285.2 2 SecondTest
INFO - heavy operation is beginning... 3 ThirdTest
.DEBUG - 47682 140735328031504 1396607285.22 _2nd SecondTest
DEBUG - 47682 140735328031504 1396607285.22 tearDownClass SecondTest
INFO - heavy operation is beginning... 3 ThirdTest
.DEBUG - 47681 140735328031504 1396607285.32 3 SecondTest
DEBUG - 47681 140735328031504 1396607285.32 tearDownClass SecondTest
INFO - heavy operation is beginning... 3 ThirdTest
.INFO - heavy operation has ended 3 ThirdTest
DEBUG - 47678 140735328031504 1396607288.06 setUpClass 3 ThirdTest
INFO - heavy operation has ended 3 ThirdTest
DEBUG - 47680 140735328031504 1396607288.1 setUpClass 3 ThirdTest
INFO - heavy operation has ended 3 ThirdTest
DEBUG - 47679 140735328031504 1396607288.2 setUpClass 3 ThirdTest
DEBUG - 47680 140735328031504 1396607288.22 4 ThirdTest
DEBUG - 47680 140735328031504 1396607288.22 tearDownClass ThirdTest
INFO - heavy operation has ended 3 ThirdTest
DEBUG - 47682 140735328031504 1396607288.22 setUpClass 3 ThirdTest
DEBUG - 47678 140735328031504 1396607288.24 5 ThirdTest
DEBUG - 47678 140735328031504 1396607288.24 tearDownClass ThirdTest
..DEBUG - 47682 140735328031504 1396607288.28 _3rd ThirdTest
DEBUG - 47682 140735328031504 1396607288.28 tearDownClass ThirdTest
DEBUG - 47679 140735328031504 1396607288.3 1 ThirdTest
DEBUG - 47679 140735328031504 1396607288.3 tearDownClass ThirdTest
..INFO - heavy operation has ended 3 ThirdTest
DEBUG - 47681 140735328031504 1396607288.33 setUpClass 3 ThirdTest
DEBUG - 47680 140735328031504 1396607288.37 2 ThirdTest
.DEBUG - 47681 140735328031504 1396607288.57 3 ThirdTest
DEBUG - 47681 140735328031504 1396607288.57 tearDownClass ThirdTest
.
----------------------------------------------------------------------
Ran 17 tests in 9.858s
OK
$ py.test -s -n 5 test_debug_parallel.py
================================================== test session starts ==================================================
platform darwin -- Python 2.7.5 -- py-1.4.20 -- pytest-2.5.2
plugins: xdist
gw0 [17] / gw1 [17] / gw2 [17] / gw3 [17] / gw4 [17]
scheduling tests via LoadScheduling
INFO - heavy operation is beginning... 1 FirstTest
INFO - heavy operation is beginning... 1 FirstTest
INFO - heavy operation is beginning... 1 FirstTest
INFO - heavy operation is beginning... 1 FirstTest
INFO - heavy operation is beginning... 1 FirstTest
INFO - heavy operation has ended 1 FirstTest
INFO - heavy operation has ended 1 FirstTest
INFO - heavy operation has ended 1 FirstTest
INFO - heavy operation has ended 1 FirstTest
INFO - heavy operation has ended 1 FirstTest
DEBUG - 47869 140735328031504 1396607478.69 setUpClass 1 FirstTest
DEBUG - 47870 140735328031504 1396607478.69 setUpClass 1 FirstTest
DEBUG - 47868 140735328031504 1396607478.69 setUpClass 1 FirstTest
DEBUG - 47872 140735328031504 1396607478.69 setUpClass 1 FirstTest
DEBUG - 47871 140735328031504 1396607478.69 setUpClass 1 FirstTest
DEBUG - 47869 140735328031504 1396607478.78 1 FirstTest
DEBUG - 47869 140735328031504 1396607478.78 tearDownClass FirstTest
.INFO - heavy operation is beginning... 2 SecondTest
DEBUG - 47872 140735328031504 1396607478.81 4 FirstTest
DEBUG - 47872 140735328031504 1396607478.81 tearDownClass FirstTest
.INFO - heavy operation is beginning... 2 SecondTest
DEBUG - 47870 140735328031504 1396607478.84 2 FirstTest
DEBUG - 47870 140735328031504 1396607478.84 tearDownClass FirstTest
.INFO - heavy operation is beginning... 2 SecondTest
DEBUG - 47868 140735328031504 1396607478.87 5 FirstTest
DEBUG - 47868 140735328031504 1396607478.87 tearDownClass FirstTest
.INFO - heavy operation is beginning... 2 ThirdTest
DEBUG - 47871 140735328031504 1396607478.93 3 FirstTest
DEBUG - 47871 140735328031504 1396607478.93 tearDownClass FirstTest
.INFO - heavy operation is beginning... 2 ThirdTest
INFO - heavy operation has ended 2 SecondTest
DEBUG - 47869 140735328031504 1396607481.79 setUpClass 2 SecondTest
INFO - heavy operation has ended 2 SecondTest
DEBUG - 47872 140735328031504 1396607481.83 setUpClass 2 SecondTest
INFO - heavy operation has ended 2 SecondTest
DEBUG - 47870 140735328031504 1396607481.84 setUpClass 2 SecondTest
INFO - heavy operation has ended 2 ThirdTest
DEBUG - 47868 140735328031504 1396607481.88 setUpClass 2 ThirdTest
DEBUG - 47872 140735328031504 1396607481.92 1 SecondTest
.INFO - heavy operation has ended 2 ThirdTest
DEBUG - 47871 140735328031504 1396607481.95 setUpClass 2 ThirdTest
DEBUG - 47869 140735328031504 1396607481.97 5 SecondTest
.DEBUG - 47871 140735328031504 1396607482.04 1 ThirdTest
.DEBUG - 47868 140735328031504 1396607482.06 5 ThirdTest
.DEBUG - 47870 140735328031504 1396607482.09 3 SecondTest
DEBUG - 47869 140735328031504 1396607482.1 4 SecondTest
DEBUG - 47869 140735328031504 1396607482.1 tearDownClass SecondTest
..DEBUG - 47871 140735328031504 1396607482.1 _3rd ThirdTest
DEBUG - 47871 140735328031504 1396607482.1 tearDownClass ThirdTest
INFO - heavy operation is beginning... 3 ThirdTest
.DEBUG - 47872 140735328031504 1396607482.13 _2nd SecondTest
DEBUG - 47872 140735328031504 1396607482.13 tearDownClass SecondTest
INFO - heavy operation is beginning... 3 ThirdTest
.DEBUG - 47868 140735328031504 1396607482.18 4 ThirdTest
DEBUG - 47868 140735328031504 1396607482.18 tearDownClass ThirdTest
.DEBUG - 47870 140735328031504 1396607482.24 2 SecondTest
DEBUG - 47870 140735328031504 1396607482.24 tearDownClass SecondTest
.INFO - heavy operation has ended 3 ThirdTest
DEBUG - 47871 140735328031504 1396607485.1 setUpClass 3 ThirdTest
INFO - heavy operation has ended 3 ThirdTest
DEBUG - 47872 140735328031504 1396607485.13 setUpClass 3 ThirdTest
DEBUG - 47871 140735328031504 1396607485.25 2 ThirdTest
DEBUG - 47871 140735328031504 1396607485.26 tearDownClass ThirdTest
.DEBUG - 47872 140735328031504 1396607485.38 3 ThirdTest
DEBUG - 47872 140735328031504 1396607485.38 tearDownClass ThirdTest
.
============================================== 17 passed in 10.19 seconds ===============================================
Raw
test_parallel.py
# Try with:
# nosetests --processes 5 test_debug_parallel.py -- setUpClass called once per suite,
# same behaviour as SHARE=False or SPLIT=False
# SHARE=True nosetests --processes 5 test_debug_parallel.py -- setUpClass called once for all inheritors
# SPLIT=True nosetests --processes 5 test_debug_parallel.py -- many-many setUpClass
# py.test -s -n 5 test_parallel.py -- same as nose _multiprocess_can_split_=True
# Requirements:
# python_2.7
# py.test
# xdist
# nose
import os
import time
import logging
from threading import current_thread
from multiprocessing.process import current_process
import testtools
log = logging.getLogger()
log.setLevel(logging.DEBUG)
handler = logging.StreamHandler()
handler.setLevel(logging.DEBUG)
formatter = logging.Formatter("%(levelname)s - %(message)s")
handler.setFormatter(formatter)
log.addHandler(handler)
def d(s):
log.debug("{0} {1} {2} {3}".format(current_process().ident, current_thread().ident, time.time(), s))
i = 0 # per process counter
quant = 0.03 # increase if too fast
class FirstTest(testtools.TestCase):
if 'SPLIT' in os.environ:
can_spilt = os.getenv('SPLIT').lower() in ['true']
_multiprocess_can_split_ = can_spilt
log.info("Can Split: "+str(can_spilt))
if 'SHARE' in os.environ:
shared = os.getenv('SHARE').lower() in ['true']
_multiprocess_shared_ = shared
log.info("Shared: "+str(shared))
@classmethod
def setUpClass(cls):
global i
i += 1
log.info("heavy operation is beginning... {0} {1}".format(i, cls.__name__))
time.sleep(100 * quant)
log.info("heavy operation has ended {0} {1}".format(i, cls.__name__))
d("setUpClass {0} {1}".format(i, cls.__name__))
@classmethod
def tearDownClass(cls):
d("tearDownClass " + cls.__name__)
def test_one(self):
time.sleep(3 * quant)
d("1 " + self.__class__.__name__)
def test_two(self):
time.sleep(5 * quant)
d("2 " + self.__class__.__name__)
def test_three(self):
time.sleep(8 * quant)
d("3 " + self.__class__.__name__)
def test_four(self):
time.sleep(4 * quant)
d("4 " + self.__class__.__name__)
def test_five(self):
time.sleep(6 * quant)
d("5 " + self.__class__.__name__)
class SecondTest(FirstTest):
def test_this(self):
time.sleep(7 * quant)
d("_2nd " + self.__class__.__name__)
class ThirdTest(FirstTest):
def test_that(self):
time.sleep(2 * quant)
d("_3rd " + self.__class__.__name__)
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment