def arguments(self, time, pid, tid, args):
thread = self.callbacks.process(pid).thread(tid)
if thread.task_stack:
for n, value in enumerate(args):
thread.task_stack[-1].add_args({n: int(value)})
else:
message('warning', "Orphan args: " + str(args))
def unpack_catapult(bindir):
path = os.path.join(bindir, 'catapult', 'tracing')
if os.path.exists(path):
message('info', 'Catapult is taken from: ' + path)
return path
zip_path = os.path.join(bindir, 'catapult.zip')
if os.path.exists(zip_path):
print("Extracting catapult...")
from zipfile import PyZipFile
pzf = PyZipFile(zip_path)
pzf.extractall(bindir)
return path
else:
print("Error: Catapult is not found at", zip_path)
return None
def add_tid_name(self, tid, name):
if name == 'kernel_task':
return
# one of the tids is equal to pid, and all threads have the same name as process (if not renamed)
pid = self.tid_map[tid] if tid in self.tid_map else tid
if abs(pid) < 4:
return
if pid not in self.pid_names:
self.pid_names[pid] = [name]
elif name not in self.pid_names[pid]:
assert abs(pid) > 100
self.pid_names[pid].append(name)
full_name = '->'.join(self.pid_names[pid])
message('warning', 'Pid %d name changed: %s' % (pid, full_name))
def complete_task(self, type, begin, end):
if self.args.distinct:
if self.last_task == (type, begin, end):
return
self.last_task = (type, begin, end)
assert (type in GoogleTrace.Phase)
if begin['type'] == 7: # frame_begin
if 'id' not in begin:
begin['id'] = id(
begin) # Async events are groupped by cat & id
res = self.format_task('b', 'frame', begin, {})
if end:
res += [',\n']
end_begin = begin.copy()
end_begin['time'] = end['time'] - 1000
if 'args' in end:
end_begin['args'] = end['args']
res += self.format_task('e', 'frame', end_begin, {})
else:
res = self.format_task(GoogleTrace.Phase[type], type, begin, end)
if not res:
return
if type in [
'task', 'counter'
] and 'data' in begin and 'str' in begin: # FIXME: move closer to the place where stack is demanded
self.handle_stack(
begin, resolve_stack(self.args, self.tree, begin['data']),
'%s:%s' % (begin['domain'], type))
if self.args.debug and begin['type'] != 7:
res = "".join(res)
try:
json.loads(res)
except Exception as exc:
import traceback
print("\n" + exc.message + ":\n" + res + "\n")
traceback.print_stack()
self.format_task(GoogleTrace.Phase[type], type, begin, end)
res += ',\n'
else:
res = "".join(res + [',\n'])
self.file.write(res)
if self.file.tell() > MAX_GT_SIZE:
self.finish(intermediate=True)
self.start_new_trace()
message('warning',
'Chrome Trace File Limit Exceeded on %d' % end['time'])
def stop(self, wait=True):
for name, data in self.processes.items():
print('Stopping:', name)
pids = [data['pid']] + list(self.get_pid_children(data['pid']))
for pid in pids:
self.sudo_execute("kill -2 %d" % pid)
for pid in pids:
try:
os.waitpid(pid, 0)
except:
pass
if not data['proc']:
continue
out, err = data['proc'].communicate()
message(None, "\n\n -= Target %s output =- {\n" % name)
if out:
self.log("Trace %s out:\n%s" % (name, out.decode()))
message(None, out.strip())
message(None, "-" * 50)
if err:
self.log("Trace %s err:\n%s" % (name, err.decode()), True)
message(None, err.strip())
message(None, "}\n\n")
if data['proc'].returncode != 0:
message('error', '%s(%d) has exited with error code %d check logs for details' % (name, data['pid'], data['proc'].returncode))
for subcollector in self.subcollectors:
print('Stopping:', subcollector)
subcollector.collect(self, False)
self.times.append(datetime.now())
sys_log = os.path.join(self.args.output, 'sys_log.json')
with open(sys_log, 'w') as file:
cmd = 'log show --source --style json --debug --signpost' # --last 1m --start, --end 'YYYY-MM-DD HH:MM:SS'
cmd += self.times[1].strftime(" --end '%Y-%m-%d %H:%M:%S'")
if self.args.ring:
cmd += (self.times[1] - timedelta(seconds=self.args.ring)).strftime(" --start '%Y-%m-%d %H:%M:%S'")
else:
cmd += self.times[0].strftime(" --start '%Y-%m-%d %H:%M:%S'")
self.execute(cmd, stdout=file) # FIXME: get time of collection or ring size
self.collect_system_info()
self.collect_codes()
res = self.files + [sys_log]
return res
def transform_dtrace(args):
if not os.path.exists(args.input):
message('error', 'File not found: ' + args.input)
return []
tree = default_tree(args)
tree['ring_buffer'] = True
args.no_left_overs = True
gt = get_exporters()['gt']
with Callbacks(args, tree) as callbacks:
if callbacks.is_empty():
return callbacks.get_result()
dtrace = DTrace(args, gt, callbacks)
size = os.path.getsize(args.input)
with Progress(
size, 50, "Parsing: %s (%s)" %
(os.path.basename(args.input), format_bytes(size))) as progress:
count = 0
with codecs.open(args.input, 'r', 'utf-8',
errors='ignore') as file:
reading_stack = None
stack = []
stat = None
for line in file:
count += 1
ends_with_vt = (11 == ord(
line[-1])) if len(line) else False
#old_line = line
line = line.strip('\r\n')
#print("%d\t%s" % (count, line))
if not line:
if reading_stack:
dtrace.handle_stack(*(reading_stack + [stack]))
reading_stack = None
stack = []
continue
if stat is not None:
parts = line.split()
dtrace.handle_stat(parts[0], ' '.join(parts[1:-1]),
parts[-1])
continue
if reading_stack:
if ends_with_vt: # Vertical Tab signifies too long stack frame description
line += '...'
end_of_line = file.readline(
) # it is also treated as line end by codecs.open
line += end_of_line.strip()
stack.append(line.replace('\t', ' '))
continue
parts = line.split('\t')
if len(parts) < 4:
if '-=STATS=-' in parts:
stat = {}
else:
message('warning', "weird line:" + line)
continue
if parts[1] in ['ustack', 'kstack', 'jstack']:
reading_stack = [
int(parts[0], 16), parts[1], parts[2],
parts[3].rstrip(':')
]
continue
dtrace.handle_record(int(parts[0], 16), parts[1],
parts[2:])
if not count % 1000:
progress.tick(file.tell())
dtrace.finalize()
return callbacks.get_result()
def gpu_call(self, time, cmd, pid, tid, args):
if 'PrepareQueueKMD' == cmd:
if len(args) == 3:
ctx_id, stamp, ctx_type = args
ring_type, channel = '0', '0'
else:
ctx_id, ctx_type, ring_type, channel, stamp = args
ctx_type = self.map_context_type(ctx_type)
self.contexts[ctx_id] = ctx_type
self.append_stage(ring_type, channel, int(stamp, 16), locals())
elif 'SubmitQueueKMD' == cmd:
if len(args) == 7:
ctx_id, ctx_type, ring_type, channel, stamp, umd_submission_id, umd_call_count = args
else:
ctx_id, stamp, ctx_type, umd_submission_id, umd_call_count = args
ring_type, channel = '0', '0'
ctx_type = self.map_context_type(ctx_type)
self.contexts[ctx_id] = ctx_type
self.append_stage(ring_type, channel, int(stamp, 16), locals())
elif 'SubmitToRing' == cmd:
if len(args) == 4:
ctx_id, ring_type, channel, stamp = args
else:
ctx_id, stamp, ring_type = args
channel = '0'
self.append_stage(ring_type, channel, int(stamp, 16), locals())
elif 'SubmitBatchBuffer' == cmd:
if len(args) == 4:
ctx_id, ring_type, channel, stamp = args
else:
ctx_id, stamp, ring_type = args
channel = '0'
self.append_stage(ring_type, channel, int(stamp, 16), locals())
elif 'SubmitExecList' == cmd:
ctx_id, ring_type, channel, stamp = args
self.append_stage(ring_type, channel, int(stamp, 16), locals())
elif 'CompleteExecute' == cmd:
if len(args) == 2:
ring_type, latest_stamp = args
channel = '0'
else:
ring_type, channel, latest_stamp = args
self.complete_stage(ring_type, channel, int(latest_stamp, 16),
locals())
elif 'CompleteExecList' == cmd:
ctx_id, ring_type, channel, latest_stamp, ctx_run_time = args
self.complete_stage(ring_type, channel, int(latest_stamp, 16),
locals())
elif 'WriteStamp' == cmd:
ctx_id, ring_type, channel, stamp = args
self.append_stage(ring_type, channel, int(stamp, 16), locals())
elif 'RemoveQueueKMD' == cmd:
if len(args) == 2:
ring_type, latest_stamp = args
channel = '0'
else:
ring_type, channel, latest_stamp = args
self.complete_stage(ring_type, channel, int(latest_stamp, 16),
locals())
elif 'SwCtxCreation' == cmd:
ctx_id, ctx_type = args
ctx_type = self.map_context_type(ctx_type)
self.contexts[ctx_id] = ctx_type
elif 'SwCtxDestroy' == cmd:
ctx_id, ctx_type = args
ctx_type = self.map_context_type(ctx_type)
self.contexts[ctx_id] = ctx_type
elif 'DidFlip' == cmd:
self.callbacks.vsync(time)
elif 'BeginExecOnGPU' == cmd:
cpu_time, ctx_id, ring_type, channel, stamp = args
if cpu_time[0] == 'f':
message('error',
"BeginExecOnGPU has wrong timestamp: " + str(args))
return
cpu_time = int(cpu_time, 16)
if not cpu_time:
if self.args.debug:
print("Warning: zero timestamp: ", cmd, args)
return
thread = self.callbacks.process(-1).thread(int(ctx_id, 16))
ring = self.map_ring_type(ring_type)
""" FIXME: fix lanes
thread.lane('GPU:Render', 'dth').frame_begin(cpu_time, ring,args={
'ring': ring, 'stamp': stamp, 'channel': int(channel, 16), 'ctx_id': int(ctx_id, 16)
})
"""
thread.task_pool[(ring_type, channel, stamp)] = thread.frame(
"GPU (%d)" % thread.tid, 'dth').begin(cpu_time,
args={
'ring':
ring,
'stamp':
stamp,
'channel':
int(channel, 16),
'ctx_id':
int(ctx_id, 16)
})
"""
thread.task_pool[(ring_type, channel, stamp)] = thread.task("GPU:" + ring, 'dth').begin(cpu_time, args={
'ring': ring, 'stamp': stamp, 'channel': int(channel, 16), 'ctx_id': int(ctx_id, 16)
})
"""
elif 'EndExecOnGPU' == cmd:
cpu_time, ctx_id, ring_type, channel, stamp = args
if cpu_time[0] == 'f':
message('error',
"EndExecOnGPU has wrong timestamp: " + str(args))
return
cpu_time = int(cpu_time, 16)
if not cpu_time:
if self.args.debug:
print("Warning: zero timestamp: ", cmd, args)
return
thread = self.callbacks.process(-1).thread(int(ctx_id, 16))
if (ring_type, channel, stamp) in thread.task_pool:
thread.task_pool[(ring_type, channel, stamp)].end(cpu_time)
del thread.task_pool[(ring_type, channel, stamp)]
else:
print("Unhandled gpu_call:", cmd)
def complete_stage(self, ring_type, channel, latest_stamp, data):
stamps = self.event_tracker.setdefault((ring_type, channel), {})
to_del = set(stamp for stamp in stamps.keys() if stamp <= latest_stamp)
if len(
to_del
) < 100: # in old driver with GuC the CompleteExecute might be called so rare that it is not reliable at all
for stamp, stages in stamps.items():
if stamp <= latest_stamp:
verbose = ['%s(%s) %d:' % (ring_type, channel, stamp)]
ctx_type = None
old_ctx_id = None
changed_context = False
for stage in stages:
verbose.append(stage['cmd'])
if 'ctx_id' in stage:
changed_context = old_ctx_id and old_ctx_id != stage[
'ctx_id']
verbose.append('(%s)' %
(('!' if changed_context else '') +
stage['ctx_id']))
old_ctx_id = stage['ctx_id']
if 'ctx_type' in stage:
assert ctx_type == stage[
'ctx_type'] or not ctx_type or changed_context
ctx_type = stage['ctx_type']
if not ctx_type and old_ctx_id:
ctx_type = self.contexts[
old_ctx_id] if old_ctx_id in self.contexts else None
if ctx_type:
verbose.append('%s - %s' % (data['cmd'], ctx_type))
else:
verbose.append(data['cmd'])
message('info', 'verbose: ' + ' '.join(verbose))
if not changed_context: # not sure what TODO with it yet
gpu_task = self.complete_gpu(stages[-1], data,
ctx_type, old_ctx_id)
found_submit = False
cpu_task = None
for stage in stages:
if stage['cmd'] in [
'SubmitQueueKMD', 'WriteStamp'
]:
found_submit = True
cpu_task = self.complete_cpu(
stage, data, ctx_type, old_ctx_id,
gpu_task)
break
for stage in stages:
if stage['cmd'] == 'PrepareQueueKMD':
self.complete_prepare(stages[0], stages[-1],
ctx_type, old_ctx_id,
cpu_task)
break
if not found_submit:
self.complete_cpu(stages[-1], data, ctx_type,
old_ctx_id, gpu_task)
else:
message('warning',
'context has changed, not handled yet')
else:
message('warning',
'timestamp order is bad, not handled yet')
else:
message('error',
'Unreliable CompleteExecutes: expect no GPU activity :(')
for stamp in to_del:
del stamps[stamp]
def arg(self, time, pid, tid, name, value):
thread = self.callbacks.process(pid).thread(tid)
if thread.task_stack:
thread.task_stack[-1].add_args({name: value})
else:
message('warning', "Orphan arg: %s %s" % (name, value))
def handle_record(self, time, cmd, args):
if not self.callbacks.check_time_in_limits(time, cmd == 'off'):
return
if cmd == 'off':
cpu, prev_tid, prev_prio, prev_name, next_tid, next_prio, next_name = args
# setting kernel activities of 0 priority as Idle:
if prev_prio == '0' and prev_name == 'kernel_task':
prev_tid = '0'
if next_prio == '0' and next_name == 'kernel_task':
next_tid = '0'
prev_tid = int(prev_tid, 16)
next_tid = int(next_tid, 16)
self.callbacks.context_switch(
time,
int(cpu, 16),
prev_tid=prev_tid,
prev_state='S',
next_tid=next_tid,
prev_prio=int(prev_prio, 16),
next_prio=int(next_prio, 16),
prev_name=prev_name.replace(' ', '_'),
next_name=next_name.replace(' ', '_'))
self.add_tid_name(prev_tid, prev_name)
self.add_tid_name(next_tid, next_name)
elif cmd == 'wkp':
prev_pid, prev_tid, prev_name, cpu, next_name, next_pid, next_tid, prim_type, prim_addr = args
self.callbacks.wakeup(time,
int(cpu, 16),
prev_pid=int(prev_pid, 16),
prev_tid=int(prev_tid, 16),
next_pid=int(next_pid, 16),
next_tid=int(next_tid, 16),
prev_name=prev_name.replace(' ', '_'),
next_name=next_name.replace(' ', '_'),
sync_prim=SYNC_PRIM[int(prim_type, 16)],
sync_prim_addr=int(prim_addr, 16))
elif cmd.startswith('dtHook'):
if not self.ignore_gpu:
pid, tid = args[0:2]
self.gpu_call(time, cmd[6:], int(pid, 16), int(tid, 16),
args[2:])
elif cmd == 'dtHookCompleteExecute':
self.ignore_gpu = False
elif cmd in ['e', 'r']:
pid, tid = args[0:2]
self.task(time, int(pid, 16), int(tid, 16), cmd == 'e', args[2],
args[3], args[4:])
elif cmd == 'm':
pid, tid = args[0:2]
self.marker(time, int(pid, 16), int(tid, 16), args[2], args[3],
args[4:])
elif cmd == 'arg':
pid, tid = args[0:2]
self.arg(time, int(pid, 16), int(tid, 16), args[2],
'\t'.join(args[3:]))
elif cmd == 'args':
pid, tid = args[0:2]
self.arguments(time, int(pid, 16), int(tid, 16), args[2:])
elif cmd in ['ie', 'ir']:
pid, tid = args[0:2]
self.interrupt(time, int(pid, 16), int(tid, 16), cmd == 'ie',
args[2], int(args[3], 16), args[4:])
elif cmd == 'io':
pid, tid = args[0:2]
self.io(time, int(pid, 16), int(tid, 16), args[2], args[3])
else:
handled = False
if self.decoders:
pid, tid = args[0:2]
pid, tid = int(pid, 16), int(tid, 16)
for decoder in self.decoders:
res = decoder.handle_record(time, pid, tid, cmd, args[2:])
handled |= True if res else False
if not handled:
message('warning',
"unsupported cmd '%s': %s" % (str(cmd), str(args)))