840137 - Refine the perf measurement output to be consumable by automation

Status: RESOLVED FIXED

(Firefox OS Graveyard :: Gaia, defect)

Description

[Julien Wajsberg [:julienw]]

Now that Bug 837139 has landed, we can move forward and releng can begin to use the work we did as part of this bug.

Prerequisites:
- a eng build (to have marionette)
- marionette enabled; _disabled_ remote debug
- some workloads (from Bug 837281)
 
We can launch the tests with the following command :

APP=<path> make test-perf

For example:
APP=sms make test-perf

This will output a JSON-serialized object, like:

{
  "stats": {
    "suites": 1,
    "tests": 1,
    "passes": 1,
    "pending": 0,
    "failures": 0,
    "start": "2013-02-11T16:34:42.272Z",
    "end": "2013-02-11T16:35:37.346Z",
    "duration": 55074
  },
  "failures": [],
  "passes": [
    {
      "title": "average startup time ",
      "fullTitle": "SMS average startup time ",
      "duration": 54769,
      "mozPerfDuration": 2016.2
    }
  ]
}

The mozPerfDuration property indicates (in ms) the average duration for this test, that's what you should use.

Working apps include sms, communications/contacts, communications/dialer, clock, gallery.

communications/contacts occasionnally fails, this will be taken care of in Bug 837673.

We're really waiting for any returns you may have: does this suit you, what is missing, what is too much, etc ?

Comment 1

[Jonathan Griffin (:jgriffin)]

FYI, this doesn't involve rel-eng at all, just the Automation & Tools Team and WebQA.

The data reported is just the average time; I think it would be better to report all the individual times so we can graph them (ala https://datazilla.mozilla.org/b2g/).  It's very useful to be able to see individual times in case the average jumps...was it just one outlier, or are all the interations increasing, etc.

In order to send the data to datazilla, we'll need to write a wrapper for it that processes the output.  Currently, the output is sent to stdout but is intermingled with other output, e.g., :

TCPSocket: window init: undefined
TCPSocket: startup called
{ JSON data here }

Can you make a revision to this to dump the JSON output to a file, e.g.,

APP=sms OUTPUT=results.json make test-perf

would result in the JSON output being written to results.json.

This will make it a lot easier to deal with in automation.

Comment 2

[Anthony Ricaud (:rik)]

Attachment: Proposed patch

This outputs all timings and also returns a valid JSON with one option.

I added the NO_DEBUG_OUTPUT option because we have to filter some things for now. Ideally, we should output those on stderr but it proved tricky and we prefer to move fast rather than having a perfect solution.
So all messages starting with "TCPSocket:" or "ERROR:" are filtered with this option.

|NO_DEBUG_OUTPUT=1 make -s test-perf| should output something consumable.

Comment 3

[Julien Wajsberg [:julienw]]

Comment on attachment 715203 [details] [diff] [review]
Proposed patch

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

I have all measurements twice, do you plan to fix this in another bug ?

Also, you should really put the text you're writing in the attachment comment as the commit log :)

::: Makefile
@@ +460,5 @@
>  .PHONY: test-perf
>  test-perf:
>  	adb forward tcp:2828 tcp:2828
>  	SHARED_PERF=`find tests/performance -name "*_test.js" -type f`; \
> +	echo '['; \

I won't be against a comment here

@@ +465,3 @@
>  	for app in ${APPS}; \
>  	do \
> +		if [ -z $${FIRST_LOOP_ITERATION} ]; then \

I learnt something: I thought we would need to put the variable between double-quotes, but my personal test showed that we need not :)

::: tests/js/bin/runner
@@ +8,5 @@
>  
>  if [ ! -x "$XPCSHELL" ]
>  then
>    PATH=$GAIA_DIR/xulrunner-sdk/bin/:$PATH;
> +  if [ -z ${NO_DEBUG_OUTPUT} ]

I wonder if we should not use DEBUG_OUTPUT and remove all debug outputs by default ? or better: VERBOSE=1

I generally don't like "negative" options and this one is no exception.

