def test_attr_int(self): """値の取得のテスト 40マイクロ秒 gtoolkit版は 180 マイクロ秒ぐらいだったのでなぜか早くなってる """ etw = ElapsedTimeWatch() m = self.get_mock_model() i = m.objects.get_by_id(1) self.assertEqual(i.value, 200) etw.logging_us() etw.write_debug_log('JsonMasterModelTest.test_attr_int')
def test_mass_access(self): """値の取得のテスト""" #s = threading.Semaphore #return try: MockLargeModel.get(1) except IOError as e: print >> sys.stderr, \ 'テストフィクスチャが作られていません' print >> sys.stderr, \ '$ ./create_testfixture.py > jsonmastermodel-testfixture-large.json' print >> sys.stderr, \ 'を実行してください。(git ignored)' return q = Queue() etw = ElapsedTimeWatch() for i in range(100): t = Worker(q) t.setDaemon(True) t.start() etw.logging_ms('create workers') for i in xrange(1, 1000): q.put(i) q.join() etw.logging_ms('task done') etw.write_debug_log()
def test_quick_filter(self): """ MockModel.quick_filter のテスト objects.filter より早い quick_filter elapsed: 6 ms """ try: m = self.get_mock_model() except IOError as e: # テストフィクスチャなければキャンセル logger.debug('LargeJsonMasterModelTest: test cancel. {}'.format( str(e))) return etw = ElapsedTimeWatch() m.quick_filter(category='category-50') # 暖気しておく # 暖気はけっこう時間かかる # quick_filter standby elapsed: 119 ms logger.debug('quick_filter standby elapsed: {} ms'.format( etw.elapsed_time_lap_ms)) for category_number in [10, 20, 30, 40, 50, 60, 70]: category = 'category-{}'.format(category_number) L = m.quick_filter(category=category) self.assertEqual(len(L), 100) # ただし、一度キャッシュに乗ってしまえば早い # quick_filter elapsed: 0 ms logger.debug('quick_filter elapsed: {} ms'.format( etw.elapsed_time_lap_ms))
def test_objects_filter(self): """ MockModel.objects.filter のテスト test_objects_filter elapsed: 125 ms """ try: m = self.get_mock_model() except IOError as e: # テストフィクスチャなければキャンセル logger.debug('LargeJsonMasterModelTest: test cancel. {}'.format( str(e))) return etw = ElapsedTimeWatch() m.objects.filter(category='category-50') # test_quick_filter の暖気と同様の処理 # test_objects_filter standby elapsed: 23 ms # 1回だけならこちらが早い logger.debug('test_objects_filter standby elapsed: {} ms'.format( etw.elapsed_time_lap_ms)) for category_number in [10, 20, 30, 40, 50, 60, 70]: category = 'category-{}'.format(category_number) L = m.objects.filter(category=category) self.assertEqual(len(L), 100) # test_objects_filter elapsed: 169 ms logger.debug('test_objects_filter elapsed: {} ms'.format( etw.elapsed_time_lap_ms))
def get_mock_model(self): """ テスト時のみ、 MockModelを評価して作る。 cached_property にすると、テストコード評価時に動作してしまうので、 memoized_property にしている。 """ etw = ElapsedTimeWatch() model = MockLargeModel logger.debug('MockLargeModel new. elapsed: {} ms'.format( etw.elapsed_time_ms)) model.objects.all() # MacBookAir ローカル環境だと、10000レコード読み込みで 110ms logger.debug('MockLargeModel create. elapsed: {} ms'.format( etw.elapsed_time_ms)) return model
def get_mock_model(self): """ テスト時のみ、 MockModelを評価して作る。 cached_property にすると、テストコード評価時に動作してしまうので、 memoized_property にしている。 """ etw = ElapsedTimeWatch() class MockModel(JsonMasterModel): MASTER_DATA_JSON_PATH = '%s/jsonmastermodel-testfixture-large.json' %\ os.path.dirname(__file__) # MacBookAir ローカル環境だと、10000レコード読み込みで 110ms logger.debug('Mockmodel create. elapsed: {} ms'.format( etw.elapsed_time_ms)) return MockModel
def test_quick_filter(self): """ MockModel.quick_filter のテスト objects.filter より早い quick_filter elapsed: 6 ms """ try: m = self.get_mock_model() except IOError as e: # テストフィクスチャなければキャンセル logger.debug('LargeJsonMasterModelTest: test cancel. {}'.format( str(e))) return etw = ElapsedTimeWatch() for category_number in [10, 20, 30, 40, 50, 60, 70]: category = 'category-{}'.format(category_number) L = m.quick_filter(category=category) self.assertEqual(len(L), 100) #logger.debug(','.join([str(i.id) for i in L])) logger.debug('quick_filter elapsed: {} ms'.format(etw.elapsed_time_ms))
def test_elapsed_time_watch(self): etw = ElapsedTimeWatch(label='test') time.sleep(0.001) self.assertTrue(etw.elapsed_time) self.assertTrue(etw.elapsed_time_ms) self.assertTrue(etw.elapsed_time_us) self.assertTrue(etw.elapsed_time_lap_ms) self.assertTrue(etw.elapsed_time_lap_us) _ = etw.elapsed_mem _ = etw.elapsed_mem_lap _ = etw.elapsed_mem_lap_mb time.sleep(0.001) self.assertIn('test', etw.log_label) etw.logging('Phase1') etw.logging_mem() etw.logging_ms() etw.logging_us() result = etw.get_log() # u'Total:6ms, Phase1:4ms' self.assertIn('Total', result) self.assertIn('Phase1', result) etw.write_debug_log()