diff options
Diffstat (limited to 'catapult/common/py_trace_event')
8 files changed, 465 insertions, 95 deletions
diff --git a/catapult/common/py_trace_event/py_trace_event/trace_event.py b/catapult/common/py_trace_event/py_trace_event/trace_event.py index f87c278f..88eef21e 100644 --- a/catapult/common/py_trace_event/py_trace_event/trace_event.py +++ b/catapult/common/py_trace_event/py_trace_event/trace_event.py @@ -102,6 +102,9 @@ if trace_event_impl: def trace_add_benchmark_metadata(*args, **kwargs): trace_event_impl.trace_add_benchmark_metadata(*args, **kwargs) + def trace_set_clock_snapshot(*args, **kwargs): + trace_event_impl.trace_set_clock_snapshot(*args, **kwargs) + def trace(name, **kwargs): return trace_event_impl.trace(name, **kwargs) @@ -110,21 +113,8 @@ if trace_event_impl: def traced(fn): return trace_event_impl.traced(fn) - def clock_sync(sync_id, issue_ts=None): - ''' - Add a clock sync event to the trace log. - - Args: - sync_id: ID of clock sync event. - issue_ts: Time at which clock sync was issued, in microseconds. - ''' - time_stamp = trace_time.Now() - args_to_log = {'sync_id': sync_id} - if issue_ts: # Issuer if issue_ts is set, else reciever. - assert issue_ts <= time_stamp - args_to_log['issue_ts'] = issue_ts - trace_event_impl.add_trace_event( - "c", time_stamp, "python", "clock_sync", args_to_log) + def clock_sync(*args, **kwargs): + return trace_event_impl.clock_sync(*args, **kwargs) def is_tracing_controllable(): return trace_event_impl.is_tracing_controllable() @@ -268,7 +258,8 @@ trace.__doc__ = """Traces a block of code using a with statement. If tracing an entire function call, prefer the @traced decorator. """ -traced.__doc__ = """ +traced.__doc__ = """Traces the provided function. + Traces the provided function, using the function name for the actual generated event. @@ -284,12 +275,15 @@ traced.__doc__ = """ urllib2.urlopen(url).read() """ -clock_sync.__doc__ = """ - Issues a clock sync marker event. +clock_sync.__doc__ = """Issues a clock sync marker event. Clock sync markers are used to synchronize the clock domains of different traces so that they can be used together. It takes a sync_id, and if it is the issuer of a clock sync event it will also require an issue_ts. The issue_ts is a timestamp from when the clocksync was first issued. This is used to calculate the time difference between clock domains. + + This function has no effect if trace format is proto and + trace_set_clock_snapshot was called before trace start. The synchronization + will be performed in trace_processor using clock snapshots in this case. """ diff --git a/catapult/common/py_trace_event/py_trace_event/trace_event_impl/log.py b/catapult/common/py_trace_event/py_trace_event/trace_event_impl/log.py index 7af86daf..130d1683 100644 --- a/catapult/common/py_trace_event/py_trace_event/trace_event_impl/log.py +++ b/catapult/common/py_trace_event/py_trace_event/trace_event_impl/log.py @@ -42,6 +42,24 @@ _log_file = None _cur_events = [] # events that have yet to be buffered _benchmark_metadata = {} +# Default timestamp values for clock snapshot. +# If a ClockSnapshot message with these default values is emitted, Telemetry +# events' time will not be translated by trace processor, because both +# TELEMETRY and BOOTTIME timestamps are the same. This allows the old-style +# synchronization (using clock_sync events) to take place in catapult. +# If we want to actually synchronize Telemetry with other trace producers +# via clock snapshots in trace processor, we should set _boottime_ts to the +# actual BOOTTIME of the device and _emit_clock_sync to False. In this case, +# trace processor will translate both Chrome's and telemetry's timestamps +# to the device time (BOOTTIME) during proto-to-json conversion, and catapult's +# clock synchronization will not take place because we do not emit the +# clock_sync event. +# Note that we can't use both synchronization methods at the same time +# because that will lead to wrong results. +_telemetry_ts = trace_time.Now() +_boottime_ts = _telemetry_ts +_emit_clock_sync = True + _tls = threading.local() # tls used to detect forking/etc _atexit_regsitered_for_pid = None @@ -72,7 +90,7 @@ def _disallow_tracing_control(): _control_allowed = False def trace_enable(log_file=None, format=None): - """ Enable tracing. + """Enable tracing. Args: log_file: file to write trace into. Can be a file-like object, @@ -80,17 +98,24 @@ def trace_enable(log_file=None, format=None): from executable name. format: trace file format. See trace_event.py for available options. """ + global _emit_clock_sync if format is None: format = JSON + # Can only write clock snapshots in protobuf format. In all other formats + # should use clock_syncs. + if format != PROTOBUF: + _emit_clock_sync = True _trace_enable(log_file, format) def _write_header(): - tid = threading.current_thread().ident - if not tid: - tid = os.getpid() - if _format == PROTOBUF: tid = threading.current_thread().ident + perfetto_trace_writer.write_clock_snapshot( + output=_log_file, + tid=tid, + telemetry_ts=_telemetry_ts, + boottime_ts=_boottime_ts, + ) perfetto_trace_writer.write_thread_descriptor_event( output=_log_file, pid=os.getpid(), @@ -103,7 +128,7 @@ def _write_header(): category="process_argv", name="process_argv", ts=trace_time.Now(), - args=sys.argv, + args={"argv": sys.argv}, tid=tid, ) else: @@ -183,6 +208,9 @@ def trace_disable(): return _enabled = False _flush(close=True) + # Clear the collected interned data so that the next trace session + # could start from a clean state. + perfetto_trace_writer.reset_global_state() multiprocessing.Process = _original_multiprocessing_process def _write_cur_events(): @@ -289,9 +317,8 @@ def trace_add_benchmark_metadata( story_tags, story_run_index, label=None, - had_failures=None, ): - """ Add benchmark metadata to be written to trace file. + """Add benchmark metadata to be written to trace file. Args: benchmark_start_time_us: Benchmark start time in microseconds. @@ -317,8 +344,12 @@ def trace_add_benchmark_metadata( story_tags=story_tags, story_run_index=story_run_index, label=label, - had_failures=had_failures, ) + if _emit_clock_sync: + perfetto_trace_writer.write_chrome_metadata( + output=_log_file, + clock_domain="TELEMETRY", + ) elif _format == JSON_WITH_METADATA: # Store metadata to write it in the footer. telemetry_metadata_for_json = { @@ -332,9 +363,8 @@ def trace_add_benchmark_metadata( } if label: telemetry_metadata_for_json["labels"] = [label] - if had_failures: - telemetry_metadata_for_json["hadFailures"] = [had_failures] + assert _emit_clock_sync _benchmark_metadata = { # TODO(crbug.com/948633): For right now, we use "TELEMETRY" as the # clock domain to guarantee that Telemetry is given its own clock @@ -356,6 +386,48 @@ def trace_add_benchmark_metadata( else: raise TraceException("Unknown format: %s" % _format) +def trace_set_clock_snapshot(telemetry_ts, boottime_ts): + """Set timestamps to be written in a ClockSnapshot message. + + This function must be called before the trace start. When trace starts, + a ClockSnapshot message with given timestamps will be written in protobuf + format. In json format, nothing will happen. Use clock_sync function + for clock synchronization in json format. + + Args: + telemetry_ts: BOOTTIME of the device where Telemetry runs. + boottime_ts: BOOTTIME of the device where the tested browser runs. + """ + global _telemetry_ts + global _boottime_ts + global _emit_clock_sync + global _enabled + if _enabled: + raise TraceException("Can't set the clock snapshot after trace started.") + _telemetry_ts = telemetry_ts + _boottime_ts = boottime_ts + _emit_clock_sync = False + +def clock_sync(sync_id, issue_ts=None): + """Add a clock sync event to the trace log. + + Adds a clock sync event if the TBMv2-style synchronization is enabled. + It's enabled in two cases: + 1) Trace format is json. + 2) The clock snapshot was not set before the trace start. + + Args: + sync_id: ID of clock sync event. + issue_ts: Time at which clock sync was issued, in microseconds. + """ + if _emit_clock_sync: + time_stamp = trace_time.Now() + args_to_log = {"sync_id": sync_id} + if issue_ts: # Issuer if issue_ts is set, else reciever. + assert issue_ts <= time_stamp + args_to_log["issue_ts"] = issue_ts + add_trace_event("c", time_stamp, "python", "clock_sync", args_to_log) + def _trace_disable_atexit(): trace_disable() diff --git a/catapult/common/py_trace_event/py_trace_event/trace_event_impl/perfetto_proto_classes.py b/catapult/common/py_trace_event/py_trace_event/trace_event_impl/perfetto_proto_classes.py index 2da179be..5be4a8e1 100644 --- a/catapult/common/py_trace_event/py_trace_event/trace_event_impl/perfetto_proto_classes.py +++ b/catapult/common/py_trace_event/py_trace_event/trace_event_impl/perfetto_proto_classes.py @@ -21,15 +21,32 @@ import wire_format class TracePacket(object): def __init__(self): + self.clock_snapshot = None + self.timestamp = None + self.timestamp_clock_id = None self.interned_data = None self.thread_descriptor = None self.incremental_state_cleared = None + self.chrome_event = None self.track_event = None self.trusted_packet_sequence_id = None self.chrome_benchmark_metadata = None def encode(self): parts = [] + if self.chrome_event is not None: + tag = encoder.TagBytes(5, wire_format.WIRETYPE_LENGTH_DELIMITED) + data = self.chrome_event.encode() + length = encoder._VarintBytes(len(data)) + parts += [tag, length, data] + if self.clock_snapshot is not None: + tag = encoder.TagBytes(6, wire_format.WIRETYPE_LENGTH_DELIMITED) + data = self.clock_snapshot.encode() + length = encoder._VarintBytes(len(data)) + parts += [tag, length, data] + if self.timestamp is not None: + writer = encoder.UInt64Encoder(8, False, False) + writer(parts.append, self.timestamp) if self.trusted_packet_sequence_id is not None: writer = encoder.UInt32Encoder(10, False, False) writer(parts.append, self.trusted_packet_sequence_id) @@ -56,6 +73,9 @@ class TracePacket(object): data = self.chrome_benchmark_metadata.encode() length = encoder._VarintBytes(len(data)) parts += [tag, length, data] + if self.timestamp_clock_id is not None: + writer = encoder.UInt32Encoder(58, False, False) + writer(parts.append, self.timestamp_clock_id) return b"".join(parts) @@ -106,11 +126,9 @@ class ThreadDescriptor(object): def __init__(self): self.pid = None self.tid = None - self.reference_timestamp_us = None def encode(self): - if (self.pid is None or self.tid is None or - self.reference_timestamp_us is None): + if (self.pid is None or self.tid is None): raise RuntimeError("Missing mandatory fields.") parts = [] @@ -118,35 +136,46 @@ class ThreadDescriptor(object): writer(parts.append, self.pid) writer = encoder.UInt32Encoder(2, False, False) writer(parts.append, self.tid) - writer = encoder.Int64Encoder(6, False, False) - writer(parts.append, self.reference_timestamp_us) + + return b"".join(parts) + + +class ChromeEventBundle(object): + def __init__(self): + self.metadata = [] + + def encode(self): + parts = [] + for item in self.metadata: + tag = encoder.TagBytes(2, wire_format.WIRETYPE_LENGTH_DELIMITED) + data = item.encode() + length = encoder._VarintBytes(len(data)) + parts += [tag, length, data] return b"".join(parts) class TrackEvent(object): def __init__(self): - self.timestamp_absolute_us = None - self.timestamp_delta_us = None self.legacy_event = None self.category_iids = None + self.debug_annotations = [] def encode(self): parts = [] - if self.timestamp_delta_us is not None: - writer = encoder.Int64Encoder(1, False, False) - writer(parts.append, self.timestamp_delta_us) if self.category_iids is not None: writer = encoder.UInt32Encoder(3, is_repeated=True, is_packed=False) writer(parts.append, self.category_iids) + for annotation in self.debug_annotations: + tag = encoder.TagBytes(4, wire_format.WIRETYPE_LENGTH_DELIMITED) + data = annotation.encode() + length = encoder._VarintBytes(len(data)) + parts += [tag, length, data] if self.legacy_event is not None: tag = encoder.TagBytes(6, wire_format.WIRETYPE_LENGTH_DELIMITED) data = self.legacy_event.encode() length = encoder._VarintBytes(len(data)) parts += [tag, length, data] - if self.timestamp_absolute_us is not None: - writer = encoder.Int64Encoder(16, False, False) - writer(parts.append, self.timestamp_absolute_us) return b"".join(parts) @@ -178,7 +207,6 @@ class ChromeBenchmarkMetadata(object): self.story_tags = None self.story_run_index = None self.label = None - self.had_failures = None def encode(self): parts = [] @@ -206,9 +234,6 @@ class ChromeBenchmarkMetadata(object): if self.story_run_index is not None: writer = encoder.Int32Encoder(8, False, False) writer(parts.append, self.story_run_index) - if self.had_failures is not None: - writer = encoder.BoolEncoder(9, False, False) - writer(parts.append, self.had_failures) return b"".join(parts) @@ -220,3 +245,87 @@ def write_trace_packet(output, trace_packet): encoder._EncodeVarint(output.write, len(binary_data)) output.write(binary_data) + +class DebugAnnotation(object): + def __init__(self): + self.name = None + self.int_value = None + self.double_value = None + self.string_value = None + + def encode(self): + if self.name is None: + raise RuntimeError("DebugAnnotation must have a name.") + if ((self.string_value is not None) + + (self.int_value is not None) + + (self.double_value is not None)) != 1: + raise RuntimeError("DebugAnnotation must have exactly one value.") + + parts = [] + writer = encoder.StringEncoder(10, False, False) + writer(parts.append, self.name) + if self.int_value is not None: + writer = encoder.Int64Encoder(4, False, False) + writer(parts.append, self.int_value) + if self.double_value is not None: + writer = encoder.DoubleEncoder(5, False, False) + writer(parts.append, self.double_value) + if self.string_value is not None: + writer = encoder.StringEncoder(6, False, False) + writer(parts.append, self.string_value) + + return b"".join(parts) + + +class ChromeMetadata(object): + def __init__(self): + self.name = None + self.string_value = None + + def encode(self): + if self.name is None or self.string_value is None: + raise RuntimeError("ChromeMetadata must have a name and a value.") + + parts = [] + writer = encoder.StringEncoder(1, False, False) + writer(parts.append, self.name) + writer = encoder.StringEncoder(2, False, False) + writer(parts.append, self.string_value) + + return b"".join(parts) + + +class Clock(object): + def __init__(self): + self.clock_id = None + self.timestamp = None + + def encode(self): + if self.clock_id is None or self.timestamp is None: + raise RuntimeError("Clock must have a clock_id and a timestamp.") + + parts = [] + writer = encoder.UInt32Encoder(1, False, False) + writer(parts.append, self.clock_id) + writer = encoder.UInt64Encoder(2, False, False) + writer(parts.append, self.timestamp) + + return b"".join(parts) + + +class ClockSnapshot(object): + def __init__(self): + self.clocks = [] + + def encode(self): + if len(self.clocks) < 2: + raise RuntimeError("ClockSnapshot must have at least two clocks.") + + parts = [] + for clock in self.clocks: + tag = encoder.TagBytes(1, wire_format.WIRETYPE_LENGTH_DELIMITED) + data = clock.encode() + length = encoder._VarintBytes(len(data)) + parts += [tag, length, data] + + return b"".join(parts) diff --git a/catapult/common/py_trace_event/py_trace_event/trace_event_impl/perfetto_trace_writer.py b/catapult/common/py_trace_event/py_trace_event/trace_event_impl/perfetto_trace_writer.py index 37809538..584352cf 100644 --- a/catapult/common/py_trace_event/py_trace_event/trace_event_impl/perfetto_trace_writer.py +++ b/catapult/common/py_trace_event/py_trace_event/trace_event_impl/perfetto_trace_writer.py @@ -9,24 +9,31 @@ import collections import perfetto_proto_classes as proto +CLOCK_BOOTTIME = 6 +CLOCK_TELEMETRY = 64 -# Dicts of strings for interning. -# Note that each thread has its own interning index. -_interned_categories_by_tid = collections.defaultdict(dict) -_interned_event_names_by_tid = collections.defaultdict(dict) +def reset_global_state(): + global _interned_categories_by_tid + global _interned_event_names_by_tid + global _next_sequence_id + global _sequence_ids + + # Dicts of strings for interning. + # Note that each thread has its own interning index. + _interned_categories_by_tid = collections.defaultdict(dict) + _interned_event_names_by_tid = collections.defaultdict(dict) -# Trusted sequence ids from telemetry should not overlap with -# trusted sequence ids from other trace producers. Chrome assigns -# sequence ids incrementally starting from 1 and we expect all its ids -# to be well below 10000. Starting from 2^20 will give us enough -# confidence that it will not overlap. -_next_sequence_id = 1<<20 -_sequence_ids = {} + # Trusted sequence ids from telemetry should not overlap with + # trusted sequence ids from other trace producers. Chrome assigns + # sequence ids incrementally starting from 1 and we expect all its ids + # to be well below 10000. Starting from 2^20 will give us enough + # confidence that it will not overlap. + _next_sequence_id = 1<<20 + _sequence_ids = {} -# Timestamp of the last event from each thread. Used for delta-encoding -# of timestamps. -_last_timestamps = {} + +reset_global_state() def _get_sequence_id(tid): @@ -67,7 +74,7 @@ def _intern_event_name(event_name, trace_packet, tid): def write_thread_descriptor_event(output, pid, tid, ts): - """ Write the first event in a sequence. + """Write the first event in a sequence. Call this function before writing any other events. Note that this function is NOT thread-safe. @@ -78,12 +85,11 @@ def write_thread_descriptor_event(output, pid, tid, ts): tid: thread ID. ts: timestamp in microseconds. """ - global _last_timestamps - ts_us = int(ts) - _last_timestamps[tid] = ts_us - thread_descriptor_packet = proto.TracePacket() thread_descriptor_packet.trusted_packet_sequence_id = _get_sequence_id(tid) + thread_descriptor_packet.timestamp = int(ts * 1e3) + thread_descriptor_packet.timestamp_clock_id = CLOCK_TELEMETRY + thread_descriptor_packet.thread_descriptor = proto.ThreadDescriptor() thread_descriptor_packet.thread_descriptor.pid = pid # Thread ID from threading module doesn't fit into int32. @@ -91,14 +97,13 @@ def write_thread_descriptor_event(output, pid, tid, ts): # distinguish one thread from another. We assume that the last 31 bits # will do for that purpose. thread_descriptor_packet.thread_descriptor.tid = tid & 0x7FFFFFFF - thread_descriptor_packet.thread_descriptor.reference_timestamp_us = ts_us thread_descriptor_packet.incremental_state_cleared = True; proto.write_trace_packet(output, thread_descriptor_packet) def write_event(output, ph, category, name, ts, args, tid): - """ Write a trace event. + """Write a trace event. Note that this function is NOT thread-safe. @@ -108,30 +113,49 @@ def write_event(output, ph, category, name, ts, args, tid): category: category of event. name: event name. ts: timestamp in microseconds. - args: this argument is currently ignored. + args: dict of arbitrary key-values to be stored as DebugAnnotations. tid: thread ID. """ - del args # TODO(khokhlov): Encode args as DebugAnnotations. - - global _last_timestamps - ts_us = int(ts) - delta_ts = ts_us - _last_timestamps[tid] - packet = proto.TracePacket() packet.trusted_packet_sequence_id = _get_sequence_id(tid) - packet.track_event = proto.TrackEvent() - - if delta_ts >= 0: - packet.track_event.timestamp_delta_us = delta_ts - _last_timestamps[tid] = ts_us - else: - packet.track_event.timestamp_absolute_us = ts_us + packet.timestamp = int(ts * 1e3) + packet.timestamp_clock_id = CLOCK_TELEMETRY + packet.track_event = proto.TrackEvent() packet.track_event.category_iids = [_intern_category(category, packet, tid)] legacy_event = proto.LegacyEvent() legacy_event.phase = ord(ph) legacy_event.name_iid = _intern_event_name(name, packet, tid) packet.track_event.legacy_event = legacy_event + + for name, value in args.iteritems(): + debug_annotation = proto.DebugAnnotation() + debug_annotation.name = name + if isinstance(value, int): + debug_annotation.int_value = value + elif isinstance(value, float): + debug_annotation.double_value = value + else: + debug_annotation.string_value = str(value) + packet.track_event.debug_annotations.append(debug_annotation) + + proto.write_trace_packet(output, packet) + + +def write_chrome_metadata(output, clock_domain): + """Write a chrome trace event with metadata. + + Args: + output: a file-like object to write events into. + clock_domain: a string representing the trace clock domain. + """ + chrome_metadata = proto.ChromeMetadata() + chrome_metadata.name = 'clock-domain' + chrome_metadata.string_value = clock_domain + chrome_event = proto.ChromeEventBundle() + chrome_event.metadata.append(chrome_metadata) + packet = proto.TracePacket() + packet.chrome_event = chrome_event proto.write_trace_packet(output, packet) @@ -145,8 +169,8 @@ def write_metadata( story_tags, story_run_index, label=None, - had_failures=None, ): + """Write a ChromeBenchmarkMetadata message.""" metadata = proto.ChromeBenchmarkMetadata() metadata.benchmark_start_time_us = int(benchmark_start_time_us) metadata.story_run_time_us = int(story_run_time_us) @@ -157,10 +181,39 @@ def write_metadata( metadata.story_run_index = int(story_run_index) if label is not None: metadata.label = label - if had_failures is not None: - metadata.had_failures = had_failures packet = proto.TracePacket() packet.chrome_benchmark_metadata = metadata proto.write_trace_packet(output, packet) + +def write_clock_snapshot( + output, + tid, + telemetry_ts=None, + boottime_ts=None, +): + """Write a ClockSnapshot message. + + Note that this function is NOT thread-safe. + + Args: + output: a file-like object to write events into. + telemetry_ts: host BOOTTIME timestamp in microseconds. + boottime_ts: device BOOTTIME timestamp in microseconds. + """ + clock_snapshot = proto.ClockSnapshot() + if telemetry_ts is not None: + clock = proto.Clock() + clock.clock_id = CLOCK_TELEMETRY + clock.timestamp = int(telemetry_ts * 1e3) + clock_snapshot.clocks.append(clock) + if boottime_ts is not None: + clock = proto.Clock() + clock.clock_id = CLOCK_BOOTTIME + clock.timestamp = int(boottime_ts * 1e3) + clock_snapshot.clocks.append(clock) + packet = proto.TracePacket() + packet.trusted_packet_sequence_id = _get_sequence_id(tid) + packet.clock_snapshot = clock_snapshot + proto.write_trace_packet(output, packet) diff --git a/catapult/common/py_trace_event/py_trace_event/trace_event_impl/perfetto_trace_writer_unittest.py b/catapult/common/py_trace_event/py_trace_event/trace_event_impl/perfetto_trace_writer_unittest.py index e49a0a4b..00dafa46 100644 --- a/catapult/common/py_trace_event/py_trace_event/trace_event_impl/perfetto_trace_writer_unittest.py +++ b/catapult/common/py_trace_event/py_trace_event/trace_event_impl/perfetto_trace_writer_unittest.py @@ -15,7 +15,8 @@ class PerfettoTraceWriterTest(unittest.TestCase): TODO(crbug.com/944078): Switch to using python-protobuf library and implement proper protobuf parsing then. """ - + def setUp(self): + perfetto_trace_writer.reset_global_state() def testWriteThreadDescriptorEvent(self): result = StringIO.StringIO() @@ -26,8 +27,8 @@ class PerfettoTraceWriterTest(unittest.TestCase): ts=1556716807306000, ) expected_output = ( - '\n\x17P\x80\x80@\xc8\x02\x01\xe2\x02\r\x08\x01\x10' - '\x020\x90\xf6\xc2\x82\xb6\xfa\xe1\x02' + '\n\x1b@\x80\xec\xea\xda\x83\xb6\xa4\xcd\x15P\x80\x80@' + '\xc8\x02\x01\xe2\x02\x04\x08\x01\x10\x02\xd0\x03@' ) self.assertEqual(expected_output, result.getvalue()) @@ -49,10 +50,11 @@ class PerfettoTraceWriterTest(unittest.TestCase): tid=2, ) expected_output = ( - '\n\x17P\x80\x80@\xc8\x02\x01\xe2\x02\r\x08\x01\x10' - '\x020\x90\xf6\xc2\x82\xb6\xfa\xe1\x02\n2P\x80\x80@Z\x0c\x08' - '\xa0\x8d\x06\x18\x012\x04\x08\x01\x10Mb\x1e\n\x0c\x08\x01' - '\x12\x08category\x12\x0e\x08\x01\x12\nevent_name' + '\n\x1b@\x80\xec\xea\xda\x83\xb6\xa4\xcd\x15P\x80\x80@' + '\xc8\x02\x01\xe2\x02\x04\x08\x01\x10\x02\xd0\x03@\n;@' + '\x80\xb0\xc2\x8a\x84\xb6\xa4\xcd\x15P\x80\x80@Z\x08' + '\x18\x012\x04\x08\x01\x10Mb\x1e\n\x0c\x08\x01\x12\x08' + 'category\x12\x0e\x08\x01\x12\nevent_name\xd0\x03@' ) self.assertEqual(expected_output, result.getvalue()) @@ -68,13 +70,61 @@ class PerfettoTraceWriterTest(unittest.TestCase): story_tags=["foo", "bar"], story_run_index=0, label="label", - had_failures=False, ) expected_output = ( - '\nI\x82\x03F\x08\x90\xf6\xc2\x82\xb6\xfa\xe1' + '\nG\x82\x03D\x08\x90\xf6\xc2\x82\xb6\xfa\xe1' '\x02\x10\xb0\x83\xc9\x82\xb6\xfa\xe1\x02\x1a\tbenchmark"' - '\x0bdescription*\x05label2\x05story:\x03foo:\x03bar@\x00H\x00' + '\x0bdescription*\x05label2\x05story:\x03foo:\x03bar@\x00' + ) + self.assertEqual(expected_output, result.getvalue()) + + def testWriteArgs(self): + result = StringIO.StringIO() + perfetto_trace_writer.write_thread_descriptor_event( + output=result, + pid=1, + tid=2, + ts=0, + ) + perfetto_trace_writer.write_event( + output=result, + ph="M", + category="", + name="", + ts=0, + args={'int': 123, 'double': 1.23, 'string': 'onetwothree'}, + tid=2, + ) + expected_output = ( + '\n\x13@\x00P\x80\x80@\xc8\x02\x01\xe2\x02\x04\x08\x01\x10' + '\x02\xd0\x03@\nT@\x00P\x80\x80@Z;\x18\x01"\x07R\x03int {"\x11' + 'R\x06double)\xaeG\xe1z\x14\xae\xf3?"\x15R\x06string2\x0bonetwothree2' + '\x04\x08\x01\x10Mb\x0c\n\x04\x08\x01\x12\x00\x12\x04\x08\x01\x12\x00' + '\xd0\x03@' ) self.assertEqual(expected_output, result.getvalue()) + def testWriteChromeMetadata(self): + result = StringIO.StringIO() + perfetto_trace_writer.write_chrome_metadata( + output=result, + clock_domain='FOO', + ) + expected_output = ( + '\n\x17*\x15\x12\x13\n\x0cclock-domain\x12\x03FOO' + ) + self.assertEqual(expected_output, result.getvalue()) + def testWriteClockSnapshot(self): + result = StringIO.StringIO() + perfetto_trace_writer.write_clock_snapshot( + output=result, + tid=1, + telemetry_ts=1234.567, + boottime_ts=7654.321, + ) + expected_output = ( + '\n\x172\x11\n\x06\x08@\x10\x87\xadK\n\x07\x08\x06\x10' + '\xb1\x97\xd3\x03P\x80\x80@' + ) + self.assertEqual(expected_output, result.getvalue()) diff --git a/catapult/common/py_trace_event/py_trace_event/trace_event_unittest.py b/catapult/common/py_trace_event/py_trace_event/trace_event_unittest.py index 9916c71d..de7b5947 100644 --- a/catapult/common/py_trace_event/py_trace_event/trace_event_unittest.py +++ b/catapult/common/py_trace_event/py_trace_event/trace_event_unittest.py @@ -512,6 +512,16 @@ class TraceEventTests(unittest.TestCase): story_run_index=0, ) + def testSetClockSnapshotProtobuf(self): + trace_event.trace_set_clock_snapshot( + telemetry_ts=1234.5678, + boottime_ts=8765.4321, + ) + with self._test_trace(format=trace_event.PROTOBUF): + trace_event.trace_disable() + with open(self._log_path, 'r') as f: + self.assertGreater(len(f.read()), 0) + if __name__ == '__main__': logging.getLogger().setLevel(logging.DEBUG) diff --git a/catapult/common/py_trace_event/third_party/protobuf/README.chromium b/catapult/common/py_trace_event/third_party/protobuf/README.chromium index f22d684e..adf4cb8a 100644 --- a/catapult/common/py_trace_event/third_party/protobuf/README.chromium +++ b/catapult/common/py_trace_event/third_party/protobuf/README.chromium @@ -9,4 +9,4 @@ extensible mechanism for serializing structured data. Local Modifications: Removed pretty much everything except functions necessary to write -bools, ints, and strings. +bools, ints, floats and strings. diff --git a/catapult/common/py_trace_event/third_party/protobuf/encoder.py b/catapult/common/py_trace_event/third_party/protobuf/encoder.py index 18aaccdc..50d10465 100644 --- a/catapult/common/py_trace_event/third_party/protobuf/encoder.py +++ b/catapult/common/py_trace_event/third_party/protobuf/encoder.py @@ -29,6 +29,7 @@ # OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE. import six +import struct import wire_format @@ -155,12 +156,93 @@ def _SimpleEncoder(wire_type, encode_value, compute_value_size): return SpecificEncoder +def _FloatingPointEncoder(wire_type, format): + """Return a constructor for an encoder for float fields. + + This is like StructPackEncoder, but catches errors that may be due to + passing non-finite floating-point values to struct.pack, and makes a + second attempt to encode those values. + + Args: + wire_type: The field's wire type, for encoding tags. + format: The format string to pass to struct.pack(). + """ + + value_size = struct.calcsize(format) + if value_size == 4: + def EncodeNonFiniteOrRaise(write, value): + # Remember that the serialized form uses little-endian byte order. + if value == _POS_INF: + write(b'\x00\x00\x80\x7F') + elif value == _NEG_INF: + write(b'\x00\x00\x80\xFF') + elif value != value: # NaN + write(b'\x00\x00\xC0\x7F') + else: + raise + elif value_size == 8: + def EncodeNonFiniteOrRaise(write, value): + if value == _POS_INF: + write(b'\x00\x00\x00\x00\x00\x00\xF0\x7F') + elif value == _NEG_INF: + write(b'\x00\x00\x00\x00\x00\x00\xF0\xFF') + elif value != value: # NaN + write(b'\x00\x00\x00\x00\x00\x00\xF8\x7F') + else: + raise + else: + raise ValueError('Can\'t encode floating-point values that are ' + '%d bytes long (only 4 or 8)' % value_size) + + def SpecificEncoder(field_number, is_repeated, is_packed): + local_struct_pack = struct.pack + if is_packed: + tag_bytes = TagBytes(field_number, wire_format.WIRETYPE_LENGTH_DELIMITED) + local_EncodeVarint = _EncodeVarint + def EncodePackedField(write, value): + write(tag_bytes) + local_EncodeVarint(write, len(value) * value_size) + for element in value: + # This try/except block is going to be faster than any code that + # we could write to check whether element is finite. + try: + write(local_struct_pack(format, element)) + except SystemError: + EncodeNonFiniteOrRaise(write, element) + return EncodePackedField + elif is_repeated: + tag_bytes = TagBytes(field_number, wire_type) + def EncodeRepeatedField(write, value): + for element in value: + write(tag_bytes) + try: + write(local_struct_pack(format, element)) + except SystemError: + EncodeNonFiniteOrRaise(write, element) + return EncodeRepeatedField + else: + tag_bytes = TagBytes(field_number, wire_type) + def EncodeField(write, value): + write(tag_bytes) + try: + write(local_struct_pack(format, value)) + except SystemError: + EncodeNonFiniteOrRaise(write, value) + return EncodeField + + return SpecificEncoder + + Int32Encoder = Int64Encoder = EnumEncoder = _SimpleEncoder( wire_format.WIRETYPE_VARINT, _EncodeSignedVarint, _SignedVarintSize) UInt32Encoder = UInt64Encoder = _SimpleEncoder( wire_format.WIRETYPE_VARINT, _EncodeVarint, _VarintSize) +FloatEncoder = _FloatingPointEncoder(wire_format.WIRETYPE_FIXED32, '<f') + +DoubleEncoder = _FloatingPointEncoder(wire_format.WIRETYPE_FIXED64, '<d') + def BoolEncoder(field_number, is_repeated, is_packed): """Returns an encoder for a boolean field.""" |