def execute_schedule(schedule, es, sampler): """ Executes tasks according to the schedule for a given operation. :param schedule: The schedule for this operation. :param es: Elasticsearch client that will be used to execute the operation. :param sampler: A container to store raw samples. """ total_start = time.perf_counter() curr_total_it = 1 # noinspection PyBroadException try: for expected_scheduled_time, sample_type_calculator, curr_iteration, total_it_for_task, runner, params in schedule: sample_type = sample_type_calculator(total_start) absolute_expected_schedule_time = total_start + expected_scheduled_time throughput_throttled = expected_scheduled_time > 0 if throughput_throttled: rest = absolute_expected_schedule_time - time.perf_counter() if rest > 0: time.sleep(rest) start = time.perf_counter() with runner: total_ops, total_ops_unit = runner(es, params) stop = time.perf_counter() service_time = stop - start # Do not calculate latency separately when we don't throttle throughput. This metric is just confusing then. latency = stop - absolute_expected_schedule_time if throughput_throttled else service_time sampler.add(sample_type, convert.seconds_to_ms(latency), convert.seconds_to_ms(service_time), total_ops, total_ops_unit, (stop - total_start), curr_total_it, total_it_for_task) curr_total_it += 1 except BaseException: logger.exception("Could not execute schedule") raise
def execute_schedule(schedule, es, sampler): """ Executes tasks according to the schedule for a given operation. :param schedule: The schedule for this operation. :param es: Elasticsearch client that will be used to execute the operation. :param sampler: A container to store raw samples. """ total_start = time.perf_counter() # noinspection PyBroadException try: for expected_scheduled_time, sample_type, percent_completed, runner, params in schedule: absolute_expected_schedule_time = total_start + expected_scheduled_time throughput_throttled = expected_scheduled_time > 0 if throughput_throttled: rest = absolute_expected_schedule_time - time.perf_counter() if rest > 0: time.sleep(rest) start = time.perf_counter() total_ops, total_ops_unit, request_meta_data = execute_single(runner, es, params) stop = time.perf_counter() service_time = stop - start # Do not calculate latency separately when we don't throttle throughput. This metric is just confusing then. latency = stop - absolute_expected_schedule_time if throughput_throttled else service_time sampler.add(sample_type, request_meta_data, convert.seconds_to_ms(latency), convert.seconds_to_ms(service_time), total_ops, total_ops_unit, (stop - total_start), percent_completed) except BaseException: logger.exception("Could not execute schedule") raise
def _index_stats(self, expected_doc_count): logger.info("Gathering indices stats") # warmup self.repeat(self.cluster.client.indices.stats, metric="_all", level="shards") durations, stats = self.repeat(self.cluster.client.indices.stats, metric="_all", level="shards") for duration in durations: self.metrics_store.put_value_cluster_level( "indices_stats_latency", convert.seconds_to_ms(duration), "ms") primaries = stats["_all"]["primaries"] self.metrics_store.put_count_cluster_level( "segments_count", primaries["segments"]["count"]) self.metrics_store.put_count_cluster_level( "segments_memory_in_bytes", primaries["segments"]["memory_in_bytes"], "byte") self.metrics_store.put_count_cluster_level( "segments_doc_values_memory_in_bytes", primaries["segments"]["doc_values_memory_in_bytes"], "byte") self.metrics_store.put_count_cluster_level( "segments_stored_fields_memory_in_bytes", primaries["segments"]["stored_fields_memory_in_bytes"], "byte") self.metrics_store.put_count_cluster_level( "segments_terms_memory_in_bytes", primaries["segments"]["terms_memory_in_bytes"], "byte") self.metrics_store.put_count_cluster_level( "segments_norms_memory_in_bytes", primaries["segments"]["norms_memory_in_bytes"], "byte") if "points_memory_in_bytes" in primaries["segments"]: self.metrics_store.put_count_cluster_level( "segments_points_memory_in_bytes", primaries["segments"]["points_memory_in_bytes"], "byte") self.metrics_store.put_value_cluster_level( "merges_total_time", primaries["merges"]["total_time_in_millis"], "ms") self.metrics_store.put_value_cluster_level( "merges_total_throttled_time", primaries["merges"]["total_throttled_time_in_millis"], "ms") self.metrics_store.put_value_cluster_level( "indexing_total_time", primaries["indexing"]["index_time_in_millis"], "ms") self.metrics_store.put_value_cluster_level( "refresh_total_time", primaries["refresh"]["total_time_in_millis"], "ms") self.metrics_store.put_value_cluster_level( "flush_total_time", primaries["flush"]["total_time_in_millis"], "ms") actual_doc_count = primaries["docs"]["count"] if expected_doc_count is not None and expected_doc_count != actual_doc_count: msg = "wrong number of documents indexed: expected %s but got %s" % ( expected_doc_count, actual_doc_count) logger.error(msg) raise RuntimeError(msg)
def run(self): logger.info("Running warmup iterations") self._run_benchmark(" Benchmarking %s (warmup iteration %d/%d)") logger.info("Running measurement iterations") times = self._run_benchmark(" Benchmarking %s (iteration %d/%d)") for q in self.queries: latencies = [t[q.name] for t in times] for latency in latencies: self.metrics_store.put_value_cluster_level( "query_latency_%s" % q.name, convert.seconds_to_ms(latency), "ms")
def execute_schedule(schedule, es, sampler, operation): """ Executes tasks according to the schedule for a given operation. :param schedule: The schedule for this operation. :param es: Elasticsearch client that will be used to execute the operation. :param sampler: A container to store raw samples. """ relative = None previous_sample_type = None total_start = time.perf_counter() curr_total_it = 1 for expected_scheduled_time, sample_type_calculator, curr_iteration, total_it_for_sample_type, total_it_for_task, runner, params in schedule: sample_type = sample_type_calculator(total_start) # restart the relative time when the sample type changes. This way all warmup samples and measurement samples will start at # the relative time zero which simplifies throughput calculation. # # Assumption: We always get the same operation here, otherwise simply resetting one timer will not work! if sample_type != previous_sample_type: relative = time.perf_counter() previous_sample_type = sample_type # expected_scheduled_time is relative to the start of the first iteration absolute_expected_schedule_time = relative + expected_scheduled_time throughput_throttled = expected_scheduled_time > 0 if throughput_throttled: rest = absolute_expected_schedule_time - time.perf_counter() if rest > 0: time.sleep(rest) start = time.perf_counter() with runner: weight = runner(es, params) stop = time.perf_counter() service_time = stop - start # Do not calculate latency separately when we don't throttle throughput. This metric is just confusing then. latency = stop - absolute_expected_schedule_time if throughput_throttled else service_time sampler.add(sample_type, convert.seconds_to_ms(latency), convert.seconds_to_ms(service_time), weight, (stop - relative), curr_total_it, total_it_for_task) curr_total_it += 1
def run(self): es = self.cluster.client logger.info("Running search benchmark (warmup)") self._run_benchmark(es, " Benchmarking search (warmup iteration %d/%d)", repetitions=1000) logger.info("Running search benchmark") times = self._run_benchmark(es, " Benchmarking search (iteration %d/%d)", repetitions=1000) logger.info("Search benchmark has finished") for q in self.track.queries: latencies = [t[q.name] for t in times] for latency in latencies: self.metrics_store.put_value_cluster_level( "query_latency_%s" % q.name, convert.seconds_to_ms(latency), "ms")
def _node_stats(self): logger.info("Gathering nodes stats") # warmup self.repeat(self.cluster.client.nodes.stats, metric="_all", level="shards") durations, stats = self.repeat(self.cluster.client.nodes.stats, metric="_all", level="shards") for duration in durations: self.metrics_store.put_value_cluster_level( "node_stats_latency", convert.seconds_to_ms(duration), "ms") total_old_gen_collection_time = 0 total_young_gen_collection_time = 0 nodes = stats["nodes"] for node in nodes.values(): node_name = node["name"] gc = node["jvm"]["gc"]["collectors"] old_gen_collection_time = gc["old"]["collection_time_in_millis"] young_gen_collection_time = gc["young"][ "collection_time_in_millis"] self.metrics_store.put_value_node_level(node_name, "node_old_gen_gc_time", old_gen_collection_time, "ms") self.metrics_store.put_value_node_level(node_name, "node_young_gen_gc_time", young_gen_collection_time, "ms") total_old_gen_collection_time += old_gen_collection_time total_young_gen_collection_time += young_gen_collection_time self.metrics_store.put_value_cluster_level( "node_total_old_gen_gc_time", total_old_gen_collection_time, "ms") self.metrics_store.put_value_cluster_level( "node_total_young_gen_gc_time", total_young_gen_collection_time, "ms")
def run(self): logger.info("Running warmup iterations") self._run_benchmark(" Benchmarking %s (warmup iteration %d/%d)", self.warmup_repetitions) logger.info("Running measurement iterations") times = self._run_benchmark(" Benchmarking %s (iteration %d/%d)", self.repetitions) for q in self.queries: latencies = [t[q.name] for t in times] for latency in latencies: self.metrics_store.put_value_cluster_level("query_latency_%s" % q.name, convert.seconds_to_ms(latency), "ms")
def execute_schedule(cancel, client_id, op, schedule, es, sampler, enable_profiling=False): """ Executes tasks according to the schedule for a given operation. :param cancel: A shared boolean that indicates we need to cancel execution. :param client_id: The id of the client that executes the operation. :param op: The operation that is executed. :param schedule: The schedule for this operation. :param es: Elasticsearch client that will be used to execute the operation. :param sampler: A container to store raw samples. :param enable_profiling: Enables a Python profiler for this execution (default: False). """ if enable_profiling: logger.debug("Enabling Python profiler for [%s]" % str(op)) import cProfile, pstats import io as python_io profiler = cProfile.Profile() profiler.enable() else: logger.debug("Python profiler for [%s] is disabled." % str(op)) total_start = time.perf_counter() # noinspection PyBroadException try: for expected_scheduled_time, sample_type, percent_completed, runner, params in schedule: if cancel.is_set(): logger.info("User cancelled execution.") break absolute_expected_schedule_time = total_start + expected_scheduled_time throughput_throttled = expected_scheduled_time > 0 if throughput_throttled: rest = absolute_expected_schedule_time - time.perf_counter() if rest > 0: time.sleep(rest) start = time.perf_counter() total_ops, total_ops_unit, request_meta_data = execute_single( runner, es, params) stop = time.perf_counter() service_time = stop - start # Do not calculate latency separately when we don't throttle throughput. This metric is just confusing then. latency = stop - absolute_expected_schedule_time if throughput_throttled else service_time sampler.add(sample_type, request_meta_data, convert.seconds_to_ms(latency), convert.seconds_to_ms(service_time), total_ops, total_ops_unit, (stop - total_start), percent_completed) except BaseException: logger.exception("Could not execute schedule") raise finally: if enable_profiling: profiler.disable() s = python_io.StringIO() sortby = 'cumulative' ps = pstats.Stats(profiler, stream=s).sort_stats(sortby) ps.print_stats() profile = "\n=== Profile START for client [%s] and operation [%s] ===\n" % ( str(client_id), str(op)) profile += s.getvalue() profile += "=== Profile END for client [%s] and operation [%s] ===" % ( str(client_id), str(op)) profile_logger.info(profile)