964645 - Autophone - improve logging, error recovery and throbber measurements.

Status: RESOLVED FIXED

(Testing Graveyard :: Autophone, defect)

Description

[Bob Clary [:bc] (inactive)]

Attachment: bug-xxxx.patch

As part of the preparation for enabling multiple repositories for autophone testing, I have been working on improving the reliability of autophone as well as improving the reliability of the throbber measurements.

This patch does the following:

#1 Replaces devicemanager's logger with the logger used by autophone. This places almost all of the devicemanager's log messages in the device's and autophone's log instead of the .out files.

For example;

2014-01-27 04:23:34,348|INFO|90_21_55_09_87_95_nexus-one|192.168.1.141|Checking SD card.
2014-01-27 04:23:34,349|INFO|90_21_55_09_87_95_nexus-one|192.168.1.141|Connecting to 192.168.1.141:20701...
2014-01-27 04:23:34,531|INFO|90_21_55_09_87_95_nexus-one|192.168.1.141|Connected.
2014-01-27 04:23:34,532|DEBUG|90_21_55_09_87_95_nexus-one|192.168.1.141|sent cmd: isdir /mnt/sdcard/tests
2014-01-27 04:23:34,532|DEBUG|90_21_55_09_87_95_nexus-one|192.168.1.141|recv'ing...
2014-01-27 04:23:34,563|DEBUG|90_21_55_09_87_95_nexus-one|192.168.1.141|response: TRUE
$>^@

Since mozlog uses the non-standard warn method, I had to add that to the LogDecorator as well.

#2 Adds the ability to retry certain device accesses in the event of failures. I found that my 'unreliable' devices were suffering from temporary failures attempting to use devicemanagerSUT to communicate with the device. Attempting up to 2 times with a 15 second wait between attempts seems to help my gs3 and nexus 7 devices considerably.

#3 Attempt to disable health reporting via the pref datareporting.healthreport.service.enabled: False

#4 Attempt to improve the reliability of the throbber measurements by

  a) Setting the std error threshold to 0 to force all iterations to be completed.

  b) Filtering the logcat messages that are returned when attempting to measure throbber start and stop. Reducing the amount of logcat traffic returned from the device can only help reduce extraneous influences.

  c) Changing the measurement of the starttime, throbber start and throbber stop to use the logcat's time stamps rather then the device's uptimemillis and zerda times. I performed a number of tests with various iterations with and without this change and documented the results at http://people.mozilla.org/~bclary/log/2014/01/27/autophone/index.html

I am considering an additional change to the throbber measurement by moving the process detection outside of the loop so that I am not sending additional ps commands to the SUTAgent while the test is running. I haven't included that change in this patch since it was not included in the test data I used when evaluating the patch.

I have been running #1 and #2 on my production autophone instance already. I am not sure that #3 is sufficient or if there are other preferences I should set to disable unneeded and potentially noisy services.

mfinkle, blassey:

Any other preferences I should use to disable extraneous services?

Please take a look at http://people.mozilla.org/~bclary/log/2014/01/27/autophone/index.html and let me know if you agree with my changing the iteration count to 4.

Comment 1

[Mark Côté [:mcote]]

Comment on attachment 8366478 [details] [diff] [review]
bug-xxxx.patch

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

Looks good to me.

::: logdecorator.py
@@ +20,5 @@
>          extradict = dict(self._extradict)
>          try:
> +            # If the message is actualy an object, such as DMError,
> +            # convert it to a string.
> +            message = "%s" % message

Use str(message) instead, since that's actually what string interpolation does underneath.

::: tests/s1s2test.py
@@ +110,1 @@
>          if not success:

You could just combine this with the above line now, like you did with self.create_profile() below.

@@ +387,5 @@
> +        start_time = 0
> +        throbber_start_time = 0
> +        throbber_stop_time = 0
> +        zerda_start_time = 0
> +        zerda_stop_time = 0

Are the zerda_*_time vars just for logging purposes?

@@ +467,5 @@
> +                base_time.replace(year=year-1)
> +                start_time.replace(year=year-1)
> +                throbber_start_time.replace(year-1)
> +            else:
> +                pass

You can just get rid of the else: ...

@@ +479,5 @@
> +
> +            self.loggerdeco.debug('analyze_logcat: base: %s, start: %s, '
> +                                  'throbber start: %s, throbber stop: %s, '
> +                                  'throbber time: %s, '
> +                                  'zerda start: %s, zerda stop: %s, ' 

Trailing space.

Comment 2

[Bob Clary [:bc] (inactive)]

(In reply to Mark Côté ( :mcote ) from comment #1)
> Comment on attachment 8366478 [details] [diff] [review]
> bug-xxxx.patch
> 
> Review of attachment 8366478 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> Looks good to me.
> 
> ::: logdecorator.py
> @@ +20,5 @@
> >          extradict = dict(self._extradict)
> >          try:
> > +            # If the message is actualy an object, such as DMError,
> > +            # convert it to a string.
> > +            message = "%s" % message
> 
> Use str(message) instead, since that's actually what string interpolation
> does underneath.
> 

If I recall correctly, I actually tried that in testing for a bit but hit something like:

>>> d = DMError(u'\xfdfd')
>>> '%s' % d
u'\xfdfd'
>>> str(d)
Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
UnicodeEncodeError: 'ascii' codec can't encode character u'\xfd' in position 0: ordinal not in range(128)


> ::: tests/s1s2test.py
> @@ +110,1 @@
> >          if not success:
> 
> You could just combine this with the above line now, like you did with
> self.create_profile() below.
> 

Ah, right.

> @@ +387,5 @@
> > +        start_time = 0
> > +        throbber_start_time = 0
> > +        throbber_stop_time = 0
> > +        zerda_start_time = 0
> > +        zerda_stop_time = 0
> 
> Are the zerda_*_time vars just for logging purposes?
> 

Yeah. I wanted to make sure the new values matched up with zerda's. Shall I just remove them altogether or leave them ?

> @@ +467,5 @@
> > +                base_time.replace(year=year-1)
> > +                start_time.replace(year=year-1)
> > +                throbber_start_time.replace(year-1)
> > +            else:
> > +                pass
> 
> You can just get rid of the else: ...
> 

Ok. I really wish emacs could reformat python if statements properly.

> @@ +479,5 @@
> > +
> > +            self.loggerdeco.debug('analyze_logcat: base: %s, start: %s, '
> > +                                  'throbber start: %s, throbber stop: %s, '
> > +                                  'throbber time: %s, '
> > +                                  'zerda start: %s, zerda stop: %s, ' 
> 
> Trailing space.

Ok.

I'm testing my idea locally for removing the call to self.is_fennec_running(app_name) in the loop that slurps the logcat looking for the throbbers on a nexus one and gs2.

The downside is that if the browser crashes or otherwise does not emit both throbber start and stop, we will wait the full 90s before terminating. I think that is worth not doing extra stuff with the device during a measurement loop.

Think that is ok?

Comment 3

[Mark Côté [:mcote]]

(In reply to Bob Clary [:bc:] from comment #2)
> > Use str(message) instead, since that's actually what string interpolation
> > does underneath.
> > 
> 
> If I recall correctly, I actually tried that in testing for a bit but hit
> something like:
> 
> >>> d = DMError(u'\xfdfd')
> >>> '%s' % d
> u'\xfdfd'
> >>> str(d)
> Traceback (most recent call last):
>   File "<stdin>", line 1, in <module>
> UnicodeEncodeError: 'ascii' codec can't encode character u'\xfd' in position
> 0: ordinal not in range(128)

Huh yeah.  I guess string interpolation does do a bit more magic.  Stupid unicode.  That's fine then.

> > @@ +387,5 @@
> > > +        start_time = 0
> > > +        throbber_start_time = 0
> > > +        throbber_stop_time = 0
> > > +        zerda_start_time = 0
> > > +        zerda_stop_time = 0
> > 
> > Are the zerda_*_time vars just for logging purposes?
> > 
> 
> Yeah. I wanted to make sure the new values matched up with zerda's. Shall I
> just remove them altogether or leave them ?

I guess that's up to you.  If you think they will be useful for debugging, you can leave them in, maybe with a comment.

> I'm testing my idea locally for removing the call to
> self.is_fennec_running(app_name) in the loop that slurps the logcat looking
> for the throbbers on a nexus one and gs2.
> 
> The downside is that if the browser crashes or otherwise does not emit both
> throbber start and stop, we will wait the full 90s before terminating. I
> think that is worth not doing extra stuff with the device during a
> measurement loop.
> 
> Think that is ok?

Up to you, since you're the one who will be dealing with the delays. :) It's fine with me if it's fine with you!

Comment 4

[Mark Finkle (:mfinkle) (use needinfo?)]

(In reply to Bob Clary [:bc:] from comment #0)

> I have been running #1 and #2 on my production autophone instance already. I
> am not sure that #3 is sufficient or if there are other preferences I should
> set to disable unneeded and potentially noisy services.
> 
> mfinkle, blassey:
> 
> Any other preferences I should use to disable extraneous services?
> 
> Please take a look at
> http://people.mozilla.org/~bclary/log/2014/01/27/autophone/index.html and
> let me know if you agree with my changing the iteration count to 4.

There is "browser.snippets.enabled", but leaving this enabled found a performance regression, so I am torn:
http://mxr.mozilla.org/mozilla-central/source/mobile/android/app/mobile.js#821

You could try it and see if it helps the noise. We have a fix for the regression in the works.

Comment 5

[Bob Clary [:bc] (inactive)]

Attachment: bug-xxxx-v2.patch

v2 of patch I checked in.

Comment 6

[Bob Clary [:bc] (inactive)]

https://github.com/mozilla/autophone/commit/61f11d6fad1586a3b47c6c89e45d6d76086dba7f

I'll need to do something similar for tests/runtestsremote.py.

Comment 7

[Bob Clary [:bc] (inactive)]

I missed the fact that Android 4.2+ have an -user in the logcat line for starting Firefox. I went ahead and fixed it and pushed.

https://github.com/mozilla/autophone/commit/56e22e7f422ccc5a86f307a146534778a6aaa38f

Comment 8

[Brad Lassey [:blassey] (use needinfo?)]

clearing ni