dmakhno / run_log

Last active April 04, 2014


    
    View run_log 
  
  
      run_log
    
    
        Raw
      
    
    File suppressed. Click to show.
  
  
            1
            2
            3
            4
            5
            6
            7
            8
            9
            10
            11
            12
            13
            14
            15
            16
            17
            18
            19
            20
            21
            22
            23
            24
            25
            26
            27
            28
            29
            30
            31
            32
            33
            34
            35
            36
            37
            38
            39
            40
            41
            42
            43
            44
            45
            46
            47
            48
            49
            50
            51
            52
            53
            54
            55
            56
            57
            58
            59
            60
            61
            62
            63
            64
            65
            66
            67
            68
            69
            70
            71
            72
            73
            74
            75
            76
            77
            78
            79
            80
            81
            82
            83
            84
            85
            86
            87
            88
            89
            90
            91
            92
            93
            94
            95
            96
            97
            98
            99
            100
            101
            102
            103
            104
            105
            106
            107
            108
            109
            110
            111
            112
            113
            114
            115
            116
            117
            118
            119
            120
            121
            122
            123
            124
            125
            126
            127
            128
            129
            130
            131
            132
            133
            134
            135
            136
            137
            138
            139
            140
            141
            142
            143
            144
            145
            146
            147
            148
            149
            150
            151
            152
            153
            154
            155
            156
            157
            158
            159
            160
            161
            162
            163
            164
            165
            166
            167
            168
            169
            170
            171
            172
            173
            174
            175
            176
            177
            178
            179
            180
            181
            182
            183
            184
            185
            186
            187
            188
            189
            190
            191
            192
            193
            194
            195
            196
            197
            198
            199
            200
            201
            202
            203
            204
            205
            206
            207
            208
            209
            210
            211
            212
            213
            214
            215
            216
            217
            218
            219
            220
            221
            222
            223
            224
            225
            226
          
          
            $ 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 ===============================================

          
    View run_log 
  
  
      test_parallel.py
    
    
        Raw
      
    
    File suppressed. Click to show.
  
  
            1
            2
            3
            4
            5
            6
            7
            8
            9
            10
            11
            12
            13
            14
            15
            16
            17
            18
            19
            20
            21
            22
            23
            24
            25
            26
            27
            28
            29
            30
            31
            32
            33
            34
            35
            36
            37
            38
            39
            40
            41
            42
            43
            44
            45
            46
            47
            48
            49
            50
            51
            52
            53
            54
            55
            56
            57
            58
            59
            60
            61
            62
            63
            64
            65
            66
            67
            68
            69
            70
            71
            72
            73
            74
            75
            76
            77
            78
            79
            80
            81
            82
            83
            84
            85
            86
            87
            88
            89
            90
            91
            92
            93
            94
            95
          
          
            # 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__)