ftrace_importer_test.html revision 8d2b206a675ec20ea07100c35df34e65ee1e45e8
1<!DOCTYPE html>
2<!--
3Copyright (c) 2013 The Chromium Authors. All rights reserved.
4Use of this source code is governed by a BSD-style license that can be
5found in the LICENSE file.
6-->
7
8<link rel="import" href="/tracing/core/test_utils.html">
9<link rel="import" href="/tracing/extras/importer/linux_perf/ftrace_importer.html">
10<link rel="import" href="/tracing/base/xhr.html">
11
12<script>
13'use strict';
14
15tr.b.unittest.testSuite(function() {
16  var LinuxPerfImporter = tr.e.importer.linux_perf.LinuxPerfImporter;
17  var LinuxPerfImporterTestExports =
18      tr.e.importer.linux_perf._LinuxPerfImporterTestExports;
19
20  function newModel(events) {
21    return tr.c.TestUtils.newModelWithEvents([events], {
22      shiftWorldToZero: false
23    });
24  }
25
26  test('lineParserWithLegacyFmt', function() {
27    var p = LinuxPerfImporterTestExports.lineParserWithLegacyFmt;
28    var x = p('   <idle>-0     [001]  4467.843475: sched_switch: ' +
29        'prev_comm=swapper prev_pid=0 prev_prio=120 prev_state=R ==> ' +
30        'next_comm=SurfaceFlinger next_pid=178 next_prio=112');
31    assert.isNotNull(x);
32    assert.equal(x.threadName, '<idle>');
33    assert.equal(x.pid, '0');
34    assert.equal(x.cpuNumber, '001');
35    assert.equal(x.timestamp, '4467.843475');
36    assert.equal(x.eventName, 'sched_switch');
37    assert.equal('prev_comm=swapper prev_pid=0 prev_prio=120 prev_state=R' +
38        ' ==> next_comm=SurfaceFlinger next_pid=178 next_prio=112', x.details);
39
40    var x = p('Binder-Thread #-647   [001]   260.464294: sched_switch: ' +
41        'prev_comm=Binder Thread # prev_pid=647 prev_prio=120 prev_state=D ' +
42        ' ==> next_comm=.android.chrome next_pid=1562 next_prio=120');
43    assert.isNotNull(x);
44    assert.equal(x.threadName, 'Binder-Thread #');
45    assert.equal(x.pid, '647');
46  });
47
48  test('lineParserWithIRQInfo', function() {
49    var p = LinuxPerfImporterTestExports.lineParserWithIRQInfo;
50    var x = p('     systrace.sh-5441  [001] d...  1031.091570: ' +
51        'sched_wakeup: comm=debugd pid=4978 prio=120 success=1 target_cpu=000');
52    assert.isNotNull(x);
53    assert.equal(x.threadName, 'systrace.sh');
54    assert.equal(x.pid, '5441');
55    assert.equal(x.cpuNumber, '001');
56    assert.equal(x.timestamp, '1031.091570');
57    assert.equal(x.eventName, 'sched_wakeup');
58    assert.equal(x.details, 'comm=debugd pid=4978 prio=120 success=1 target_cpu=000'); // @suppress longLineCheck
59  });
60
61  test('lineParserWithIRQInfoNeedResched', function() {
62    var p = LinuxPerfImporterTestExports.lineParserWithIRQInfo; // @suppress longLineCheck
63    var x = p('     systrace.sh-5441  [001] .N..  1031.091570: ' +
64        'sched_wakeup: comm=debugd pid=4978 prio=120 success=1 target_cpu=000');
65    assert.isNotNull(x);
66    assert.equal(x.threadName, 'systrace.sh');
67    assert.equal(x.pid, '5441');
68    assert.equal(x.cpuNumber, '001');
69    assert.equal(x.timestamp, '1031.091570');
70    assert.equal(x.eventName, 'sched_wakeup');
71    assert.equal(x.details, 'comm=debugd pid=4978 prio=120 success=1 target_cpu=000'); // @suppress longLineCheck
72
73    var x = p('     systrace.sh-5441  [001] .n..  1031.091570: ' +
74        'sched_wakeup: comm=debugd pid=4978 prio=120 success=1 target_cpu=000');
75    assert.isNotNull(x);
76    assert.equal(x.threadName, 'systrace.sh');
77
78    var x = p('     systrace.sh-5441  [001] .p..  1031.091570: ' +
79        'sched_wakeup: comm=debugd pid=4978 prio=120 success=1 target_cpu=000');
80    assert.isNotNull(x);
81    assert.equal(x.threadName, 'systrace.sh');
82  });
83
84  test('lineParserWithTGID', function() {
85    var p = LinuxPerfImporterTestExports.lineParserWithTGID;
86    var x = p('     systrace.sh-5441  (54321) [001] d...  1031.091570: ' +
87        'sched_wakeup: comm=debugd pid=4978 prio=120 success=1 target_cpu=000');
88    assert.isNotNull(x);
89    assert.equal(x.threadName, 'systrace.sh');
90    assert.equal(x.pid, '5441');
91    assert.equal(x.tgid, '54321');
92    assert.equal(x.cpuNumber, '001');
93    assert.equal(x.timestamp, '1031.091570');
94    assert.equal(x.eventName, 'sched_wakeup');
95    assert.equal(x.details, 'comm=debugd pid=4978 prio=120 success=1 target_cpu=000'); // @suppress longLineCheck
96
97    var x = p('     systrace.sh-5441  (  321) [001] d...  1031.091570: ' +
98        'sched_wakeup: comm=debugd pid=4978 prio=120 success=1 target_cpu=000');
99    assert.isNotNull(x);
100    assert.equal(x.tgid, '321');
101
102    var x = p('     systrace.sh-5441  (-----) [001] d...  1031.091570: ' +
103        'sched_wakeup: comm=debugd pid=4978 prio=120 success=1 target_cpu=000');
104    assert.isNotNull(x);
105    assert.isUndefined(x.tgid);
106  });
107
108  test('lineParserWithTGIDNeedResched', function() {
109    var p = LinuxPerfImporterTestExports.lineParserWithTGID;
110    var x = p('     systrace.sh-5441  (54321) [001] .N..  1031.091570: ' +
111        'sched_wakeup: comm=debugd pid=4978 prio=120 success=1 target_cpu=000');
112    assert.isNotNull(x);
113    assert.equal(x.threadName, 'systrace.sh');
114    assert.equal(x.pid, '5441');
115    assert.equal(x.tgid, '54321');
116    assert.equal(x.cpuNumber, '001');
117    assert.equal(x.timestamp, '1031.091570');
118    assert.equal(x.eventName, 'sched_wakeup');
119    assert.equal(x.details, 'comm=debugd pid=4978 prio=120 success=1 target_cpu=000'); // @suppress longLineCheck
120
121    var x = p('     systrace.sh-5441  (  321) [001] .n..  1031.091570: ' +
122        'sched_wakeup: comm=debugd pid=4978 prio=120 success=1 target_cpu=000');
123    assert.isNotNull(x);
124    assert.equal(x.tgid, '321');
125
126    var x = p('     systrace.sh-5441  (-----) [001] .p..  1031.091570: ' +
127        'sched_wakeup: comm=debugd pid=4978 prio=120 success=1 target_cpu=000');
128    assert.isNotNull(x);
129    assert.isUndefined(x.tgid);
130  });
131
132  test('autodetectLineCornerCases', function() {
133    var detectParser =
134        LinuxPerfImporterTestExports.autoDetectLineParser;
135    var lineParserWithLegacyFmt =
136        LinuxPerfImporterTestExports.lineParserWithLegacyFmt;
137    var lineParserWithIRQInfo =
138        LinuxPerfImporterTestExports.lineParserWithIRQInfo;
139    var lineParserWithTGID =
140        LinuxPerfImporterTestExports.lineParserWithTGID;
141
142    var lineWithLegacyFmt =
143        'systrace.sh-8170  [001] 15180.978813: sched_switch: ' +
144        'prev_comm=systrace.sh prev_pid=8170 prev_prio=120 ' +
145        'prev_state=x ==> next_comm=kworker/1:0 next_pid=7873 ' +
146        'next_prio=120';
147    var detected = detectParser(lineWithLegacyFmt);
148    assert.equal(lineParserWithLegacyFmt, detected);
149
150    var lineWithIRQInfo =
151        'systrace.sh-8170  [001] d... 15180.978813: sched_switch: ' +
152        'prev_comm=systrace.sh prev_pid=8170 prev_prio=120 ' +
153        'prev_state=x ==> next_comm=kworker/1:0 next_pid=7873 ' +
154        'next_prio=120';
155    var detected = detectParser(lineWithIRQInfo);
156    assert.equal(lineParserWithIRQInfo, detected);
157
158    var lineWithTGID =
159        'systrace.sh-8170  (54321) [001] d... 15180.978813: sched_switch: ' +
160        'prev_comm=systrace.sh prev_pid=8170 prev_prio=120 ' +
161        'prev_state=x ==> next_comm=kworker/1:0 next_pid=7873 ' +
162        'next_prio=120';
163    var detected = detectParser(lineWithTGID);
164    assert.equal(lineParserWithTGID, detected);
165  });
166
167  test('traceEventClockSyncRE', function() {
168    var re = LinuxPerfImporterTestExports.traceEventClockSyncRE;
169    var x = re.exec('trace_event_clock_sync: parent_ts=19581477508');
170    assert.isNotNull(x);
171    assert.equal(x[1], '19581477508');
172
173    var x = re.exec('trace_event_clock_sync: parent_ts=123.456');
174    assert.isNotNull(x);
175    assert.equal(x[1], '123.456');
176  });
177
178  test('genericClockSync', function() {
179    var lines = [
180      '# tracer: nop',
181      '#',
182      '#           TASK-PID    CPU#    TIMESTAMP  FUNCTION',
183      '#              | |       |          |         |',
184      'sh-26121 [000] ...1 107464.0: tracing_mark_write: trace_event_clock_sync: name=battor regulator=8941_smbb_boost' // @suppress longLineCheck
185    ];
186    var m = newModel(lines.join('\n'));
187    assert.isFalse(m.hasImportWarnings);
188
189    var battorSyncs = m.getClockSyncRecordsNamed('battor');
190    assert.equal(battorSyncs.length, 1);
191    assert.equal(battorSyncs[0].ts, 107464000.0);
192    assert.equal(battorSyncs[0].args.perfTS, 107464000.0);
193    assert.equal(battorSyncs[0].args.regulator, '8941_smbb_boost');
194  });
195
196  test('canImport', function() {
197    var lines = [
198      '# tracer: nop',
199      '#',
200      '#           TASK-PID    CPU#    TIMESTAMP  FUNCTION',
201      '#              | |       |          |         |',
202      '          <idle>-0     [001]  4467.843475: sched_switch: ' +
203          'prev_comm=swapper prev_pid=0 prev_prio=120 prev_state=R ==> ' +
204          'next_comm=SurfaceFlinger next_pid=178 next_prio=112',
205
206      '  SurfaceFlinger-178   [001]  4467.843536: sched_switch: ' +
207          'prev_comm=SurfaceFlinger prev_pid=178 prev_prio=112 prev_state=S ' +
208          '==> next_comm=kworker/u:2 next_pid=2844 next_prio=120',
209
210      '     kworker/u:2-2844  [001]  4467.843567: sched_switch: ' +
211          'prev_comm=kworker/u:2 prev_pid=2844 prev_prio=120 prev_state=S ' +
212          '==> next_comm=swapper next_pid=0 next_prio=120',
213
214      '          <idle>-0     [001]  4467.844208: sched_switch: ' +
215          'prev_comm=swapper prev_pid=0 prev_prio=120 prev_state=R ==> ' +
216          'next_comm=kworker/u:2 next_pid=2844 next_prio=120'
217    ];
218    assert.isTrue(LinuxPerfImporter.canImport(lines.join('\n')));
219
220    var lines = [
221      '          <idle>-0     [001]  4467.843475: sched_switch: ' +
222          'prev_comm=swapper prev_pid=0 prev_prio=120 prev_state=R ==> ' +
223              'next_comm=SurfaceFlinger next_pid=178 next_prio=112'
224    ];
225    assert.isTrue(LinuxPerfImporter.canImport(lines.join('\n')));
226
227    var lines = [
228      '          <idle>-0     [001]  4467.843475: sched_switch: ' +
229          'prev_comm=swapper prev_pid=0 prev_prio=120 prev_state=R ==> ' +
230          'next_comm=SurfaceFlinger next_pid=178 next_prio=112',
231
232      '  SurfaceFlinger-178   [001]  4467.843536: sched_switch: ' +
233          'prev_comm=SurfaceFlinger prev_pid=178 prev_prio=112 ' +
234          'prev_state=S ==> next_comm=kworker/u:2 next_pid=2844 ' +
235          'next_prio=120'
236    ];
237    assert.isTrue(LinuxPerfImporter.canImport(lines.join('\n')));
238
239    var lines = [
240      'SomeRandomText',
241      'More random text'
242    ];
243    assert.isFalse(LinuxPerfImporter.canImport(lines.join('\n')));
244  });
245
246  test('canImport34AndLater', function() {
247    var lines = [
248      '# tracer: nop',
249      '#',
250      '# entries-in-buffer/entries-written: 55191/55191   #P:2',
251      '#',
252      '#                              _-----=> irqs-off',
253      '#                             / _----=> need-resched',
254      '#                            | / _---=> hardirq/softirq',
255      '#                            || / _--=> preempt-depth',
256      '#                            ||| /     delay',
257      '#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION',
258      '#              | |       |   ||||       |         |',
259      '     systrace.sh-5441  [001] d...  1031.091570: sched_wakeup: ' +
260          'comm=debugd pid=4978 prio=120 success=1 target_cpu=000',
261      '     systrace.sh-5441  [001] d...  1031.091584: sched_switch: ' +
262          'prev_comm=systrace.sh prev_pid=5441 prev_prio=120 prev_state=x ' +
263          '==> next_comm=chrome next_pid=5418 next_prio=120'
264    ];
265    assert.isTrue(LinuxPerfImporter.canImport(lines.join('\n')));
266
267    var lines = [
268      '     systrace.sh-5441  [001] d...  1031.091570: sched_wakeup: ' +
269          'comm=debugd pid=4978 prio=120 success=1 target_cpu=000',
270      '     systrace.sh-5441  [001] d...  1031.091584: sched_switch: ' +
271          'prev_comm=systrace.sh prev_pid=5441 prev_prio=120 prev_state=x ' +
272          '==> next_comm=chrome next_pid=5418 next_prio=120'
273    ];
274    assert.isTrue(LinuxPerfImporter.canImport(lines.join('\n')));
275  });
276
277  test('importOneSequence', function() {
278    var lines = [
279      '          <idle>-0     [001]  4467.843475: sched_switch: ' +
280          'prev_comm=swapper prev_pid=0 prev_prio=120 prev_state=R ==> ' +
281          'next_comm=SurfaceFlinger next_pid=178 next_prio=112',
282
283      '  SurfaceFlinger-178   [001]  4467.843536: sched_switch: ' +
284          'prev_comm=SurfaceFlinger prev_pid=178 prev_prio=112 ' +
285          'prev_state=S ==> next_comm=kworker/u:2 next_pid=2844 ' +
286          'next_prio=120',
287
288      '     kworker/u:2-2844  [001]  4467.843567: sched_switch: ' +
289          'prev_comm=kworker/u:2 prev_pid=2844 prev_prio=120 ' +
290          'prev_state=S ==> next_comm=swapper next_pid=0 next_prio=120'
291    ];
292    var m = newModel(lines.join('\n'));
293    assert.isFalse(m.hasImportWarnings);
294
295    var c = m.kernel.cpus[1];
296    assert.equal(c.slices.length, 2);
297
298    assert.equal(c.slices[0].title, 'SurfaceFlinger');
299    assert.equal(c.slices[0].start, 4467843.475);
300    assert.closeTo(.536 - .475, c.slices[0].duration, 1e-5);
301  });
302
303  test('importOneSequenceWithSpacyThreadName', function() {
304    var lines = [
305      '          <idle>-0     [001]  4467.843475: sched_switch: ' +
306          'prev_comm=swapper prev_pid=0 prev_prio=120 prev_state=R ==> ' +
307          'next_comm=Surface Flinger  next_pid=178 next_prio=112',
308
309      'Surface Flinger -178   [001]  4467.843536: sched_switch: ' +
310          'prev_comm=Surface Flinger  prev_pid=178 prev_prio=112 ' +
311          'prev_state=S ==> next_comm=kworker/u:2 next_pid=2844 ' +
312          'next_prio=120',
313
314      '     kworker/u:2-2844  [001]  4467.843567: sched_switch: ' +
315          'prev_comm=kworker/u:2 prev_pid=2844 prev_prio=120 ' +
316          'prev_state=S ==> next_comm=swapper next_pid=0 next_prio=120'
317    ];
318    var m = newModel(lines.join('\n'));
319    assert.isFalse(m.hasImportWarnings);
320
321    var c = m.kernel.cpus[1];
322    assert.equal(c.slices.length, 2);
323
324    assert.equal(c.slices[0].title, 'Surface Flinger ');
325    assert.equal(c.slices[0].start, 4467843.475);
326    assert.closeTo(.536 - .475, c.slices[0].duration, 1e-5);
327  });
328
329  test('importWithNewline', function() {
330    var lines = [
331      ''
332    ];
333    var m = newModel(lines.join('\n'));
334    assert.isFalse(m.hasImportWarnings);
335  });
336
337  test('importSystraceHtml', function() {
338    var p = tr.b.getAsync(
339        '/test_data/trivial_systrace.html');
340    return p.then(function(data) {
341      var m = newModel(data);
342      assert.isFalse(m.hasImportWarnings);
343
344      assert.isDefined(m.processes[124]);
345      assert.isDefined(m.processes[360]);
346
347      assert.isDefined(m.processes[124].counters['android.StatusBar']);
348      assert.equal(m.processes[124].counters['android.StatusBar'].numSamples,
349                   1);
350      assert.isDefined(m.processes[124].counters['android.VSYNC']);
351      assert.equal(2, m.processes[124].counters['android.VSYNC'].numSamples);
352      assert.isDefined(m.processes[360].counters['android.iq']);
353      assert.equal(1, m.processes[360].counters['android.iq'].numSamples);
354    }, function(err) {
355      throw err;
356    });
357  });
358
359  test('importMultiTraceHtml', function() {
360    var lines = [
361      '<!DoCTYPE hTml>', // check must be case insensitive
362      '<body>',
363      '  <div class="view">',
364      '  <\/div>',
365      '  <script class="trace-data" type="application/text">',
366      'test1',
367      'test2',
368      '  <\/script>',
369      '  <script class="trace-data" type="application/text">',
370      '# tracer: nop',
371      '#',
372      '#            TASK-PID    CPU#    TIMESTAMP  FUNCTION',
373      '#               | |       |          |         |',
374      '     hwc_eventmon-336   [000] 50260.929925: 0: C|124|VSYNC|1',
375      '         Binder_1-340   [000] 50260.935656: 0: C|124|StatusBar|1',
376      '     hwc_eventmon-336   [000] 50260.946573: 0: C|124|VSYNC|0',
377      '      InputReader-419   [000] 50262.538578: 0: C|360|iq|1',
378      '  <\/script>',
379      '<\/body>',
380      '<\/html>'
381    ];
382
383    var m = newModel(lines.join('\n'));
384    assert.isFalse(m.hasImportWarnings);
385
386    assert.isDefined(m.processes[124]);
387    assert.isDefined(m.processes[360]);
388
389    assert.isDefined(m.processes[124].counters['android.StatusBar']);
390    assert.equal(m.processes[124].counters['android.StatusBar'].numSamples,
391                 1);
392    assert.isDefined(m.processes[124].counters['android.VSYNC']);
393    assert.equal(2, m.processes[124].counters['android.VSYNC'].numSamples);
394    assert.isDefined(m.processes[360].counters['android.iq']);
395    assert.equal(1, m.processes[360].counters['android.iq'].numSamples);
396  });
397
398  test('clockSync', function() {
399    var lines = [
400      '          <idle>-0     [001]  4467.843475: sched_switch: ' +
401          'prev_comm=swapper prev_pid=0 prev_prio=120 prev_state=R ' +
402          '==> next_comm=SurfaceFlinger next_pid=178 next_prio=112',
403      '  SurfaceFlinger-178   [001]  4467.843536: sched_switch: ' +
404          'prev_comm=SurfaceFlinger prev_pid=178 prev_prio=112 ' +
405          'prev_state=S ==> next_comm=kworker/u:2 next_pid=2844 ' +
406          'next_prio=120',
407      '     kworker/u:2-2844  [001]  4467.843567: sched_switch: ' +
408          'prev_comm=kworker/u:2 prev_pid=2844 prev_prio=120 ' +
409          'prev_state=S ==> next_comm=swapper next_pid=0 ' +
410          'next_prio=120',
411      '     kworker/u:2-2844  [001]  4467.843000: 0: ' +
412          'trace_event_clock_sync: parent_ts=0.1'
413    ];
414    var m = newModel(lines.join('\n'));
415    assert.isFalse(m.hasImportWarnings);
416
417    var c = m.kernel.cpus[1];
418    assert.equal(c.slices.length, 2);
419
420    assert.closeTo(
421        (467.843475 - (467.843 - 0.1)) * 1000,
422        c.slices[0].start,
423        1e-5);
424  });
425
426  test('clockSyncMarkWrite', function() {
427    var lines = [
428      'systrace.sh-8170  [001] 15180.978813: sched_switch: ' +
429          'prev_comm=systrace.sh prev_pid=8170 prev_prio=120 ' +
430          'prev_state=x ==> next_comm=kworker/1:0 next_pid=7873 ' +
431          'next_prio=120',
432      ' kworker/1:0-7873  [001] 15180.978836: sched_switch: ' +
433          'prev_comm=kworker/1:0 prev_pid=7873 prev_prio=120 ' +
434          'prev_state=S ==> next_comm=debugd next_pid=4404 next_prio=120',
435      '     debugd-4404  [001] 15180.979010: sched_switch: prev_comm=debugd ' +
436          'prev_pid=4404 prev_prio=120 prev_state=S ==> ' +
437          'next_comm=dbus-daemon next_pid=510 next_prio=120',
438      'systrace.sh-8182  [000] 15186.203900: tracing_mark_write: ' +
439          'trace_event_clock_sync: parent_ts=0'
440    ];
441    var m = newModel(lines.join('\n'));
442    assert.isFalse(m.hasImportWarnings);
443
444    var c = m.kernel.cpus[1];
445    assert.equal(c.slices.length, 2);
446
447    assert.closeTo((15180.978813 - 0) * 1000, c.slices[0].start, 1e-5);
448  });
449
450  test('tracingMarkWriteEOLCleanup', function() {
451    var lines = [
452      'systrace.sh-8182  [001] ...1 2068001.677892: tracing_mark_write: ' +
453          'B|9304|test\\n\\',
454      'systrace.sh-8182  [002] ...1 2068991.686415: tracing_mark_write: E\\n\\'
455    ];
456
457    var m = newModel(lines.join('\n'));
458    assert.isFalse(m.hasImportWarnings);
459
460    var c = m.processes[9304].threads[8182].sliceGroup;
461    assert.equal(c.slices.length, 1);
462
463    assert.closeTo((2068001.677892 - 0) * 1000, c.slices[0].start, 1e-5);
464    assert.closeTo(
465        (2068991.686415 - 2068001.677892) * 1000,
466        c.slices[0].duration,
467        1e-5);
468  });
469
470  test('cpuCount', function() {
471    var lines = [
472      'systrace.sh-8170  [001] 15180.978813: sched_switch: ' +
473          'prev_comm=systrace.sh prev_pid=8170 prev_prio=120 ' +
474          'prev_state=x ==> next_comm=kworker/1:0 next_pid=7873 ' +
475          'next_prio=120',
476      ' kworker/1:0-7873  [001] 15180.978836: sched_switch: ' +
477          'prev_comm=kworker/1:0 prev_pid=7873 prev_prio=120 ' +
478          'prev_state=S ==> next_comm=debugd next_pid=4404 next_prio=120',
479      '     debugd-4404  [000] 15180.979010: sched_switch: prev_comm=debugd ' +
480          'prev_pid=4404 prev_prio=120 prev_state=S ==> ' +
481          'next_comm=dbus-daemon next_pid=510 next_prio=120'
482    ];
483    var m = newModel(lines.join('\n'));
484    assert.isFalse(m.hasImportWarnings);
485
486    assert.equal(tr.b.dictionaryLength(m.kernel.cpus), 2);
487    assert.equal(m.kernel.bestGuessAtCpuCount, 2);
488  });
489});
490</script>
491