← Back to branch summary

~mir-team/mir/development-branch

« back to all changes in this revision

Viewing changes to tests/acceptance-tests/test_latency.cpp

  • Committer: Tarmac
  • Author(s): Daniel van Vugt
  • Date: 2015-09-07 07:49:17 UTC
  • mfrom: (2902.1.5 fix-1447947)
  • Revision ID: tarmac-20150907074917-1ooflurzzu5vurd4
Fix the ClientLatency acceptance test (LP: #1491876) (LP: #1447947)

There were multiple problems:
  * Samples where latency was actually nbuffers were incorrectly recorded
    as a latency of zero because the old code did not account for the
    fact that we might have record of the same buffer_id twice before
    the compositor has cleared out the old instance. All due to the
    "early release optimization".
  * The simulated compositor was not sleeping at all, so did not
    realistically allow the client to get ahead of it to fill the
    buffer queue, hence creating spuriously low latency measurements,
    which finally explains LP: #1447947.
  * The final average measurement was calculated prematurely, possibly
    missing some samples which made the result unpredictable and racy.
  * Slow devices (like mako) will after a while start to use the
    "early release" optimization that was introduced recently. However
    since we don't have dynamic queue scaling enabled to keep latency
    limited, the peak buffer latency is actually now nbuffers in some
    cases instead of nbuffers-1 frames (LP: #1491876). This extra
    latency is actually a good sign that the new feature is helping
    the slow device to maintain a better frame rate. The higher latency
    however will go away (and even reach all time lows) after we soon
    re-enable dynamic queue scaling.
  * Unresolved: The test still measures time in integer frame numbers,
    which is a feature. However this means any slight change in
    scheduling on the host where the client or server gets more time
    than the other, results in an exaggerated whole number change in
    frame latency averages. Fixes: https://bugs.launchpad.net/bugs/1447947, https://bugs.launchpad.net/bugs/1491876.

Approved by PS Jenkins bot, Alexandros Frantzis.

Show diffs side-by-side

added added

removed removed

Lines of Context:
tests/acceptance-tests/test_latency.cpp
28
28
 
29
29
#include <gtest/gtest.h>
30
30
#include <gmock/gmock.h>
31
 
#include <unordered_map>
 
31
#include <deque>
32
32
 
33
33
namespace mtf = mir_test_framework;
34
34
namespace mtd = mir::test::doubles;
49
49
    void record_submission(uint32_t submission_id)
50
50
    {
51
51
        std::lock_guard<std::mutex> lock{mutex};
52
 
        timestamps[submission_id] = post_count;
 
52
        submissions.push_back({submission_id, post_count});
53
53
    }
54
54
 
55
55
    auto latency_for(uint32_t submission_id)
57
57
        std::lock_guard<std::mutex> lock{mutex};
58
58
 
59
59
        mir::optional_value<uint32_t> latency;
60
 
        auto const it = timestamps.find(submission_id);
61
60
 
62
 
        if (it != timestamps.end())
63
 
            latency = post_count - it->second;
 
61
        for (auto i = submissions.begin(); i != submissions.end(); i++)
 
62
        {
 
63
            if (i->buffer_id == submission_id)
 
64
            {
 
65
                latency = post_count - i->time;
 
66
                submissions.erase(i);
 
67
                break;
 
68
            }
 
69
        }
64
70
 
65
71
        return latency;
66
72
    }
68
74
private:
69
75
    std::mutex mutex;
70
76
    unsigned int post_count{0};
71
 
    std::unordered_map<uint32_t, uint32_t> timestamps;
 
77
 
 
78
    // Note that a buffer_id may appear twice in the list as the client is
 
79
    // faster than the compositor and can produce a new frame before the
 
80
    // compositor has measured the previous submisson of the same buffer id.
 
81
    struct Submission
 
82
    {
 
83
        uint32_t buffer_id;
 
84
        uint32_t time;
 
85
    };
 
86
    std::deque<Submission> submissions;
72
87
};
73
88
/*
74
89
 * Note: we're not aiming to check performance in terms of CPU or GPU time processing
78
93
class IdCollectingDB : public mtd::NullDisplayBuffer
79
94
{
80
95
public:
81
 
    IdCollectingDB(Stats& stats) : stats{stats} {}
82
 
 
83
96
    mir::geometry::Rectangle view_area() const override
84
97
    {
85
98
        return {{0,0}, {1920, 1080}};
87
100
 
88
101
    bool post_renderables_if_optimizable(mg::RenderableList const& renderables) override
89
102
    {
90
 
        /*
91
 
         * Clients are blocked only until the below buffer() goes out of
92
 
         * scope. Thereafter we'll be racing the client thread. So we need
93
 
         * to increment the post_count (represents universal time) here
94
 
         * where the client thread is predictably blocked in its call to
95
 
         * mir_buffer_stream_swap_buffers_sync().
96
 
         */
