xref: /external/chromium-trace/catapult/common/py_trace_event/py_trace_event/trace_event_impl/log.py

# Copyright 2016 The Chromium Authors. All rights reserved.
# Use of this source code is governed by a BSD-style license that can be
# found in the LICENSE file.
import atexit
import json
import os
import sys
import time
import threading
import multiprocessing
import multiprocessing_shim

from py_trace_event.trace_event_impl import perfetto_trace_writer
from py_trace_event import trace_time

from py_utils import lock


# Trace file formats:

# Legacy format: json list of events.
# Events can be written from multiple processes, but since no process
# can be sure that it is the last one, nobody writes the closing ']'.
# So the resulting file is not technically correct json.
JSON = "json"

# Full json with events and metadata.
# This format produces correct json ready to feed into TraceDataBuilder.
# Note that it is the responsibility of the user of py_trace_event to make sure
# that trace_disable() is called after all child processes have finished.
JSON_WITH_METADATA = "json_with_metadata"

# Perfetto protobuf trace format.
PROTOBUF = "protobuf"


_lock = threading.Lock()

_enabled = False
_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

_control_allowed = True

_original_multiprocessing_process = multiprocessing.Process

class TraceException(Exception):
  pass

def _note(msg, *args):
  pass
#  print "%i: %s" % (os.getpid(), msg)


def _locked(fn):
  def locked_fn(*args,**kwargs):
    _lock.acquire()
    try:
      ret = fn(*args,**kwargs)
    finally:
      _lock.release()
    return ret
  return locked_fn

def _disallow_tracing_control():
  global _control_allowed
  _control_allowed = False

