From 29ed118b9dc63721e78c3040912c76f54054a1be Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?C=C3=A9dric=20Ollivier?= Date: Thu, 30 Apr 2020 13:59:24 +0200 Subject: [PATCH] Try to detect the race conditions MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Change-Id: I9b468ec1cf79e0a66abeb1fb48f5f0f067c2c198 Signed-off-by: Cédric Ollivier --- rally/plugins/task/runners/constant.py | 30 ++++++++++++++++++- .../task/scenarios/requests/http_requests.py | 9 ++++++ .../plugins/task/scenarios/requests/utils.py | 9 ++++++ rally/task/runner.py | 27 +++++++++++++++-- rally/task/utils.py | 15 ++++++++++ 5 files changed, 87 insertions(+), 3 deletions(-) diff --git a/rally/plugins/task/runners/constant.py b/rally/plugins/task/runners/constant.py index 5feb1fee1..38a01e28e 100644 --- a/rally/plugins/task/runners/constant.py +++ b/rally/plugins/task/runners/constant.py @@ -24,6 +24,10 @@ from rally.common import validation from rally import consts from rally.task import runner +from rally.common import cfg +from rally.common import logging +CONF = cfg.CONF +LOG = logging.getLogger(__file__) def _worker_process(queue, iteration_gen, timeout, concurrency, times, duration, context, cls, method_name, args, event_queue, @@ -55,6 +59,9 @@ def _worker_process(queue, iteration_gen, timeout, concurrency, times, """ def _to_be_continued(iteration, current_duration, aborted, times=None, duration=None): + LOG.warning( + "!! _to_be_continued %(iteration)s %(current_duration)s %(aborted)s %(times)s %(duration)s !! " % + {"iteration": iteration, "current_duration": current_duration, "aborted": aborted, "times": times, "duration": duration}) if times is not None: return iteration < times and not aborted.is_set() elif duration is not None: @@ -82,6 +89,7 @@ def _worker_process(queue, iteration_gen, timeout, concurrency, times, collector_thr_by_timeout.start() iteration = next(iteration_gen) + LOG.warning("!! iteration %(iteration)s !! " % {"iteration": iteration}) start_time = time.time() # NOTE(msimonin): keep the previous behaviour # > when duration is 0, scenario executes exactly 1 time @@ -93,13 +101,25 @@ def _worker_process(queue, iteration_gen, timeout, concurrency, times, worker_args = ( queue, cls, method_name, scenario_context, args, event_queue) + LOG.warn( + "Cedric _to_be_continued threading.Thread {} {}".format( + runner._worker_thread, worker_args)) thread = threading.Thread(target=runner._worker_thread, args=worker_args) + LOG.warn( + "Cedric _to_be_continued thread.start() {} {}".format( + runner._worker_thread, worker_args)) thread.start() + LOG.warn( + "Cedric _to_be_continued thread.start() {} {}".format( + runner._worker_thread, worker_args)) if timeout: timeout_queue.put((thread, time.time() + timeout)) pool.append(thread) + LOG.warn( + "Cedric _to_be_continued pool.append {} {}".format( + pool, thread)) alive_threads_in_pool += 1 while alive_threads_in_pool == concurrency: @@ -128,7 +148,14 @@ def _worker_process(queue, iteration_gen, timeout, concurrency, times, # Wait until all threads are done while pool: - pool.popleft().join() + thr = pool.popleft() + LOG.warn( + "Cedric _worker_process wait_all_threads {} {} BEFORE JOIN".format( + pool, thr)) + thr.join() + LOG.warn( + "Cedric _worker_process wait_all_threads {} {} AFTER JOIN".format( + pool, thr)) if timeout: timeout_queue.put((None, None,)) @@ -340,3 +367,4 @@ class ConstantForDurationScenarioRunner(runner.ScenarioRunner): processes_to_start, _worker_process, worker_args_gen(concurrency_overhead)) self._join_processes(process_pool, result_queue, event_queue) + diff --git a/rally/plugins/task/scenarios/requests/http_requests.py b/rally/plugins/task/scenarios/requests/http_requests.py index e85ee5af2..4afdf29f1 100644 --- a/rally/plugins/task/scenarios/requests/http_requests.py +++ b/rally/plugins/task/scenarios/requests/http_requests.py @@ -15,6 +15,11 @@ import random from rally.plugins.task.scenarios.requests import utils from rally.task import scenario +from rally.common import cfg +from rally.common import logging +CONF = cfg.CONF +LOG = logging.getLogger(__file__) + """Scenarios for HTTP requests.""" @@ -34,6 +39,10 @@ class HttpRequestsCheckRequest(utils.RequestScenario): :param kwargs: optional additional request parameters """ + LOG.warn("Cedric run url {}".format(url)) + LOG.warn("Cedric run method {}".format(method)) + LOG.warn("Cedric run status_code {}".format(status_code)) + LOG.warn("Cedric run kwargs {}".format(kwargs)) self._check_request(url, method, status_code, **kwargs) diff --git a/rally/plugins/task/scenarios/requests/utils.py b/rally/plugins/task/scenarios/requests/utils.py index 8fd35347a..cd69900a5 100644 --- a/rally/plugins/task/scenarios/requests/utils.py +++ b/rally/plugins/task/scenarios/requests/utils.py @@ -15,6 +15,11 @@ import requests from rally.task import atomic from rally.task import scenario +from rally.common import cfg +from rally.common import logging +CONF = cfg.CONF +LOG = logging.getLogger(__file__) + class RequestScenario(scenario.Scenario): """Base class for Request scenarios with basic atomic actions.""" @@ -31,6 +36,10 @@ class RequestScenario(scenario.Scenario): not equal to expected status code """ + LOG.warn("Cedric _check_request url {}".format(url)) + LOG.warn("Cedric _check_request method {}".format(method)) + LOG.warn("Cedric _check_request status_code {}".format(status_code)) + LOG.warn("Cedric _check_request kwargs {}".format(kwargs)) resp = requests.request(method, url, **kwargs) if status_code != resp.status_code: error_msg = "Expected HTTP request code is `%s` actual `%s`" diff --git a/rally/task/runner.py b/rally/task/runner.py index 3397e1193..57f9428f4 100644 --- a/rally/task/runner.py +++ b/rally/task/runner.py @@ -87,6 +87,11 @@ def _run_scenario_once(cls, method_name, context_obj, scenario_kwargs, def _worker_thread(queue, cls, method_name, context_obj, scenario_kwargs, event_queue): + LOG.debug( + "queue.put _run_scenario_once:\n\t%(cls)s\n\t%(method_name)s\n\t" + "%(context_obj)s\n\t%(scenario_kwargs)s\n\t%(event_queue)s" % + {"cls": cls, "method_name": method_name, "context_obj": context_obj, + "scenario_kwargs": scenario_kwargs, "event_queue": event_queue}) queue.put(_run_scenario_once(cls, method_name, context_obj, scenario_kwargs, event_queue)) @@ -186,6 +191,8 @@ class ScenarioRunner(plugin.Plugin, validation.ValidatablePluginMixin, for i in range(processes_to_start): kwrgs = {"processes_to_start": processes_to_start, "processes_counter": i} + LOG.warning( + "!! _create_process_pool %(kwrgs)s !! " % {"kwrgs": kwrgs}) process = multiprocessing.Process(target=worker_process, args=next(worker_args_gen), kwargs={"info": kwrgs}) @@ -202,18 +209,26 @@ class ScenarioRunner(plugin.Plugin, validation.ValidatablePluginMixin, :param event_queue: multiprocessing.Queue that receives the events """ while process_pool: + LOG.warn("Cedric _join_processes process_pool {}".format(process_pool)) while process_pool and not process_pool[0].is_alive(): + LOG.warn("Cedric _join_processes process_pool {}".format(process_pool)) process_pool.popleft().join() if result_queue.empty() and event_queue.empty(): # sleep a bit to avoid 100% usage of CPU by this method + LOG.warn("Cedric _join_processes result_queue is empty {}".format(result_queue)) + LOG.warn("Cedric _join_processes event_queue is empty {}".format(event_queue)) time.sleep(0.01) while not event_queue.empty(): - self.send_event(**event_queue.get()) + col_event_queue = event_queue.get() + LOG.warn("Cedric _join_processes event_queue is not empty {}".format(col_event_queue)) + self.send_event(**col_event_queue) while not result_queue.empty(): - self._send_result(result_queue.get()) + col_result_queue = result_queue.get() + LOG.warn("Cedric _join_processes result_queue is not empty {}".format(col_result_queue)) + self._send_result(col_result_queue) self._flush_results() result_queue.close() @@ -245,8 +260,13 @@ class ScenarioRunner(plugin.Plugin, validation.ValidatablePluginMixin, if len(self.result_batch) >= self.batch_size: sorted_batch = sorted(self.result_batch, key=lambda r: result["timestamp"]) + LOG.debug("result_queue.append:\n\t%(sorted_batch)s" % { + "sorted_batch": sorted_batch + }) self.result_queue.append(sorted_batch) del self.result_batch[:] + else: + LOG.debug("WAHT DOEST IT MEAN? ") def send_event(self, type, value=None): """Store event to send it to consumer later. @@ -254,6 +274,9 @@ class ScenarioRunner(plugin.Plugin, validation.ValidatablePluginMixin, :param type: Event type :param value: Optional event data """ + LOG.debug("send_event:\n\t%(type)s\n\t%(value)s" % { + "type": type, "value": value + }) self.event_queue.append({"type": type, "value": value}) diff --git a/rally/task/utils.py b/rally/task/utils.py index 1252a1fc7..783adf3c6 100644 --- a/rally/task/utils.py +++ b/rally/task/utils.py @@ -176,6 +176,9 @@ def wait_for_status(resource, ready_statuses, failure_statuses=["error"], timeout=60, check_interval=1, check_deletion=False, id_attr="id"): + LOG.debug( + "Waiting for status %(resource)s" % {"resource": resource}) + resource_repr = getattr(resource, "name", repr(resource)) if not isinstance(ready_statuses, (set, list, tuple)): raise ValueError("Ready statuses should be supplied as set, list or " @@ -187,7 +190,11 @@ def wait_for_status(resource, ready_statuses, failure_statuses=["error"], # make all statuses upper case ready_statuses = set(s.upper() for s in ready_statuses or []) + LOG.debug("%(resource)s: ready_statuses %(ready_statuses)s" % { + "resource": resource_repr, "ready_statuses": ready_statuses}) failure_statuses = set(s.upper() for s in failure_statuses or []) + LOG.debug("%(resource)s: failure_statuses %(failure_statuses)s" % { + "resource": resource_repr, "failure_statuses": failure_statuses}) if (ready_statuses & failure_statuses): raise ValueError( @@ -205,9 +212,13 @@ def wait_for_status(resource, ready_statuses, failure_statuses=["error"], start = time.time() latest_status = get_status(resource, status_attr) + LOG.debug("%(resource)s: latest_status %(latest_status)s" % { + "resource": resource_repr, "latest_status": latest_status}) latest_status_update = start while True: + LOG.debug("%(resource)s: timeout %(timeout)s" % { + "resource": resource_repr, "timeout": timeout}) try: if id_attr == "id": resource = update_resource(resource) @@ -240,7 +251,11 @@ def wait_for_status(resource, ready_statuses, failure_statuses=["error"], status=status, fault="Status in failure list %s" % str(failure_statuses)) + LOG.debug("%(resource)s: check_interval %(check_interval)s" % { + "resource": resource_repr, "check_interval": check_interval}) time.sleep(check_interval) + LOG.debug("%(resource)s: elapsed_time %(elapsed_time)s" % { + "resource": resource_repr, "elapsed_time": time.time() - start}) if time.time() - start > timeout: raise exceptions.TimeoutException( desired_status="('%s')" % "', '".join(ready_statuses), -- 2.26.2