#!/usr/bin/python # This code is one big hack... But basically it takes a chrome DNS trace and groups the requests/jobs to print it in a more readable fashion. import re import sys class ParsedLine: def __init__(self): self.t = None self.type = None self.raw_line = None self.details = {} class EntryBase: def __init__(self, entries, id, parsed_lines): self.entries = entries self.id = id self.parsed_lines = parsed_lines def HasParsedLineOfType(self, type): for l in self.parsed_lines: if l.type == type: return True return False def GetElapsedTime(self): return self.GetEndTime() - self.GetStartTime() def GetStartTime(self): return self.parsed_lines[0].t def GetEndTime(self): return self.parsed_lines[-1].t def HasUnknownStart(self): return self.parsed_lines[0].details.has_key('is_fake') def HasUnknownEnd(self): return self.parsed_lines[-1].details.has_key('is_fake') def WasAliveAt(self, t): return t >= self.GetStartTime() and t <= self.GetEndTime() def IsJob(self): return self.id.startswith('j') def IsRequest(self): return self.id.startswith('r') def GetLiveJobsAtStart(self): # Count how many jobs were live at our start. jobs = [] for e in self.entries: if e != self and e.WasAliveAt(self.GetStartTime()) and e.IsJob(): jobs.append(e) return jobs def GetLiveRequestsAtStart(self): # Count how many requests were live at our start. requests = [] for e in self.entries: if e != self and e.WasAliveAt(self.GetStartTime()) and e.IsRequest(): requests.append(e) return requests def Print(self): print '------------------------' print self.GetCaption() print '------------------------' print self.GetDetails() def GetElapsedTimeString(self): if self.HasUnknownStart() or self.HasUnknownEnd(): return "%d+ millis" % self.GetElapsedTime() return "%d millis" % self.GetElapsedTime() class RequestEntry(EntryBase): def __init__(self, entries, id, parsed_lines, min_time, max_time): EntryBase.__init__(self, entries, id, parsed_lines) self.request_details = '???' for l in parsed_lines: if l.details.has_key('request_details'): self.request_details = l.details['request_details'] # If the log didn't capture when the request was received, manufacture a start time. if not (self.HasParsedLineOfType('received_request')): fake_line = ParsedLine() fake_line.t = min_time - 1 fake_line.type = 'received_request' fake_line.raw_line = 'Unknown start of request' fake_line.details['is_fake'] = True self.parsed_lines.insert(0, fake_line) # If the log didn't capture when the job ended, manufacture an end time. if not (self.HasParsedLineOfType('finished_request') or self.HasParsedLineOfType('cancelled_request')): fake_line = ParsedLine() fake_line.t = max_time + 1 fake_line.type = 'finished_request' fake_line.raw_line = 'Unknown end of request' fake_line.details['is_fake'] = True self.parsed_lines.append(fake_line) def GetCaption(self): return 'Request %s (took %s) for %s ' % (self.id, self.GetElapsedTimeString(), self.request_details) def GetDetails(self): out = [] reqs = self.GetLiveRequestsAtStart() out.append('There were %d requests already in progress when this started:' % len(reqs)) for r in reqs: out.append(' ' + r.GetCaption()) out.append('Log lines:') for l in self.parsed_lines: out.append(' ' + l.raw_line) return '\n'.join(out) class JobEntry(EntryBase): def __init__(self, entries, id, parsed_lines, min_time, max_time): EntryBase.__init__(self, entries, id, parsed_lines) # Find the hostname/address_family of the job self.hostname = '???' self.address_family = '???' for l in parsed_lines: if l.details.has_key('hostname'): self.hostname = l.details['hostname'] if l.details.has_key('address_family'): self.address_family = l.details['address_family'] # If the log didn't capture when the job started, manufacture a start time. if not (self.HasParsedLineOfType('created_job') or self.HasParsedLineOfType('outstanding_job') or self.HasParsedLineOfType('starting_job')): fake_line = ParsedLine() fake_line.t = min_time - 1 fake_line.type = 'outstanding_job' fake_line.raw_line = 'Unknown start of job' fake_line.details['is_fake'] = True self.parsed_lines.insert(0, fake_line) # If the log didn't capture when the job ended, manufacture an end time. if not self.HasParsedLineOfType('completing_job'): fake_line = ParsedLine() fake_line.t = max_time + 1 fake_line.type = 'completing_job' fake_line.raw_line = 'Unknown end of job' fake_line.details['is_fake'] = True self.parsed_lines.append(fake_line) def GetCaption(self): return 'Job %s (took %s) for "%s" ' % (self.id, self.GetElapsedTimeString(), self.hostname) def GetDetails(self): out = [] jobs = self.GetLiveJobsAtStart() out.append('There were %d jobs already in progress when this started:' % len(jobs)) for j in jobs: out.append(' ' + j.GetCaption()) out.append('Log lines:') for l in self.parsed_lines: out.append(' ' + l.raw_line) return '\n'.join(out) def ParseLine(line): m = re.search(r'^t=(\d+): "(.*)"\s*$', line) if not m: print 'fail' return None parsed = ParsedLine() parsed.t = int(m.group(1)) parsed.raw_line = line.strip() msg = m.group(2) m = re.search(r"^Received request (r\d+) for (.*)$", msg) if m: parsed.type = 'received_request' parsed.id = m.group(1) parsed.details['request_details'] = m.group(2) return parsed m = re.search(r"^Created job (j\d+) for {hostname='([^']*)', address_family=(\d+)}$", msg) if m: parsed.type = 'created_job' parsed.id = m.group(1) parsed.details['hostname'] = m.group(2) parsed.details['address_family'] = m.group(3) return parsed m = re.search(r"^Outstanding job (j\d+) for {hostname='([^']*)', address_family=(\d+)}, which was started at t=(\d+)$", msg) if m: parsed.type = 'outstanding_job' parsed.t = int(m.group(4)) parsed.id = m.group(1) parsed.details['hostname'] = m.group(2) parsed.details['address_family'] = m.group(3) return parsed m = re.search(r"^Attached request (r\d+) to job (j\d+)$", msg) if m: parsed.type = 'attached_request' parsed.id = m.group(1) parsed.details['job_id'] = m.group(2) return parsed m = re.search(r'^Finished request (r\d+) (.*)$', msg) if m: parsed.type = 'finished_request' parsed.id = m.group(1) parsed.details['extra'] = m.group(2) return parsed m = re.search(r'^Cancelled request (r\d+)$', msg) if m: parsed.type = 'cancelled_request' parsed.id = m.group(1) return parsed m = re.search(r'^Starting job (j\d+)$', msg) if m: parsed.type = 'starting_job' parsed.id = m.group(1) return parsed m = re.search(r'\[resolver thread\] Running job (j\d+)$', msg) if m: parsed.type = 'running_job' parsed.id = m.group(1) return parsed m = re.search(r'\[resolver thread\] Completed job (j\d+)$', msg) if m: parsed.type = 'completed_job' parsed.id = m.group(1) return parsed m = re.search(r'Completing job (j\d+).*$', msg) if m: parsed.type = 'completing_job' parsed.id = m.group(1) return parsed return None def ParseFile(path): f = open(path, 'r') entries = [] for line in f: parsed = ParseLine(line) if parsed: entries.append(parsed) f.close() return entries[0].t, entries[-1].t, entries row_height = 40 max_width = 1200 def PrintEntryRow(entry, i, min_time, max_time): min_width = 2 top_px = i * row_height left_px = int(entry.GetStartTime() * max_width / max_time) dt = entry.GetElapsedTime() width_px = max(min_width, int(dt * max_width / max_time)) caption_offset_x = width_px + 15 caption_offset_y = 4 # Print a box on the timeline. bg = '' if entry.IsRequest(): bg = 'blue' if entry.IsJob(): bg = 'purple' print ('
 
