CI failure in TestClientInput.receives_one_touch_event_per_frame

Fix committed into lp:mir at revision None, scheduled for release in mir, milestone 0.22.0

Still happening in CI yesterday and today. Needs fixing more.

Although I suspect the test is theoretically correct, the main issue is one or two CI machines are often too slow to do time-sensitive tests.

https://mir-jenkins.ubuntu.com/job/build-2-binpkg-mir/arch=i386,compiler=gcc,platform=mesa,release=xenial/1015/consoleFull

...
22:06:59 11: Expected: to be called between 50 and 150 times
22:06:59 11: Actual: called 167 times - over-saturated and active
22:06:59 11: /��BUILDDIR��/mir-0.23.0+xenial1042bzr3496/tests/acceptance-tests/test_client_input.cpp:648: Failure
22:06:59 11: Value of: client_input_events_per_frame
22:06:59 11: Expected: is < 1.5
22:06:59 11: Actual: 1.5 (of type float)
22:06:59 11: [2016-05-04 22:06:58.560725] mirserver: Stopping
22:06:59 11: [ FAILED ] TestClientInput.receives_one_touch_event_per_frame (6775 ms)

Ive been getting this as well here:
https://code.launchpad.net/~brandontschaefer/mir/mir-event-capnproto/+merge/290760

Nice to see i might not be 100% my fault. Thought the fix should be moving away from real time for the test.

Brandon: This actually only happens once or twice a week or so for the rest of us. If your branch hits it more often that might indicate that branch needs fixing.

This bug was fixed in the package mir - 0.22.1+16.04.20160516.2-0ubuntu2

---------------
mir (0.22.1+16.04.20160516.2-0ubuntu2) yakkety; urgency=medium

  [ Dimitri John Ledkov ]
  * Fix FTBFS error: call of overloaded ‘abs(float)’ is ambiguous, by
    including cmath c++ header.

 -- Łukasz 'sil2100' Zemczak <email address hidden> Thu, 19 May 2016 21:58:43 +0200

Another instance:
https://mir-jenkins.ubuntu.com/job/build-2-binpkg-mir/arch=i386,compiler=gcc,platform=mesa,release=xenial/1221/consoleFull

Again: https://mir-jenkins.ubuntu.com/job/build-2-binpkg-mir/arch=i386,compiler=gcc,platform=mesa,release=xenial/1476/consoleFull

10:15:01 11: [ RUN ] TestClientInput.receives_one_touch_event_per_frame
10:15:01 11: [2016-07-08 10:15:01.272873] mirserver: Starting
10:15:01 11: [2016-07-08 10:15:01.280984] mirserver: Selected driver: mir:stub-graphics (version 0.24.0)
10:15:01 11: [2016-07-08 10:15:01.307161] mirserver: Using software cursor
10:15:01 11: [2016-07-08 10:15:01.349685] mirserver: Initial display configuration:
10:15:01 11: [2016-07-08 10:15:01.350581] mirserver: 1.1: VGA 0.0" 0x0mm
10:15:01 11: [2016-07-08 10:15:01.350908] mirserver: Current mode 1000x800 60.00Hz
10:15:01 11: [2016-07-08 10:15:01.351197] mirserver: Preferred mode 1000x800 60.00Hz
10:15:01 11: [2016-07-08 10:15:01.351457] mirserver: Logical position +0+0
10:15:01 11: [2016-07-08 10:15:01.400097] mirserver: Selected input driver: mir:stub-input (version: 0.24.0)
10:15:01 11: [2016-07-08 10:15:01.402038] mirserver: Mir version 0.24.0
10:15:05 11: /��BUILDDIR��/mir-0.24.0+xenial1505bzr3584/tests/acceptance-tests/test_client_input.cpp:605: Failure
10:15:05 11: Mock function called more times than expected - returning directly.
10:15:05 11: Function call: handle_input(touch_event(when=1248754090633088 (30.776176ms ago), from=3, touch = {{id=1, action=change, tool=finger, x=10.7758, y=17.2414, pressure=1, major=5, minor=8, size=8}, modifiers=1))
10:15:05 11: Expected: to be called between 50 and 150 times
10:15:05 11: Actual: called 151 times - over-saturated and active
10:15:05 11: /��BUILDDIR��/mir-0.24.0+xenial1505bzr3584/tests/acceptance-tests/test_client_input.cpp:605: Failure
10:15:05 11: Mock function called more times than expected - returning directly.
10:15:05 11: Function call: handle_input(touch_event(when=1248754260124608 (23.596715ms ago), from=3, touch = {{id=1, action=change, tool=finger, x=10.904, y=17.4465, pressure=1, major=5, minor=8, size=8}, modifiers=1))
10:15:05 11: Expected: to be called between 50 and 150 times
10:15:05 11: Actual: called 152 times - over-saturated and active
10:15:05 11: /��BUILDDIR��/mir-0.24.0+xenial1505bzr3584/tests/acceptance-tests/test_client_input.cpp:605: Failure
10:15:05 11: Mock function called more times than expected - returning directly.
10:15:05 11: Function call: handle_input(touch_event(when=1248754294022912 (11.838520ms ago), from=3, touch = {{id=1, action=change, tool=finger, x=10.9697, y=17.5516, pressure=1, major=5, minor=8, size=8}, modifiers=1))
10:15:05 11: Expected: to be called between 50 and 150 times
10:15:05 11: Actual: called 153 times - over-saturated and active
10:15:05 11: /��BUILDDIR��/mir-0.24.0+xenial1505bzr3584/tests/acceptance-tests/test_client_input.cpp:605: Failure
10:15:05 11: Mock function called more times than expected - returning directly.
10:15:05 11: Function call: handle_input(touch_event(when=1248754310972064 (8.995567ms ago), from=3, touch = {{id=1, action=change, tool=finger, x=11.0002, y=17.6003, pressure=1, major=5, minor=8, size=8}, modifiers=1))
10:15:05 11: Expected: to be called between 50 and 150 times
10:15:05 11: Actual: called 154 times - over-saturated and active
10:1...

And again: https://mir-jenkins.ubuntu.com/job/build-2-binpkg-mir/arch=i386,compiler=gcc,platform=mesa,release=xenial/1474/console

and: https://mir-jenkins.ubuntu.com/job/build-2-binpkg-mir/arch=i386,compiler=gcc,platform=mesa,release=xenial/1475/console

Raising importance to high.

Fix committed into lp:mir at revision None, scheduled for release in mir, milestone 0.25.0

Maybe fixed? Not yet sure if that branch just landed is sufficient.

Fix committed into lp:mir at revision None, scheduled for release in mir, milestone 0.25.0

I think the attached recent branches have solved this in general. It's still failing in Brandon's branches only, but probably for good reason.

Reopened because it's happening again:

https://mir-jenkins.ubuntu.com/job/build-2-binpkg-mir/arch=amd64,compiler=clang,platform=mesa,release=yakkety/2804/consoleFull

Although possibly for different reasons now (anpok modified the test and brandon made the event system slower and more likely to fail).

18:00:31 /<<BUILDDIR>>/mir-0.25.0+yakkety2832bzr3817/tests/acceptance-tests/test_client_input.cpp:636: Failure
18:00:31 Value of: first_client.all_events_received.wait_for(120s)
18:00:31 Actual: false
18:00:31 Expected: true
18:00:31 /<<BUILDDIR>>/mir-0.25.0+yakkety2832bzr3817/tests/acceptance-tests/test_client_input.cpp:601: Failure
18:00:31 Actual function call count doesn't match EXPECT_CALL(first_client, handle_input(_))...
18:00:31 Expected: to be called between 20 and 180 times
18:00:31 Actual: called 19 times - unsatisfied and active
18:00:31 [2016-11-10 17:51:29.932919] mirserver: Stopping
18:00:31 [ FAILED ] TestClientInput.receives_one_touch_event_per_frame (124727 ms)

Brandon said he had plans to continue with Capn Proto work that would solve the performance problems it has introduced here. So this failure should go away when the Capn Proto work is finished. Although I'm not too familiar with the changes Anpok also made to the test itself. It was pretty quiet (not failing) for months prior to the recent changes.

End of the day and I have better news now:

The first prototype of client-side vsync is working well and I'm hopeful to get it into Mir 0.26. With some luck that will solve the incompatibility between Qt's input resampler logic and our nested architecture. So then if Unity8 is able to use Qt's input resampling, Mir won't need that feature any more (we just declare it's now the toolkit's job to resample touch events).

Once Mir doesn't need to provide input resampling any more, the failing test case here will be removed along with the feature.

Again:

https://mir-jenkins.ubuntu.com/job/build-2-binpkg-mir/arch=amd64,compiler=clang,platform=mesa,release=yakkety/2970/consoleFull

12:05:28 9: Actual function call count doesn't match EXPECT_CALL(first_client, handle_input(_))...
12:05:28 9: Expected: to be called between 20 and 180 times
12:05:28 9: Actual: called 18 times - unsatisfied and active
12:05:28 9: [2016-11-24 12:05:28.455825] mirserver: Stopping
12:05:28 9: [ FAILED ] TestClientInput.receives_one_touch_event_per_frame (124506 ms)

And again:

08:36:20 11: /<<BUILDDIR>>/mir-0.25.0+xenial3097bzr3867/tests/acceptance-tests/test_client_input.cpp:667: Failure
08:36:20 11: Mock function called more times than expected - returning directly.
08:36:20 11: Function call: handle_input(touch_event(when=2424279781829824 (29.428950ms ago), from=3, touch = {{id=1, action=change, tool=finger, x=10.2777, y=16.4444, pressure=1, major=8, minor=5, size=8}, modifiers=none))
08:36:20 11: Expected: to be called between 20 and 180 times
08:36:20 11: Actual: called 181 times - over-saturated and active
08:36:20 11: /<<BUILDDIR>>/mir-0.25.0+xenial3097bzr3867/tests/acceptance-tests/test_client_input.cpp:667: Failure
08:36:20 11: Mock function called more times than expected - returning directly.
08:36:20 11: Function call: handle_input(touch_event(when=2424279784896425 (132.877864ms ago), from=3, touch = {{id=1, action=change, tool=finger, x=10.2997, y=16.4795, pressure=1, major=8, minor=5, size=8}, modifiers=none))
08:36:20 11: Expected: to be called between 20 and 180 times
08:36:20 11: Actual: called 182 times - over-saturated and active
08:36:20 11: [2016-12-06 08:36:20.370900] mirserver: Stopping
08:36:20 11: [ FAILED ] TestClientInput.receives_one_touch_event_per_frame (5403 ms)

https://mir-jenkins.ubuntu.com/job/build-2-binpkg-mir/arch=i386,compiler=gcc,platform=mesa,release=xenial+overlay/3068/consoleFull

And again:

06:27:08 11: /<<BUILDDIR>>/mir-0.25.0+xenial3115bzr3852/tests/acceptance-tests/test_client_input.cpp:667: Failure
06:27:08 11: Mock function called more times than expected - returning directly.
06:27:08 11: Function call: handle_input(touch_event(when=1476068422342080 (39.829455ms ago), from=3, touch = {{id=1, action=change, tool=finger, x=10.9263, y=17.4821, pressure=1, major=8, minor=5, size=8}, modifiers=none))
06:27:08 11: Expected: to be called between 20 and 180 times
06:27:08 11: Actual: called 181 times - over-saturated and active
06:27:08 11:
06:27:08 11: GMOCK WARNING:
06:27:08 11: Uninteresting mock function call - returning directly.
06:27:08 11: Function call: handle_input(touch_event(when=1476068744375968 (24.843672ms ago), from=3, touch = {{id=1, action=change, tool=finger, x=10.97, y=17.552, pressure=1, major=8, minor=5, size=8}, modifiers=none))
06:27:08 11: Stack trace:
06:27:08 11: [2016-12-08 06:27:08.848436] mirserver: Stopping
06:27:08 11: [ FAILED ] TestClientInput.receives_one_touch_event_per_frame (5518 ms)

https://mir-jenkins.ubuntu.com/job/build-2-binpkg-mir/arch=i386,compiler=gcc,platform=mesa,release=xenial+overlay/3086/consoleFull

12:32:46 11: [ RUN ] TestClientInput.receives_one_touch_event_per_frame
12:32:46 11: [2016-12-13 12:32:46.184830] mirserver: Starting
12:32:46 11: [2016-12-13 12:32:46.188127] mirserver: Selected driver: mir:stub-graphics (version 0.26.0)
12:32:46 11: [2016-12-13 12:32:46.501072] mirserver: Using software cursor
12:32:46 11: [2016-12-13 12:32:46.583720] mirserver: Selected input driver: mir:stub-input (version: 0.26.0)
12:32:46 11: [2016-12-13 12:32:46.586385] mirserver: Mir version 0.26.0
12:32:46 11: [2016-12-13 12:32:46.885544] mirserver: Initial display configuration:
12:32:46 11: [2016-12-13 12:32:46.885985] mirserver: Output 1: VGA connected, used
12:32:46 11: [2016-12-13 12:32:46.886267] mirserver: Physical size 0.0" 0x0mm
12:32:46 11: [2016-12-13 12:32:46.886495] mirserver: Power is on
12:32:47 11: [2016-12-13 12:32:46.886786] mirserver: Current mode 1000x800 60.00Hz
12:32:47 11: [2016-12-13 12:32:46.887065] mirserver: Preferred mode 1000x800 60.00Hz
12:32:47 11: [2016-12-13 12:32:46.887299] mirserver: Orientation normal
12:32:47 11: [2016-12-13 12:32:46.887551] mirserver: Logical size 1000x800
12:32:47 11: [2016-12-13 12:32:46.887795] mirserver: Logical position +0+0
12:32:51 11: /<<BUILDDIR>>/mir-0.25.0+xenial3168bzr3882/tests/acceptance-tests/test_client_input.cpp:667: Failure
12:32:51 11: Mock function called more times than expected - returning directly.
12:32:51 11: Function call: handle_input(touch_event(when=3043267954730209 (36.826310ms ago), from=3, touch = {{id=1, action=change, tool=finger, x=11.7035, y=18.7256, pressure=1, major=8, minor=5, size=8}, modifiers=none))
12:32:51 11: Expected: to be called between 20 and 180 times
12:32:51 11: Actual: called 181 times - over-saturated and active
12:32:51 11:
12:32:51 11: GMOCK WARNING:
12:32:51 11: Uninteresting mock function call - returning directly.
12:32:51 11: Function call: handle_input(touch_event(when=3043267976114041 (162.322519ms ago), from=3, touch = {{id=1, action=change, tool=finger, x=11.7339, y=18.7742, pressure=1, major=8, minor=5, size=8}, modifiers=none))
12:32:51 11: Stack trace:
12:32:51 11: [2016-12-13 12:32:51.256090] mirserver: Stopping
12:32:51 11: [ FAILED ] TestClientInput.receives_one_touch_event_per_frame (5183 ms)
12:32:51 11: [ RUN ]

https://mir-jenkins.ubuntu.com/job/build-2-binpkg-mir/arch=amd64,compiler=gcc,platform=mesa,release=xenial+overlay/3138/consoleFull

Yeah this failure has become more of a problem with the CapnProto event code. Prior to that it wasn't failing for months at a time.

Long term we expect input resampling functionality to get dropped from Mir, and this test case with it. Because client-side vsync should allow Unity8 to use the default QML_TOUCH_COMPRESSION instead.

Shorter term, I noticed the new Capnproto code seems to do multiple mallocs per event. Fixing that could help here.

10:15:27 Expected: to be called between 20 and 180 times
10:15:27 Actual: called 181 times - over-saturated and active
10:15:27
10:15:27 GMOCK WARNING:
10:15:27 Uninteresting mock function call - returning directly.
10:15:27 Function call: handle_input(touch_event(when=3725515999186980 (164.850700ms ago), from=3, touch = {{id=1, action=change, tool=finger, x=11.9781, y=19.165, pressure=1, major=8, minor=5, size=8}, modifiers=none))
10:15:27 Stack trace:
10:15:27 [2016-12-21 10:03:39.345580] mirserver: Stopping
10:15:27 [ FAILED ] TestClientInput.receives_one_touch_event_per_frame (5473 ms)

https://mir-jenkins.ubuntu.com/job/build-2-binpkg-mir/arch=amd64,compiler=gcc,platform=mesa,release=xenial+overlay/3250/consoleFull

Fix committed into lp:mir at revision 3949, scheduled for release in mir, milestone 1.0.0

This bug was fixed in the package mir - 0.26.0+17.04.20170126.3-0ubuntu1

---------------
mir (0.26.0+17.04.20170126.3-0ubuntu1) zesty; urgency=medium

  [ Daniel van Vugt ]
  * New upstream release 0.26.0 (https://launchpad.net/mir/+milestone/0.26.0)
    - ABI summary:
      . mirclient ABI unchanged at 9
      . mirserver ABI bumped to 43
      . mircommon ABI unchanged at 7
      . mirplatform ABI unchanged at 14
      . mirprotobuf ABI unchanged at 3
      . mirplatformgraphics ABI unchanged at 11
      . mirclientplatform ABI unchanged at 5
      . mirinputplatform ABI unchanged at 6
      . mircore ABI unchanged at 1
    - Enhancements:
      . New/improved toolkit APIs: MirInputConfig and related functions,
        MirWindow and related functions, DisplayConfig and related functions,
        MirScreencastSpec and related functions,
      . Support for configuring input configuration
      . Introduce toolkit extension mechanism for platform specific APIs.
      . Toolkit extensions for: mesa_drm_auth, set_gbm_device and
        window_coordinate_translation
      . Screencasting to a specific MirBuffer.
      . Add DisplayConfigurationController::base_configuration() so downstreams
        can get the base configuration. (Weirdly they can already set it.).
      . x11 platform: allow adjustable scale parameter.
      . Added EDID support: client API, server logging and in mirout.
      . mirout: Add newer attributes only available in the new display
        config API: scaling factor, subpixel arrangement and form factor.
      . mirout: Log the orientation and logical size of each output too.
      . Replace the mir::Server-overridable Reports with Observers.
      . Add xkbcommon to mirclient.pc Requires.private.
      . Deprecate legacy toolkit APIs that will be removed in Mir 1.0
      . Introduced 'client-side vsync', which dramatically reduces latency
        from the client to the screen (particularly for nested servers like
        Unity8).
    - Bugs fixed:
      . [performance] Restore support for better-than-triple buffering by
        default. (LP: #1240909)
      . Frame rate is artificially low on Diamondville Intel Atom systems due
        to aggressive power management (LP: #1388490)
      . [testsfail] failure in CI in
        AndroidInputReceiverSetup.slow_raw_input_doesnt_cause_frameskipping
        (LP: #1394369)
      . [trusted prompt sessions] Can't open two prompt sessions at the same
        time (LP: #1494197)
      . Changing scale, formFactor or DPI in display configuration causes
        renderer teardown/recreate unnecessarily (LP: #1556142)
      . [testsfail] ApplicationNotRespondingDetection.failure_to_pong_is_
        noticed (LP: #1570327)
      . CI failure in TestClientInput.receives_one_touch_event_per_frame
        (LP: #1570698)
      . Mir-on-X mouse input is jerky/stuttery compared to Mir-on-KMS
        (LP: #1576600)
      . [regression] Two fingers in mir_proving_server now resizes/moves app
        windows (two finger apps unusable) (LP: #1586311)
      . Pointer/cursor input lag in unity8 session (LP: #1591328)
      . PointerConfinement.test_we_update_our_confined_region_on_a_resize
      ...