@@ +10,5 @@
>  then
>    PATH=$GAIA_DIR/xulrunner-sdk/bin/:$PATH;
> +  if [ -z ${NO_DEBUG_OUTPUT} ]
> +  then
> +    echo "xpcshell is not found adding xulrunner-sdk using $GAIA_DIR/xulrunner-sdk/bin/xpcshell."

do we really need this line at all ?

@@ +18,5 @@
> +if [ -z ${NO_DEBUG_OUTPUT} ]
> +then
> +  $XPCWINDOW $DIR/../xpc.js $@
> +else
> +  $XPCWINDOW $DIR/../xpc.js $@ | grep -v "^TCPSocket: " | grep -v "^ERROR: "

please use :
  grep -Ev '^(TCPSocket|ERROR): '
or
  grep -v -e '^TCPSocket: ' -e '^ERROR: '

(one invocation of grep, single-quotes)

::: tests/reporters/jsonmozperf.js
@@ +39,5 @@
>        passes.push({
>          title: test.title + ' ' + title,
>          fullTitle: test.fullTitle() + ' ' + title,
>          duration: test.duration,
> +        mozPerfDuration: global.mozPerfDurations[title],

nit: mozPerfDurations or mozPerfDurationValues

Comment 4

[Julien Wajsberg [:julienw]]

Comment on attachment 715203 [details] [diff] [review]
Proposed patch

Also, we still have these outputs even in "NO_DEBUG_OUTPUT" mode :

  'homescreen' is an excluded app, skipping tests.

Comment 5

[Anthony Ricaud (:rik)]

Attachment: Proposed patch v2

(In reply to Julien Wajsberg [:julienw] from comment #3)
> I have all measurements twice, do you plan to fix this in another bug ?
Opened bug 842616 for that.

> Also, you should really put the text you're writing in the attachment
> comment as the commit log :)
I mostly see one line commits in the project. Readers have a link to the bug for details.

> ::: Makefile
> @@ +460,5 @@
> >  .PHONY: test-perf
> >  test-perf:
> >  	adb forward tcp:2828 tcp:2828
> >  	SHARED_PERF=`find tests/performance -name "*_test.js" -type f`; \
> > +	echo '['; \
> 
> I won't be against a comment here
Done.

> I wonder if we should not use DEBUG_OUTPUT and remove all debug outputs by
> default ? or better: VERBOSE=1
> 
> I generally don't like "negative" options and this one is no exception.
Done.
> 
> @@ +10,5 @@
> >  then
> >    PATH=$GAIA_DIR/xulrunner-sdk/bin/:$PATH;
> > +  if [ -z ${NO_DEBUG_OUTPUT} ]
> > +  then
> > +    echo "xpcshell is not found adding xulrunner-sdk using $GAIA_DIR/xulrunner-sdk/bin/xpcshell."
> 
> do we really need this line at all ?
I think it's useful to be sure which xulrunner-sdk you're running.

> @@ +18,5 @@
> > +if [ -z ${NO_DEBUG_OUTPUT} ]
> > +then
> > +  $XPCWINDOW $DIR/../xpc.js $@
> > +else
> > +  $XPCWINDOW $DIR/../xpc.js $@ | grep -v "^TCPSocket: " | grep -v "^ERROR: "
> 
> please use :
>   grep -Ev '^(TCPSocket|ERROR): '
> or
>   grep -v -e '^TCPSocket: ' -e '^ERROR: '
> 
> (one invocation of grep, single-quotes)
Done.

> ::: tests/reporters/jsonmozperf.js
> @@ +39,5 @@
> >        passes.push({
> >          title: test.title + ' ' + title,
> >          fullTitle: test.fullTitle() + ' ' + title,
> >          duration: test.duration,
> > +        mozPerfDuration: global.mozPerfDurations[title],
> 
> nit: mozPerfDurations or mozPerfDurationValues
mozPerfDurations and mozPerfDurationsAverage

Comment 6

[Julien Wajsberg [:julienw]]

Comment on attachment 715555 [details] [diff] [review]
Proposed patch v2

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

::: Makefile
@@ +460,5 @@
>  .PHONY: test-perf
>  test-perf:
>  	adb forward tcp:2828 tcp:2828
>  	SHARED_PERF=`find tests/performance -name "*_test.js" -type f`; \
> +	# All echo calls help create a JSON array

you need to put this comment before SHARED_PERF because otherwise you're losing the SHARED_PERF env variable for the following script (as the SHARED_PERF line + the comment get executed by one shell invocation, and the rest by another shell invocation).

@@ +466,3 @@
>  	for app in ${APPS}; \
>  	do \
> +		if [ -z $${FIRST_LOOP_ITERATION} ]; then \

also here, double quotes then

::: tests/js/bin/runner
@@ +8,5 @@
>  
>  if [ ! -x "$XPCSHELL" ]
>  then
>    PATH=$GAIA_DIR/xulrunner-sdk/bin/:$PATH;
> +  if [ ! -z ${VERBOSE} ]

if [ -n "${VERBOSE}" ]

(you need the dble quotes here)

@@ +16,3 @@
>  fi
>  
> +if [ -z ${VERBOSE} ]

I've just read that it's safer (and probably more consistent too) to use double quotes here too :

  if [ -z "${VERBOSE}" ]

::: tests/js/xpc.js
@@ +12,4 @@
>    if (excludedApps.indexOf(window.mozTestInfo.appPath) !== -1) {
> +    if (env.get('VERBOSE')) {
> +      console.log("'" + window.mozTestInfo.appPath + "' is an excluded app, skipping tests.");
> +    }

\o/

Comment 7

[Julien Wajsberg [:julienw]]

(In reply to Anthony Ricaud (:rik) from comment #5)
> > Also, you should really put the text you're writing in the attachment
> > comment as the commit log :)
> I mostly see one line commits in the project. Readers have a link to the bug
> for details.

That doesn't mean it's good practice ! Really, finding that the changes description are in comment 2 from the bug number in the commit log is time consuming. The bug number is nice to see the discussion behind the changes but having the actual changes described in the commit log is always a good practice imho.

Also it's nice because it shows off in the "Overview" tab in the Splinter review interface.

Comment 8

[Anthony Ricaud (:rik)]

Attachment: Proposed patch v3

Comment 9

[Anthony Ricaud (:rik)]

Attachment: Proposed patch v4

Comment 10

[Julien Wajsberg [:julienw]]

Comment on attachment 716042 [details] [diff] [review]
Proposed patch v4

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

r=me with the latest nits addressed (if you feel like it). Also add in the commit log that we need to use |make -s| to filter all make commands.

I've got lots of ScriptTimeout but I think this is for another bug.

::: tests/js/xpc.js
@@ +14,5 @@
> +      console.log("'" + window.mozTestInfo.appPath + "' is an excluded app, skipping tests.");
> +    }
> +
> +    var output = {};
> +    output.stats = {"application": window.mozTestInfo.appPath};

nit: I would have put |suites: 0| too

note: you don't need to put application between quotes, stringify will take care of this for you :)

Comment 11

[Anthony Ricaud (:rik)]

https://github.com/mozilla-b2g/gaia/commit/7b14dfbcf9875a63641b963fa210bad9314d5c74

Jonathan, let us know if the output is ok for you. (you might run into bug 842616 while testing)

Comment 12

[Julien Wajsberg [:julienw]]

Jonathan, you need to run this with "make -s", eg:

  make -s test-perf

or

  make -s test-perf APP=sms

or

  make -s test-perf APPS="sms email"

Comment 13

[Jonathan Griffin (:jgriffin)]

Yes, this looks much better, thanks.

Comment 14

[Julien Wajsberg [:julienw]]

Comment on attachment 716042 [details] [diff] [review]
Proposed patch v4

Only changes are in the test framework and the build script (only the tests goals).

Comment 15

[Vivien Nicolas (:vingtetun) (:21) - (NOT reading bugmails, needinfo? please)]

Comment on attachment 716042 [details] [diff] [review]
Proposed patch v4

a=tests

Comment 16

[John Ford [:jhford] CET/CEST Berlin Time]

This doesn't apply cleanly on v1-train

Comment 17

[Julien Wajsberg [:julienw]]

v1-train: b7f3a0da611957859be06f245a8bb8c142f316e3