97
 
        stats.post();
98
 
 
99
103
        //the surface will be the frontmost of the renderables
100
104
        if (!renderables.empty())
101
105
            last = renderables.front()->buffer()->id();
107
111
        return last;
108
112
    }
109
113
private:
110
 
    Stats& stats;
111
114
    mg::BufferID last{0};
112
115
};
113
116
 
114
117
class TimeTrackingGroup : public mtd::NullDisplaySyncGroup
115
118
{
116
119
public:
117
 
    TimeTrackingGroup(Stats& stats) : stats{stats}, db{stats} {}
 
120
    TimeTrackingGroup(Stats& stats) : stats{stats} {}
118
121
 
119
122
    void for_each_display_buffer(std::function<void(mg::DisplayBuffer&)> const& f) override
120
123
    {
129
132
            std::lock_guard<std::mutex> lock{mutex};
130
133
            latency_list.push_back(latency.value());
131
134
        }
 
135
 
 
136
        stats.post();
 
137
 
 
138
        /*
 
139
         * Sleep a little to make the test more realistic. This way the
 
140
         * client will actually fill the buffer queue. If we don't do this,
 
141
         * then it's like having an infinite refresh rate and the measured
 
142
         * latency would never exceed 1.0.  (LP: #1447947)
 
143
         */
 
144
        std::this_thread::sleep_for(std::chrono::milliseconds(16));
132
145
    }
133
146
 
134
147
    float average_latency()
188
201
        mir_buffer_stream_swap_buffers_sync(stream);
189
202
    }
190
203
 
 
204
    // Wait for the compositor to finish rendering all those frames,
 
205
    // or else we'll be missing some samples and get a spurious average.
 
206
    std::this_thread::sleep_for(std::chrono::milliseconds(500));
 
207
 
191
208
    unsigned int const expected_client_buffers = 3;
192
 
    unsigned int const expected_latency = expected_client_buffers - 1;
193
 
 
 
209
 
 
210
    // Note: Using the "early release" optimization without dynamic queue
 
211
    //       scaling enabled makes the expected latency possibly up to
 
212
    //       nbuffers instead of nbuffers-1. After dynamic queue scaling is
 
213
    //       enabled, the average will be lower than this.
 
214
    float const expected_max_latency = expected_client_buffers;
 
215
    float const expected_min_latency = expected_client_buffers - 1;
 
216
 
 
217
    auto observed_latency = display.group.average_latency();
 
218
 
 
219
    // We still have a margin for error here. The client and server will
 
220
    // be scheduled somewhat unpredictably which affects results. Also
 
221
    // affecting results will be the first few frames before the buffer
 
222
    // quere is full (during which there will be no buffer latency).
194
223
    float const error_margin = 0.1f;
195
 
    auto observed_latency = display.group.average_latency();
196
 
 
197
 
    // FIXME: LP: #1447947: This actually doesn't work as intended. Raising
198
 
    //        the queue length isn't affecting the measured latency for some
199
 
    //        reason. But latency too low is better than too high.
200
 
    //EXPECT_THAT(observed_latency, AllOf(Gt(expected_latency-error_margin),
201
 
    //                                    Lt(expected_latency+error_margin)));
202
 
 
203
 
    EXPECT_THAT(observed_latency, Lt(expected_latency+error_margin));
 
224
 
 
225
    EXPECT_THAT(observed_latency, Gt(expected_min_latency-error_margin));
 
226
    EXPECT_THAT(observed_latency, Lt(expected_max_latency+error_margin));
204
227
}