Mir

[ FAILED ] ClientLatency.dropping_latency_is_limited_to_one (AKA dropping_latency_is_closer_to_zero_than_one)

Bug #1640366 reported by Daniel van Vugt on 2016-11-09
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Mir
Triaged
Medium
Unassigned
mir (Ubuntu)
Medium
Unassigned

Bug Description

20:35:16 10: [ RUN ] ClientLatency.dropping_latency_is_limited_to_one
20:35:16 10: [2016-11-08 20:35:16.713374] mirserver: Starting
20:35:16 10: [2016-11-08 20:35:16.713544] mirserver: Selected driver: mir:stub-graphics (version 0.25.0)
20:35:16 10: [2016-11-08 20:35:16.714686] mirserver: Using software cursor
20:35:16 10: [2016-11-08 20:35:16.733467] mirserver: Initial display configuration:
20:35:16 10: [2016-11-08 20:35:16.734637] mirserver: Selected input driver: mir:stub-input (version: 0.25.0)
20:35:16 10: [2016-11-08 20:35:16.734766] mirserver: Mir version 0.25.0
20:35:18 10: /<<BUILDDIR>>/mir-0.25.0+yakkety2807bzr3804/tests/acceptance-tests/test_latency.cpp:341: Failure
20:35:18 10: Value of: max_latency
20:35:18 10: Expected: is <= 1
20:35:18 10: Actual: 2 (of type unsigned int)
20:35:18 10: [ debug ] 98 frames sampled, averaging 1.0 frames latency
20:35:18 10: [ debug ] 0: 1 1 1 1 1 1 1 2 1 1
20:35:18 10: [ debug ] 10: 1 1 1 1 1 1 1 1 1 1
20:35:18 10: [ debug ] 20: 1 1 1 1 1 1 1 1 1 1
20:35:18 10: [ debug ] 30: 1 1 1 1 1 1 1 1 1 1
20:35:18 10: [ debug ] 40: 1 1 1 1 1 1 1 1 1 1
20:35:18 10: [ debug ] 50: 1 1 1 1 1 1 1 1 1 1
20:35:18 10: [ debug ] 60: 1 1 1 1 1 1 1 1 1 1
20:35:18 10: [ debug ] 70: 1 1 1 1 1 1 1 1 1 1
20:35:18 10: [ debug ] 80: 1 1 1 1 1 1 1 1 1 1
20:35:18 10: [ debug ] 90: 1 1 1 1 1 1 1 1
20:35:18 10: [2016-11-08 20:35:18.575646] mirserver: Stopping
20:35:18 10: [ FAILED ] ClientLatency.dropping_latency_is_limited_to_one (1879 ms)

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

Related branches

Daniel van Vugt (vanvugt) wrote :

One frame hiccup out of 98. Wait and see how often this happens in CI I guess.

Although this should never happen if threads are being scheduled adequately. The client should be producing many frames per compositor frames and so should never miss like this.

description: updated
Daniel van Vugt (vanvugt) wrote :

Again:

04:08:00 12: /<<BUILDDIR>>/mir-0.25.0+yakkety2810bzr3811/tests/acceptance-tests/test_latency.cpp:341: Failure
04:08:00 12: Value of: max_latency
04:08:00 12: Expected: is <= 1
04:08:00 12: Actual: 2 (of type unsigned int)
04:08:00 12: [ debug ] 98 frames sampled, averaging 1.0 frames latency
04:08:00 12: [ debug ] 0: 1 1 1 1 1 1 1 1 1 1
04:08:00 12: [ debug ] 10: 1 1 1 1 1 1 1 1 1 1
04:08:00 12: [ debug ] 20: 1 1 1 1 1 1 1 1 1 1
04:08:00 12: [ debug ] 30: 1 1 1 1 1 1 1 1 1 1
04:08:00 12: [ debug ] 40: 1 1 1 1 1 1 1 1 1 1
04:08:00 12: [ debug ] 50: 1 1 1 1 1 1 1 1 1 1
04:08:00 12: [ debug ] 60: 1 1 1 1 1 1 1 1 1 1
04:08:00 12: [ debug ] 70: 1 1 1 1 1 1 1 1 1 1
04:08:00 12: [ debug ] 80: 1 1 1 1 1 1 1 1 1 1
04:08:00 12: [ debug ] 90: 1 1 1 2 1 1 1 1
04:08:00 12: [2016-11-09 04:08:00.110391] mirserver: Stopping
04:08:00 12: [ FAILED ] ClientLatency.dropping_latency_is_limited_to_one (1821 ms)

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

Changed in mir:
importance: Undecided → Medium
Daniel van Vugt (vanvugt) wrote :

Interesting the test only started failing after:

------------------------------------------------------------
revno: 3810 [merge]
author: Kevin DuBois <email address hidden>
committer: Tarmac
branch nick: development-branch
timestamp: Tue 2016-11-08 00:46:03 +0000
message:
  split out the swap interval arrangements from mcl::BufferStream so that MirPresentationChain can alter its submit behaviour as well. Add private functions so that the nested server can make the host server and the nested client agree on swapintervals.

  Approved by mir-ci-bot, Cemil Azizoglu.
------------------------------------------------------------

Daniel van Vugt (vanvugt) wrote :

Although this might help to mask the failures in future and stop the test (under a new name) from failing:

https://code.launchpad.net/~vanvugt/mir/test-for-fractional-latency/+merge/309541

Changed in mir:
milestone: none → 0.26.0
status: New → In Progress
Mir CI Bot (mir-ci-bot) wrote :

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