def trace_enable(log_file=None, format=None):
  """Enable tracing.

  Args:
    log_file: file to write trace into. Can be a file-like object,
      a name of file, or None. If None, file name is constructed
      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():
  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(),
        tid=tid,
        ts=trace_time.Now(),
    )
    perfetto_trace_writer.write_event(
        output=_log_file,
        ph="M",
        category="process_argv",
        name="process_argv",
        ts=trace_time.Now(),
        args={"argv": sys.argv},
        tid=tid,
    )
  else:
    if _format == JSON:
      _log_file.write('[')
    elif _format == JSON_WITH_METADATA:
      _log_file.write('{"traceEvents": [\n')
    else:
      raise TraceException("Unknown format: %s" % _format)
    json.dump({
        "ph": "M",
        "category": "process_argv",
        "pid": os.getpid(),
        "tid": threading.current_thread().ident,
        "ts": trace_time.Now(),
        "name": "process_argv",
        "args": {"argv": sys.argv},
    }, _log_file)
    _log_file.write('\n')


@_locked
def _trace_enable(log_file=None, format=None):
  global _format
  _format = format
  global _enabled
  if _enabled:
    raise TraceException("Already enabled")
  if not _control_allowed:
    raise TraceException("Tracing control not allowed in child processes.")
  _enabled = True
  global _log_file
  if log_file == None:
    if sys.argv[0] == '':
      n = 'trace_event'
    else:
      n = sys.argv[0]
    if _format == PROTOBUF:
      log_file = open("%s.pb" % n, "ab", False)
    else:
      log_file = open("%s.json" % n, "ab", False)
  elif isinstance(log_file, basestring):
    log_file = open("%s" % log_file, "ab", False)
  elif not hasattr(log_file, 'fileno'):
    raise TraceException(
        "Log file must be None, a string, or file-like object with a fileno()")

  _note("trace_event: tracelog name is %s" % log_file)

  _log_file = log_file
  with lock.FileLock(_log_file, lock.LOCK_EX):
    _log_file.seek(0, os.SEEK_END)

    lastpos = _log_file.tell()
    creator = lastpos == 0
    if creator:
      _note("trace_event: Opened new tracelog, lastpos=%i", lastpos)
      _write_header()
    else:
      _note("trace_event: Opened existing tracelog")
    _log_file.flush()
  # Monkeypatch in our process replacement for the multiprocessing.Process class
  if multiprocessing.Process != multiprocessing_shim.ProcessShim:
      multiprocessing.Process = multiprocessing_shim.ProcessShim

@_locked
def trace_flush():
  if _enabled:
    _flush()

@_locked
def trace_disable():
  global _enabled
  if not _control_allowed:
    raise TraceException("Tracing control not allowed in child processes.")
  if not _enabled:
    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():
  if _format == PROTOBUF:
    for e in _cur_events:
      perfetto_trace_writer.write_event(
          output=_log_file,
          ph=e["ph"],
          category=e["category"],
          name=e["name"],
          ts=e["ts"],
          args=e["args"],
          tid=threading.current_thread().ident,
      )
  elif _format in (JSON, JSON_WITH_METADATA):
    for e in _cur_events:
      _log_file.write(",\n")
      json.dump(e, _log_file)
  else:
    raise TraceException("Unknown format: %s" % _format)
  del _cur_events[:]

def _write_footer():
  if _format in [JSON, PROTOBUF]:
    # In JSON format we might not be the only process writing to this logfile.
    # So, we will simply close the file rather than writing the trailing ] that
    # it technically requires. The trace viewer understands this and
    # will insert a trailing ] during loading.
    # In PROTOBUF format there's no need for a footer. The metadata has already
    # been written in a special proto message.
    pass
  elif _format == JSON_WITH_METADATA:
    _log_file.write('],\n"metadata": ')
    json.dump(_benchmark_metadata, _log_file)
    _log_file.write('}')
  else:
    raise TraceException("Unknown format: %s" % _format)

def _flush(close=False):
  global _log_file
  with lock.FileLock(_log_file, lock.LOCK_EX):
    _log_file.seek(0, os.SEEK_END)
    if len(_cur_events):
      _write_cur_events()
    if close:
      _write_footer()
    _log_file.flush()

  if close:
    _note("trace_event: Closed")
    _log_file.close()
    _log_file = None
  else:
    _note("trace_event: Flushed")

@_locked
def trace_is_enabled():
  return _enabled

@_locked
def add_trace_event(ph, ts, category, name, args=None):
  global _enabled
  if not _enabled:
    return
  if not hasattr(_tls, 'pid') or _tls.pid != os.getpid():
    _tls.pid = os.getpid()
    global _atexit_regsitered_for_pid
    if _tls.pid != _atexit_regsitered_for_pid:
      _atexit_regsitered_for_pid = _tls.pid
      atexit.register(_trace_disable_atexit)
      _tls.pid = os.getpid()
      del _cur_events[:] # we forked, clear the event buffer!
    tid = threading.current_thread().ident
    if not tid:
      tid = os.getpid()
    _tls.tid = tid

  _cur_events.append({
      "ph": ph,
      "category": category,
      "pid": _tls.pid,
      "tid": _tls.tid,
      "ts": ts,
      "name": name,
      "args": args or {},
  });

def trace_begin(name, args=None):
  add_trace_event("B", trace_time.Now(), "python", name, args)

def trace_end(name, args=None):
  add_trace_event("E", trace_time.Now(), "python", name, args)

def trace_set_thread_name(thread_name):
  add_trace_event("M", trace_time.Now(), "__metadata", "thread_name",
                  {"name": thread_name})

def trace_add_benchmark_metadata(
    benchmark_start_time_us,
    story_run_time_us,
    benchmark_name,
    benchmark_description,
    story_name,
    story_tags,
    story_run_index,
    label=None,
):
  """Add benchmark metadata to be written to trace file.

  Args:
    benchmark_start_time_us: Benchmark start time in microseconds.
    story_run_time_us: Story start time in microseconds.
    benchmark_name: Name of the benchmark.
    benchmark_description: Description of the benchmark.
    story_name: Name of the story.
    story_tags: List of story tags.
    story_run_index: Index of the story run.
    label: Optional label.
    had_failures: Whether this story run failed.
  """
  global _benchmark_metadata
  if _format == PROTOBUF:
    # Write metadata immediately.
    perfetto_trace_writer.write_metadata(
        output=_log_file,
        benchmark_start_time_us=benchmark_start_time_us,
        story_run_time_us=story_run_time_us,
        benchmark_name=benchmark_name,
        benchmark_description=benchmark_description,
        story_name=story_name,
        story_tags=story_tags,
        story_run_index=story_run_index,
        label=label,
    )
    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 = {
        "benchmarkStart": benchmark_start_time_us / 1000.0,
        "traceStart": story_run_time_us / 1000.0,
        "benchmarks": [benchmark_name],
        "benchmarkDescriptions": [benchmark_description],
        "stories": [story_name],
        "storyTags": story_tags,
        "storysetRepeats": [story_run_index],
    }
    if label:
      telemetry_metadata_for_json["labels"] = [label]

    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
        # domain. Telemetry isn't really a clock domain, though: it's a
        # system that USES a clock domain like LINUX_CLOCK_MONOTONIC or
        # WIN_QPC. However, there's a chance that a Telemetry controller
        # running on Linux (using LINUX_CLOCK_MONOTONIC) is interacting
        # with an Android phone (also using LINUX_CLOCK_MONOTONIC, but
        # on a different machine). The current logic collapses clock
        # domains based solely on the clock domain string, but we really
        # should to collapse based on some (device ID, clock domain ID)
        # tuple. Giving Telemetry its own clock domain is a work-around
        # for this.
        "clock-domain": "TELEMETRY",
        "telemetry": telemetry_metadata_for_json,
    }
  elif _format == JSON:
    raise TraceException("Can't write metadata in JSON format")
  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()

def is_tracing_controllable():
  global _control_allowed
  return _control_allowed