[NOT FOR REVIEW] Tracing performance assessment for task profiler.

[NOT FOR REVIEW] Tracing performance assessment for task profiler.

tot == top of trunk with default args,
old == top of trunk with enable_memory_task_profiler=false,
see tot.args.gn and old.args.gn.

Test device: Nexus 5.
See perf_cmp.py for comparison metric.

BUG=695522

[kraynov, 2017-02-24 13:57:12]

kraynov@chromium.org changed reviewers:
+ primiano@chromium.org

[kraynov, 2017-02-24 13:57:15]

Submit_10000_TRACE_EVENT0_multithreaded: events_over_multiple_threads
[98, 100, 100, 102, 102, 103, 103, 104, 106, 110, 110, 111, 112, 112, 112, 115,
117, 118, 119, 119, 119, 119, 119, 120, 120, 121, 121, 121, 121, 121, 121, 123,
123, 124, 124, 126, 126, 126, 127, 130, 131, 131, 132, 134, 135, 140, 141, 151,
164, 165]
median(tot)= 121
mean(tot)= 120

[95, 105, 107, 112, 112, 115, 116, 116, 116, 117, 117, 117, 118, 119, 119, 120,
120, 120, 121, 121, 122, 122, 122, 122, 122, 122, 123, 124, 124, 125, 125, 125,
126, 126, 126, 126, 128, 130, 131, 133, 144, 149, 151, 152, 154, 157, 158, 160,
164, 164]
median(old)= 122
mean(old)= 126


Submit_10000_TRACE_EVENT0_in_traceable_tasks: flush
[410, 411, 412, 413, 414, 415, 463, 464, 464, 465, 465, 466, 468, 470, 557, 557,
558, 558, 559, 560, 560, 561, 562, 562, 562, 563, 563, 563, 564, 564, 564, 564,
565, 565, 565, 566, 566, 566, 567, 568, 569, 569, 569, 571, 573, 750, 752, 753,
757, 759]
median(tot)= 563
mean(tot)= 545

[417, 469, 476, 565, 566, 568, 568, 568, 569, 569, 569, 570, 570, 570, 570, 570,
570, 570, 570, 570, 571, 571, 571, 571, 571, 571, 572, 572, 573, 573, 573, 574,
574, 574, 575, 575, 576, 577, 579, 754, 757, 757, 759, 759, 760, 762, 762, 763,
764, 766]
median(old)= 571
mean(old)= 605


Long_TRACE_EVENT0: long_event
[48, 50, 50, 50, 51, 51, 52, 54, 54, 54, 55, 55, 55, 55, 55, 63, 63, 63, 63, 63,
63, 63, 63, 64, 64, 64, 64, 64, 64, 64, 64, 64, 64, 64, 64, 64, 64, 64, 64, 64,
64, 64, 64, 64, 64, 65, 65, 83, 83, 85]
median(tot)= 64
mean(tot)= 61

[50, 54, 54, 62, 62, 62, 62, 62, 62, 62, 62, 62, 62, 62, 62, 62, 62, 62, 62, 63,
63, 63, 63, 63, 63, 63, 63, 63, 63, 63, 63, 63, 63, 64, 64, 64, 64, 64, 65, 81,
82, 82, 82, 82, 83, 83, 83, 83, 84, 84]
median(old)= 63
mean(old)= 66


Submit_10000_TRACE_EVENT0_multithreaded: flush
[258, 259, 260, 261, 265, 266, 293, 293, 294, 294, 294, 296, 298, 299, 350, 350,
351, 352, 352, 352, 352, 352, 353, 353, 353, 354, 354, 355, 355, 355, 356, 357,
357, 358, 358, 359, 361, 362, 362, 362, 363, 364, 364, 365, 368, 370, 471, 476,
476, 481]
median(tot)= 354
mean(tot)= 343

[268, 293, 305, 356, 356, 357, 357, 357, 357, 358, 358, 359, 359, 359, 359, 360,
360, 360, 361, 361, 361, 362, 362, 362, 362, 362, 363, 363, 363, 364, 364, 364,
364, 365, 365, 365, 365, 368, 376, 377, 477, 478, 478, 479, 479, 480, 481, 481,
487, 493]
median(old)= 362
mean(old)= 381


