Merge lp:~vanvugt/mir/latency-acceptance-test-2 into lp:~kdub/mir/latency-acceptance-test

[Daniel van Vugt]

Avoid racing for post_count. Update it in a place where the threads are not racing. This way when we sample it in the client thread, it actually represents the client render time more accurately (one higher than previously).

[Alberto Aguirre (albaguirre)]

68 + auto lag_post_to_eye = hardware_framebuffers - 1;

You are assuming the hardware and/or driver actually prime an internal queue. That may or may not be the case. We certainly don't prime the display buffer queue within Mir.

I think the most salient point is that the extra latency varies depending on when your flip call lands. Best case you flip right before the start of scanout (so no flip wait) and worst case you just barely missed the deadline so you wait an extra vsync period (basically due to FIFO underflow).

So the latency is bounded by 1 < latency < 2.

This is why it's helpful to know where in the scan-out the hardware currently is - that could help eliminate 1 vsync_period of lag by using the newest frame (the tradeoff being judder) - However, I'm not sure all HW supports such option.

===
TEST_F(ClientLatency, double_buffered)
===

This is not a report. The test name should indicate some sort of expectation.

==
64 + if (it != timestamps.end())
65 + {
66 + auto render_time = it->second;
67 + auto lag_client_to_post = post_count - render_time;
68 + auto lag_post_to_eye = hardware_framebuffers - 1;
69 + auto total_lag = lag_client_to_post + lag_post_to_eye;
70 +
71 + latency.push_back(total_lag);
72 + }
===

Maybe the timestamp should be removed from the map at the end of this scope?

===
98 + EXPECT_LT(expected_latency-error_margin, observed_latency);
99 + EXPECT_GT(expected_latency+error_margin, observed_latency);
==

I prefer EXPECT_THAT, reads like English that way.

review: Needs Fixing

[Kevin DuBois (kdub)]

62 + // XXX The test framework seems to insert artificial buffers we didn't
63 + // introduce ourselves. So identify and ignore those.
This is the cursor... would be better if we could turn this off from the acceptance test level.

101 + std::cout << "Expected latency " << expected_latency << " frames "
102 + << "and measured latency " << observed_latency << " frames.\n";
Is it useful to print this? If the test fails, we'll see the failure number, and if it succeeds, the code met our expectations, and we don't mind by how much.

67 + auto lag_client_to_post = post_count - render_time;
68 + auto lag_post_to_eye = hardware_framebuffers - 1;
69 + auto total_lag = lag_client_to_post + lag_post_to_eye;
I was really only concerned about the "lag_client_to_post" in this test. "post to eye" is a bit different per-platform, and it seems dangerous to assume what the platforms are doing. I'd rather have a test that checks "client to post" than a test that checks "client to eye", where we have to assume things about the hardware. There's also the "input to client" part of the lag, that we don't aim to cover... I was really hoping this would just be a sanity test that we'd have to back up with forthcoming or existing benchmarks on hardware when we're talking about our latency.

[Daniel van Vugt (vanvugt)]

Alberto:
"You are assuming the hardware and/or driver actually prime an internal queue. That may or may not be the case. We certainly don't prime the display buffer queue within Mir."

Correct, and that assumption is correct. The queue only drains when all producers go idle, which should happen frequently for the sake of battery but is not the most important use case when measuring lag. The most important use case is for something trying to render constantly (e.g. a smooth scroll) so the queues will all be full for the duration of such a gesture.

"This is why it's helpful to know where in the scan-out the hardware currently is - that could help eliminate 1 vsync_period of lag by using the newest frame (the tradeoff being judder) - However, I'm not sure all HW supports such option."

Yeah we intentionally don't do that because of the judder (if done properly). If not done properly it would both judder and consume from the queue at double frame rate (which you'd notice).

Kdub, Alberto:
If it makes people happier I will remove the lag-to-eye stuff. Although it weakens the case for this being an "acceptance test". It's just an integration test at most if we only measure the client queue.

