1#!/usr/local/bin/python3.8
2
3import re
4import sys
5import gzip
6import io
7
8# Captures per-frame state, including all the renderpasses, and
9# time spent in blits and compute jobs:
10class Frame:
11    def __init__(self):
12        self.frame_nr = None
13        self.renderpasses = []
14        # Times in ns:
15        self.times_sysmem = []
16        self.times_gmem = []
17        self.times_compute = []
18        self.times_blit = []
19
20    def print(self):
21        print("FRAME[{}]: {} blits ({:,} ns), {} SYSMEM ({:,} ns), {} GMEM ({:,} ns), {} COMPUTE ({:,} ns)".format(
22                self.frame_nr,
23                len(self.times_blit),    sum(self.times_blit),
24                len(self.times_sysmem),  sum(self.times_sysmem),
25                len(self.times_gmem),    sum(self.times_gmem),
26                len(self.times_compute), sum(self.times_compute)
27            ))
28
29        i = 0
30        prologue_time = 0
31        binning_time = 0
32        restore_clear_time = 0
33        draw_time = 0
34        resolve_time = 0
35        elapsed_time = 0
36        total_time = sum(self.times_blit) + sum(self.times_sysmem) + sum(self.times_gmem) + sum(self.times_compute)
37
38        for renderpass in self.renderpasses:
39            renderpass.print(i)
40            prologue_time += renderpass.prologue_time
41            binning_time += renderpass.binning_time
42            restore_clear_time += renderpass.restore_clear_time
43            draw_time += renderpass.draw_time
44            resolve_time += renderpass.resolve_time
45            elapsed_time += renderpass.elapsed_time
46            i += 1
47
48        print("  TOTAL: prologue: {:,} ns ({}%), binning: {:,} ns ({}%), restore/clear: {:,} ns ({}%), draw: {:,} ns ({}%), resolve: {:,} ns ({}%), blit: {:,} ns ({}%), compute: {:,} ns ({}%), GMEM: {:,} ns ({}%), sysmem: {:,} ns ({}%), total: {:,} ns\n".format(
49                prologue_time, 100.0 * prologue_time / total_time,
50                binning_time, 100.0 * binning_time / total_time,
51                restore_clear_time, 100.0 * restore_clear_time / total_time,
52                draw_time, 100.0 * draw_time / total_time,
53                resolve_time, 100.0 * resolve_time / total_time,
54                sum(self.times_blit), 100.0 * sum(self.times_blit) / total_time,
55                sum(self.times_compute), 100.0 * sum(self.times_compute) / total_time,
56                sum(self.times_gmem), 100.0 * sum(self.times_gmem) / total_time,
57                sum(self.times_sysmem), 100.0 * sum(self.times_sysmem) / total_time,
58                total_time
59            ))
60
61class FramebufferState:
62    def __init__(self, width, height, layers, samples, nr_cbufs):
63        self.width = width
64        self.height = height
65        self.layers = layers
66        self.samples = samples
67        self.nr_cbufs = nr_cbufs
68        self.surfaces = []        # per MRT + zsbuf
69
70    def get_formats(self):
71        formats = []
72        for surface in self.surfaces:
73            formats.append(surface.format)
74        return formats
75
76class SurfaceState:
77    def __init__(self, width, height, samples, format):
78        self.width = width
79        self.height = height
80        self.samples = samples
81        self.format = format
82
83class BinningState:
84    def __init__(self, nbins_x, nbins_y, bin_w, bin_h):
85        self.nbins_x = nbins_x
86        self.nbins_y = nbins_y
87        self.bin_w = bin_w
88        self.bin_h = bin_h
89
90# Captures per-renderpass state, which can be either a binning or
91# sysmem pass.  Blits and compute jobs are not tracked separately
92# but have their time their times accounted for in the Frame state
93class RenderPass:
94    def __init__(self, cleared, gmem_reason, num_draws):
95        self.cleared = cleared
96        self.gmem_reason = gmem_reason
97        self.num_draws = num_draws
98
99        # The rest of the parameters aren't known until we see a later trace:
100        self.binning_state = None   # None for sysmem passes, else BinningState
101        self.fb = None
102        self.fast_cleared = None
103
104        self.elapsed_time = 0
105        self.state_restore_time = 0
106        self.prologue_time = 0
107        self.draw_time = 0
108        self.restore_clear_time = 0
109
110        # Specific to GMEM passes:
111        self.binning_time = 0
112        self.vsc_overflow_test_time = 0
113        self.resolve_time = 0
114
115    def print_gmem_pass(self, nr):
116        print("  GMEM[{}]: {}x{} ({}x{} tiles), {} draws, prologue: {:,} ns, binning: {:,} ns, restore/clear: {:,} ns, draw: {:,} ns, resolve: {:,} ns, total: {:,} ns, rt/zs: {}".format(
117                nr, self.fb.width, self.fb.height,
118                self.binning_state.nbins_x, self.binning_state.nbins_y,
119                self.num_draws, self.prologue_time, self.binning_time,
120                self.restore_clear_time, self.draw_time, self.resolve_time,
121                self.elapsed_time,
122                ", ".join(self.fb.get_formats())
123            ))
124
125    def print_sysmem_pass(self, nr):
126        print("  SYSMEM[{}]: {}x{}, {} draws, prologue: {:,} ns, clear: {:,} ns, draw: {:,} ns, total: {:,} ns, rt/zs: {}".format(
127                nr, self.fb.width, self.fb.height,
128                self.num_draws, self.prologue_time,
129                self.restore_clear_time, self.draw_time,
130                self.elapsed_time,
131                ", ".join(self.fb.get_formats())
132            ))
133
134    def print(self, nr):
135        if self.binning_state:
136            self.print_gmem_pass(nr)
137        else:
138            self.print_sysmem_pass(nr)
139
140def main():
141    filename = sys.argv[1]
142    if filename.endswith(".gz"):
143        file = gzip.open(filename, "r")
144        file = io.TextIOWrapper(file)
145    else:
146        file = open(filename, "r")
147    lines = file.read().split('\n')
148
149    flush_batch_match = re.compile(r": flush_batch: (\S+): cleared=(\S+), gmem_reason=(\S+), num_draws=(\S+)")
150    framebuffer_match = re.compile(r": framebuffer: (\S+)x(\S+)x(\S+)@(\S+), nr_cbufs: (\S+)")
151    surface_match     = re.compile(r": surface: (\S+)x(\S+)@(\S+), fmt=(\S+)")
152
153    # draw/renderpass passes:
154    gmem_match          = re.compile(r": render_gmem: (\S+)x(\S+) bins of (\S+)x(\S+)")
155    sysmem_match        = re.compile(r": render_sysmem")
156    state_restore_match = re.compile(r"\+(\S+): end_state_restore")
157    prologue_match      = re.compile(r"\+(\S+): end_prologue")
158    binning_ib_match    = re.compile(r"\+(\S+): end_binning_ib")
159    vsc_overflow_match  = re.compile(r"\+(\S+): end_vsc_overflow_test")
160    draw_ib_match       = re.compile(r"\+(\S+): end_draw_ib")
161    resolve_match       = re.compile(r"\+(\S+): end_resolve")
162
163    start_clear_restore_match = re.compile(r"start_clear_restore: fast_cleared: (\S+)")
164    end_clear_restore_match   = re.compile(r"\+(\S+): end_clear_restore")
165
166    # Non-draw passes:
167    compute_match = re.compile(r": start_compute")
168    blit_match    = re.compile(r": start_blit")
169
170    # End of pass/frame markers:
171    elapsed_match = re.compile(r"ELAPSED: (\S+) ns")
172    eof_match     = re.compile(r"END OF FRAME (\S+)")
173
174    frame = Frame()      # current frame state
175    renderpass = None    # current renderpass state
176    times = None
177
178    # Helper to set the appropriate times table for the current pass,
179    # which is expected to only happen once for a given render pass
180    def set_times(t):
181        nonlocal times
182        if times  is not None:
183            print("expected times to not be set yet")
184        times = t
185
186    for line in lines:
187        # Note, we only expect the flush_batch trace for !nondraw:
188        match = re.search(flush_batch_match, line)
189        if match is not None:
190            assert(renderpass is None)
191            renderpass = RenderPass(cleared=match.group(2),
192                                    gmem_reason=match.group(3),
193                                    num_draws=match.group(4))
194            frame.renderpasses.append(renderpass)
195            continue
196
197        match = re.search(framebuffer_match, line)
198        if match is not None:
199            assert(renderpass.fb is None)
200            renderpass.fb = FramebufferState(width=match.group(1),
201                                             height=match.group(2),
202                                             layers=match.group(3),
203                                             samples=match.group(4),
204                                             nr_cbufs=match.group(5))
205            continue
206
207        match = re.search(surface_match, line)
208        if match is not None:
209            surface = SurfaceState(width=match.group(1),
210                                   height=match.group(2),
211                                   samples=match.group(3),
212                                   format=match.group(4))
213            renderpass.fb.surfaces.append(surface)
214            continue
215
216        match = re.search(gmem_match, line)
217        if match is not None:
218            assert(renderpass.binning_state is None)
219            renderpass.binning_state = BinningState(nbins_x=match.group(1),
220                                                    nbins_y=match.group(2),
221                                                    bin_w=match.group(3),
222                                                    bin_h=match.group(4))
223            set_times(frame.times_gmem)
224            continue
225
226        match = re.search(sysmem_match, line)
227        if match is not None:
228            assert(renderpass.binning_state is None)
229            set_times(frame.times_sysmem)
230            continue
231
232        match = re.search(state_restore_match, line)
233        if match is not None:
234            renderpass.state_restore_time += int(match.group(1))
235            continue
236
237        match = re.search(prologue_match, line)
238        if match is not None:
239            renderpass.prologue_time += int(match.group(1))
240            continue
241
242        match = re.search(binning_ib_match, line)
243        if match is not None:
244            assert(renderpass.binning_state is not None)
245            renderpass.binning_time += int(match.group(1))
246            continue
247
248        match = re.search(vsc_overflow_match, line)
249        if match is not None:
250            assert(renderpass.binning_state is not None)
251            renderpass.vsc_overflow_test_time += int(match.group(1))
252            continue
253
254        match = re.search(draw_ib_match, line)
255        if match is not None:
256            renderpass.draw_time += int(match.group(1))
257            continue
258
259        match = re.search(resolve_match, line)
260        if match is not None:
261            assert(renderpass.binning_state is not None)
262            renderpass.resolve_time += int(match.group(1))
263            continue
264
265        match = re.search(start_clear_restore_match, line)
266        if match is not None:
267            renderpass.fast_cleared = match.group(1)
268            continue
269
270        match = re.search(end_clear_restore_match, line)
271        if match is not None:
272            renderpass.restore_clear_time += int(match.group(1))
273            continue
274
275        match = re.search(compute_match, line)
276        if match is not None:
277            set_times(frame.times_compute)
278            continue
279
280        match = re.search(blit_match, line)
281        if match is not None:
282            set_times(frame.times_blit)
283            continue
284
285        match = re.search(eof_match, line)
286        if match is not None:
287            frame.frame_nr = int(match.group(1))
288            frame.print()
289            frame = Frame()
290            times = None
291            renderpass = None
292            continue
293
294        match = re.search(elapsed_match, line)
295        if match is not None:
296            time = int(match.group(1))
297            #print("ELAPSED: " + str(time) + " ns")
298            if renderpass is not None:
299                renderpass.elapsed_time = time
300            times.append(time)
301            times = None
302            renderpass = None
303            continue
304
305
306if __name__ == "__main__":
307    main()
308
309