def test_basic_sampler(self):
# Set up state sampler.
counter_factory = CounterFactory()
sampler = statesampler.StateSampler('basic-',
counter_factory,
sampling_period_ms=1)
# Run basic workload transitioning between 3 states.
sampler.start()
with sampler.scoped_state('statea'):
time.sleep(0.1)
with sampler.scoped_state('stateb'):
time.sleep(0.2 / 2)
with sampler.scoped_state('statec'):
time.sleep(0.3)
time.sleep(0.2 / 2)
sampler.stop()
sampler.commit_counters()
# Test that sampled state timings are close to their expected values.
expected_counter_values = {
'basic-statea-msecs': 100,
'basic-stateb-msecs': 200,
'basic-statec-msecs': 300,
}
for counter in counter_factory.get_counters():
self.assertIn(counter.name, expected_counter_values)
expected_value = expected_counter_values[counter.name]
actual_value = counter.value()
self.assertGreater(actual_value, expected_value * 0.75)
self.assertLess(actual_value, expected_value * 1.25)
def test_basic_sampler(self):
# Set up state sampler.
counter_factory = CounterFactory()
sampler = statesampler.StateSampler('basic', counter_factory,
sampling_period_ms=1)
# Run basic workload transitioning between 3 states.
sampler.start()
with sampler.scoped_state('statea'):
time.sleep(0.1)
with sampler.scoped_state('stateb'):
time.sleep(0.2 / 2)
with sampler.scoped_state('statec'):
time.sleep(0.3)
time.sleep(0.2 / 2)
sampler.stop()
sampler.commit_counters()
# Test that sampled state timings are close to their expected values.
expected_counter_values = {
'basic-statea-msecs': 100,
'basic-stateb-msecs': 200,
'basic-statec-msecs': 300,
}
for counter in counter_factory.get_counters():
self.assertIn(counter.name, expected_counter_values)
expected_value = expected_counter_values[counter.name]
actual_value = counter.value()
self.assertGreater(actual_value, expected_value * 0.75)
self.assertLess(actual_value, expected_value * 1.25)
def test_basic_sampler(self):
# Set up state sampler.
counter_factory = CounterFactory()
sampler = statesampler.StateSampler(
'basic', counter_factory, sampling_period_ms=1)
# Duration of the fastest state. Total test duration is 6 times longer.
state_duration_ms = 1000
margin_of_error = 0.25
# Run basic workload transitioning between 3 states.
sampler.start()
with sampler.scoped_state('step1', 'statea'):
time.sleep(state_duration_ms / 1000)
self.assertEqual(
sampler.current_state().name,
CounterName('statea-msecs', step_name='step1', stage_name='basic'))
with sampler.scoped_state('step1', 'stateb'):
time.sleep(state_duration_ms / 1000)
self.assertEqual(
sampler.current_state().name,
CounterName('stateb-msecs', step_name='step1', stage_name='basic'))
with sampler.scoped_state('step1', 'statec'):
time.sleep(3 * state_duration_ms / 1000)
self.assertEqual(
sampler.current_state().name,
CounterName(
'statec-msecs', step_name='step1', stage_name='basic'))
time.sleep(state_duration_ms / 1000)
sampler.stop()
sampler.commit_counters()
if not statesampler.FAST_SAMPLER:
# The slow sampler does not implement sampling, so we won't test it.
return
# Test that sampled state timings are close to their expected values.
# yapf: disable
expected_counter_values = {
CounterName('statea-msecs', step_name='step1', stage_name='basic'):
state_duration_ms,
CounterName('stateb-msecs', step_name='step1', stage_name='basic'): 2 *
state_duration_ms,
CounterName('statec-msecs', step_name='step1', stage_name='basic'): 3 *
state_duration_ms,
}
# yapf: enable
for counter in counter_factory.get_counters():
self.assertIn(counter.name, expected_counter_values)
expected_value = expected_counter_values[counter.name]
actual_value = counter.value()
deviation = float(abs(actual_value - expected_value)) / expected_value
_LOGGER.info('Sampling deviation from expectation: %f', deviation)
self.assertGreater(actual_value, expected_value * (1.0 - margin_of_error))
self.assertLess(actual_value, expected_value * (1.0 + margin_of_error))
def test_basic_sampler(self):
# Set up state sampler.
counter_factory = CounterFactory()
sampler = statesampler.StateSampler('basic', counter_factory,
sampling_period_ms=1)
# Run basic workload transitioning between 3 states.
sampler.start()
with sampler.scoped_state('step1', 'statea'):
time.sleep(0.1)
self.assertEqual(
sampler.current_state().name,
CounterName(
'statea-msecs', step_name='step1', stage_name='basic'))
with sampler.scoped_state('step1', 'stateb'):
time.sleep(0.2 / 2)
self.assertEqual(
sampler.current_state().name,
CounterName(
'stateb-msecs', step_name='step1', stage_name='basic'))
with sampler.scoped_state('step1', 'statec'):
time.sleep(0.3)
self.assertEqual(
sampler.current_state().name,
CounterName(
'statec-msecs', step_name='step1', stage_name='basic'))
time.sleep(0.2 / 2)
sampler.stop()
sampler.commit_counters()
if not statesampler.FAST_SAMPLER:
# The slow sampler does not implement sampling, so we won't test it.
return
# Test that sampled state timings are close to their expected values.
expected_counter_values = {
CounterName('statea-msecs', step_name='step1', stage_name='basic'): 100,
CounterName('stateb-msecs', step_name='step1', stage_name='basic'): 200,
CounterName('statec-msecs', step_name='step1', stage_name='basic'): 300,
}
for counter in counter_factory.get_counters():
self.assertIn(counter.name, expected_counter_values)
expected_value = expected_counter_values[counter.name]
actual_value = counter.value()
deviation = float(abs(actual_value - expected_value)) / expected_value
logging.info('Sampling deviation from expectation: %f', deviation)
self.assertGreater(actual_value, expected_value * 0.75)
self.assertLess(actual_value, expected_value * 1.25)
def test_should_sample(self):
# Order of magnitude more buckets than highest constant in code under test.
buckets = [0] * 300
# The seed is arbitrary and exists just to ensure this test is robust.
# If you don't like this seed, try your own; the test should still pass.
random.seed(1720)
# Do enough runs that the expected hits even in the last buckets
# is big enough to expect some statistical smoothing.
total_runs = 10 * len(buckets)
# Fill the buckets.
for _ in range(total_runs):
opcounts = OperationCounters(CounterFactory(), 'some-name',
coders.PickleCoder(), 0)
for i in range(len(buckets)):
if opcounts.should_sample():
buckets[i] += 1
# Look at the buckets to see if they are likely.
for i in range(10):
self.assertEqual(total_runs, buckets[i])
for i in range(10, len(buckets)):
self.assertTrue(
buckets[i] > 7 * total_runs / i,
'i=%d, buckets[i]=%d, expected=%d, ratio=%f' %
(i, buckets[i], 10 * total_runs / i, buckets[i] /
(10.0 * total_runs / i)))
self.assertTrue(
buckets[i] < 14 * total_runs / i,
'i=%d, buckets[i]=%d, expected=%d, ratio=%f' %
(i, buckets[i], 10 * total_runs / i, buckets[i] /
(10.0 * total_runs / i)))
def test_sampler_transition_overhead(self):
# Set up state sampler.
counter_factory = CounterFactory()
sampler = statesampler.StateSampler('overhead-',
counter_factory,
sampling_period_ms=10)
# Run basic workload transitioning between 3 states.
state_a = sampler.scoped_state('step1', 'statea')
state_b = sampler.scoped_state('step1', 'stateb')
state_c = sampler.scoped_state('step1', 'statec')
start_time = time.time()
sampler.start()
for _ in range(100000):
with state_a:
with state_b:
for _ in range(10):
with state_c:
pass
sampler.stop()
elapsed_time = time.time() - start_time
state_transition_count = sampler.get_info().transition_count
overhead_us = 1000000.0 * elapsed_time / state_transition_count
# TODO: This test is flaky when it is run under load. A better solution
# would be to change the test structure to not depend on specific timings.
overhead_us = 2 * overhead_us
_LOGGER.info('Overhead per transition: %fus', overhead_us)
# Conservative upper bound on overhead in microseconds (we expect this to
# take 0.17us when compiled in opt mode or 0.48 us when compiled with in
# debug mode).
self.assertLess(overhead_us, 10.0)
def test_sampler_transition_overhead(self):
# Set up state sampler.
counter_factory = CounterFactory()
sampler = statesampler.StateSampler('overhead-', counter_factory,
sampling_period_ms=10)
# Run basic workload transitioning between 3 states.
state_a = sampler.scoped_state('step1', 'statea')
state_b = sampler.scoped_state('step1', 'stateb')
state_c = sampler.scoped_state('step1', 'statec')
start_time = time.time()
sampler.start()
for _ in range(100000):
with state_a:
with state_b:
for _ in range(10):
with state_c:
pass
sampler.stop()
elapsed_time = time.time() - start_time
state_transition_count = sampler.get_info().transition_count
overhead_us = 1000000.0 * elapsed_time / state_transition_count
logging.info('Overhead per transition: %fus', overhead_us)
# Conservative upper bound on overhead in microseconds (we expect this to
# take 0.17us when compiled in opt mode or 0.48 us when compiled with in
# debug mode).
self.assertLess(overhead_us, 10.0)
def test_update_int(self):
opcounts = OperationCounters(CounterFactory(), 'some-name',
coders.PickleCoder(), 0)
self.verify_counters(opcounts, 0)
opcounts.update_from(GlobalWindows.windowed_value(1))
opcounts.update_collect()
self.verify_counters(opcounts, 1)
def run_benchmark(num_runs=50, input_per_source=4000, num_sources=4):
print("Number of runs:", num_runs)
print("Input size:", num_sources * input_per_source)
print("Sources:", num_sources)
times = []
for i in range(num_runs):
counter_factory = CounterFactory()
state_sampler = statesampler.StateSampler('basic', counter_factory)
with state_sampler.scoped_state('step1', 'state'):
si_counter = opcounters.SideInputReadCounter(
counter_factory, state_sampler, 'step1', 1)
si_counter = opcounters.NoOpTransformIOCounter()
sources = [
FakeSource(long_generator(i, input_per_source))
for i in range(num_sources)]
iterator_fn = sideinputs.get_iterator_fn_for_sources(
sources, read_counter=si_counter)
start = time.time()
list(iterator_fn())
time_cost = time.time() - start
times.append(time_cost)
print("Runtimes:", times)
avg_runtime = sum(times) // len(times)
print("Average runtime:", avg_runtime)
print("Time per element:", avg_runtime // (input_per_source *
num_sources))
def execute_map_tasks(self, ordered_map_tasks):
tt = time.time()
for ix, (_, map_task) in enumerate(ordered_map_tasks):
logging.info('Running %s', map_task)
t = time.time()
stage_names, all_operations = zip(*map_task)
# TODO(robertwb): The DataflowRunner worker receives system step names
# (e.g. "s3") that are used to label the output msec counters. We use the
# operation names here, but this is not the same scheme used by the
# DataflowRunner; the result is that the output msec counters are named
# differently.
system_names = stage_names
# Create the CounterFactory and StateSampler for this MapTask.
# TODO(robertwb): Output counters produced here are currently ignored.
counter_factory = CounterFactory()
state_sampler = statesampler.StateSampler('%s-' % ix,
counter_factory)
map_executor = operations.SimpleMapTaskExecutor(
operation_specs.MapTask(all_operations, 'S%02d' % ix,
system_names, stage_names,
system_names), counter_factory,
state_sampler)
self.executors.append(map_executor)
map_executor.execute()
logging.info('Stage %s finished: %0.3f sec', stage_names[0],
time.time() - t)
logging.info('Total time: %0.3f sec', time.time() - tt)
def test_nested_with_per_thread_info(self):
self.maxDiff = None
tracker = statesampler.StateSampler('stage', CounterFactory())
statesampler.set_current_tracker(tracker)
formatter = logger.JsonLogFormatter(job_id='jobid', worker_id='workerid')
with logger.PerThreadLoggingContext(work_item_id='workitem'):
with tracker.scoped_state('step1', 'process'):
record = self.create_log_record(**self.SAMPLE_RECORD)
log_output1 = json.loads(formatter.format(record))
with tracker.scoped_state('step2', 'process'):
record = self.create_log_record(**self.SAMPLE_RECORD)
log_output2 = json.loads(formatter.format(record))
record = self.create_log_record(**self.SAMPLE_RECORD)
log_output3 = json.loads(formatter.format(record))
statesampler.set_current_tracker(None)
record = self.create_log_record(**self.SAMPLE_RECORD)
log_output4 = json.loads(formatter.format(record))
self.assertEqual(
log_output1,
dict(self.SAMPLE_OUTPUT, work='workitem', stage='stage', step='step1'))
self.assertEqual(
log_output2,
dict(self.SAMPLE_OUTPUT, work='workitem', stage='stage', step='step2'))
self.assertEqual(
log_output3,
dict(self.SAMPLE_OUTPUT, work='workitem', stage='stage', step='step1'))
self.assertEqual(log_output4, self.SAMPLE_OUTPUT)
def test_update_str(self):
coder = coders.PickleCoder()
opcounts = OperationCounters(CounterFactory(), 'some-name', coder, 0)
self.verify_counters(opcounts, 0, float('nan'))
value = GlobalWindows.windowed_value('abcde')
opcounts.update_from(value)
estimated_size = coder.estimate_size(value)
self.verify_counters(opcounts, 1, estimated_size)
def test_update_old_object(self):
coder = coders.PickleCoder()
opcounts = OperationCounters(CounterFactory(), 'some-name', coder, 0)
self.verify_counters(opcounts, 0, float('nan'))
obj = OldClassThatDoesNotImplementLen()
value = GlobalWindows.windowed_value(obj)
opcounts.update_from(value)
estimated_size = coder.estimate_size(value)
self.verify_counters(opcounts, 1, estimated_size)
def test_basic_counters(self):
counter_factory = CounterFactory()
sampler = statesampler.StateSampler('stage1', counter_factory)
sampler.start()
with sampler.scoped_state('step1', 'stateA'):
counter = opcounters.SideInputReadCounter(counter_factory,
sampler,
declaring_step='step1',
input_index=1)
with sampler.scoped_state('step2', 'stateB'):
with counter:
counter.add_bytes_read(10)
counter.update_current_step()
sampler.stop()
sampler.commit_counters()
actual_counter_names = set(
[c.name for c in counter_factory.get_counters()])
expected_counter_names = set([
# Counter names for STEP 1
counters.CounterName('read-sideinput-msecs',
stage_name='stage1',
step_name='step1',
io_target=counters.side_input_id('step1', 1)),
counters.CounterName('read-sideinput-byte-count',
step_name='step1',
io_target=counters.side_input_id('step1', 1)),
# Counter names for STEP 2
counters.CounterName('read-sideinput-msecs',
stage_name='stage1',
step_name='step1',
io_target=counters.side_input_id('step2', 1)),
counters.CounterName('read-sideinput-byte-count',
step_name='step1',
io_target=counters.side_input_id('step2', 1)),
])
self.assertTrue(
actual_counter_names.issuperset(expected_counter_names))
def test_basic_counters(self):
counter_factory = CounterFactory()
sampler = statesampler.StateSampler('stage1', counter_factory)
sampler.start()
with sampler.scoped_state('step1', 'stateA'):
counter = opcounters.SideInputReadCounter(counter_factory, sampler,
declaring_step='step1',
input_index=1)
with sampler.scoped_state('step2', 'stateB'):
with counter:
counter.add_bytes_read(10)
counter.update_current_step()
sampler.stop()
sampler.commit_counters()
actual_counter_names = set([c.name for c in counter_factory.get_counters()])
expected_counter_names = set([
# Counter names for STEP 1
counters.CounterName('read-sideinput-msecs',
stage_name='stage1',
step_name='step1',
io_target=counters.side_input_id('step1', 1)),
counters.CounterName('read-sideinput-byte-count',
step_name='step1',
io_target=counters.side_input_id('step1', 1)),
# Counter names for STEP 2
counters.CounterName('read-sideinput-msecs',
stage_name='stage1',
step_name='step1',
io_target=counters.side_input_id('step2', 1)),
counters.CounterName('read-sideinput-byte-count',
step_name='step1',
io_target=counters.side_input_id('step2', 1)),
])
self.assertTrue(actual_counter_names.issuperset(expected_counter_names))
def test_record_with_per_thread_info(self):
self.maxDiff = None
tracker = statesampler.StateSampler('stage', CounterFactory())
statesampler.set_current_tracker(tracker)
formatter = logger.JsonLogFormatter(job_id='jobid', worker_id='workerid')
with logger.PerThreadLoggingContext(work_item_id='workitem'):
with tracker.scoped_state('step', 'process'):
record = self.create_log_record(**self.SAMPLE_RECORD)
log_output = json.loads(formatter.format(record))
expected_output = dict(self.SAMPLE_OUTPUT)
expected_output.update(
{'work': 'workitem', 'stage': 'stage', 'step': 'step'})
self.assertEqual(log_output, expected_output)
statesampler.set_current_tracker(None)
def test_update_multiple(self):
coder = coders.PickleCoder()
total_size = 0
opcounts = OperationCounters(CounterFactory(), 'some-name', coder, 0)
self.verify_counters(opcounts, 0, float('nan'))
value = GlobalWindows.windowed_value('abcde')
opcounts.update_from(value)
total_size += coder.estimate_size(value)
value = GlobalWindows.windowed_value('defghij')
opcounts.update_from(value)
total_size += coder.estimate_size(value)
self.verify_counters(opcounts, 2, float(total_size) / 2)
value = GlobalWindows.windowed_value('klmnop')
opcounts.update_from(value)
total_size += coder.estimate_size(value)
self.verify_counters(opcounts, 3, float(total_size) / 3)
def test_update_batch(self):
coder = coders.FastPrimitivesCoder()
opcounts = OperationCounters(
CounterFactory(),
'some-name',
coder,
0,
producer_batch_converter=typehints.batch.BatchConverter.
from_typehints(element_type=typehints.Any,
batch_type=typehints.List[typehints.Any]))
size_per_element = coder.estimate_size(50)
self.verify_counters(opcounts, 0, float('nan'))
opcounts.update_from_batch(
GlobalWindows.windowed_batch(list(range(100))))
self.verify_counters(opcounts, 100, size_per_element)
opcounts.update_from_batch(
GlobalWindows.windowed_batch(list(range(100, 200))))
self.verify_counters(opcounts, 200, size_per_element)
def for_test():
set_current_tracker(StateSampler('test', CounterFactory()))
return get_current_tracker()