') % (top_px, left_px, width_px, row_height, bg) # Print a caption besides it. print ('%s') % (top_px + caption_offset_y, left_px + caption_offset_x, entry.id, entry.GetCaption()) def EscapeForJs(text): return text.replace('"', '\\"').replace("'", "\\'").replace('\n', '\\n') def PrintEntries(min_time, max_time, entries): print ('') print ('
' % (max_width, row_height * len(entries))) print '' for i in range(len(entries)): PrintEntryRow(entries[i], i, min_time, max_time) print ('
') print ('") sys.exit(1) min_time, max_time, parsed_lines = ParseFile(sys.argv[1]) entries = BuildEntries(parsed_lines, min_time, max_time) for e in entries: e.Print() #PrintEntries(min_time, max_time, entries) def RunTest(line): print("----------------") print(line) print("----------------") print ParseLine(line) def RunTests(): RunTest('''t=170099840: "Received request r17 for {hostname='clients1.google.lv', port=80, priority=3, speculative=0, address_family=0, allow_cached=1, referrer=''}"''') RunTest('''t=170099840: "Created job j15 for {hostname='clients1.google.lv', address_family=0}"''') RunTest('''t=170099840: "Attached request r17 to job j15"''') RunTest('''t=170103144: "Finished request r18 with error=0"''') RunTest('''t=170103461: "Starting job j16"''') RunTest('''t=170103461: "[resolver thread] Running job j16"''') RunTest('''t=170110496: "[resolver thread] Completed job j16"''') RunTest('''t=170110496: "Completing job j16"''') RunTest('''t=170110496: "Cancelled request r9"''') if __name__ == "__main__": main()