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 |