1#!/usr/bin/env python3 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