From d6bf4d7af6dd39ce3a6a2e0f40bf5a2b25f9b27a Mon Sep 17 00:00:00 2001 From: Sergey Miryanov Date: Mon, 20 Jan 2025 02:39:57 +0500 Subject: [PATCH 01/21] Add sync_marker to snaptrace --- src/viztracer/modules/snaptrace.c | 26 ++++++++++++++++++++++++++ src/viztracer/modules/snaptrace.h | 1 + src/viztracer/snaptrace.pyi | 8 ++++++++ 3 files changed, 35 insertions(+) diff --git a/src/viztracer/modules/snaptrace.c b/src/viztracer/modules/snaptrace.c index 02639e9e..5acbf9da 100644 --- a/src/viztracer/modules/snaptrace.c +++ b/src/viztracer/modules/snaptrace.c @@ -1925,6 +1925,29 @@ tracer_getfunctionarg(TracerObject* self, PyObject* Py_UNUSED(unused)) return Py_NewRef(fnode->args); } +static PyObject* +tracer_set_sync_marker(TracerObject* self, PyObject* Py_UNUSED(unused)) +{ + if (self->sync_marker != 0) + { + PyErr_WarnFormat(PyExc_RuntimeWarning, 1, "Synchronization warning already set"); + } + self->sync_marker = get_ts(); + Py_RETURN_NONE; +} + +static PyObject* +tracer_get_sync_marker(TracerObject* self, PyObject* Py_UNUSED(unused)) +{ + if (self->sync_marker == 0) + { + return PyLong_FromInt64(self->sync_marker); + } + + double ts_sync_marker = system_ts_to_us(self->sync_marker); + return PyFloat_FromDouble(ts_sync_marker); +} + static PyMethodDef Tracer_methods[] = { {"threadtracefunc", (PyCFunction)tracer_threadtracefunc, METH_VARARGS, "trace function"}, {"start", (PyCFunction)tracer_start, METH_NOARGS, "start profiling"}, @@ -1945,6 +1968,8 @@ static PyMethodDef Tracer_methods[] = { {"pause", (PyCFunction)tracer_pause, METH_NOARGS, "pause profiling"}, {"resume", (PyCFunction)tracer_resume, METH_NOARGS, "resume profiling"}, {"setignorestackcounter", (PyCFunction)tracer_setignorestackcounter, METH_O, "reset ignore stack depth"}, + {"set_sync_marker", (PyCFunction)tracer_set_sync_marker, METH_NOARGS, "put current timestamp to synchronization marker"}, + {"get_sync_marker", (PyCFunction)tracer_get_sync_marker, METH_NOARGS, "get synchronization marker"}, {NULL, NULL, 0, NULL} }; @@ -1970,6 +1995,7 @@ Tracer_New(PyTypeObject* type, PyObject* args, PyObject* kwargs) self->buffer = NULL; self->buffer_head_idx = 0; self->buffer_tail_idx = 0; + self->sync_marker = 0; self->metadata_head = NULL; } diff --git a/src/viztracer/modules/snaptrace.h b/src/viztracer/modules/snaptrace.h index 72879da4..e43ed93f 100644 --- a/src/viztracer/modules/snaptrace.h +++ b/src/viztracer/modules/snaptrace.h @@ -121,6 +121,7 @@ typedef struct { long buffer_size; long buffer_head_idx; long buffer_tail_idx; + int64_t sync_marker; struct MetadataNode* metadata_head; } TracerObject; diff --git a/src/viztracer/snaptrace.pyi b/src/viztracer/snaptrace.pyi index ec23aa78..6ab2fa16 100644 --- a/src/viztracer/snaptrace.pyi +++ b/src/viztracer/snaptrace.pyi @@ -67,3 +67,11 @@ class Tracer: def add_instant(self, name: str, args: Any = None, scope: Literal["g", "p", "t"] = "g") -> None: ... + + def set_sync_marker(self) -> None: + """put current timestamp to synchronization marker""" + ... + + def get_sync_marker(self) -> float: + """get synchronization marker""" + ... From d38cd781eec8867f6b5d5678d07862a713489594 Mon Sep 17 00:00:00 2001 From: Sergey Miryanov Date: Mon, 20 Jan 2025 02:41:27 +0500 Subject: [PATCH 02/21] Store sync_marker to viztracer_metadata --- src/viztracer/modules/snaptrace.c | 11 ++++++++++- src/viztracer/viztracer.py | 4 ++++ 2 files changed, 14 insertions(+), 1 deletion(-) diff --git a/src/viztracer/modules/snaptrace.c b/src/viztracer/modules/snaptrace.c index 5acbf9da..0d6d3a8e 100644 --- a/src/viztracer/modules/snaptrace.c +++ b/src/viztracer/modules/snaptrace.c @@ -1612,7 +1612,16 @@ tracer_dump(TracerObject* self, PyObject* args, PyObject* kw) self->buffer_tail_idx = self->buffer_head_idx; fseek(fptr, -1, SEEK_CUR); - fprintf(fptr, "], \"viztracer_metadata\": {\"overflow\":%s}}", overflowed? "true": "false"); + fprintf(fptr, "], \"viztracer_metadata\": {\"overflow\":%s", overflowed? "true": "false"); + + if (self->sync_marker > 0) + { + long long ts_sync_marker = system_ts_to_ns(self->sync_marker); + fprintf(fptr, ",\"sync_marker\":%lld.%03lld", ts_sync_marker / 1000, ts_sync_marker % 1000); + + } + + fprintf(fptr, "}}"); fclose(fptr); SNAPTRACE_THREAD_PROTECT_END(self); Py_RETURN_NONE; diff --git a/src/viztracer/viztracer.py b/src/viztracer/viztracer.py index 05e4d6c5..bf16f16d 100644 --- a/src/viztracer/viztracer.py +++ b/src/viztracer/viztracer.py @@ -254,6 +254,10 @@ def parse(self) -> int: "overflow": False, }, } + sync_marker = self.get_sync_marker() + if sync_marker > 0: + self.data['viztracer_metadata']['sync_marker'] = sync_marker + metadata_count = 0 for d in self.data["traceEvents"]: if d["ph"] == "M": From 5b176e91fab8ff10c7d397e287d622e1c5af2812 Mon Sep 17 00:00:00 2001 From: Sergey Miryanov Date: Sun, 26 Jan 2025 02:34:43 +0500 Subject: [PATCH 03/21] Use sync_marker to align combined json to particular time marker --- src/viztracer/report_builder.py | 11 ++++++++--- 1 file changed, 8 insertions(+), 3 deletions(-) diff --git a/src/viztracer/report_builder.py b/src/viztracer/report_builder.py index 9142657b..189f90b0 100644 --- a/src/viztracer/report_builder.py +++ b/src/viztracer/report_builder.py @@ -125,7 +125,7 @@ def combine_json(self) -> None: raise ValueError("Can't get report of nothing") if self.align: for one in self.jsons: - self.align_events(one["traceEvents"]) + self.align_events(one["traceEvents"], one['viztracer_metadata'].get('sync_marker', None)) self.combined_json = self.jsons[0] if "viztracer_metadata" not in self.combined_json: self.combined_json["viztracer_metadata"] = {} @@ -143,14 +143,19 @@ def combine_json(self) -> None: self.combined_json["file_info"]["files"].update(one["file_info"]["files"]) self.combined_json["file_info"]["functions"].update(one["file_info"]["functions"]) - def align_events(self, original_events: list[dict[str, Any]]) -> list[dict[str, Any]]: + def align_events(self, original_events: list[dict[str, Any]], sync_marker: Optional[float] = None) -> list[dict[str, Any]]: """ Apply an offset to all the trace events, making the start timestamp 0 This is useful when comparing multiple runs of the same script + If sync_marker is not None then sync_marker be used as an offset + This function will change the timestamp in place, and return the original list """ - offset_ts = min((event["ts"] for event in original_events if "ts" in event)) + offset_ts = sync_marker + if offset_ts is None: + offset_ts = min((event["ts"] for event in original_events if "ts" in event)) + for event in original_events: if "ts" in event: event["ts"] -= offset_ts From cf8208f5b5ab9355fbdfc2257137de234a60042d Mon Sep 17 00:00:00 2001 From: Sergey Miryanov Date: Sun, 26 Jan 2025 02:35:19 +0500 Subject: [PATCH 04/21] Add tests for align_combine with sync_marker --- tests/test_cmdline.py | 83 +++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 83 insertions(+) diff --git a/tests/test_cmdline.py b/tests/test_cmdline.py index 2d5f3959..1231358c 100644 --- a/tests/test_cmdline.py +++ b/tests/test_cmdline.py @@ -3,7 +3,9 @@ import configparser import importlib.util +import json import os +import pathlib import re import signal import sys @@ -347,6 +349,87 @@ def test_combine(self): os.path.join(example_json_dir, "different_sorts.json")], expected_output_file="result.json") + @package_matrix(["~orjson", "orjson"]) + def test_align_combine_sync_marker(self): + test_script = """ +from viztracer import get_tracer + +if get_tracer() is not None: + get_tracer().set_sync_marker() + +def fib(n): + if n < 2: + return 1 + return fib(n-1) + fib(n-2) +fib(5) +""" + + def expect_sync_marker(data): + self.assertIsNotNone(data['viztracer_metadata'].get('sync_marker')) + self.assertGreater(data['viztracer_metadata'].get('sync_marker'), 0) + + def expect_aligned_to_sync_marker(data, res1_filename, res2_filename): + with open(res1_filename, 'r') as f: + result1 = json.load(f) + with open(res2_filename, 'r') as f: + result2 = json.load(f) + + self.assertIn('sync_marker', result1['viztracer_metadata']) + self.assertIn('sync_marker', result2['viztracer_metadata']) + + sync_marker_1 = result1['viztracer_metadata']['sync_marker'] + sync_marker_2 = result1['viztracer_metadata']['sync_marker'] + + self.assertGreater(sync_marker_1, 0) + self.assertGreater(sync_marker_2, 0) + + offset_ts_1 = min((event["ts"] for event in result1["traceEvents"] if "ts" in event)) + offset_ts_2 = min((event["ts"] for event in result2["traceEvents"] if "ts" in event)) + + diff_1 = abs(sync_marker_1 - offset_ts_1) + diff_2 = abs(sync_marker_2 - offset_ts_2) + + offset_ts = min((event["ts"] for event in data["traceEvents"] if "ts" in event)) + + if round(diff_1, 7) == 0 or round(diff_2, 7) == 0: + self.assertAlmostEqual(0, offset_ts) + else: + self.assertNotAlmostEqual(0, offset_ts) + + def create_results(tmpdir, extra_args): + res1_filename = pathlib.Path(tmpdir, 'res1.json').as_posix() + res2_filename = pathlib.Path(tmpdir, 'res2.json').as_posix() + + common_cmd_line = [sys.executable, "-m", "viztracer", "--ignore_frozen", "--output_dir", tmpdir] + extra_args + self.template( + common_cmd_line + ["-o", "res1.json", "cmdline_test.py"], + expected_output_file=res1_filename, + script=test_script, + cleanup=False, + check_func=expect_sync_marker, + ) + self.template( + common_cmd_line + ["-o", "res2.json", "cmdline_test.py"], + expected_output_file=res2_filename, + script=test_script, + cleanup=False, + check_func=expect_sync_marker, + ) + + return res1_filename, res2_filename + + for extra_args in [[], ["--dump_raw"]]: + + with tempfile.TemporaryDirectory() as tmpdir: + res1_filename, res2_filename = create_results(tmpdir, extra_args) + + self.template( + [sys.executable, "-m", "viztracer", "--align_combine", res1_filename, res2_filename], + expected_output_file="result.json", + check_func=lambda data: expect_aligned_to_sync_marker(data, res1_filename, res2_filename), + ) + + def test_tracer_entries(self): self.template([sys.executable, "-m", "viztracer", "--tracer_entries", "1000", "cmdline_test.py"]) self.template([sys.executable, "-m", "viztracer", "--tracer_entries", "50", "cmdline_test.py"]) From 6946f4bd0fc962fe5b220809e96c6c21d6898049 Mon Sep 17 00:00:00 2001 From: Sergey Miryanov Date: Sun, 26 Jan 2025 14:42:18 +0500 Subject: [PATCH 05/21] Make linter happy --- tests/test_cmdline.py | 1 - 1 file changed, 1 deletion(-) diff --git a/tests/test_cmdline.py b/tests/test_cmdline.py index 1231358c..6eb984e7 100644 --- a/tests/test_cmdline.py +++ b/tests/test_cmdline.py @@ -429,7 +429,6 @@ def create_results(tmpdir, extra_args): check_func=lambda data: expect_aligned_to_sync_marker(data, res1_filename, res2_filename), ) - def test_tracer_entries(self): self.template([sys.executable, "-m", "viztracer", "--tracer_entries", "1000", "cmdline_test.py"]) self.template([sys.executable, "-m", "viztracer", "--tracer_entries", "50", "cmdline_test.py"]) From 6bb2cc8a1110200e6d19bc8672717f3fcdd22b2b Mon Sep 17 00:00:00 2001 From: Sergey Miryanov Date: Sun, 26 Jan 2025 20:20:25 +0500 Subject: [PATCH 06/21] Fix typo in set_sync_marker warning --- src/viztracer/modules/snaptrace.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/viztracer/modules/snaptrace.c b/src/viztracer/modules/snaptrace.c index 0d6d3a8e..1fd5ae65 100644 --- a/src/viztracer/modules/snaptrace.c +++ b/src/viztracer/modules/snaptrace.c @@ -1939,7 +1939,7 @@ tracer_set_sync_marker(TracerObject* self, PyObject* Py_UNUSED(unused)) { if (self->sync_marker != 0) { - PyErr_WarnFormat(PyExc_RuntimeWarning, 1, "Synchronization warning already set"); + PyErr_WarnFormat(PyExc_RuntimeWarning, 1, "Synchronization marker already set"); } self->sync_marker = get_ts(); Py_RETURN_NONE; From 0946f4dd2dc3777b20ccd8669d6e737cff4ede60 Mon Sep 17 00:00:00 2001 From: Sergey Miryanov Date: Sun, 26 Jan 2025 20:20:51 +0500 Subject: [PATCH 07/21] Add test_set_sync_marker and simplify test_align_combine_sync_marker --- tests/test_cmdline.py | 76 ++++++++++++++++++++++++++++--------------- 1 file changed, 49 insertions(+), 27 deletions(-) diff --git a/tests/test_cmdline.py b/tests/test_cmdline.py index 6eb984e7..52623e88 100644 --- a/tests/test_cmdline.py +++ b/tests/test_cmdline.py @@ -349,8 +349,7 @@ def test_combine(self): os.path.join(example_json_dir, "different_sorts.json")], expected_output_file="result.json") - @package_matrix(["~orjson", "orjson"]) - def test_align_combine_sync_marker(self): + def test_set_sync_marker(self): test_script = """ from viztracer import get_tracer @@ -362,12 +361,39 @@ def fib(n): return 1 return fib(n-1) + fib(n-2) fib(5) + +if get_tracer() is not None: + get_tracer().set_sync_marker() + """ def expect_sync_marker(data): self.assertIsNotNone(data['viztracer_metadata'].get('sync_marker')) self.assertGreater(data['viztracer_metadata'].get('sync_marker'), 0) + self.template( + [sys.executable, "-m", "viztracer", "--ignore_frozen", "-o", "result.json", "cmdline_test.py"], + expected_output_file="result.json", + expected_stderr="Synchronization marker already set", + script=test_script, + check_func=expect_sync_marker, + ) + + @package_matrix(["~orjson", "orjson"]) + def test_align_combine_sync_marker(self): + test_script = """ +from viztracer import get_tracer + +if get_tracer() is not None: + get_tracer().set_sync_marker() + +def fib(n): + if n < 2: + return 1 + return fib(n-1) + fib(n-2) +fib(5) +""" + def expect_aligned_to_sync_marker(data, res1_filename, res2_filename): with open(res1_filename, 'r') as f: result1 = json.load(f) @@ -396,39 +422,35 @@ def expect_aligned_to_sync_marker(data, res1_filename, res2_filename): else: self.assertNotAlmostEqual(0, offset_ts) - def create_results(tmpdir, extra_args): - res1_filename = pathlib.Path(tmpdir, 'res1.json').as_posix() - res2_filename = pathlib.Path(tmpdir, 'res2.json').as_posix() - - common_cmd_line = [sys.executable, "-m", "viztracer", "--ignore_frozen", "--output_dir", tmpdir] + extra_args - self.template( - common_cmd_line + ["-o", "res1.json", "cmdline_test.py"], - expected_output_file=res1_filename, - script=test_script, - cleanup=False, - check_func=expect_sync_marker, - ) - self.template( - common_cmd_line + ["-o", "res2.json", "cmdline_test.py"], - expected_output_file=res2_filename, - script=test_script, - cleanup=False, - check_func=expect_sync_marker, - ) - - return res1_filename, res2_filename - - for extra_args in [[], ["--dump_raw"]]: - + def test_align(extra_args): with tempfile.TemporaryDirectory() as tmpdir: - res1_filename, res2_filename = create_results(tmpdir, extra_args) + res1_filename = pathlib.Path(tmpdir, 'res1.json').as_posix() + res2_filename = pathlib.Path(tmpdir, 'res2.json').as_posix() + + common_cmd_line = [sys.executable, "-m", "viztracer", "--ignore_frozen", "--output_dir", tmpdir] + extra_args + self.template( + common_cmd_line + ["-o", "res1.json", "cmdline_test.py"], + expected_output_file=res1_filename, + script=test_script, + cleanup=False, + ) + self.template( + common_cmd_line + ["-o", "res2.json", "cmdline_test.py"], + expected_output_file=res2_filename, + script=test_script, + cleanup=False, + ) self.template( [sys.executable, "-m", "viztracer", "--align_combine", res1_filename, res2_filename], expected_output_file="result.json", + script='', check_func=lambda data: expect_aligned_to_sync_marker(data, res1_filename, res2_filename), ) + test_align([]) + test_align(['--dump_raw']) + def test_tracer_entries(self): self.template([sys.executable, "-m", "viztracer", "--tracer_entries", "1000", "cmdline_test.py"]) self.template([sys.executable, "-m", "viztracer", "--tracer_entries", "50", "cmdline_test.py"]) From 46713597a9f52bb1f0818cbe44991e9dc3b8a21a Mon Sep 17 00:00:00 2001 From: Sergey Miryanov Date: Mon, 27 Jan 2025 00:19:44 +0500 Subject: [PATCH 08/21] get_sync_marker return None if not set --- src/viztracer/modules/snaptrace.c | 7 +++---- src/viztracer/report_builder.py | 5 +++-- src/viztracer/snaptrace.pyi | 6 +++--- src/viztracer/viztracer.py | 2 +- 4 files changed, 10 insertions(+), 10 deletions(-) diff --git a/src/viztracer/modules/snaptrace.c b/src/viztracer/modules/snaptrace.c index 1fd5ae65..508792d6 100644 --- a/src/viztracer/modules/snaptrace.c +++ b/src/viztracer/modules/snaptrace.c @@ -1618,7 +1618,6 @@ tracer_dump(TracerObject* self, PyObject* args, PyObject* kw) { long long ts_sync_marker = system_ts_to_ns(self->sync_marker); fprintf(fptr, ",\"sync_marker\":%lld.%03lld", ts_sync_marker / 1000, ts_sync_marker % 1000); - } fprintf(fptr, "}}"); @@ -1950,7 +1949,7 @@ tracer_get_sync_marker(TracerObject* self, PyObject* Py_UNUSED(unused)) { if (self->sync_marker == 0) { - return PyLong_FromInt64(self->sync_marker); + Py_RETURN_NONE; } double ts_sync_marker = system_ts_to_us(self->sync_marker); @@ -1977,8 +1976,8 @@ static PyMethodDef Tracer_methods[] = { {"pause", (PyCFunction)tracer_pause, METH_NOARGS, "pause profiling"}, {"resume", (PyCFunction)tracer_resume, METH_NOARGS, "resume profiling"}, {"setignorestackcounter", (PyCFunction)tracer_setignorestackcounter, METH_O, "reset ignore stack depth"}, - {"set_sync_marker", (PyCFunction)tracer_set_sync_marker, METH_NOARGS, "put current timestamp to synchronization marker"}, - {"get_sync_marker", (PyCFunction)tracer_get_sync_marker, METH_NOARGS, "get synchronization marker"}, + {"set_sync_marker", (PyCFunction)tracer_set_sync_marker, METH_NOARGS, "set current timestamp to synchronization marker"}, + {"get_sync_marker", (PyCFunction)tracer_get_sync_marker, METH_NOARGS, "get synchronization marker or None if not set"}, {NULL, NULL, 0, NULL} }; diff --git a/src/viztracer/report_builder.py b/src/viztracer/report_builder.py index 189f90b0..05b6a2e9 100644 --- a/src/viztracer/report_builder.py +++ b/src/viztracer/report_builder.py @@ -152,9 +152,10 @@ def align_events(self, original_events: list[dict[str, Any]], sync_marker: Optio This function will change the timestamp in place, and return the original list """ - offset_ts = sync_marker - if offset_ts is None: + if sync_marker is None: offset_ts = min((event["ts"] for event in original_events if "ts" in event)) + else: + offset_ts = sync_marker for event in original_events: if "ts" in event: diff --git a/src/viztracer/snaptrace.pyi b/src/viztracer/snaptrace.pyi index 6ab2fa16..7afc794f 100644 --- a/src/viztracer/snaptrace.pyi +++ b/src/viztracer/snaptrace.pyi @@ -69,9 +69,9 @@ class Tracer: ... def set_sync_marker(self) -> None: - """put current timestamp to synchronization marker""" + """set current timestamp to synchronization marker""" ... - def get_sync_marker(self) -> float: - """get synchronization marker""" + def get_sync_marker(self) -> Optional[float]: + """get synchronization marker or None if not set""" ... diff --git a/src/viztracer/viztracer.py b/src/viztracer/viztracer.py index bf16f16d..3615c625 100644 --- a/src/viztracer/viztracer.py +++ b/src/viztracer/viztracer.py @@ -255,7 +255,7 @@ def parse(self) -> int: }, } sync_marker = self.get_sync_marker() - if sync_marker > 0: + if sync_marker is not None: self.data['viztracer_metadata']['sync_marker'] = sync_marker metadata_count = 0 From 514ae36bbe2c8585ca937386977a0f9872d36c85 Mon Sep 17 00:00:00 2001 From: Sergey Miryanov Date: Mon, 27 Jan 2025 00:22:53 +0500 Subject: [PATCH 09/21] Use dedent for test_scripts in sync_marker tests --- tests/test_cmdline.py | 44 +++++++++++++++++++++---------------------- 1 file changed, 22 insertions(+), 22 deletions(-) diff --git a/tests/test_cmdline.py b/tests/test_cmdline.py index 52623e88..bd04c6e9 100644 --- a/tests/test_cmdline.py +++ b/tests/test_cmdline.py @@ -350,22 +350,22 @@ def test_combine(self): expected_output_file="result.json") def test_set_sync_marker(self): - test_script = """ -from viztracer import get_tracer + test_script = textwrap.dedent(""" + from viztracer import get_tracer -if get_tracer() is not None: - get_tracer().set_sync_marker() + if get_tracer() is not None: + get_tracer().set_sync_marker() -def fib(n): - if n < 2: - return 1 - return fib(n-1) + fib(n-2) -fib(5) + def fib(n): + if n < 2: + return 1 + return fib(n-1) + fib(n-2) + fib(5) -if get_tracer() is not None: - get_tracer().set_sync_marker() + if get_tracer() is not None: + get_tracer().set_sync_marker() -""" + """) def expect_sync_marker(data): self.assertIsNotNone(data['viztracer_metadata'].get('sync_marker')) @@ -381,18 +381,18 @@ def expect_sync_marker(data): @package_matrix(["~orjson", "orjson"]) def test_align_combine_sync_marker(self): - test_script = """ -from viztracer import get_tracer + test_script = textwrap.dedent(""" + from viztracer import get_tracer -if get_tracer() is not None: - get_tracer().set_sync_marker() + if get_tracer() is not None: + get_tracer().set_sync_marker() -def fib(n): - if n < 2: - return 1 - return fib(n-1) + fib(n-2) -fib(5) -""" + def fib(n): + if n < 2: + return 1 + return fib(n-1) + fib(n-2) + fib(5) + """) def expect_aligned_to_sync_marker(data, res1_filename, res2_filename): with open(res1_filename, 'r') as f: From c4b4f595f725707980ed92b92c62afe78f3fa195 Mon Sep 17 00:00:00 2001 From: Sergey Miryanov Date: Mon, 27 Jan 2025 00:23:13 +0500 Subject: [PATCH 10/21] Remove package_matrix from align_combine_sync_marker test --- tests/test_cmdline.py | 1 - 1 file changed, 1 deletion(-) diff --git a/tests/test_cmdline.py b/tests/test_cmdline.py index bd04c6e9..0ba9f8ae 100644 --- a/tests/test_cmdline.py +++ b/tests/test_cmdline.py @@ -379,7 +379,6 @@ def expect_sync_marker(data): check_func=expect_sync_marker, ) - @package_matrix(["~orjson", "orjson"]) def test_align_combine_sync_marker(self): test_script = textwrap.dedent(""" from viztracer import get_tracer From 88f592f3b7f8b3b44e6f956795da71cb4bcabce9 Mon Sep 17 00:00:00 2001 From: Sergey Miryanov Date: Mon, 27 Jan 2025 00:23:33 +0500 Subject: [PATCH 11/21] Simplify checks for set_sync_marker test --- tests/test_cmdline.py | 1 - 1 file changed, 1 deletion(-) diff --git a/tests/test_cmdline.py b/tests/test_cmdline.py index 0ba9f8ae..ab98fc76 100644 --- a/tests/test_cmdline.py +++ b/tests/test_cmdline.py @@ -368,7 +368,6 @@ def fib(n): """) def expect_sync_marker(data): - self.assertIsNotNone(data['viztracer_metadata'].get('sync_marker')) self.assertGreater(data['viztracer_metadata'].get('sync_marker'), 0) self.template( From 9b3c2cb57f2066ec453cf05703670703b536a5da Mon Sep 17 00:00:00 2001 From: Sergey Miryanov Date: Mon, 27 Jan 2025 20:36:03 +0500 Subject: [PATCH 12/21] Simplify checks for test_align_combine_sync_marker --- tests/test_cmdline.py | 45 +++++++++++++++++++++---------------------- 1 file changed, 22 insertions(+), 23 deletions(-) diff --git a/tests/test_cmdline.py b/tests/test_cmdline.py index ab98fc76..23d1149b 100644 --- a/tests/test_cmdline.py +++ b/tests/test_cmdline.py @@ -380,16 +380,21 @@ def expect_sync_marker(data): def test_align_combine_sync_marker(self): test_script = textwrap.dedent(""" + import random + import time from viztracer import get_tracer + # will sleep from 50ms to 100ms + time.sleep(0.05 + 0.05 * random.random()) if get_tracer() is not None: get_tracer().set_sync_marker() - def fib(n): - if n < 2: - return 1 - return fib(n-1) + fib(n-2) - fib(5) + def func(): + a = pow(2, 3) + b = pow(3, 2) + return a * b + + func() """) def expect_aligned_to_sync_marker(data, res1_filename, res2_filename): @@ -398,27 +403,21 @@ def expect_aligned_to_sync_marker(data, res1_filename, res2_filename): with open(res2_filename, 'r') as f: result2 = json.load(f) - self.assertIn('sync_marker', result1['viztracer_metadata']) - self.assertIn('sync_marker', result2['viztracer_metadata']) - - sync_marker_1 = result1['viztracer_metadata']['sync_marker'] - sync_marker_2 = result1['viztracer_metadata']['sync_marker'] - - self.assertGreater(sync_marker_1, 0) - self.assertGreater(sync_marker_2, 0) - - offset_ts_1 = min((event["ts"] for event in result1["traceEvents"] if "ts" in event)) - offset_ts_2 = min((event["ts"] for event in result2["traceEvents"] if "ts" in event)) + func_1 = [event for event in result1['traceEvents'] if 'ts' in event and event['name'].startswith('func ')] + func_2 = [event for event in result2['traceEvents'] if 'ts' in event and event['name'].startswith('func ')] + funcs = [event for event in data['traceEvents'] if 'ts' in event and event['name'].startswith('func ')] - diff_1 = abs(sync_marker_1 - offset_ts_1) - diff_2 = abs(sync_marker_2 - offset_ts_2) + self.assertEqual(len(func_1), 1) + self.assertEqual(len(func_2), 1) + self.assertEqual(len(funcs), 2) - offset_ts = min((event["ts"] for event in data["traceEvents"] if "ts" in event)) + # we expect that unaligned events shifted more than 100ms + original_diff = abs(func_1[0]['ts'] - func_2[0]['ts']) + self.assertGreaterEqual(original_diff, 100000.0) - if round(diff_1, 7) == 0 or round(diff_2, 7) == 0: - self.assertAlmostEqual(0, offset_ts) - else: - self.assertNotAlmostEqual(0, offset_ts) + # we expect that aligned events shifted not more than 0.1ms + aligned_diff = abs(funcs[1]['ts'] - funcs[0]['ts']) + self.assertLessEqual(aligned_diff, 100.0) def test_align(extra_args): with tempfile.TemporaryDirectory() as tmpdir: From b32bee4e0e015dc67be94a5a83684bbb6af2d17b Mon Sep 17 00:00:00 2001 From: Sergey Miryanov Date: Mon, 27 Jan 2025 20:46:37 +0500 Subject: [PATCH 13/21] Try to increase time delta for aligned and unaligned events --- tests/test_cmdline.py | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/tests/test_cmdline.py b/tests/test_cmdline.py index 23d1149b..7b8fc0f0 100644 --- a/tests/test_cmdline.py +++ b/tests/test_cmdline.py @@ -411,13 +411,13 @@ def expect_aligned_to_sync_marker(data, res1_filename, res2_filename): self.assertEqual(len(func_2), 1) self.assertEqual(len(funcs), 2) - # we expect that unaligned events shifted more than 100ms + # we expect that unaligned events shifted more than 1s original_diff = abs(func_1[0]['ts'] - func_2[0]['ts']) - self.assertGreaterEqual(original_diff, 100000.0) + self.assertGreaterEqual(original_diff, 1000000.0) - # we expect that aligned events shifted not more than 0.1ms + # we expect that aligned events shifted not more than 50ms aligned_diff = abs(funcs[1]['ts'] - funcs[0]['ts']) - self.assertLessEqual(aligned_diff, 100.0) + self.assertLessEqual(aligned_diff, 50000.0, str(data)) def test_align(extra_args): with tempfile.TemporaryDirectory() as tmpdir: From 6907d418cd0f2d502d1b0a3b7513392f17669773 Mon Sep 17 00:00:00 2001 From: Sergey Miryanov Date: Mon, 27 Jan 2025 20:52:51 +0500 Subject: [PATCH 14/21] Another one try to fix time deltas --- tests/test_cmdline.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/tests/test_cmdline.py b/tests/test_cmdline.py index 7b8fc0f0..7c6c6189 100644 --- a/tests/test_cmdline.py +++ b/tests/test_cmdline.py @@ -411,9 +411,9 @@ def expect_aligned_to_sync_marker(data, res1_filename, res2_filename): self.assertEqual(len(func_2), 1) self.assertEqual(len(funcs), 2) - # we expect that unaligned events shifted more than 1s + # we expect that unaligned events shifted more than 100ms original_diff = abs(func_1[0]['ts'] - func_2[0]['ts']) - self.assertGreaterEqual(original_diff, 1000000.0) + self.assertGreaterEqual(original_diff, 100000.0) # we expect that aligned events shifted not more than 50ms aligned_diff = abs(funcs[1]['ts'] - funcs[0]['ts']) From 858e9fb0f56a3d46518015f18f08cb740b6a8fe4 Mon Sep 17 00:00:00 2001 From: Sergey Miryanov Date: Mon, 27 Jan 2025 23:55:21 +0500 Subject: [PATCH 15/21] More simplify checks in test_align_combine_sync_marker --- tests/test_cmdline.py | 38 +++++++++++++------------------------- 1 file changed, 13 insertions(+), 25 deletions(-) diff --git a/tests/test_cmdline.py b/tests/test_cmdline.py index 7c6c6189..7aff2072 100644 --- a/tests/test_cmdline.py +++ b/tests/test_cmdline.py @@ -384,40 +384,28 @@ def test_align_combine_sync_marker(self): import time from viztracer import get_tracer - # will sleep from 50ms to 100ms - time.sleep(0.05 + 0.05 * random.random()) - if get_tracer() is not None: - get_tracer().set_sync_marker() + tracer = get_tracer() + assert tracer is not None - def func(): - a = pow(2, 3) - b = pow(3, 2) + def func(a, b): return a * b - func() + # will should sleep from 50ms to 100ms + rnd = random.random() + time.sleep(0.05 + 0.05 * rnd) + + get_tracer().set_sync_marker() + func(rnd, rnd) """) - def expect_aligned_to_sync_marker(data, res1_filename, res2_filename): - with open(res1_filename, 'r') as f: - result1 = json.load(f) - with open(res2_filename, 'r') as f: - result2 = json.load(f) + def expect_aligned_to_sync_marker(data): - func_1 = [event for event in result1['traceEvents'] if 'ts' in event and event['name'].startswith('func ')] - func_2 = [event for event in result2['traceEvents'] if 'ts' in event and event['name'].startswith('func ')] funcs = [event for event in data['traceEvents'] if 'ts' in event and event['name'].startswith('func ')] - - self.assertEqual(len(func_1), 1) - self.assertEqual(len(func_2), 1) self.assertEqual(len(funcs), 2) - # we expect that unaligned events shifted more than 100ms - original_diff = abs(func_1[0]['ts'] - func_2[0]['ts']) - self.assertGreaterEqual(original_diff, 100000.0) - - # we expect that aligned events shifted not more than 50ms + # we expect that aligned events shifted not more than 1ms aligned_diff = abs(funcs[1]['ts'] - funcs[0]['ts']) - self.assertLessEqual(aligned_diff, 50000.0, str(data)) + self.assertLessEqual(aligned_diff, 1000.0, str(data)) def test_align(extra_args): with tempfile.TemporaryDirectory() as tmpdir: @@ -442,7 +430,7 @@ def test_align(extra_args): [sys.executable, "-m", "viztracer", "--align_combine", res1_filename, res2_filename], expected_output_file="result.json", script='', - check_func=lambda data: expect_aligned_to_sync_marker(data, res1_filename, res2_filename), + check_func=expect_aligned_to_sync_marker, ) test_align([]) From 42253b3cd0bb857647c6e9244147884069ba3f89 Mon Sep 17 00:00:00 2001 From: Sergey Miryanov Date: Mon, 27 Jan 2025 23:56:53 +0500 Subject: [PATCH 16/21] Make linter happy --- tests/test_cmdline.py | 1 - 1 file changed, 1 deletion(-) diff --git a/tests/test_cmdline.py b/tests/test_cmdline.py index 7aff2072..c0d72c82 100644 --- a/tests/test_cmdline.py +++ b/tests/test_cmdline.py @@ -3,7 +3,6 @@ import configparser import importlib.util -import json import os import pathlib import re From 6369def94f72d84779da1bcab671a332be57e8a7 Mon Sep 17 00:00:00 2001 From: Sergey Miryanov Date: Tue, 28 Jan 2025 02:21:24 +0500 Subject: [PATCH 17/21] More simplify tests --- tests/test_cmdline.py | 36 +++++++++++------------------------- 1 file changed, 11 insertions(+), 25 deletions(-) diff --git a/tests/test_cmdline.py b/tests/test_cmdline.py index c0d72c82..3dc73af7 100644 --- a/tests/test_cmdline.py +++ b/tests/test_cmdline.py @@ -4,7 +4,6 @@ import configparser import importlib.util import os -import pathlib import re import signal import sys @@ -352,17 +351,8 @@ def test_set_sync_marker(self): test_script = textwrap.dedent(""" from viztracer import get_tracer - if get_tracer() is not None: - get_tracer().set_sync_marker() - - def fib(n): - if n < 2: - return 1 - return fib(n-1) + fib(n-2) - fib(5) - - if get_tracer() is not None: - get_tracer().set_sync_marker() + get_tracer().set_sync_marker() + get_tracer().set_sync_marker() """) @@ -383,18 +373,14 @@ def test_align_combine_sync_marker(self): import time from viztracer import get_tracer - tracer = get_tracer() - assert tracer is not None - - def func(a, b): - return a * b + def func(): + return 2 * 4 # will should sleep from 50ms to 100ms - rnd = random.random() - time.sleep(0.05 + 0.05 * rnd) + time.sleep(random.uniform(0.05, 0.1)) get_tracer().set_sync_marker() - func(rnd, rnd) + func() """) def expect_aligned_to_sync_marker(data): @@ -408,18 +394,18 @@ def expect_aligned_to_sync_marker(data): def test_align(extra_args): with tempfile.TemporaryDirectory() as tmpdir: - res1_filename = pathlib.Path(tmpdir, 'res1.json').as_posix() - res2_filename = pathlib.Path(tmpdir, 'res2.json').as_posix() + res1_filename = os.path.join(tmpdir, 'res1.json') + res2_filename = os.path.join(tmpdir, 'res2.json') - common_cmd_line = [sys.executable, "-m", "viztracer", "--ignore_frozen", "--output_dir", tmpdir] + extra_args + common_cmd_line = [sys.executable, "-m", "viztracer", "--ignore_frozen"] + extra_args self.template( - common_cmd_line + ["-o", "res1.json", "cmdline_test.py"], + common_cmd_line + ["-o", res1_filename, "cmdline_test.py"], expected_output_file=res1_filename, script=test_script, cleanup=False, ) self.template( - common_cmd_line + ["-o", "res2.json", "cmdline_test.py"], + common_cmd_line + ["-o", res2_filename, "cmdline_test.py"], expected_output_file=res2_filename, script=test_script, cleanup=False, From 1fa04f33a3a2acd7d92033f2fc21a710afffefff Mon Sep 17 00:00:00 2001 From: Sergey Miryanov Date: Tue, 28 Jan 2025 17:54:15 +0500 Subject: [PATCH 18/21] Replace test_align with for-loop --- tests/test_cmdline.py | 6 +----- 1 file changed, 1 insertion(+), 5 deletions(-) diff --git a/tests/test_cmdline.py b/tests/test_cmdline.py index 3dc73af7..f994a65f 100644 --- a/tests/test_cmdline.py +++ b/tests/test_cmdline.py @@ -392,7 +392,7 @@ def expect_aligned_to_sync_marker(data): aligned_diff = abs(funcs[1]['ts'] - funcs[0]['ts']) self.assertLessEqual(aligned_diff, 1000.0, str(data)) - def test_align(extra_args): + for extra_args in [[], ["--dump_raw"]]: with tempfile.TemporaryDirectory() as tmpdir: res1_filename = os.path.join(tmpdir, 'res1.json') res2_filename = os.path.join(tmpdir, 'res2.json') @@ -414,13 +414,9 @@ def test_align(extra_args): self.template( [sys.executable, "-m", "viztracer", "--align_combine", res1_filename, res2_filename], expected_output_file="result.json", - script='', check_func=expect_aligned_to_sync_marker, ) - test_align([]) - test_align(['--dump_raw']) - def test_tracer_entries(self): self.template([sys.executable, "-m", "viztracer", "--tracer_entries", "1000", "cmdline_test.py"]) self.template([sys.executable, "-m", "viztracer", "--tracer_entries", "50", "cmdline_test.py"]) From 4a3f2e6e48bf8f0a86287b71d748fb28a9867142 Mon Sep 17 00:00:00 2001 From: Sergey Miryanov Date: Tue, 28 Jan 2025 22:05:14 +0500 Subject: [PATCH 19/21] Rename test function and fix comment in test script --- tests/test_cmdline.py | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/tests/test_cmdline.py b/tests/test_cmdline.py index f994a65f..7f7b032f 100644 --- a/tests/test_cmdline.py +++ b/tests/test_cmdline.py @@ -373,19 +373,19 @@ def test_align_combine_sync_marker(self): import time from viztracer import get_tracer - def func(): + def test_func(): return 2 * 4 - # will should sleep from 50ms to 100ms + # should sleep from 50ms to 100ms time.sleep(random.uniform(0.05, 0.1)) get_tracer().set_sync_marker() - func() + test_func() """) def expect_aligned_to_sync_marker(data): - funcs = [event for event in data['traceEvents'] if 'ts' in event and event['name'].startswith('func ')] + funcs = [event for event in data['traceEvents'] if 'ts' in event and event['name'].startswith('test_func')] self.assertEqual(len(funcs), 2) # we expect that aligned events shifted not more than 1ms From 81576e1d2394193e0ba09947c57941de569905c1 Mon Sep 17 00:00:00 2001 From: Sergey Miryanov Date: Tue, 28 Jan 2025 22:15:13 +0500 Subject: [PATCH 20/21] Update concurency.rst --- docs/source/concurrency.rst | 15 +++++++++++++++ 1 file changed, 15 insertions(+) diff --git a/docs/source/concurrency.rst b/docs/source/concurrency.rst index e6a54385..511f1302 100644 --- a/docs/source/concurrency.rst +++ b/docs/source/concurrency.rst @@ -126,3 +126,18 @@ After generating ``json`` files, you need to combine them viztracer --combine ./temp_dir/*.json This will generate the report with all the process info. You can specify ``--output_file`` when using ``--combine``. + +Another usage of combining reports would be to compare between different runs of the same program. Unlike combining from multiple +sources, this requires a pre-alignment of all the trace data. VizTracer also provides a way to align the start of all reports for +this usage. + +.. code-block:: + + viztracer --align_combine run1.json run2.json -o compare_report.json + +You can also set a sync-marker from your source code, and VizTracer will align both reports to this particular timestamp. + +.. code-block:: + + from viztracer import get_tracer + get_tracer().set_sync_marker() From 5f3ebfabca8842900ca34cc49efc2e3bf71ffba3 Mon Sep 17 00:00:00 2001 From: Sergey Miryanov Date: Wed, 29 Jan 2025 00:02:31 +0500 Subject: [PATCH 21/21] Move set_sync_marker doc to basic_usage --- docs/source/basic_usage.rst | 8 ++++++++ docs/source/concurrency.rst | 15 --------------- 2 files changed, 8 insertions(+), 15 deletions(-) diff --git a/docs/source/basic_usage.rst b/docs/source/basic_usage.rst index d694e067..d7ce9cd9 100644 --- a/docs/source/basic_usage.rst +++ b/docs/source/basic_usage.rst @@ -271,6 +271,14 @@ this usage. viztracer --align_combine run1.json run2.json -o compare_report.json +You can also set a sync-marker from your source code, and VizTracer will align both reports to this particular timestamp. + +.. code-block:: + + from viztracer import get_tracer + get_tracer().set_sync_marker() + + Compress Your Report -------------------- diff --git a/docs/source/concurrency.rst b/docs/source/concurrency.rst index 511f1302..e6a54385 100644 --- a/docs/source/concurrency.rst +++ b/docs/source/concurrency.rst @@ -126,18 +126,3 @@ After generating ``json`` files, you need to combine them viztracer --combine ./temp_dir/*.json This will generate the report with all the process info. You can specify ``--output_file`` when using ``--combine``. - -Another usage of combining reports would be to compare between different runs of the same program. Unlike combining from multiple -sources, this requires a pre-alignment of all the trace data. VizTracer also provides a way to align the start of all reports for -this usage. - -.. code-block:: - - viztracer --align_combine run1.json run2.json -o compare_report.json - -You can also set a sync-marker from your source code, and VizTracer will align both reports to this particular timestamp. - -.. code-block:: - - from viztracer import get_tracer - get_tracer().set_sync_marker()