849831 - Improve s1s2 logcat analysis

Status: RESOLVED FIXED

(Testing Graveyard :: Autophone, defect)

Description

[Bob Clary [:bc] (inactive)]

Attachment: patch

The current method of analyzing the logcat output for throbberstart and throbberstop can be improved:

1. accordring to device manager getInfo, uptimemillis is now always supported on all implementations, therefore a zero starttime should not be use to exclude data points.

2. currently zero throbberstart and/or throbber start results can be submitted to the database.

3. analyze_logcat simply waits 10 seconds for the throbberstop to appear in the logcat output. If it takes longer than 10 seconds, s1s2 will abort the attempt, kill the browser and try another attempt. 

4. currently if we fail to kill the browser on the first attempt, we allow the exception to terminate the test.

This patch 

* allows zero starttime
* prevents zero throbberstart or throbberstop results being submitted
* attempts up to 3 times with 20 second delays to kill the browser
* collects the logcat output every 4 seconds up to a maximum of 15 times (1 minute). This allows the throbber stop to be detected even if the time exceeds 10 seconds.

I've tested this patch over the weekend and it performs very well.

Possibile todo items:

check that the browser process is still running so we can terminate the logcat analysis early if the browser crashes.

change the throbberstop collection condition to require throbberstart being collected first.

Comment 1

[Mark Côté [:mcote]]

Comment on attachment 723464 [details] [diff] [review]
patch

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

Looks good, just a few comments/questions.

::: tests/s1s2test.py
@@ +80,5 @@
>                          attempt = attempt + 1
>  
>                  # Publish results
> +                self.logger.debug('successfully got throbbers: %s after %d attempts' %
> +                                  (success, attempt))

Should this move below the "if success"?

@@ +143,5 @@
>          throbstart = 0
>          throbstop = 0
> +        attempt = 0
> +        max_attempts = 15
> +        buf = [x.strip('\r\n') for x in self.dm.getLogcat()]

I think you can move this to the while block and get rid of the duplicate below.

@@ +154,5 @@
> +                elif throbberstopRE.match(line) and not throbstop:
> +                    throbstop = line.split(' ')[-4]
> +                if throbstart and throbstop:
> +                    break
> +            sleep(4)

This will always be run, since the break above just stops the for loop.  Is this desired?

Comment 2

[Bob Clary [:bc] (inactive)]

(In reply to Mark Côté ( :mcote ) from comment #1)
> Comment on attachment 723464 [details] [diff] [review]
> patch
> 
> Review of attachment 723464 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> Looks good, just a few comments/questions.
> 
> ::: tests/s1s2test.py
> @@ +80,5 @@
> >                          attempt = attempt + 1
> >  
> >                  # Publish results
> > +                self.logger.debug('successfully got throbbers: %s after %d attempts' %
> > +                                  (success, attempt))
> 
> Should this move below the "if success"?
> 

Well, the wording is funky but it will report "succesfully got throbbers: False..." if it fails so we get some indication that it didn't get the throbbers.  I could reword it a bit, but I didn't like the alternatives I cam up with.

> @@ +143,5 @@
> >          throbstart = 0
> >          throbstop = 0
> > +        attempt = 0
> > +        max_attempts = 15
> > +        buf = [x.strip('\r\n') for x in self.dm.getLogcat()]
> 
> I think you can move this to the while block and get rid of the duplicate
> below.
> 

true.

> @@ +154,5 @@
> > +                elif throbberstopRE.match(line) and not throbstop:
> > +                    throbstop = line.split(' ')[-4]
> > +                if throbstart and throbstop:
> > +                    break
> > +            sleep(4)
> 
> This will always be run, since the break above just stops the for loop.  Is
> this desired?

true, doh.

I'll rework this and do a short test before pushing.

Thanks.

Comment 3

[Bob Clary [:bc] (inactive)]

Attachment: updated patch

This is what I'll check in.

Comment 4

[Bob Clary [:bc] (inactive)]

Attachment: patch v2

pegs logcat analysis to 90 seconds

checks if fennec is running and stops logcat analysis if it is not

if fennec is still running and no throbber stop is seen in 90 seconds, pegs thobberstop to throbberstart + 90 seconds.

Comment 5

[Mark Côté [:mcote]]

Comment on attachment 724092 [details] [diff] [review]
patch v2

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

So I guess the pegging won't be uniform on the throbberstop page then?  I suppose there's no way to do it such that it's pegged at a uniform level on both that and the total throbber time views, though... so yeah this is ok.  A few little things below.

::: tests/s1s2test.py
@@ +136,4 @@
>          self._iterations = cfg.getint('settings', 'iterations')
>          self._resulturl = cfg.get('settings', 'resulturl')
>  
> +    def is_fennec_running(self, job):

There's actually a processExist() method in DeviceManagerSUT that returns the pid (or None if not found).

@@ +151,5 @@
>          throbstop = 0
> +        attempt = 0
> +        max_time = 90 # maximum time to wait for throbbers
> +        wait_time = 4 # time to wait between attempts
> +        max_attempts = max_time / wait_time

Did you purposefully pick something that rounds down?  Max_attempts will be 22 for a total time of 88 seconds...

@@ +162,4 @@
>                  break
> +            buf = [x.strip('\r\n') for x in self.dm.getLogcat()]
> +            for line in buf:
> +                line = line.strip()

This is from before your patch, but I just realized that each line is being stripped twice here.  The x.strip('\r\n') can just be x.strip() and the line.strip() can be removed.  Sorry I missed that before.

Comment 6

[Bob Clary [:bc] (inactive)]

https://github.com/mozilla/autophone/commit/cbcf1ca5162e419c10386ff4a8f35bc575f6cc15