diff --git a/programs/vkd3d-fsync-log-to-profile.py b/programs/vkd3d-fsync-log-to-profile.py new file mode 100644 index 0000000000..c7982b6710 --- /dev/null +++ b/programs/vkd3d-fsync-log-to-profile.py @@ -0,0 +1,134 @@ +#!/usr/bin/env python3 + +""" +Copyright 2024 Hans-Kristian Arntzen for Valve Corporation + +This library is free software; you can redistribute it and/or +modify it under the terms of the GNU Lesser General Public +License as published by the Free Software Foundation; either +version 2.1 of the License, or (at your option) any later version. + +This library is distributed in the hope that it will be useful, +but WITHOUT ANY WARRANTY; without even the implied warranty of +MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU +Lesser General Public License for more details. + +You should have received a copy of the GNU Lesser General Public +License along with this library; if not, write to the Free Software +Foundation, Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301, USA +""" + +""" +Hacky script that parses PROTON_LOG=+fsync,+microsecs and emits wait-states in VKD3D_QUEUE_PROFILE format with VKD3D_QUEUE_PROFILE_ABSOLUTE=1. +Equivalent in more plain Wine would be WINEDEBUG=+fsync,+timestamp,+pid,+tid,+threadname,+microsecs WINEFSYNC=1. +Can be used to directly append to vkd3d-proton generated JSON. +""" + +import re +import sys + +def print_json_wait(tid, desc, start_ts, end_ts): + print('{', '"name": "{}", "ph" : "X", "tid": "{}", "pid": "fsync wait", "ts": {}, "dur": {}'.format(desc, tid, start_ts, end_ts - start_ts), '},') + +def print_json_signal(tid, desc, ts): + print('{', '"name": "{}", "ph" : "i", "tid": "{}", "pid": "fsync signal", "ts": {}'.format(desc, tid, ts), '},') + +def strip_hex_prefix(x): + if x.startswith('0x'): + return x[2:] + else: + return x + +def parse_proton_log(file): + find_threadname = re.compile('.+:([0-9A-Fa-f]+):warn:threadname:.*renamed to L"(.+)"$') + find_wait = re.compile('(\d+\.\d+):.+:([0-9A-Fa-f]+):trace:fsync:__fsync_wait_objects Waiting for (all|any) of \d+ handles: ([^,]+),.*$') + find_wake = re.compile('(\d+\.\d+):.+:([0-9A-Fa-f]+):trace:fsync:__fsync_wait_objects Woken up by handle 0x([0-9A-Fa-f]+) .*$') + find_wake_timeout = re.compile('(\d+\.\d+):.+:([0-9A-Fa-f]+):trace:fsync:__fsync_wait_objects Wait timed out.$') + find_set_event = re.compile('(\d+\.\d+):.+:([0-9A-Fa-f]+):trace:fsync:fsync_set_event 0x([0-9A-Fa-f]+)\.$') + find_release_sem = re.compile('(\d+\.\d+):.+:([0-9A-Fa-f]+):trace:fsync:fsync_release_semaphore 0x([0-9A-Fa-f]+),.*$') + thread_id_to_name = {} + sleep_states = {} + signal_cause = {} + + for line in file.readlines(): + m = find_threadname.match(line) + if m: + thread_id_to_name[m[1]] = m[1] + ' (' + m[2] + ')' + + m = find_wait.search(line) + if m: + time = int(float(m[1]) * 1e6) + tid = m[2] + any_or_all = m[3] + handle_list = m[4] + if tid in sleep_states: + raise Exception('{} has a sleep state already. line: "{}"'.format(tid, m[0])) + sleep_states[tid] = (any_or_all, [strip_hex_prefix(x) for x in handle_list.split(' ')], time) + continue + + m = find_wake_timeout.search(line) + if m: + time = int(float(m[1]) * 1e6) + tid = m[2] + try: + state = sleep_states.pop(tid) + name = thread_id_to_name.get(tid, tid) + pretty_list = ', '.join(state[1]) + desc = '{} {} timeout'.format(state[0], pretty_list) + print_json_wait(name, desc, state[2], time) + except KeyError as e: + raise Exception('{} timed out, but there is no wait state? line: "{}"'.format(tid, m[0])) + continue + + m = find_wake.search(line) + if m: + time = int(float(m[1]) * 1e6) + tid = m[2] + handle = m[3] + try: + state = sleep_states.pop(tid) + name = thread_id_to_name.get(tid, tid) + + pretty_list = ', '.join(state[1]) + if len(state[1]) > 1 and state[0] == 'any': + desc = '{} {} woken by {}'.format(state[0], pretty_list, handle) + else: + desc = '{} {}'.format(state[0], pretty_list) + + cause_tid = signal_cause.get(handle) + if cause_tid: + cause_tid = signal_cause.pop(handle) + desc += ' [signal by {}]'.format(thread_id_to_name.get(cause_tid, cause_tid)) + + print_json_wait(name, desc, state[2], time) + except KeyError as e: + raise Exception('{} was woken up, but there is no wait state? line: "{}"'.format(tid, m[0])) + continue + + m = find_set_event.search(line) + if m: + time = int(float(m[1]) * 1e6) + tid = m[2] + handle = m[3] + name = thread_id_to_name.get(tid, tid) + print_json_signal(name, 'event ' + handle, time) + signal_cause[handle] = tid + continue + + m = find_release_sem.search(line) + if m: + time = int(float(m[1]) * 1e6) + tid = m[2] + handle = m[3] + name = thread_id_to_name.get(tid, tid) + print_json_signal(name, 'semaphore ' + handle, time) + signal_cause[handle] = tid + continue + +def main(): + file = sys.argv[1] + with open(file, 'r') as f: + parse_proton_log(f) + +if __name__ == '__main__': + main()