Submit_10000_TRACE_EVENT_with_TracedValue: flush
[5071, 5076, 5079, 5127, 5189, 5205, 5706, 5706, 5714, 5746, 5751, 5795, 5799,
5799, 6953, 6994, 7003, 7026, 7027, 7035, 7054, 7067, 7067, 7069, 7070, 7071,
7082, 7089, 7093, 7098, 7099, 7117, 7118, 7119, 7122, 7127, 7129, 7148, 7149,
7155, 7158, 7166, 7190, 7195, 7229, 7795, 7897, 8654, 8717, 9403]
median(tot)= 7071
mean(tot)= 6760

[5148, 5684, 5735, 6893, 6897, 6913, 6922, 6927, 6927, 6935, 6944, 6945, 6945,
6950, 6951, 6960, 6963, 6965, 6968, 6974, 6977, 6978, 6978, 6979, 6989, 6991,
6997, 7003, 7012, 7016, 7031, 7033, 7137, 7359, 7491, 7628, 7859, 8025, 8065,
8254, 8311, 8395, 8485, 8506, 8869, 8888, 9306, 9318, 9374, 9388]
median(old)= 6991
mean(old)= 7382


Submit_10000_TRACE_EVENT0: events
[53, 53, 54, 54, 54, 56, 56, 57, 58, 58, 59, 59, 59, 60, 60, 62, 63, 63, 63, 63,
64, 64, 64, 64, 64, 65, 65, 65, 65, 65, 65, 67, 67, 68, 68, 68, 68, 69, 69, 69,
69, 69, 70, 70, 70, 71, 71, 86, 90, 92]
median(tot)= 65
mean(tot)= 64

[51, 54, 55, 55, 62, 62, 62, 63, 63, 63, 63, 64, 64, 64, 64, 65, 65, 66, 66, 66,
66, 67, 67, 67, 68, 68, 68, 68, 68, 68, 69, 69, 69, 69, 69, 70, 70, 70, 72, 85,
86, 87, 87, 87, 88, 89, 90, 90, 90, 92]
median(old)= 68
mean(old)= 70


Submit_10000_TRACE_EVENT_with_TracedValue: events_with_value
[124, 124, 124, 125, 126, 128, 136, 137, 138, 139, 140, 141, 142, 143, 162, 163,
163, 163, 163, 163, 163, 163, 164, 164, 164, 164, 164, 164, 164, 164, 164, 164,
165, 165, 165, 165, 165, 165, 165, 165, 166, 166, 167, 167, 168, 168, 169, 222,
222, 222]
median(tot)= 164
mean(tot)= 158

[122, 133, 137, 156, 157, 157, 157, 157, 158, 158, 158, 158, 158, 158, 158, 158,
158, 158, 158, 158, 158, 159, 159, 159, 159, 159, 159, 159, 159, 160, 161, 161,
161, 161, 161, 161, 161, 162, 163, 211, 211, 213, 213, 214, 214, 215, 215, 215,
217, 217]
median(old)= 159
mean(old)= 169


Submit_10000_TRACE_EVENT0_with_tracing_disabled: events
[0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0,
0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0]
median(tot)= 0
mean(tot)= 0

[0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0,
0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0]
median(old)= 0
mean(old)= 0


Long_TRACE_EVENT0: flush
[411, 413, 413, 414, 417, 417, 463, 463, 464, 464, 464, 464, 464, 467, 470, 559,
559, 560, 560, 561, 561, 561, 561, 562, 562, 562, 562, 563, 563, 564, 564, 564,
564, 564, 565, 565, 566, 567, 568, 569, 570, 570, 571, 571, 572, 572, 576, 748,
749, 755]
median(tot)= 562
mean(tot)= 536

[418, 469, 471, 565, 567, 567, 569, 569, 569, 569, 570, 571, 571, 571, 571, 571,
571, 571, 571, 572, 572, 572, 573, 573, 573, 573, 573, 573, 573, 573, 574, 574,
575, 578, 578, 582, 583, 584, 591, 757, 760, 760, 762, 762, 763, 765, 765, 766,
769, 781]
median(old)= 573
mean(old)= 607