Changed in mir:
status: In Progress → Fix Committed
summary: - [ FAILED ] ClientLatency.dropping_latency_is_limited_to_one
+ [ FAILED ] ClientLatency.dropping_latency_is_limited_to_one (AKA
+ dropping_latency_is_closer_to_zero_than_one)
Changed in mir:
status: Fix Committed → In Progress
Mir CI Bot (mir-ci-bot) wrote :

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

Changed in mir:
status: In Progress → Fix Committed
Download full text (4.9 KiB)

Same problem or a different type of testfail?

19:54:42 [ RUN ] ClientLatency.dropping_latency_is_closer_to_zero_than_one
19:54:42 [2017-01-31 19:54:42.347490] mirserver: Starting
19:54:42 [2017-01-31 19:54:42.347814] mirserver: Selected driver: mir:stub-graphics (version 0.26.0)
19:54:42 [2017-01-31 19:54:42.365959] mirserver: Using software cursor
19:54:42 [2017-01-31 19:54:42.378848] mirserver: Selected input driver: mir:stub-input (version: 0.26.0)
19:54:42 [2017-01-31 19:54:42.379166] mirserver: Mir version 0.26.0
19:54:42 [2017-01-31 19:54:42.387115] mirserver: Initial display configuration:
19:54:42 [2017-01-31 19:54:42.387331] mirserver: Output 1: HDMI-A connected, used
19:54:42 [2017-01-31 19:54:42.387422] mirserver: Physical size 0.0" 0x0mm
19:54:42 [2017-01-31 19:54:42.387506] mirserver: Power is on
19:54:42 [2017-01-31 19:54:42.387580] mirserver: Current mode 1920x1080 60.00Hz
19:54:42 [2017-01-31 19:54:42.387647] mirserver: Preferred mode 1920x1080 60.00Hz
19:54:42 [2017-01-31 19:54:42.387710] mirserver: Orientation normal
19:54:42 [2017-01-31 19:54:42.387786] mirserver: Logical size 1920x1080
19:54:42 [2017-01-31 19:54:42.387887] mirserver: Logical position +0+0
19:54:44 /&lt;&lt;BUILDDIR&gt;&gt;/mir-0.26.0+xenial3900bzr3541/tests/acceptance-tests/test_latency.cpp:376: Failure
19:54:44 Value of: average_latency
19:54:44 Expected: is &lt; 0.5
19:54:44 Actual: 0.50877 (of type float)
19:54:44 [ debug ] 97 frames sampled, averaging 0.509 frames latency
19:54:44 [ debug ] 0: 1.00 1.00 0.50 0.50 0.06 0.07 0.07 0.07 0.08 0.08
19:54:44 [ debug ] 10: 0.08 0.08 0.25 0.25 0.12 0.10 0.17 0.08 0.04 0.25
19:54:44 [ debug ] 20: 0.20 0.50 0.09 0.33 1.00 0.50 1.00 1.00 1.00 1.00
19:54:44 [ debug ] 30: 1.00 1.00 1.00 1.00 1.00 0.50 0.12 0.11 3.00 0.04
19:54:44 [ debug ] 40: 0.10 0.14 2.00 1.00 0.17 0.50 0.50 0.33 0.33 0.25
19:54:44 [ debug ] 50: 0.08 0.07 0.07 0.08 0.07 0.08 0.33 0.33 1.00 0.20
19:54:44 [ debug ] 60: 1.00 0.11 0.17 0.33 1.00 0.11 0.06 0.33 0.50 0.11
19:54:44 [ debug ] 70: 0.11 0.04 0.04 0.07 0.04 0.07 0.06 0.04 0.33 2.00
19:54:44 [ debug ] 80: 2.00 0.50 0.50 1.00 1.00 2.00 1.00 1.00 2.00 1.00
19:54:44 [ debug ] 90: 0.14 1.00 0.14 0.50 0.14 0.04 1.00
19:54:44 [2017-01-31 19:54:44.472992] mirserver: Stopping
19:54:44 [ FAILED ] ClientLatency.dropping_latency_is_closer_to_zero_than_one (2234 ms)

in the same run:
19:54:48 [ RUN ] ClientLatency.async_swap_dropping_latency_is_closer_to_zero_than_one
19:54:48 [2017-01-31 19:54:48.485202] mirserver: Starting
19:54:48 [2017-01-31 19:54:48.485592] mirserver: Selected driver: mir:stub-graphics (version 0.26.0)
19:54:48 [2017-01-31 19:54:48.507703] mirserver: Using software cursor
19:54:48 [2017-01-31 19:54:48.524831] mirserver: Selected input driver: mir:stub-input (version: 0.26.0)
19:54:48 [2017-01-31 19:54:48.525074] mirserver: Mir version 0.26.0
19:54:48 [2017-01-31 19:54:48.535165] mirserver: Initial display configuration:
19:54:48 [2017-01-31 19:54:48.535282] mirserver: Output 1: HDMI-A connecte...

Read more...

Daniel van Vugt (vanvugt) wrote :

It appears my fix branch just made the bug less likely, not impossible.

Changed in mir:
milestone: 0.26.0 → none
status: Fix Committed → Triaged
Launchpad Janitor (janitor) wrote :
Download full text (7.2 KiB)

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
      ...

Read more...

Changed in mir (Ubuntu):
status: New → Fix Released
Daniel van Vugt (vanvugt) wrote :

OK, two fails in two days, but zero during the previous 6 weeks or so.

This is an important test so I'd rather have it fail on the odd occasion than to weaken it too much. Although I may well weaken it a little...

Changed in mir (Ubuntu):
status: Fix Released → Triaged
importance: Undecided → Medium
Changed in mir:
assignee: Daniel van Vugt (vanvugt) → nobody
To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers