1035794 - Make talos pageloader addon logs more readable/informative for humans

Status: RESOLVED FIXED

(Testing :: Talos, defect)

Description

[Avi Halachmi (:avih)]

Here's a sample from tscrollx log as it appears on the talos run logs (this is from a local run though with 5 tppagecycles):

> |0;tiled.html;3.201242916540756;3.1733981526987423;3.2949227673317596;3.170702278660242;3.0418815561999755
> |1;tiled-fixed.html;3.631526622740206;3.5975789293263722;4.051485202254075;3.7941154711936895;3.608586884756151
> |2;tiled-downscale.html;3.4860675611220735;3.334567000891805;4.0740232762709585;3.4918798749999995;3.4095411244586074
> |3;tiled-fixed-downscale.html;3.679511290442154;3.554806442280809;3.699679547052711;3.59577144147409;3.666771454495091
> |4;iframe.svg;5.270385247143827;5.121561659118311;4.921048208736382;5.2655628857199845;5.098445835630378
> |5;reader.htm;4.516483122186724;4.485920536404889;4.514902479503446;4.646722628796783;4.58047399474249

As you can tell, it's not easy to real this. What I think could help read and analyze the output:
1. Pretty print of the results (spacing, 1-2 decimal points, etc).
2. Some stats (e.g. average and stddev)

3. Optionally and arguably, replicate the graph server "score" formula and DataZilla "datapoint" formula and display them too at the log. This will be duplicating formulas which are defined elsewhere, but since both should be rather simple formulas, and neither of those change frequently (or at all), I think it's not a big burden to make sure they match, and even if they don't match for a while, it's not the end of the world. Also, we could display it as "Estimated GS/DZ score: ...".


One potential issue we could have, is that the place where the above log outputs (and where it's probably the easiest to add the extra outputs) is being parsed further, so we can't interrupt that parsing with more prints. We have two possible approaches for this, depending on how hard/easy they would be to implement once we start looking at the code:

1. Output the pretty print + extra info outside of the parsed section.
2. Allow the parser to ignore some lines, e.g. which start with '#', and use this prefix for our extra output.

Comment 1

[Avi Halachmi (:avih)]

Attachment: bug1035794.v1.patch

Sample output, the original report outputs as is, the humane report follows:

> __start_tp_report
> _x_x_mozilla_page_load
> _x_x_mozilla_page_load_details
> |i|pagename|runs|
> |0;tiled.html;3.3815091755057654;3.577835266553349;3.508966494191598;3.447223707058441;3.314750318531658;3.140813430410517;3.3392423486641514;3.233077927484977;3.3050938524742106;3.3540684618304053
> |1;tiled-fixed.html;3.624484952346899;3.6518098923895654;3.935018187955001;3.6616317493508603;3.621640228800737;3.7637559070217796;3.865235040167698;3.6840445795492816;3.628697694940594;3.794672192405117
> |2;tiled-downscale.html;3.4552876949845635;3.654456146851113;3.528451905391933;3.539169235961196;3.528513336299076;3.7372342942263685;3.730273699901622;3.5353865097175032;3.5594225335008196;3.6757584952665634
> |3;tiled-fixed-downscale.html;3.7185663866364753;4.112555872325603;3.681714930532242;3.901207561754347;3.7640417970127147;3.7446414439915;3.9544020018858292;4.115511644050064;3.6725380980959486;3.6779581942877244
> |4;iframe.svg;5.528177095596724;5.347954855713156;5.014351267798297;5.487206753127875;5.174338738897633;5.40450642030757;5.539734997455123;5.115851478957898;5.144999449564771;5.100771061732723
> |5;reader.htm;4.571843632628734;4.760853955860159;4.755946420904359;4.659921411854664;4.548349935811288;4.478935883074669;4.768172283297449;4.459165288385159;4.457156993431014;4.505733413762401
> __end_tp_report
> __start_cc_report
> _x_x_mozilla_cycle_collect,3903
> __end_cc_report
> __startTimestamp1405123632973__endTimestamp
> 
> ------- Summary: start -------
> Number of tests: 6
> 
> [#0] tiled.html  Cycles:10  Average:3.36  Median:3.37  stddev:0.13, stddev-sans-first: 0.14
> Values: 3.4  3.6  3.5  3.4  3.3  3.1  3.3  3.2  3.3  3.4
> 
> [#1] tiled-fixed.html  Cycles:10  Average:3.72  Median:3.72  stddev:0.11, stddev-sans-first: 0.11
> Values: 3.6  3.7  3.9  3.7  3.6  3.8  3.9  3.7  3.6  3.8
> 
> [#2] tiled-downscale.html  Cycles:10  Average:3.59  Median:3.61  stddev:0.10, stddev-sans-first: 0.09
> Values: 3.5  3.7  3.5  3.5  3.5  3.7  3.7  3.5  3.6  3.7> 
> 
> [#3] tiled-fixed-downscale.html  Cycles:10  Average:3.83  Median:3.83  stddev:0.18, stddev-sans-first: 0.18
> Values: 3.7  4.1  3.7  3.9  3.8  3.7  4.0  4.1  3.7  3.7
> 
> [#4] iframe.svg  Cycles:10  Average:5.29  Median:5.38  stddev:0.20, stddev-sans-first: 0.19
> Values: 5.5  5.3  5.0  5.5  5.2  5.4  5.5  5.1  5.1  5.1
> 
> [#5] reader.htm  Cycles:10  Average:4.60  Median:4.62  stddev:0.13, stddev-sans-first: 0.14
> Values: 4.6  4.8  4.8  4.7  4.5  4.5  4.8  4.5  4.5  4.5
> -------- Summary: end --------

Comment 2

[Avi Halachmi (:avih)]

Attachment: bug1035794.v2.patch - add stddev percentage

This adds percentage (of the average) to the stddev value. E.g.:
> stddev:0.15 (3.8%)

Which allows quicker evaluation of the consistency of the values.

Comment 3

[Avi Halachmi (:avih)]

(In reply to Avi Halachmi (:avih) from comment #2)
> This adds percentage (of the average) to the stddev value. E.g.:

^ typo - it's actually percentage of the median. Since we usually/always use medians, I've used it also as a base for the percentage value.

Comment 4

[Joel Maher ( :jmaher ) (UTC -8)]

Comment on attachment 8454823 [details] [diff] [review]
bug1035794.v2.patch - add stddev percentage

Review of attachment 8454823 [details] [diff] [review]:
-----------------------------------------------------------------

this looks great.  I would change getReportHumane to getReportSummary

Comment 5

[Avi Halachmi (:avih)]

Attachment: bug1035794.v3.patch - rename function and minor format fix

Carrying r+

Thanks!

https://hg.mozilla.org/build/talos/rev/32835ed2e5e7

Comment 6

[Joel Maher ( :jmaher ) (UTC -8)]

shall we close this?

Comment 7

[Avi Halachmi (:avih)]

Yeah, it works well.