Create_10000_TracedValue: create_traced_values
[50, 51, 51, 51, 51, 51, 58, 58, 58, 58, 59, 59, 59, 59, 59, 72, 72, 72, 72, 72,
72, 72, 72, 72, 72, 72, 72, 72, 73, 73, 73, 73, 73, 74, 74, 75, 75, 75, 75, 76,
76, 77, 78, 79, 79, 79, 81, 96, 97, 97]
median(tot)= 72
mean(tot)= 69

[50, 56, 57, 69, 69, 69, 69, 69, 69, 69, 70, 70, 70, 70, 70, 70, 70, 70, 70, 70,
70, 70, 70, 70, 70, 70, 70, 70, 70, 70, 70, 70, 70, 71, 71, 72, 73, 76, 78, 93,
93, 93, 93, 93, 94, 94, 94, 95, 95, 96]
median(old)= 70
mean(old)= 74


Submit_10000_TRACE_EVENT0: flush
[412, 420, 422, 423, 424, 427, 468, 470, 471, 473, 473, 478, 480, 482, 485, 560,
562, 562, 562, 562, 563, 563, 564, 565, 565, 565, 566, 566, 567, 567, 567, 568,
568, 568, 570, 570, 571, 571, 571, 572, 572, 573, 573, 573, 576, 576, 577, 751,
753, 760]
median(tot)= 565
mean(tot)= 541

[442, 473, 474, 475, 567, 568, 568, 568, 569, 570, 571, 571, 571, 571, 572, 572,
572, 572, 573, 575, 575, 576, 577, 577, 577, 577, 577, 578, 579, 579, 579, 580,
580, 580, 582, 583, 583, 583, 584, 756, 757, 764, 764, 768, 769, 770, 770, 773,
779, 782]
median(old)= 577
mean(old)= 608


Submit_10000_TRACE_EVENT0_in_traceable_tasks: events_in_task
[50, 50, 50, 50, 50, 50, 53, 54, 54, 54, 54, 55, 55, 55, 61, 61, 61, 62, 62, 62,
62, 62, 62, 62, 62, 62, 62, 62, 62, 62, 62, 62, 62, 62, 62, 62, 62, 62, 63, 63,
63, 63, 63, 63, 63, 81, 81, 82, 82, 82]
median(tot)= 62
mean(tot)= 60

[49, 54, 54, 62, 62, 62, 62, 62, 62, 62, 62, 62, 62, 62, 62, 62, 62, 62, 62, 62,
62, 62, 62, 62, 62, 62, 62, 62, 62, 63, 63, 63, 63, 63, 63, 63, 63, 63, 63, 63,
80, 81, 81, 81, 81, 81, 82, 82, 82, 82]
median(old)= 62
mean(old)= 65

[kraynov, 2017-02-27 08:36:51]

As I can see in previous figures, regression by median was observed (see
previous message) in tests involving TracedValue. And other graphs (without
TracedValue) look like a noise deviation. So my sespect is that creation of
TracedValue became somehow slower.

I've added test (see patch set #2) which creates 10M TracedValue and got the
following results on Nexus 5:
tot: 55,116ms 55,635ms and 58,842ms
old: 52,906ms 50,187ms and 51,113ms

Looks like regression is here.

[kraynov, 2017-03-02 16:26:00]

Description was changed from

==========
[NOT FOR REVIEW] Tracing performance assessment for task profiler.

tot == top of trunk with default args,
old == top of trunk with enable_memory_task_profiler=false,
see tot.args.gn and old.args.gn.

Test device: Nexus 5.
See perf_cmp.py for comparison metric.

BUG=695522
==========

to

==========
[NOT FOR REVIEW] Tracing performance assessment for task profiler.

tot == top of trunk with default args,
old == top of trunk with enable_memory_task_profiler=false,
see tot.args.gn and old.args.gn.

Test device: Nexus 5.
See perf_cmp.py for comparison metric.

BUG=695522
==========