def traced_function(*args, **kwargs):
# Everything outside traced_function is done at decoration-time.
# Everything inside traced_function is done at run-time and must be fast.
if not log._enabled: # This check must be at run-time.
return func(*args, **kwargs)
def get_arg_value(name, index, default):
if name in kwargs:
return kwargs[name]
elif index < len(args):
return args[index]
else:
return default
if is_method:
name = "%s.%s" % (args[0].__class__.__name__, func.__name__)
else:
name = "%s.%s" % (func.__module__, func.__name__)
# Be sure to repr before calling func. Argument values may change.
arg_values = {
name: repr(get_arg_value(name, index, default))
for name, index, default in args_to_log
}
start = trace_time.Now()
log.add_trace_event("B", start, category, name, arg_values)
try:
return func(*args, **kwargs)
finally:
end = trace_time.Now()
log.add_trace_event("E", end, category, name)
def trace(name, **kwargs):
category = "python"
start = trace_time.Now()
args_to_log = {key: repr(value) for key, value in kwargs.iteritems()}
log.add_trace_event("B", start, category, name, args_to_log)
try:
yield
finally:
end = trace_time.Now()
log.add_trace_event("E", end, category, name)
def RecordClockSyncMarker(self, sync_id, did_record_sync_marker_callback):
with self._device.adb.PersistentShell(self._device.serial) as shell:
ts_in_controller_domain = trace_time_module.Now()
output = shell.RunCommand(HELPER_COMMAND + ' --echo-ts', close=True)
ts_in_agent_domain = int(output[0][0])
self._clock_sync_markers[sync_id] = ts_in_agent_domain
did_record_sync_marker_callback(ts_in_controller_domain, sync_id)
def RecordClockSyncMarker(self, sync_id,
record_controller_clock_sync_marker_callback):
devtools_clients = (
chrome_tracing_devtools_manager.GetActiveDevToolsClients(
self._platform_backend))
if not devtools_clients:
logging.info('No devtools clients for issuing clock sync.')
return False
has_clock_synced = False
for client in devtools_clients:
try:
timestamp = trace_time.Now()
client.RecordChromeClockSyncMarker(sync_id)
# We only need one successful clock sync.
has_clock_synced = True
break
except Exception: # pylint: disable=broad-except
logging.exception(
'Failed to record clock sync marker with sync_id=%r '
'via DevTools client %r:', sync_id, client)
if not has_clock_synced:
raise ChromeClockSyncError(
'Failed to issue clock sync to devtools client')
record_controller_clock_sync_marker_callback(sync_id, timestamp)
return True
def RecordClockSyncMarker(self, sync_id, did_record_clock_sync_callback):
cmd = 'cat /proc/timer_list | grep now'
t1 = trace_time_module.Now()
command_result = self._device_utils.RunShellCommand(cmd, shell=True)
nsec = command_result[0].split()[2]
self._clock_sync_marker = format_clock_sync_marker(sync_id, nsec)
did_record_clock_sync_callback(t1, sync_id)
def _KeepTakingSnapshots(self):
"""Take CPU snapshots every SNAPSHOT_FREQUENCY seconds."""
if not self._snapshot_ongoing:
return
# Assume CpuTracingAgent shares the same clock domain as telemetry
self._snapshots.append((self._parser.GetProcesses(), trace_time.Now()))
Timer(self.SNAPSHOT_FREQUENCY, self._KeepTakingSnapshots).start()
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_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=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)
from py_trace_event import checkFileCode
encoding = checkFileCode(_log_file)
print str(encoding)
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,
encoding=encoding)
_log_file.write('\n')
def testGetWinNowFunction_QPC(self):
if not (sys.platform.startswith(trace_time._PLATFORMS['windows'])
or sys.platform.startswith(trace_time._PLATFORMS['cygwin'])):
return True
# Test requires QPC to be available on platform.
if not trace_time.IsQPCUsable():
return True
self.assertGreater(trace_time.Now(), 0)
def _IssueClockSyncMarker(self):
with self._DisableGarbageCollection():
for agent in self._active_agents_instances:
if agent.SupportsExplicitClockSync():
sync_id = self._GenerateClockSyncId()
ts = trace_time.Now()
agent.RecordClockSyncMarker(sync_id)
self._RecordIssuerClockSyncMarker(sync_id, ts)
def _SaveTraceData(self, trace_device_file, device, test_class):
trace_host_file = self._env.trace_output
if device.FileExists(trace_device_file.name):
try:
java_trace_json = device.ReadFile(trace_device_file.name)
except IOError:
raise Exception('error pulling trace file from device')
finally:
trace_device_file.close()
process_name = '%s (device %s)' % (test_class, device.serial)
process_hash = int(hashlib.md5(process_name).hexdigest()[:6], 16)
java_trace = json.loads(java_trace_json)
java_trace.sort(key=lambda event: event['ts'])
get_date_command = 'echo $EPOCHREALTIME'
device_time = device.RunShellCommand(get_date_command, single_line=True)
device_time = float(device_time) * 1e6
system_time = trace_time.Now()
time_difference = system_time - device_time
threads_to_add = set()
for event in java_trace:
# Ensure thread ID and thread name will be linked in the metadata.
threads_to_add.add((event['tid'], event['name']))
event['pid'] = process_hash
# Adjust time stamp to align with Python trace times (from
# trace_time.Now()).
event['ts'] += time_difference
for tid, thread_name in threads_to_add:
thread_name_metadata = {'pid': process_hash, 'tid': tid,
'ts': 0, 'ph': 'M', 'cat': '__metadata',
'name': 'thread_name',
'args': {'name': thread_name}}
java_trace.append(thread_name_metadata)
process_name_metadata = {'pid': process_hash, 'tid': 0, 'ts': 0,
'ph': 'M', 'cat': '__metadata',
'name': 'process_name',
'args': {'name': process_name}}
java_trace.append(process_name_metadata)
java_trace_json = json.dumps(java_trace)
java_trace_json = java_trace_json.rstrip(' ]')
with open(trace_host_file, 'r') as host_handle:
host_contents = host_handle.readline()
if host_contents:
java_trace_json = ',%s' % java_trace_json.lstrip(' [')
with open(trace_host_file, 'a') as host_handle:
host_handle.write(java_trace_json)
def _KeepTakingSnapshots(self):
"""Take CPU snapshots every SNAPSHOT_FREQUENCY seconds."""
if not self._snapshot_ongoing:
return
# Assume CpuTracingAgent shares the same clock domain as telemetry
self._snapshots.append(
(self._collector.GetProcesses(), trace_time.Now()))
interval = self._SNAPSHOT_INTERVAL_BY_OS[self._os_name]
Timer(interval, self._KeepTakingSnapshots).start()
def clock_sync(sync_id, issue_ts=None):
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
# Convert to right units for ts.
args_to_log['issue_ts'] = issue_ts
trace_event_impl.add_trace_event("c", time_stamp, "python",
"clock_sync", args_to_log)
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')
def RecordClockSyncMarker(self, sync_id, did_record_sync_marker_callback):
"""Records a clock sync marker.
Args:
sync_id: ID string for clock sync marker.
did_record_sync_marker_callback: Callback function to call after
the clock sync marker is recorded.
"""
ts = trace_time.Now()
self._battor_wrapper.RecordClockSyncMarker(sync_id)
did_record_sync_marker_callback(ts, sync_id)
def RecordClockSyncMarker(self, sync_id, did_record_sync_marker_callback):
"""Records a clock sync marker.
Args:
sync_id: ID string for clock sync marker.
"""
cmd = 'echo name=%s > /sys/kernel/debug/tracing/trace_marker' % sync_id
with self._device_utils.adb.PersistentShell(
self._device_serial_number) as shell:
t1 = trace_time.Now()
shell.RunCommand(cmd, close=True)
did_record_sync_marker_callback(t1, sync_id)
def RecordClockSyncMarker(self, sync_id,
record_controller_clock_sync_marker_callback):
"""Records a clock sync marker in the BattOr trace.
Args:
sync_id: Unique id for sync event.
record_controller_clock_sync_marker_callback: Function that takes a sync
ID and a timestamp as arguments. This function typically will record the
tracing controller clock sync marker.
"""
timestamp = trace_time.Now()
self._battor.RecordClockSyncMarker(sync_id)
record_controller_clock_sync_marker_callback(sync_id, timestamp)
def RecordClockSyncMarker(self, sync_id, did_record_sync_marker_callback):
"""Records a clock sync marker.
Args:
sync_id: ID string for clock sync marker.
"""
cmd = 'echo trace_event_clock_sync: name=%s >' \
' %s/trace_marker' % (sync_id, self._tracing_path)
with self._device_utils.adb.PersistentShell(
self._device_serial_number) as shell:
t1 = trace_time_module.Now()
shell.RunCommand(cmd, close=True)
did_record_sync_marker_callback(t1, sync_id)
def _trace_enable(log_file=None):
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]
log_file = open("%s.json" % n, "ab", False)
_note("trace_event: tracelog name is %s.json" % n)
elif isinstance(log_file, basestring):
_note("trace_event: tracelog name is %s" % log_file)
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()"
)
_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)
_log_file.write('[')
tid = threading.current_thread().ident
if not tid:
tid = os.getpid()
x = {
"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.write("%s\n" % json.dumps(x))
else:
_note("trace_event: Opened existing tracelog")
_log_file.flush()
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 testClockSyncWithTs(self):
with self._test_trace():
with open(self._log_path, 'r') as f:
trace_event.clock_sync('id', issue_ts=trace_time.Now())
trace_event.trace_flush()
log_output = json.loads(f.read() + ']')
self.assertEquals(len(log_output), 2)
current_entry = log_output.pop(0)
self.assertEquals(current_entry['category'], 'process_argv')
self.assertEquals(current_entry['name'], 'process_argv')
self.assertTrue(current_entry['args']['argv'])
self.assertEquals(current_entry['ph'], 'M')
current_entry = log_output.pop(0)
self.assertEquals(current_entry['category'], 'python')
self.assertEquals(current_entry['name'], 'clock_sync')
self.assertTrue(current_entry['args']['issue_ts'])
self.assertEquals(current_entry['ph'], 'c')
def _RecordClockSyncMarkerAsyncEvent(
self, sync_id, record_controller_clock_sync_marker_callback):
has_clock_synced = False
for backend in self._IterInspectorBackends():
try:
timestamp = trace_time.Now()
backend.EvaluateJavaScript(
"console.time('ClockSyncEvent.%s');" % sync_id)
backend.EvaluateJavaScript(
"console.timeEnd('ClockSyncEvent.%s');" % sync_id)
has_clock_synced = True
break
except Exception:
pass
if not has_clock_synced:
raise ChromeClockSyncError()
record_controller_clock_sync_marker_callback(sync_id, timestamp)
def _RecordClockSyncMarkerAsyncEvent(
self, sync_id, record_controller_clock_sync_marker_callback):
has_clock_synced = False
for backend in self._IterFirstTabBackends():
try:
timestamp = trace_time.Now()
backend.AddTimelineMarker('ClockSyncEvent.%s' % sync_id)
has_clock_synced = True
break
except Exception: # pylint: disable=broad-except
logging.exception(
'Failed to record clock sync marker with sync_id=%r '
'via inspector backend %r:', sync_id, backend)
if not has_clock_synced:
raise ChromeClockSyncError(
'Failed to issue clock sync to devtools client')
record_controller_clock_sync_marker_callback(sync_id, timestamp)
def __init__(self, platform_backend):
super(TelemetryTracingAgent, self).__init__(platform_backend)
self._trace_file = None
# When tracing Chrome on Android, Telemetry and the browser run on
# different devices. The trace_set_clock_snapshot() function provides
# a clock snapshot for the perfetto trace processor to synchronize
# host and device clocks.
if platform_backend and platform_backend.GetOSName() == 'android':
telemetry_ts = trace_time.Now()
device_uptime = platform_backend.device.RunShellCommand(
['cat', '/proc/uptime'], single_line=True)
boottime_ts = float(device_uptime.split(' ')[0]) * 1e6
trace_event.trace_set_clock_snapshot(
telemetry_ts=telemetry_ts,
boottime_ts=boottime_ts,
)
def _RecordClockSyncMarkerDevTools(
self, sync_id, record_controller_clock_sync_marker_callback,
devtools_clients):
has_clock_synced = False
for client in devtools_clients:
try:
timestamp = trace_time.Now()
client.RecordChromeClockSyncMarker(sync_id)
# We only need one successful clock sync.
has_clock_synced = True
break
except Exception:
logging.exception(
'Failed to record clock sync marker with sync_id=%r '
'via DevTools client %r:' % (sync_id, client))
if not has_clock_synced:
raise ChromeClockSyncError(
'Failed to issue clock sync to devtools client')
record_controller_clock_sync_marker_callback(sync_id, timestamp)
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 RecordClockSyncMarker(self, sync_id,
record_controller_clock_sync_marker_callback):
"""Records a clock sync marker in the BattOr trace.
Args:
sync_id: Unique id for sync event.
record_controller_clock_sync_marker_callback: Function that takes a sync
ID and a timestamp as arguments. This function typically will record the
tracing controller clock sync marker.
"""
timestamp = trace_time.Now()
try:
self._battor.RecordClockSyncMarker(sync_id)
except battor_error.BattOrError:
logging.critical(
'Error while clock syncing with BattOr. Killing BattOr shell.')
self._battor.KillBattOrShell()
raise
record_controller_clock_sync_marker_callback(sync_id, timestamp)
def _RecordClockSyncMarkerDevTools(
self, sync_id, record_controller_clock_sync_marker_callback,
devtools_clients):
has_clock_synced = False
if not devtools_clients:
raise ChromeClockSyncError()
for client in devtools_clients:
try:
timestamp = trace_time.Now()
client.RecordChromeClockSyncMarker(sync_id)
# We only need one successful clock sync.
has_clock_synced = True
break
except Exception:
pass
if not has_clock_synced:
raise ChromeClockSyncError()
record_controller_clock_sync_marker_callback(sync_id, timestamp)
def _RecordClockSyncMarkerAsyncEvent(
self, sync_id, record_controller_clock_sync_marker_callback):
has_clock_synced = False
for backend in self._IterInspectorBackends():
try:
timestamp = trace_time.Now()
backend.EvaluateJavaScript(
"console.time('ClockSyncEvent.%s');" % sync_id)
backend.EvaluateJavaScript(
"console.timeEnd('ClockSyncEvent.%s');" % sync_id)
has_clock_synced = True
break
except Exception:
logging.exception(
'Failed to record clock sync marker with sync_id=%r '
'via inspector backend %r:' % (sync_id, backend))
if not has_clock_synced:
raise ChromeClockSyncError(
'Failed to issue clock sync to devtools client')
record_controller_clock_sync_marker_callback(sync_id, timestamp)
def trace_set_thread_name(thread_name):
trace_event_impl.add_trace_event("M", trace_time.Now(), "__metadata",
"thread_name", {"name": thread_name})
def trace_end(name):
trace_event_impl.add_trace_event("E", trace_time.Now(), "python", name)