[Kevin DuBois (kdub)]

Keeping the lag to eye type stuff doesn't make it any more of an acceptance test, because we're making assumptions about how a 3rd party black box might work.

I do buy the argument though that overriding the display at all makes this less pure of an acceptance test, if you consider "acceptance tests" are (server+platform). We have some current infrastructure limitations about how effective our (server+platform) acceptance tests can be (we mostly test that things dont crash, and return the right codes). So, most of our mir_acceptance_tests are an acceptance test of just the server code with a stub platform, and classifying this test in the same manner seems acceptable to me.

68 + // FIXME(kdub): `latency' only ever has size 2, because the client
In the original proposal and this MP's changes, the size seems to grow with each iteration. It is a good improvement to check that there is a buffer id in the map though before appending it to the latency vector, pulled that improvement over.

[Alberto Aguirre (albaguirre)]

Ok.

review: Approve

[Kevin DuBois (kdub)]

okay by me too

review: Approve

=== modified file 'tests/acceptance-tests/test_latency.cpp'
--- tests/acceptance-tests/test_latency.cpp	2015-03-03 21:13:30 +0000
+++ tests/acceptance-tests/test_latency.cpp	2015-03-04 03:38:58 +0000
@@ -42,12 +42,23 @@
  */
 struct IdCollectingDB : mtd::NullDisplayBuffer
 {
+    IdCollectingDB(unsigned int& count) : post_count{count} {}
+
     mir::geometry::Rectangle view_area() const override
     {
         return {{0,0}, {1920, 1080}};
     } 
     bool post_renderables_if_optimizable(mg::RenderableList const& renderables) override
     {
+        /*
+         * Clients are blocked only until the below buffer() goes out of
+         * scope. Thereafter we'll be racing the client thread. So we need
+         * to increment the post_count (represents universal time) here
+         * where the client thread is predictably blocked in its call to
+         * mir_buffer_stream_swap_buffers_sync().
+         */
+        ++post_count;
+
         //the surface will be the frontmost of the renderables
         if (!renderables.empty())
             last = renderables.front()->buffer()->id();
@@ -58,13 +69,14 @@
         return last;
     }
 private:
+    unsigned int& post_count;
     mg::BufferID last{0};
 };
 
 struct TimeTrackingGroup : mtd::NullDisplaySyncGroup
 {
     TimeTrackingGroup(unsigned int& count, std::unordered_map<uint32_t, uint32_t>& map) :
-        post_count(count), timestamps(map) {}
+        post_count(count), timestamps(map), db(count) {}
     void for_each_display_buffer(std::function<void(mg::DisplayBuffer&)> const& f) override
     {
         f(db);
@@ -75,7 +87,6 @@
         auto const it = timestamps.find(db.last_id().as_value());
         if (it != timestamps.end())
             latency.push_back(post_count - it->second);
-        post_count++;
     }
 
     float average_latency()
@@ -119,7 +130,7 @@
 };
 }
 
-TEST_F(ClientLatency, does_not_exceed_one_frame_double_buffered)
+TEST_F(ClientLatency, double_buffered_client_uses_all_buffers)
 {
     using namespace testing;
 
@@ -129,8 +140,14 @@
         timestamps[submission_id] = post_count; 
         mir_buffer_stream_swap_buffers_sync(stream);
     }
-    //Default is double buffered
-    EXPECT_THAT(display.group.average_latency(), Lt(1.0));
+
+    unsigned int const expected_client_buffers = 2;
+    unsigned int const expected_latency = expected_client_buffers - 1;
+
+    float const error_margin = 0.1f;
+    auto observed_latency = display.group.average_latency();
+    EXPECT_THAT(observed_latency, AllOf(Gt(expected_latency-error_margin),
+                                        Lt(expected_latency+error_margin)));
 }
 
 //TODO: configure and add test for triple buffer