888102 - We should track when events are actually triggered on device

Status: RESOLVED FIXED

(Testing Graveyard :: Eideticker, defect)

Description

[William Lachance (:wlach)]

For the purposes of doing responsiveness tests (e.g. how long does it take from the time I press this button to seeing a response?) we should track when orangutan actions are actually triggered on the device. If we synchronize the time between the device and the host, we should be able to map that back to the point in the capture when the action is registered.

This would be useful for more realistic app startup time tests on b2g. The feenec team was also interested in doing responsiveness tests with eideticker (bug 882936), this would be useful there as well.

Comment 1

[William Lachance (:wlach)]

Adding some tags that should be useful for putting this dependant bug into a fxos-perf sprint.

Comment 2

[William Lachance (:wlach)]

Attachment: Patch to orangutan to time input events

Here's a patch to orangutan to optionally output timings for when events are fired. You wind up with a bunch of output like:

START drag <time> ...
 START press <time> ...
 ...
END drag

The idea is that we can correlate this information with the test start inside eideticker and assuming that the clocks are reasonably in sync between the device and machine, we'll have timings for when events in the test are actually occurring!

Comment 3

[William Lachance (:wlach)]

Attachment: 0001-Bug-888102-Add-ability-to-create-a-set-of-input-timi.patch

Here's a patch to hook into the output of orangutan, to produce a json file corresponding to input timings when running eideticker tests. We don't do anything with this information yet, but the baseline is there.

Comment 4

[Geoff Brown [:gbrown]]

Comment on attachment 794910 [details] [diff] [review]
Patch to orangutan to time input events

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

This looks good - just nits and suggestions here.

::: orng.c
@@ +61,5 @@
> +
> +static int print_actions = 0;
> +static int action_indent = 0;
> +
> +void print_action(int start_end, const char *action_desc, int num_args, ...)

I could see myself one day trying to call this with:

print_action(ACTION_START, "mynewaction (param=%s %d)", 2, mystring, 3);

I get that you only need integer arguments now, but I still wonder if it wouldn't be better to support full printf-style format strings.

@@ -139,5 @@
>      write_event(fd, EV_SYN, SYN_REPORT, 0);
>    }
> -}
> -
> -void execute_move_unsynced(int fd, uint32_t device_flags,

You intended to remove this, right? (just checking)

@@ +419,5 @@
> +    }
> +  }
> +
> +  if((argc - optind) != 2) {
> +    fprintf(stderr, "Usage: %s [options] <device> <script file>\n", argv[0]);

Let's report that there is a -t option now!

Comment 5

[William Lachance (:wlach)]

Attachment: 0001-Add-support-for-outputting-input-timings-using-t-par.patch

I decided to change the format of the timings to a JSON-like structure (one structure per event, per line), which will hopefully be easier to parse and extend (referring to your previous comment).

I also updated the help.

I'll send this for re-review since it's a pretty big reworking of the previous patch.

Comment 6

[Geoff Brown [:gbrown]]

Comment on attachment 796252 [details] [diff] [review]
0001-Add-support-for-outputting-input-timings-using-t-par.patch

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

::: orng.c
@@ +292,5 @@
>    int sleeptime = duration_msec / num_steps;
>    int i;
>  
> +  print_action(ACTION_START, "pinch", "\"touch1_x1\": %d, "
> +               "\"touch1_x1\": %d, \"touch1_y1\": %d, \"touch1_x2\": %d,"

You probably want a trailing space:  ... %d, "

@@ +298,5 @@
> +               "\"touch2_x2\": %d, \"touch2_y2\": %d, \"num_steps\": %d, "
> +               "\"duration_msec\": %d",
> +               touch1_x1, touch1_y1, touch1_x2, touch1_y2,
> +               touch2_x1, touch2_y1, touch2_x2, touch2_y2,
> +               num_steps, duration_msec);

Unless my eyes fail me (all those embedded quotes!), there are 11 %d's but only 10 arguments here. There is an extra "touch1_x1: %d".

Comment 7

[Geoff Brown [:gbrown]]

Comment on attachment 794915 [details] [diff] [review]
0001-Bug-888102-Add-ability-to-create-a-set-of-input-timi.patch

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

::: src/eideticker/eideticker/test.py
@@ +136,4 @@
>              self.log("Starting capture on device '%s' with mode: '%s'" % (
>                      self.capture_metadata['device'],
>                      self.device.hdmiResolution))
> +            self.capture_start_time = time.time()

Is this for future use?

Comment 8

[William Lachance (:wlach)]

(In reply to Geoff Brown [:gbrown] from comment #7)
> >              self.log("Starting capture on device '%s' with mode: '%s'" % (
> >                      self.capture_metadata['device'],
> >                      self.device.hdmiResolution))
> > +            self.capture_start_time = time.time()
> 
> Is this for future use?

Nope, just a piece of code I forgot to delete. ;)

Comment 9

[William Lachance (:wlach)]

(Oops, didn't mean to resolve the bug before... but no matter, we are done here)

Pushed the orangutan and eideticker patches with minor changes, carrying forward the r+'s:

https://github.com/wlach/orangutan/commit/7edbbd3cdfeb7f16c0b407f67b05fbe8ac8f5541
https://github.com/mozilla/eideticker/commit/a00b90e86acd9d5202d13ae6f891acb442be9111