|
|
@@ -0,0 +1,133 @@
|
|
|
+"""
|
|
|
+Opt-in tracing for the cloud integration suites.
|
|
|
+
|
|
|
+The AWS suite's wall time is dominated by one or two tests, and end-to-end
|
|
|
+timings have proved too noisy to attribute - test_create_and_list_image alone
|
|
|
+has measured 26.2, 60.6 and 33.8 minutes across three runs of the same 123
|
|
|
+tests. Answering *where* that time goes needs the individual waits timed
|
|
|
+rather than the test as a whole.
|
|
|
+
|
|
|
+Set CB_TEST_TRACE=1 to capture, per xdist worker:
|
|
|
+
|
|
|
+
|
|
|
+* every ``wait_for`` poll, which brackets each wait - the span from a wait's
|
|
|
+ first poll to its last is the wait itself, and the gap between consecutive
|
|
|
+ polls shows whether the state call is slow (the interval is 1s for real
|
|
|
+ providers, so a larger gap is the API, not the sleep);
|
|
|
+* botocore retries, which is how throttling appears client-side. Those
|
|
|
+ loggers stay silent unless a request is actually retried, so anything they
|
|
|
+ emit is signal.
|
|
|
+
|
|
|
+Records go to cb-trace-<worker>.log rather than stderr because pytest
|
|
|
+captures stderr at file-descriptor level, and captured output is discarded
|
|
|
+for passing tests - which these are. tox prints the files once the run
|
|
|
+finishes.
|
|
|
+
|
|
|
+CB_TEST_TRACE=2 additionally logs one line per boto invocation. Level 1
|
|
|
+answers whether time is going into polling or into throttled retries; when
|
|
|
+the answer is neither - as it was for test_create_and_list_image, where 1184
|
|
|
+of 1400 seconds passed in a single stretch with no polls and no retries at
|
|
|
+all - level 2 is what names the call that blocked, since the gap between two
|
|
|
+consecutive request lines is that request.
|
|
|
+
|
|
|
+Deliberately opt-in: at a 1s poll interval a 30 minute wait is ~1800 lines
|
|
|
+for a single waiting resource, and level 2 is roughly 20x that again.
|
|
|
+"""
|
|
|
+import logging
|
|
|
+import os
|
|
|
+
|
|
|
+TRACE_FILE_PREFIX = 'cb-trace-'
|
|
|
+
|
|
|
+
|
|
|
+def _trace_level():
|
|
|
+ """
|
|
|
+ 0 off; 1 waits and retries; 2 also every provider request.
|
|
|
+
|
|
|
+ Level 1 answers "is the time going into polling, or into throttled
|
|
|
+ retries" - it is cheap enough to leave on. Level 2 additionally logs each
|
|
|
+ boto invocation, so the gap between two consecutive lines names the call
|
|
|
+ that blocked; that is what level 1 cannot show, at perhaps 20x the volume.
|
|
|
+ """
|
|
|
+ raw = (os.environ.get('CB_TEST_TRACE') or '').lower()
|
|
|
+ if raw in ('2', 'requests', 'all'):
|
|
|
+ return 2
|
|
|
+ return 1 if raw in ('1', 'true', 'yes') else 0
|
|
|
+
|
|
|
+
|
|
|
+def _trace_path():
|
|
|
+ # Each xdist worker needs its own file; they run in one directory and
|
|
|
+ # would otherwise interleave mid-line.
|
|
|
+ worker = os.environ.get('PYTEST_XDIST_WORKER', 'main')
|
|
|
+ return '{0}{1}.log'.format(TRACE_FILE_PREFIX, worker)
|
|
|
+
|
|
|
+
|
|
|
+class _TraceFilter(logging.Filter):
|
|
|
+ """
|
|
|
+ Keep the test markers, the poll lines and genuine retries; at level 2
|
|
|
+ keep the provider request lines too, and drop everything else.
|
|
|
+
|
|
|
+ cloudbridge at DEBUG is far too chatty to keep wholesale - roughly 20x
|
|
|
+ the volume - and most of it says nothing about where the time went.
|
|
|
+ """
|
|
|
+
|
|
|
+ def __init__(self, level):
|
|
|
+ super(_TraceFilter, self).__init__()
|
|
|
+ self.level = level
|
|
|
+
|
|
|
+ def filter(self, record):
|
|
|
+ message = record.getMessage()
|
|
|
+ if record.name.startswith('botocore'):
|
|
|
+ # botocore logs a line per request whether or not it retried;
|
|
|
+ # only an actual backoff says anything about throttling. The two
|
|
|
+ # retry implementations word the negative case differently.
|
|
|
+ return not (message.startswith('Not retrying')
|
|
|
+ or message.startswith('No retry needed'))
|
|
|
+ if record.name.startswith('cloudbridge.providers'):
|
|
|
+ return self.level >= 2
|
|
|
+ return message.startswith('=== ') or 'Waiting another' in message
|
|
|
+
|
|
|
+
|
|
|
+def pytest_configure(config):
|
|
|
+ level = _trace_level()
|
|
|
+ if not level:
|
|
|
+ return
|
|
|
+
|
|
|
+ handler = logging.FileHandler(_trace_path(), mode='w')
|
|
|
+ handler.setFormatter(logging.Formatter(
|
|
|
+ '%(asctime)s %(name)s %(message)s'))
|
|
|
+ handler.addFilter(_TraceFilter(level))
|
|
|
+
|
|
|
+ # wait_for logs one line per poll at DEBUG, naming the object and the
|
|
|
+ # state it is waiting on. Scope the level to that module rather than the
|
|
|
+ # cloudbridge tree: raising the whole tree to DEBUG would have every
|
|
|
+ # provider request build a log record that the filter then discards, and
|
|
|
+ # those records still propagate to pytest's own capture handler, which
|
|
|
+ # holds them for the duration of the test.
|
|
|
+ loggers = ['cloudbridge.base.resources',
|
|
|
+ # Quiet unless a request is actually retried, which is how
|
|
|
+ # throttling shows up client-side. Enabling botocore wholesale
|
|
|
+ # would log every request and response.
|
|
|
+ 'botocore.retries', 'botocore.retryhandler']
|
|
|
+ if level >= 2:
|
|
|
+ # One line per boto invocation, so a stretch with no wait_for polling
|
|
|
+ # can still be attributed to the call that blocked.
|
|
|
+ loggers.append('cloudbridge.providers')
|
|
|
+
|
|
|
+ for name in loggers:
|
|
|
+ target = logging.getLogger(name)
|
|
|
+ target.addHandler(handler)
|
|
|
+ target.setLevel(logging.DEBUG)
|
|
|
+
|
|
|
+
|
|
|
+def pytest_runtest_logstart(nodeid, location):
|
|
|
+ # Stamps the trace with test boundaries, so a span of polls can be
|
|
|
+ # attributed to the test that caused it.
|
|
|
+ if _trace_level():
|
|
|
+ logging.getLogger('cloudbridge.base.resources').debug(
|
|
|
+ '=== START %s', nodeid)
|
|
|
+
|
|
|
+
|
|
|
+def pytest_runtest_logfinish(nodeid, location):
|
|
|
+ if _trace_level():
|
|
|
+ logging.getLogger('cloudbridge.base.resources').debug(
|
|
|
+ '=== END %s', nodeid)
|
Nuwan Goonasekera