diff --git a/tests/ansible/lib/callback/fork_histogram.py b/tests/ansible/lib/callback/fork_histogram.py new file mode 100644 index 00000000..484f81cd --- /dev/null +++ b/tests/ansible/lib/callback/fork_histogram.py @@ -0,0 +1,92 @@ + +# Monkey-patch os.fork() to produce a latency histogram on run completion. +# Requires 'hdrhsitograms' PyPI module. + +from __future__ import print_function + +import os +import resource +import sys +import time + +import ansible.plugins.callback +import hdrh.histogram + + +def get_fault_count(who=resource.RUSAGE_CHILDREN): + ru = resource.getrusage(who) + return ru.ru_minflt + ru.ru_majflt + + +class CallbackModule(ansible.plugins.callback.CallbackBase): + hist = None + + def v2_playbook_on_start(self, playbook): + if self.hist is not None: + return + + self.hist = hdrh.histogram.HdrHistogram(1, int(1e6*60), 3) + self.fork_latency_sum_usec = 0.0 + self.install() + + def install(self): + self.faults_at_start = get_fault_count(resource.RUSAGE_SELF) + self.run_start_time = time.time() + self.real_fork = os.fork + os.fork = self.my_fork + + self_fault_usec = 1.113664156753052 + child_fault_usec = 4.734975610975617 + + dummy_heap_size = int(os.environ.get('FORK_STATS_FAKE_HEAP_MB', '0')) + dummy_heap = 'x' * (dummy_heap_size * 1048576) + + def my_fork(self): + # doesnt count last child, oh well + now_faults = get_fault_count() + t0 = time.time() + try: + return self.real_fork() + finally: + latency_usec = (1e6 * (time.time() - t0)) + self.fork_latency_sum_usec += latency_usec + self.hist.record_value(latency_usec) + + def playbook_on_stats(self, stats): + self_faults = get_fault_count(resource.RUSAGE_SELF) - self.faults_at_start + child_faults = get_fault_count() + run_duration_sec = time.time() - self.run_start_time + fault_wastage_usec = ( + ((self.self_fault_usec * self_faults) + + (self.child_fault_usec * child_faults)) + ) + fork_wastage = self.hist.get_total_count() + all_wastage_usec = ((2*self.fork_latency_sum_usec) + fault_wastage_usec) + + print('--- Fork statistics ---') + print('Post-boot run duration: %.02f ms, %d total forks' % ( + 1000 * run_duration_sec, + self.hist.get_total_count(), + )) + print('Self faults during boot: %d, post-boot: %d, avg %d/child' % ( + self.faults_at_start, + self_faults, + self_faults / self.hist.get_total_count(), + )) + print('Total child faults: %d, avg %d/child' % ( + child_faults, + child_faults / self.hist.get_total_count(), + )) + print('Est. wastage on faults: %d ms, forks+faults+waits: %d ms (%.2f%%)' % ( + fault_wastage_usec / 1000, + all_wastage_usec / 1000, + 100 * (all_wastage_usec / (run_duration_sec * 1e6)), + )) + print('99th%% fork latency: %.03f msec, max %d new tasks/sec' % ( + self.hist.get_value_at_percentile(99) / 1000.0, + 1e6 / self.hist.get_value_at_percentile(99), + )) + + self.hist.output_percentile_distribution(sys.stdout, 10) + print('--- End fork statistics ---') + print() diff --git a/tests/ansible/requirements.txt b/tests/ansible/requirements.txt index 74477c22..507151c5 100644 --- a/tests/ansible/requirements.txt +++ b/tests/ansible/requirements.txt @@ -2,5 +2,6 @@ ansible; python_version >= '2.7' ansible<2.7; python_version < '2.7' paramiko==2.3.2 # Last 2.6-compat version. google-api-python-client==1.6.5 +hdrhistogram==0.6.1 PyYAML==3.11; python_version < '2.7' PyYAML==3.12; python_version >= '2.7'