From 5201d0c13a9bc395a3c4e6f7142417b0d4e10e72 Mon Sep 17 00:00:00 2001 From: bloodearnest Date: Wed, 9 Nov 2022 16:53:46 +0000 Subject: [PATCH 1/3] fix: tick spans were not correctly parented --- jobrunner/record_stats.py | 15 ++++++--------- tests/test_record_stats.py | 9 +++++---- 2 files changed, 11 insertions(+), 13 deletions(-) diff --git a/jobrunner/record_stats.py b/jobrunner/record_stats.py index e1752828..e855725d 100644 --- a/jobrunner/record_stats.py +++ b/jobrunner/record_stats.py @@ -105,15 +105,12 @@ def record_tick_trace(last_run): models.Job, state__in=[models.State.PENDING, models.State.RUNNING] ) - root = tracer.start_span("TICK", start_time=start_time) - - for job in active_jobs: - span = tracer.start_span(job.status_code.name, start_time=start_time) - # TODO add cpu/memory as attributes? - tracing.set_span_metadata(span, job, tick=True) - span.end(end_time) - - root.end(end_time) + with tracer.start_as_current_span("TICK", start_time=start_time): + for job in active_jobs: + span = tracer.start_span(job.status_code.name, start_time=start_time) + # TODO add cpu/memory as attributes? + tracing.set_span_metadata(span, job, tick=True) + span.end(end_time) return end_time diff --git a/tests/test_record_stats.py b/tests/test_record_stats.py index 703db8e7..d40fc4a8 100644 --- a/tests/test_record_stats.py +++ b/tests/test_record_stats.py @@ -25,19 +25,20 @@ def test_record_tick_trace(db): end_time = spans[0].end_time + root = spans[-1] + assert root.name == "TICK" + assert root.start_time == last_run + for job, span in zip(jobs, spans): assert span.name == job.status_code.name assert span.start_time == last_run assert span.end_time == end_time assert span.attributes["tick"] is True assert span.attributes["job"] == job.id + assert span.parent.span_id == root.context.span_id assert "SUCCEEDED" not in [s.name for s in spans] - assert spans[-1].name == "TICK" - assert spans[-1].start_time == last_run - assert spans[-1].end_time == end_time - def test_record_tick_trace_last_run_is_none(db): now = int((time.time() - 10) * 1e9) From 23793712952058c9e436388a6fd79fb798a2a8f9 Mon Sep 17 00:00:00 2001 From: bloodearnest Date: Wed, 9 Nov 2022 17:00:07 +0000 Subject: [PATCH 2/3] refactor record_trick_trace tests to check duration --- tests/test_record_stats.py | 24 ++++++++++-------------- 1 file changed, 10 insertions(+), 14 deletions(-) diff --git a/tests/test_record_stats.py b/tests/test_record_stats.py index d40fc4a8..5ed74485 100644 --- a/tests/test_record_stats.py +++ b/tests/test_record_stats.py @@ -18,30 +18,26 @@ def test_record_tick_trace(db): # this should not be tick'd job_factory(state=State.SUCCEEDED, status_code=StatusCode.SUCCEEDED) - last_run = int((time.time() - 10) * 1e9) - record_stats.record_tick_trace(last_run) + last_run1 = record_stats.record_tick_trace(None) + assert len(get_trace()) == 0 - spans = get_trace() + time.sleep(0.1) + last_run2 = record_stats.record_tick_trace(last_run1) + assert last_run2 > last_run1 - end_time = spans[0].end_time + spans = get_trace() root = spans[-1] assert root.name == "TICK" - assert root.start_time == last_run + assert root.start_time == last_run1 + assert root.end_time >= last_run2 for job, span in zip(jobs, spans): assert span.name == job.status_code.name - assert span.start_time == last_run - assert span.end_time == end_time + assert span.start_time == last_run1 + assert span.end_time == last_run2 assert span.attributes["tick"] is True assert span.attributes["job"] == job.id assert span.parent.span_id == root.context.span_id assert "SUCCEEDED" not in [s.name for s in spans] - - -def test_record_tick_trace_last_run_is_none(db): - now = int((time.time() - 10) * 1e9) - last_run = record_stats.record_tick_trace(None) - assert last_run > now - assert len(get_trace()) == 0 From e1dcf50fe37631db9b925777257882114c130148 Mon Sep 17 00:00:00 2001 From: bloodearnest Date: Wed, 9 Nov 2022 17:06:20 +0000 Subject: [PATCH 3/3] fix order of magnitude measuring error :facepalm: --- jobrunner/record_stats.py | 2 +- tests/test_record_stats.py | 11 +++++------ 2 files changed, 6 insertions(+), 7 deletions(-) diff --git a/jobrunner/record_stats.py b/jobrunner/record_stats.py index e855725d..571f1686 100644 --- a/jobrunner/record_stats.py +++ b/jobrunner/record_stats.py @@ -92,7 +92,7 @@ def record_tick_trace(last_run): Not that this will emit number of active jobs + 1 events every call, so we don't want to call it on too tight a loop. """ - now = int(time.time() * 10e9) + now = time.time_ns() if last_run is None: return now diff --git a/tests/test_record_stats.py b/tests/test_record_stats.py index 5ed74485..e62a9a77 100644 --- a/tests/test_record_stats.py +++ b/tests/test_record_stats.py @@ -1,12 +1,10 @@ -import time - from jobrunner import record_stats from jobrunner.models import State, StatusCode from tests.conftest import get_trace from tests.factories import job_factory -def test_record_tick_trace(db): +def test_record_tick_trace(db, freezer): jobs = [] jobs.append(job_factory(status_code=StatusCode.CREATED)) @@ -21,16 +19,17 @@ def test_record_tick_trace(db): last_run1 = record_stats.record_tick_trace(None) assert len(get_trace()) == 0 - time.sleep(0.1) + freezer.tick(10) + last_run2 = record_stats.record_tick_trace(last_run1) - assert last_run2 > last_run1 + assert last_run2 == last_run1 + 10 * 1e9 spans = get_trace() root = spans[-1] assert root.name == "TICK" assert root.start_time == last_run1 - assert root.end_time >= last_run2 + assert root.end_time == last_run2 for job, span in zip(jobs, spans): assert span.name == job.status_code.name