| OLD | NEW |
| (Empty) |
| 1 #!/usr/bin/python2.4 | |
| 2 # Copyright (c) 2010 The Chromium Authors. All rights reserved. | |
| 3 # Use of this source code is governed by a BSD-style license that can be | |
| 4 # found in the LICENSE file. | |
| 5 | |
| 6 """Application to format Chromium's host resolver traces to something readable. | |
| 7 | |
| 8 To use it, start by enabling tracing in Chromium: | |
| 9 chrome://net-internals/hostresolver | |
| 10 | |
| 11 Next, copy-paste the trace results (those lines starting with "t=") and save | |
| 12 them to a text file. | |
| 13 | |
| 14 Lastly, run: | |
| 15 python formatter.py <file-containing-trace> | |
| 16 """ | |
| 17 | |
| 18 import sys | |
| 19 | |
| 20 import parser | |
| 21 | |
| 22 # The log lines of the host resolver trace either describe a "request" or a | |
| 23 # "job". The "request" is the actual DNS resolve request, whereas the "job" is | |
| 24 # a helper that was spawned to service requests on a particular thread. | |
| 25 # | |
| 26 # In the log lines, each request or job is identified using a unique numeric ID. | |
| 27 # | |
| 28 # Since DNS resolving is multi-threaded, the log lines may appear jumbled. | |
| 29 # | |
| 30 # The first thing this code does is to group the log lines by id. This | |
| 31 # collection of log lines is called an "entry", and represented by either | |
| 32 # RequestEntry or JobEntry. | |
| 33 # | |
| 34 # So for example, say we had a log resembling: | |
| 35 # | |
| 36 # t=1: starting request r1 | |
| 37 # t=1: starting job j1 | |
| 38 # t=2: starting request r2 | |
| 39 # t=3: completed job j1 | |
| 40 # t=4: finished request r2 | |
| 41 # t=5: cancelled request r1 | |
| 42 # | |
| 43 # We would start by building three entries: | |
| 44 # | |
| 45 # (id='r1') | |
| 46 # t=1: starting request r1 | |
| 47 # t=5: cancelled request r1 | |
| 48 # | |
| 49 # (id='j1') | |
| 50 # t=1: starting job j1 | |
| 51 # t=3: completed job j1 | |
| 52 # | |
| 53 # (id='r2') | |
| 54 # t=2: starting request r2 | |
| 55 # t=4: finished request r2 | |
| 56 | |
| 57 (ENTRY_TYPE_JOB, ENTRY_TYPE_REQUEST) = (0, 1) | |
| 58 | |
| 59 | |
| 60 class EntryBase(object): | |
| 61 """Helper structure that describes an individual hostresolver request/job.""" | |
| 62 | |
| 63 def __init__(self, entries, entity_id, parsed_lines): | |
| 64 """Constructor for EntryBase. | |
| 65 | |
| 66 Args: | |
| 67 entries: The full list of EntryBase that this new instance belongs to. | |
| 68 entity_id: The ID of this request/job. | |
| 69 parsed_lines: An ordered list of ParsedLine for the log lines that apply | |
| 70 to this request/job. | |
| 71 """ | |
| 72 self._entries = entries | |
| 73 self._entity_id = entity_id | |
| 74 self._parsed_lines = parsed_lines | |
| 75 | |
| 76 def HasParsedLineOfType(self, line_type): | |
| 77 """Returns true if this request/job contains a log line of type |type|.""" | |
| 78 for line in self._parsed_lines: | |
| 79 if line.line_type == line_type: | |
| 80 return True | |
| 81 return False | |
| 82 | |
| 83 def GetElapsedTime(self): | |
| 84 """Returns the start to finish duration of this request/job.""" | |
| 85 return self.GetEndTime() - self.GetStartTime() | |
| 86 | |
| 87 def GetStartTime(self): | |
| 88 """Returns the start time for this request/job.""" | |
| 89 return self._parsed_lines[0].t | |
| 90 | |
| 91 def GetEndTime(self): | |
| 92 """Returns the end time of this request/job.""" | |
| 93 return self._parsed_lines[-1].t | |
| 94 | |
| 95 def HasUnknownStart(self): | |
| 96 """Returns true if the exact start of this request/job is unknown.""" | |
| 97 return 'is_fake' in self._parsed_lines[0].details | |
| 98 | |
| 99 def HasUnknownEnd(self): | |
| 100 """Returns true if the exact end of this request/job is unknown.""" | |
| 101 return 'is_fake' in self._parsed_lines[-1].details | |
| 102 | |
| 103 def WasAliveAt(self, t): | |
| 104 """Returns true if this request/job was running at time |t|.""" | |
| 105 return t >= self.GetStartTime() and t <= self.GetEndTime() | |
| 106 | |
| 107 def GetEntryType(self): | |
| 108 """Returns whether this entry represents a request or a job. | |
| 109 Should be one of the enums ENTRY_TYPE_*""" | |
| 110 return None | |
| 111 | |
| 112 def GetLiveEntriesAtStart(self, entry_type): | |
| 113 return [entry for entry in self._entries | |
| 114 if (entry != self and entry.WasAliveAt(self.GetStartTime()) and | |
| 115 entry.GetEntryType() == entry_type)] | |
| 116 | |
| 117 def Print(self): | |
| 118 """Outputs a text description of this request/job.""" | |
| 119 print '------------------------' | |
| 120 print self.GetCaption() | |
| 121 print '------------------------' | |
| 122 print self.GetDetails() | |
| 123 | |
| 124 def GetElapsedTimeString(self): | |
| 125 """Returns a string that describes how long this request/job took.""" | |
| 126 if self.HasUnknownStart() or self.HasUnknownEnd(): | |
| 127 return '%d+ millis' % self.GetElapsedTime() | |
| 128 return '%d millis' % self.GetElapsedTime() | |
| 129 | |
| 130 | |
| 131 class RequestEntry(EntryBase): | |
| 132 """Specialization of EntryBase that describes hostresolver request.""" | |
| 133 | |
| 134 def __init__(self, entries, entity_id, parsed_lines, min_time, max_time): | |
| 135 """Constructor for RequestEntry. | |
| 136 | |
| 137 Args: | |
| 138 entries: The full list of EntryBase that this new instance belongs to. | |
| 139 entity_id: The ID of this request. | |
| 140 parsed_lines: An ordered list of ParsedLine for the log lines that apply | |
| 141 to this request. | |
| 142 min_time: The start time of the log. | |
| 143 max_time: The end time of the log. | |
| 144 """ | |
| 145 EntryBase.__init__(self, entries, entity_id, parsed_lines) | |
| 146 | |
| 147 # Scan the parsed lines for this request to find the details on the request. | |
| 148 self.request_details = '???' | |
| 149 for line in parsed_lines: | |
| 150 if 'request_details' in line.details: | |
| 151 self.request_details = line.details['request_details'] | |
| 152 break | |
| 153 | |
| 154 # If the log didn't capture when the request was received, manufacture a log | |
| 155 # entry for the start, at t = min_time - 1 | |
| 156 if not self.HasParsedLineOfType(parser.LINE_TYPE_RECEIVED_REQUEST): | |
| 157 fake_line = parser.ParsedLine() | |
| 158 fake_line.t = min_time - 1 | |
| 159 fake_line.line_type = parser.LINE_TYPE_RECEIVED_REQUEST | |
| 160 fake_line.raw_line = 'Unknown start of request' | |
| 161 fake_line.details['is_fake'] = True | |
| 162 self._parsed_lines.insert(0, fake_line) | |
| 163 | |
| 164 # If the log didn't capture when the job ended, manufacture a log entry for | |
| 165 # the end, at t = max_time + 1 | |
| 166 if not (self.HasParsedLineOfType(parser.LINE_TYPE_FINISHED_REQUEST) or | |
| 167 self.HasParsedLineOfType(parser.LINE_TYPE_CANCELLED_REQUEST)): | |
| 168 fake_line = parser.ParsedLine() | |
| 169 fake_line.t = max_time + 1 | |
| 170 fake_line.line_type = parser.LINE_TYPE_FINISHED_REQUEST | |
| 171 fake_line.raw_line = 'Unknown end of request' | |
| 172 fake_line.details['is_fake'] = True | |
| 173 self._parsed_lines.append(fake_line) | |
| 174 | |
| 175 def GetEntryType(self): | |
| 176 return ENTRY_TYPE_REQUEST | |
| 177 | |
| 178 def GetCaption(self): | |
| 179 return 'Request %s (took %s) for %s ' % (self._entity_id, | |
| 180 self.GetElapsedTimeString(), | |
| 181 self.request_details) | |
| 182 | |
| 183 def GetDetails(self): | |
| 184 reqs = self.GetLiveEntriesAtStart(ENTRY_TYPE_REQUEST) | |
| 185 out = [('There were %d requests already in progress when this ' | |
| 186 'started:') % len(reqs)] | |
| 187 out.extend([' ' + r.GetCaption() for r in reqs]) | |
| 188 | |
| 189 out.append('Log lines:') | |
| 190 out.extend([' ' + line.raw_line for line in self._parsed_lines]) | |
| 191 | |
| 192 return '\n'.join(out) | |
| 193 | |
| 194 | |
| 195 class JobEntry(EntryBase): | |
| 196 """Specialization of EntryBase that describes hostresolver request.""" | |
| 197 | |
| 198 def __init__(self, entries, entity_id, parsed_lines, min_time, max_time): | |
| 199 """Constructor for JobEntry. | |
| 200 | |
| 201 Args: | |
| 202 entries: The full list of EntryBase that this new instance belongs to. | |
| 203 entity_id: The ID of this job. | |
| 204 parsed_lines: An ordered list of ParsedLine for the log lines that apply | |
| 205 to this job. | |
| 206 min_time: The start time of the log. | |
| 207 max_time: The end time of the log. | |
| 208 """ | |
| 209 EntryBase.__init__(self, entries, entity_id, parsed_lines) | |
| 210 | |
| 211 # Find the hostname/address_family of the job | |
| 212 self.hostname = '???' | |
| 213 self.address_family = '???' | |
| 214 | |
| 215 for line in parsed_lines: | |
| 216 if 'hostname' in line.details and 'address_family' in line.details: | |
| 217 self.hostname = line.details['hostname'] | |
| 218 self.address_family = line.details['address_family'] | |
| 219 break | |
| 220 | |
| 221 # If the log didn't capture when the job started, manufacture a start time. | |
| 222 if not (self.HasParsedLineOfType(parser.LINE_TYPE_CREATED_JOB) or | |
| 223 self.HasParsedLineOfType(parser.LINE_TYPE_OUTSTANDING_JOB) or | |
| 224 self.HasParsedLineOfType(parser.LINE_TYPE_STARTING_JOB)): | |
| 225 fake_line = parser.ParsedLine() | |
| 226 fake_line.t = min_time - 1 | |
| 227 fake_line.line_type = parser.LINE_TYPE_OUTSTANDING_JOB | |
| 228 fake_line.raw_line = 'Unknown start of job' | |
| 229 fake_line.details['is_fake'] = True | |
| 230 self._parsed_lines.insert(0, fake_line) | |
| 231 | |
| 232 # If the log didn't capture when the job ended, manufacture an end time. | |
| 233 if not self.HasParsedLineOfType(parser.LINE_TYPE_COMPLETING_JOB): | |
| 234 fake_line = parser.ParsedLine() | |
| 235 fake_line.t = max_time + 1 | |
| 236 fake_line.line_type = parser.LINE_TYPE_COMPLETING_JOB | |
| 237 fake_line.raw_line = 'Unknown end of job' | |
| 238 fake_line.details['is_fake'] = True | |
| 239 self._parsed_lines.append(fake_line) | |
| 240 | |
| 241 def GetEntryType(self): | |
| 242 return ENTRY_TYPE_JOB | |
| 243 | |
| 244 def GetCaption(self): | |
| 245 return 'Job %s (took %s) for "%s" ' % (self._entity_id, | |
| 246 self.GetElapsedTimeString(), | |
| 247 self.hostname) | |
| 248 | |
| 249 def GetDetails(self): | |
| 250 jobs = self.GetLiveEntriesAtStart(ENTRY_TYPE_JOB) | |
| 251 out = [('There were %d jobs already in progress when ' | |
| 252 'this started:' % len(jobs))] | |
| 253 out.extend([' ' + j.GetCaption() for j in jobs]) | |
| 254 | |
| 255 out.append('Log lines:') | |
| 256 out.extend([' ' + line.raw_line for line in self._parsed_lines]) | |
| 257 | |
| 258 return '\n'.join(out) | |
| 259 | |
| 260 | |
| 261 def BuildEntries(parsed_lines, min_time, max_time): | |
| 262 """Returns a list of BaseEntrys built from |parsed_lines|.""" | |
| 263 | |
| 264 # In this loop we aggregate all of the parsed lines with common entity_id, and | |
| 265 # also determine the order that entity_ids are first seen in. | |
| 266 id_to_line_list = {} | |
| 267 entity_ids = [] | |
| 268 for line in parsed_lines: | |
| 269 entity_id = line.entity_id | |
| 270 if not entity_id in entity_ids: | |
| 271 entity_ids.append(entity_id) | |
| 272 lines = id_to_line_list.setdefault(entity_id, []) | |
| 273 lines.append(line) | |
| 274 | |
| 275 # Create an entry (either JobEntry or RequestEntry) for each unique entity_id | |
| 276 # in the trace. Ordered by their first appearance in the trace. | |
| 277 | |
| 278 entries = [] | |
| 279 for entity_id in entity_ids: | |
| 280 if entity_id.startswith('j'): | |
| 281 entries.append(JobEntry(entries, | |
| 282 entity_id, id_to_line_list[entity_id], | |
| 283 min_time, max_time)) | |
| 284 if entity_id.startswith('r'): | |
| 285 entries.append(RequestEntry(entries, | |
| 286 entity_id, id_to_line_list[entity_id], | |
| 287 min_time, max_time)) | |
| 288 | |
| 289 return entries | |
| 290 | |
| 291 | |
| 292 def main(): | |
| 293 if len(sys.argv) != 2: | |
| 294 print 'Usage: %s <logfile_path>' % sys.argv[0] | |
| 295 sys.exit(1) | |
| 296 | |
| 297 parsed_lines = parser.ParseFile(sys.argv[1]) | |
| 298 | |
| 299 min_time = parsed_lines[0].t | |
| 300 max_time = parsed_lines[-1].t | |
| 301 | |
| 302 entries = BuildEntries(parsed_lines, min_time, max_time) | |
| 303 | |
| 304 for entry in entries: | |
| 305 entry.Print() | |
| 306 | |
| 307 | |
| 308 if __name__ == '__main__': | |
| 309 main() | |
| 310 | |
| OLD | NEW |