1#
2# Copyright (C) 2022 The Android Open Source Project
3#
4# Licensed under the Apache License, Version 2.0 (the "License");
5# you may not use this file except in compliance with the License.
6# You may obtain a copy of the License at
7#
8#      http://www.apache.org/licenses/LICENSE-2.0
9#
10# Unless required by applicable law or agreed to in writing, software
11# distributed under the License is distributed on an "AS IS" BASIS,
12# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
13# See the License for the specific language governing permissions and
14# limitations under the License.
15
16"""
17Command line tool to process minidump files and print what was logged by GfxApiLogger.
18
19For more details see:
20
21design: go/bstar-gfx-logging
22g3doc:  http://g3doc/play/g3doc/games/battlestar/kiwivm/graphics-tips.md#gfx-logs
23C++:    http://source/play-internal/battlestar/aosp/device/generic/vulkan-cereal/utils/include/utils/GfxApiLogger.h
24
25Usage:
26
27python3 print_gfx_logs.py <path to minidump file>
28"""
29
30from __future__ import annotations
31import argparse
32import ctypes
33import sys
34from datetime import datetime
35import mmap
36import textwrap
37from . import command_printer
38from typing import NamedTuple, Optional, List
39import traceback
40
41
42class Header(ctypes.Structure):
43    """The C struct that we use to represent the data in memory
44    Keep in sync with GfxApiLogger.h
45    """
46    _fields_ = [('signature', ctypes.c_char * 10),
47                ('version', ctypes.c_uint16),
48                ('thread_id', ctypes.c_uint32),
49                ('last_written_time', ctypes.c_uint64),
50                ('write_index', ctypes.c_uint32),
51                ('committed_index', ctypes.c_uint32),
52                ('capture_id', ctypes.c_uint64),
53                ('data_size', ctypes.c_uint32)]
54
55
56class Command(NamedTuple):
57    """A single command in the stream"""
58    timestamp: int # Unix timestamp when command was recorded, in microseconds
59    opcode: int
60    original_size: int
61    data: bytes
62
63
64class Stream(NamedTuple):
65    """Stream of commands received from the guest"""
66    pos_in_file: int  # Location of this stream in the minidump file, useful for debugging
67    timestamp: int  # Unix timestamp of last command received, in microseconds
68    thread_id: int
69    capture_id: int
70    commands: List[Command]
71    error_message: Optional[str]  # `None` if there were no errors parsing this stream
72
73    @staticmethod
74    def error(pos_in_file: int, error_message: str) -> Stream:
75        return Stream(
76            pos_in_file=pos_in_file, timestamp=0, thread_id=0, capture_id=0, commands=[],
77            error_message=error_message)
78
79def timestampToUnixUs(timestamp: int) -> int:
80    # Convert Windows' GetSystemTimeAsFileTime to Unix timestamp in microseconds
81    # https://stackoverflow.com/questions/1695288/getting-the-current-time-in-milliseconds-from-the-system-clock-in-windows
82    timestamp_us = int(timestamp / 10 - 11644473600000000)
83    if timestamp_us <= 0: timestamp_us = 0
84    return timestamp_us
85
86def read_uint32(buf: bytes, pos: int) -> int:
87    """Reads a single uint32 from buf at a given position"""
88    assert pos + 4 <= len(buf)
89    return int.from_bytes(buf[pos:pos + 4], byteorder='little', signed=False)
90
91def read_uint64(buf: bytes, pos: int) -> int:
92    """Reads a single uint32 from buf at a given position"""
93    assert pos + 8 <= len(buf)
94    return int.from_bytes(buf[pos:pos + 8], byteorder='little', signed=False)
95
96def process_command(buf: bytes, version: int) -> Command:
97    pos = 0
98    if version >= 3:
99        timestamp_us = read_uint64(buf, pos)
100        pos += 8
101    else:
102        timestamp_us = 0
103    opcode = read_uint32(buf, pos)
104    pos += 4
105    size = read_uint32(buf, pos)
106    pos += 4
107    return Command(timestamp_us, opcode, size, bytes(buf[pos:]))
108
109
110def process_stream(file_bytes: mmap, file_pos: int) -> Stream:
111    # Read the header
112    file_bytes.seek(file_pos)
113    header = Header()
114    header_bytes = file_bytes.read(ctypes.sizeof(header))
115    ctypes.memmove(ctypes.addressof(header), header_bytes, ctypes.sizeof(header))
116
117    if header.signature != b'GFXAPILOG':
118        return Stream.error(file_pos, error_message="Signature doesn't match")
119
120    if header.version < 2:
121        return Stream.error(
122            file_pos,
123            error_message=(
124                "This script can only process version 2 or later of the graphics API logs, but the "
125                + "dump file uses version {} ").format(header.version))
126
127    if header.version == 2:
128        timestamp_us = timestampToUnixUs(int(header.last_written_time))
129    else:
130        timestamp_us = int(header.last_written_time)
131
132    # Sanity check the size
133    if header.data_size > 5_000_000:
134        return Stream.error(
135            file_pos,
136            error_message="data size is larger than 5MB. This likely indicates garbage/corrupted " +
137            "data")
138
139    if header.committed_index >= header.data_size:
140        return Stream.error(
141            file_pos,
142            error_message="index is larger than buffer size. Likely indicates garbage/corrupted " +
143            "data")
144
145    file_bytes.seek(file_pos + ctypes.sizeof(header))
146    data = file_bytes.read(header.data_size)
147
148    # Reorder the buffer so that we can read it in a single pass from back to front
149    buf = data[header.committed_index:] + data[:header.committed_index]
150
151    commands = []
152    i = len(buf)
153    while i >= 4:
154        i -= 4
155        size = read_uint32(buf, i)
156        if size == 0 or size > i:
157            # We reached the end of the stream
158            break
159        cmd = process_command(buf[i - size:i], header.version)
160
161        commands.append(cmd)
162        i -= size
163
164    commands.reverse()  # so that they're sorted from oldest to most recent
165    return Stream(file_pos, timestamp_us, header.thread_id, header.capture_id, commands, None)
166
167
168def process_minidump(mm: mmap) -> List[Stream]:
169    """
170    Extracts a list of commands streams from a minidump file
171    """
172    streams = []
173    pos = 0
174    while True:
175        pos = mm.find(b'GFXAPILOG', pos)
176        if pos == -1:
177            break
178        streams.append(process_stream(mm, pos))
179        pos += 1
180
181    return streams
182
183
184def main():
185    parser = argparse.ArgumentParser(description="""Command line tool to process crash reports and print out the
186    commands logged by GfxApiLogger""")
187    parser.add_argument('dump_file', help="Path to  minidump file")
188
189    args = parser.parse_args()
190    streams = None
191    with open(args.dump_file, "r+b") as f:
192        with mmap.mmap(f.fileno(), 0) as mm:
193            streams = process_minidump(mm)
194
195    streams.sort(key=lambda s: s.timestamp)
196
197    total_commands = 0
198    num_errors = 0
199    for stream_idx, stream in enumerate(streams):
200        print(textwrap.dedent("""
201                  =======================================================
202                  GfxApiLog command stream #{} at offset {} in dump
203                    - Timestamp: {}
204                    - Thread id: {}
205                    - Capture id: {}""".format(stream_idx, stream.pos_in_file,
206                                               datetime.fromtimestamp(stream.timestamp / 1000000.0),
207                                               stream.thread_id,
208                                               stream.capture_id)))
209        if stream.error_message:
210            print("Could not decode stream. Error: ", stream.error_message)
211            continue
212
213        subdecode_size = 0
214        for cmd_idx, cmd in enumerate(stream.commands):
215            total_commands += 1
216            cmd_printer = command_printer.CommandPrinter(
217                cmd.opcode, cmd.original_size, cmd.data, cmd.timestamp, stream_idx, cmd_idx)
218
219            try:
220                cmd_printer.print_cmd()
221            except:
222                num_errors += 1
223                # Print stack trace and continue
224                traceback.print_exc(file=sys.stdout)
225
226            if subdecode_size > 0:
227                subdecode_size -= cmd.original_size
228                assert subdecode_size >= 0
229                if subdecode_size == 0:
230                    print("\n--- end of subdecode ---")
231
232            if cmd_printer.cmd_name() == "OP_vkQueueFlushCommandsGOOGLE":
233                assert subdecode_size == 0
234                subdecode_size = cmd.original_size - 36
235                print("\n--- start of subdecode, size = {} bytes ---".format(subdecode_size))
236    print("\nDone: {} commands, {} errors".format(total_commands, num_errors))
237    if num_errors > 0:
238        print("""
239NOTE: This script uses some simplifying assumptions to decode the commands. All
240decoding errors are almost certainly a bug with this script, NOT a sign of bad
241or corrupted data.""")
242
243
244if __name__ == '__main__':
245    main()
246