tp: write back converted timestamps for systrace lines (#6200)
SystraceTraceParser and JsonTraceTokenizer (for embedded
systemTraceEvents) converted line timestamps to trace time but only
used the result as the sorter key: SystraceLineParser populates tables
from line.ts, so events were written with the unconverted value. This
was masked whenever the conversion was the identity, but inside an
archive where a proto trace provides a MONOTONIC<->BOOTTIME snapshot
the converted and raw values differ.
Write the converted timestamp back into the line before pushing it to
the sorter.
diff --git a/src/trace_processor/importers/json/json_trace_tokenizer.cc b/src/trace_processor/importers/json/json_trace_tokenizer.cc
index 1fa29cd..013661c 100644
--- a/src/trace_processor/importers/json/json_trace_tokenizer.cc
+++ b/src/trace_processor/importers/json/json_trace_tokenizer.cc
@@ -984,6 +984,9 @@
auto trace_ts =
context_->clock_tracker->ToTraceTime(trace_file_clock_, line.ts);
if (trace_ts) {
+ // SystraceLineParser populates tables from line.ts, so the conversion
+ // must be written back, not just used as the sorting key.
+ line.ts = *trace_ts;
systrace_stream_->Push(*trace_ts, std::move(line));
}
}
diff --git a/src/trace_processor/importers/systrace/systrace_trace_parser.cc b/src/trace_processor/importers/systrace/systrace_trace_parser.cc
index 2b9c2e8..c71978a 100644
--- a/src/trace_processor/importers/systrace/systrace_trace_parser.cc
+++ b/src/trace_processor/importers/systrace/systrace_trace_parser.cc
@@ -191,6 +191,10 @@
ClockId::Machine(protos::pbzero::BUILTIN_CLOCK_MONOTONIC),
line.ts);
if (trace_ts) {
+ // The converted timestamp is both the sorting key and the value
+ // the parser stage reads: SystraceLineParser populates tables
+ // from line.ts, so the conversion must be written back.
+ line.ts = *trace_ts;
stream_->Push(*trace_ts, std::move(line));
}
} else {
diff --git a/test/trace_processor/diff_tests/parser/zip/tests.py b/test/trace_processor/diff_tests/parser/zip/tests.py
index f84efc1..b79a329 100644
--- a/test/trace_processor/diff_tests/parser/zip/tests.py
+++ b/test/trace_processor/diff_tests/parser/zip/tests.py
@@ -152,6 +152,38 @@
"a.systrace","systrace",2
'''))
+ # Systrace timestamps must be written back after clock conversion: inside a
+ # zip with a proto trace providing a MONOTONIC<->BOOTTIME snapshot the
+ # conversion is not the identity, and the value written to tables must be
+ # the converted one (which is also the sorting key). The 1.0s MONOTONIC
+ # slice lands at BOOTTIME 1_000_000_000 + 500_000_000.
+ def test_zip_systrace_converted_timestamps(self):
+ return DiffTestBlueprint(
+ trace=ZipTrace({
+ 'sys.systrace':
+ '''# tracer: nop
+#
+ app-100 ( 100) [001] ...1 1.000000: tracing_mark_write: B|100|sys_slice
+ app-100 ( 100) [001] ...1 1.500000: tracing_mark_write: E|100
+''',
+ 'spine.pb':
+ TextProto('''
+ packet {
+ clock_snapshot {
+ clocks { clock_id: 6 timestamp: 1000000000 }
+ clocks { clock_id: 3 timestamp: 500000000 }
+ }
+ }
+ '''),
+ }),
+ query='''
+ SELECT name, ts, dur FROM slice WHERE name = 'sys_slice';
+ ''',
+ out=Csv('''
+ "name","ts","dur"
+ "sys_slice",1500000000,500000000
+ '''))
+
# A tar archive with an external file (DataPath) as a member: the raw bytes
# of the checked-in trace are included verbatim.
def test_tar_blueprint_external_member(self):
