Mir

Merge lp:~vanvugt/mir/fix-1408906 into lp:mir

  1. fix-1408906
  2. Merge into development-branch
Proposed by Daniel van Vugt
Status: Merged
Approved by: Daniel van Vugt
Approved revision: no longer in the source branch.
Merged at revision: 2212
Proposed branch: lp:~vanvugt/mir/fix-1408906
Merge into: lp:mir
Diff against target: 412 lines (+124/-37)
13 files modified
playground/demo-shell/demo_compositor.cpp (+3/-2)
src/include/server/mir/compositor/compositor_report.h (+2/-1)
src/server/compositor/default_display_buffer_compositor.cpp (+3/-2)
src/server/report/logging/compositor_report.cpp (+14/-7)
src/server/report/logging/compositor_report.h (+3/-1)
src/server/report/lttng/compositor_report.cpp (+8/-3)
src/server/report/lttng/compositor_report.h (+2/-1)
src/server/report/lttng/compositor_report_tp.h (+11/-3)
src/server/report/null/compositor_report.cpp (+5/-1)
src/server/report/null/compositor_report.h (+2/-1)
tests/include/mir_test_doubles/mock_compositor_report.h (+4/-2)
tests/unit-tests/compositor/test_default_display_buffer_compositor.cpp (+33/-5)
tests/unit-tests/logging/test_compositor_report.cpp (+34/-8)
To merge this branch: bzr merge lp:~vanvugt/mir/fix-1408906
Reviewer Review Type Date Requested Status
PS Jenkins bot (community) continuous-integration Approve
Alexandros Frantzis (community) Approve
Alan Griffiths Approve
Kevin DuBois (community) Approve
Review via email: mp+245934@code.launchpad.net

Commit message

CompositorReport: Ensure bypass reports zero render time instead of the
frame time (LP: #1408906).

Also clean up the reporting interface so it makes more sense.

To post a comment you must log in.
Revision history for this message
PS Jenkins bot (ps-jenkins) wrote :

FAILED: Continuous integration, rev:2214
http://jenkins.qa.ubuntu.com/job/mir-ci/2605/
Executed test runs:
    SUCCESS: http://jenkins.qa.ubuntu.com/job/mir-android-vivid-i386-build/783
    SUCCESS: http://jenkins.qa.ubuntu.com/job/mir-clang-vivid-amd64-build/783
    SUCCESS: http://jenkins.qa.ubuntu.com/job/mir-mediumtests-vivid-touch/745
    FAILURE: http://jenkins.qa.ubuntu.com/job/mir-vivid-amd64-ci/602/console
    SUCCESS: http://jenkins.qa.ubuntu.com/job/mir-mediumtests-builder-vivid-armhf/745
        deb: http://jenkins.qa.ubuntu.com/job/mir-mediumtests-builder-vivid-armhf/745/artifact/work/output/*zip*/output.zip
    SUCCESS: http://jenkins.qa.ubuntu.com/job/mir-mediumtests-runner-mako/3874
    SUCCESS: http://s-jenkins.ubuntu-ci:8080/job/touch-flash-device/16966

Click here to trigger a rebuild:
http://s-jenkins.ubuntu-ci:8080/job/mir-ci/2605/rebuild

review: Needs Fixing (continuous-integration)
Revision history for this message
Kevin DuBois (kdub) wrote :

pre-existing, but for some android driver versions we can't seperate flip() from the gl rendering (and won't really have an accurate time)

okay by me, pre-existing nit:
39 + virtual void rendered_frame(SubCompositorId id = 0) = 0;
40 + virtual void finished_frame(SubCompositorId id = 0) = 0;
default parameters
http://unity.ubuntu.com/mir/cppguide/index.html?showone=Default_Arguments#Default_Arguments

review: Approve
Revision history for this message
PS Jenkins bot (ps-jenkins) wrote :

PASSED: Continuous integration, rev:2215
http://jenkins.qa.ubuntu.com/job/mir-ci/2614/
Executed test runs:
    SUCCESS: http://jenkins.qa.ubuntu.com/job/mir-android-vivid-i386-build/794
    SUCCESS: http://jenkins.qa.ubuntu.com/job/mir-clang-vivid-amd64-build/794
    SUCCESS: http://jenkins.qa.ubuntu.com/job/mir-mediumtests-vivid-touch/756
    SUCCESS: http://jenkins.qa.ubuntu.com/job/mir-vivid-amd64-ci/611
        deb: http://jenkins.qa.ubuntu.com/job/mir-vivid-amd64-ci/611/artifact/work/output/*zip*/output.zip
    SUCCESS: http://jenkins.qa.ubuntu.com/job/mir-mediumtests-builder-vivid-armhf/756
        deb: http://jenkins.qa.ubuntu.com/job/mir-mediumtests-builder-vivid-armhf/756/artifact/work/output/*zip*/output.zip
    SUCCESS: http://jenkins.qa.ubuntu.com/job/mir-mediumtests-runner-mako/3885
    SUCCESS: http://s-jenkins.ubuntu-ci:8080/job/touch-flash-device/16987

Click here to trigger a rebuild:
http://s-jenkins.ubuntu-ci:8080/job/mir-ci/2614/rebuild

review: Approve (continuous-integration)
Revision history for this message
Alan Griffiths (alan-griffiths) wrote :

211 - )
212 + )

Seems an odd whitespace change.

review: Approve
Revision history for this message
Alexandros Frantzis (afrantzis) wrote :

OK.

We should make it more clear in the log output that the "ms/frame" value applies to rendering only, though, e.g., by changing "NNN ms/frame" to "rendering NNN ms/frame".

review: Approve
Revision history for this message
Daniel van Vugt (vanvugt) wrote :

That odd whitespace change was just a copy/paste mistake. Although now I look at the whole file, that makes it completely consistent now(!?). So we can fix them all another day...

Revision history for this message
PS Jenkins bot (ps-jenkins) wrote :

FAILED: Autolanding.
More details in the following jenkins job:
http://jenkins.qa.ubuntu.com/job/mir-autolanding/1002/
Executed test runs:
    SUCCESS: http://jenkins.qa.ubuntu.com/job/mir-android-vivid-i386-build/814
    SUCCESS: http://jenkins.qa.ubuntu.com/job/mir-clang-vivid-amd64-build/814
    SUCCESS: http://jenkins.qa.ubuntu.com/job/mir-mediumtests-vivid-touch/776
    FAILURE: http://jenkins.qa.ubuntu.com/job/mir-vivid-amd64-autolanding/182/console
    SUCCESS: http://jenkins.qa.ubuntu.com/job/mir-mediumtests-builder-vivid-armhf/776
        deb: http://jenkins.qa.ubuntu.com/job/mir-mediumtests-builder-vivid-armhf/776/artifact/work/output/*zip*/output.zip
    SUCCESS: http://jenkins.qa.ubuntu.com/job/mir-mediumtests-runner-mako/3901
    SUCCESS: http://s-jenkins.ubuntu-ci:8080/job/touch-flash-device/17019

review: Needs Fixing (continuous-integration)
Revision history for this message
Daniel van Vugt (vanvugt) wrote :

Interesting Jenkins always needs fixing due to new bugs on a regular basis...

Revision history for this message
PS Jenkins bot (ps-jenkins) :
review: Approve (continuous-integration)

Preview Diff

[H/L] Next/Prev Comment, [J/K] Next/Prev File, [N/P] Next/Prev Hunk
1=== modified file 'playground/demo-shell/demo_compositor.cpp'
2--- playground/demo-shell/demo_compositor.cpp 2015-01-03 10:01:42 +0000
3+++ playground/demo-shell/demo_compositor.cpp 2015-01-12 04:06:36 +0000
4@@ -123,7 +123,6 @@
5 display_buffer.post_renderables_if_optimizable(renderable_list))
6 {
7 renderer.suspend();
8- report->finished_frame(true, this);
9 }
10 else
11 {
12@@ -135,7 +134,7 @@
13 renderer.render(renderable_list);
14
15 display_buffer.gl_swap_buffers();
16- report->finished_frame(false, this);
17+ report->rendered_frame(this);
18
19 // Release buffers back to the clients now that the swap has returned.
20 // It's important to do this before starting on the potentially slow
21@@ -145,6 +144,8 @@
22
23 display_buffer.flip();
24 }
25+
26+ report->finished_frame(this);
27 }
28
29 void me::DemoCompositor::on_cursor_movement(
30
31=== modified file 'src/include/server/mir/compositor/compositor_report.h'
32--- src/include/server/mir/compositor/compositor_report.h 2014-12-08 04:03:47 +0000
33+++ src/include/server/mir/compositor/compositor_report.h 2015-01-12 04:06:36 +0000
34@@ -30,7 +30,8 @@
35 typedef const void* SubCompositorId; // e.g. thread/display buffer ID
36 virtual void added_display(int width, int height, int x, int y, SubCompositorId id = 0) = 0;
37 virtual void began_frame(SubCompositorId id = 0) = 0;
38- virtual void finished_frame(bool bypassed, SubCompositorId id = 0) = 0;
39+ virtual void rendered_frame(SubCompositorId id = 0) = 0;
40+ virtual void finished_frame(SubCompositorId id = 0) = 0;
41 virtual void started() = 0;
42 virtual void stopped() = 0;
43 virtual void scheduled() = 0;
44
45=== modified file 'src/server/compositor/default_display_buffer_compositor.cpp'
46--- src/server/compositor/default_display_buffer_compositor.cpp 2014-12-18 09:37:22 +0000
47+++ src/server/compositor/default_display_buffer_compositor.cpp 2015-01-12 04:06:36 +0000
48@@ -77,7 +77,6 @@
49 if (display_buffer.post_renderables_if_optimizable(renderable_list))
50 {
51 renderer->suspend();
52- report->finished_frame(true, this);
53 }
54 else
55 {
56@@ -88,7 +87,7 @@
57 renderer->render(renderable_list);
58
59 display_buffer.gl_swap_buffers();
60- report->finished_frame(false, this);
61+ report->rendered_frame(this);
62
63 // Release the buffers we did use back to the clients, before starting
64 // on the potentially slow flip().
65@@ -97,4 +96,6 @@
66
67 display_buffer.flip();
68 }
69+
70+ report->finished_frame(this);
71 }
72
73=== modified file 'src/server/report/logging/compositor_report.cpp'
74--- src/server/report/logging/compositor_report.cpp 2014-12-18 09:37:22 +0000
75+++ src/server/report/logging/compositor_report.cpp 2015-01-12 04:06:36 +0000
76@@ -59,6 +59,15 @@
77 auto t = now();
78 inst.start_of_frame = t;
79 inst.latency_sum += t - last_scheduled;
80+ inst.bypassed = true;
81+}
82+
83+void mrl::CompositorReport::rendered_frame(SubCompositorId id)
84+{
85+ std::lock_guard<std::mutex> lock(mutex);
86+ auto& inst = instance[id];
87+ inst.render_time_sum += now() - inst.start_of_frame;
88+ inst.bypassed = false;
89 }
90
91 void mrl::CompositorReport::Instance::log(ml::Logger& logger, SubCompositorId id)
92@@ -119,18 +128,16 @@
93 last_reported_bypassed = nbypassed;
94 }
95
96-void mrl::CompositorReport::finished_frame(bool bypassed,
97- SubCompositorId id)
98+void mrl::CompositorReport::finished_frame(SubCompositorId id)
99 {
100 std::lock_guard<std::mutex> lock(mutex);
101 auto& inst = instance[id];
102
103 auto t = now();
104 inst.total_time_sum += t - inst.end_of_frame;
105- inst.render_time_sum += t - inst.start_of_frame;
106 inst.end_of_frame = t;
107 inst.nframes++;
108- if (bypassed)
109+ if (inst.bypassed)
110 ++inst.nbypassed;
111
112 /*
113@@ -145,14 +152,14 @@
114 i.second.log(*logger, i.first);
115 }
116
117- if (bypassed != inst.prev_bypassed || inst.nframes == 1)
118+ if (inst.bypassed != inst.prev_bypassed || inst.nframes == 1)
119 {
120 char msg[128];
121 snprintf(msg, sizeof msg, "Display %p bypass %s",
122- id, bypassed ? "ON" : "OFF");
123+ id, inst.bypassed ? "ON" : "OFF");
124 logger->log(ml::Severity::informational, msg, component);
125 }
126- inst.prev_bypassed = bypassed;
127+ inst.prev_bypassed = inst.bypassed;
128 }
129
130 void mrl::CompositorReport::started()
131
132=== modified file 'src/server/report/logging/compositor_report.h'
133--- src/server/report/logging/compositor_report.h 2014-12-18 09:37:22 +0000
134+++ src/server/report/logging/compositor_report.h 2015-01-12 04:06:36 +0000
135@@ -44,7 +44,8 @@
136 std::shared_ptr<time::Clock> const& clock);
137 void added_display(int width, int height, int x, int y, SubCompositorId id) override;
138 void began_frame(SubCompositorId id) override;
139- void finished_frame(bool bypassed, SubCompositorId id) override;
140+ void rendered_frame(SubCompositorId id) override;
141+ void finished_frame(SubCompositorId id) override;
142 void started() override;
143 void stopped() override;
144 void scheduled() override;
145@@ -65,6 +66,7 @@
146 TimePoint latency_sum;
147 long nframes = 0;
148 long nbypassed = 0;
149+ bool bypassed = true;
150 bool prev_bypassed = false;
151
152 TimePoint last_reported_total_time_sum;
153
154=== modified file 'src/server/report/lttng/compositor_report.cpp'
155--- src/server/report/lttng/compositor_report.cpp 2014-02-09 16:18:16 +0000
156+++ src/server/report/lttng/compositor_report.cpp 2015-01-12 04:06:36 +0000
157@@ -42,8 +42,13 @@
158 mir_tracepoint(mir_server_compositor, began_frame, id);
159 }
160
161-void mir::report::lttng::CompositorReport::finished_frame(bool bypassed, SubCompositorId id)
162-{
163- mir_tracepoint(mir_server_compositor, finished_frame, bypassed, id);
164+void mir::report::lttng::CompositorReport::rendered_frame(SubCompositorId id)
165+{
166+ mir_tracepoint(mir_server_compositor, rendered_frame, id);
167+}
168+
169+void mir::report::lttng::CompositorReport::finished_frame(SubCompositorId id)
170+{
171+ mir_tracepoint(mir_server_compositor, finished_frame, id);
172 }
173
174
175=== modified file 'src/server/report/lttng/compositor_report.h'
176--- src/server/report/lttng/compositor_report.h 2014-02-09 16:18:16 +0000
177+++ src/server/report/lttng/compositor_report.h 2015-01-12 04:06:36 +0000
178@@ -37,7 +37,8 @@
179 virtual ~CompositorReport() = default;
180 void added_display(int width, int height, int x, int y, SubCompositorId id = 0) override;
181 void began_frame(SubCompositorId id = 0) override;
182- void finished_frame(bool bypassed, SubCompositorId id = 0) override;
183+ void rendered_frame(SubCompositorId id = 0) override;
184+ void finished_frame(SubCompositorId id = 0) override;
185 void started() override;
186 void stopped() override;
187 void scheduled() override;
188
189=== modified file 'src/server/report/lttng/compositor_report_tp.h'
190--- src/server/report/lttng/compositor_report_tp.h 2014-12-08 04:03:47 +0000
191+++ src/server/report/lttng/compositor_report_tp.h 2015-01-12 04:06:36 +0000
192@@ -61,12 +61,20 @@
193
194 TRACEPOINT_EVENT(
195 mir_server_compositor,
196+ rendered_frame,
197+ TP_ARGS(void const*, id),
198+ TP_FIELDS(
199+ ctf_integer_hex(uintptr_t, id, (uintptr_t)(id))
200+ )
201+)
202+
203+TRACEPOINT_EVENT(
204+ mir_server_compositor,
205 finished_frame,
206- TP_ARGS(int, bypassed, void const*, id),
207+ TP_ARGS(void const*, id),
208 TP_FIELDS(
209- ctf_integer(int, bypassed, bypassed)
210 ctf_integer_hex(uintptr_t, id, (uintptr_t)(id))
211- )
212+ )
213 )
214
215 #endif /* MIR_LTTNG_COMPOSITOR_REPORT_TP_H_ */
216
217=== modified file 'src/server/report/null/compositor_report.cpp'
218--- src/server/report/null/compositor_report.cpp 2014-03-06 06:05:17 +0000
219+++ src/server/report/null/compositor_report.cpp 2015-01-12 04:06:36 +0000
220@@ -28,7 +28,11 @@
221 {
222 }
223
224-void mrn::CompositorReport::finished_frame(bool, SubCompositorId)
225+void mrn::CompositorReport::rendered_frame(SubCompositorId)
226+{
227+}
228+
229+void mrn::CompositorReport::finished_frame(SubCompositorId)
230 {
231 }
232
233
234=== modified file 'src/server/report/null/compositor_report.h'
235--- src/server/report/null/compositor_report.h 2014-02-09 16:18:16 +0000
236+++ src/server/report/null/compositor_report.h 2015-01-12 04:06:36 +0000
237@@ -33,7 +33,8 @@
238 public:
239 void added_display(int width, int height, int x, int y, SubCompositorId id) override;
240 void began_frame(SubCompositorId id) override;
241- void finished_frame(bool bypassed, SubCompositorId id) override;
242+ void rendered_frame(SubCompositorId id) override;
243+ void finished_frame(SubCompositorId id) override;
244 void started() override;
245 void stopped() override;
246 void scheduled() override;
247
248=== modified file 'tests/include/mir_test_doubles/mock_compositor_report.h'
249--- tests/include/mir_test_doubles/mock_compositor_report.h 2014-01-07 03:12:28 +0000
250+++ tests/include/mir_test_doubles/mock_compositor_report.h 2015-01-12 04:06:36 +0000
251@@ -37,8 +37,10 @@
252 compositor::CompositorReport::SubCompositorId));
253 MOCK_METHOD1(began_frame,
254 void(compositor::CompositorReport::SubCompositorId));
255- MOCK_METHOD2(finished_frame,
256- void(bool,compositor::CompositorReport::SubCompositorId));
257+ MOCK_METHOD1(rendered_frame,
258+ void(compositor::CompositorReport::SubCompositorId));
259+ MOCK_METHOD1(finished_frame,
260+ void(compositor::CompositorReport::SubCompositorId));
261 MOCK_METHOD0(started, void());
262 MOCK_METHOD0(stopped, void());
263 MOCK_METHOD0(scheduled, void());
264
265=== modified file 'tests/unit-tests/compositor/test_default_display_buffer_compositor.cpp'
266--- tests/unit-tests/compositor/test_default_display_buffer_compositor.cpp 2014-12-18 08:12:19 +0000
267+++ tests/unit-tests/compositor/test_default_display_buffer_compositor.cpp 2015-01-12 04:06:36 +0000
268@@ -203,11 +203,39 @@
269 .WillOnce(Return(true));
270 EXPECT_CALL(mock_renderer, suspend())
271 .InSequence(seq);
272- EXPECT_CALL(*report, finished_frame(true,_))
273- .InSequence(seq);
274-
275- EXPECT_CALL(mock_renderer, render(_))
276- .Times(0);
277+ EXPECT_CALL(*report, rendered_frame(_))
278+ .Times(0);
279+ EXPECT_CALL(*report, finished_frame(_))
280+ .InSequence(seq);
281+
282+ EXPECT_CALL(mock_renderer, render(_))
283+ .Times(0);
284+
285+ mc::DefaultDisplayBufferCompositor compositor(
286+ display_buffer,
287+ mt::fake_shared(mock_renderer),
288+ report);
289+ compositor.composite(make_scene_elements({}));
290+}
291+
292+TEST_F(DefaultDisplayBufferCompositor, rendering_reports_everything)
293+{
294+ using namespace testing;
295+ auto report = std::make_shared<mtd::MockCompositorReport>();
296+
297+ Sequence seq;
298+ EXPECT_CALL(*report, began_frame(_))
299+ .InSequence(seq);
300+ EXPECT_CALL(display_buffer, post_renderables_if_optimizable(_))
301+ .InSequence(seq)
302+ .WillOnce(Return(false));
303+ EXPECT_CALL(*report, rendered_frame(_))
304+ .InSequence(seq);
305+ EXPECT_CALL(*report, finished_frame(_))
306+ .InSequence(seq);
307+
308+ EXPECT_CALL(mock_renderer, render(_))
309+ .Times(1);
310
311 mc::DefaultDisplayBufferCompositor compositor(
312 display_buffer,
313
314=== modified file 'tests/unit-tests/logging/test_compositor_report.cpp'
315--- tests/unit-tests/logging/test_compositor_report.cpp 2014-11-17 18:26:11 +0000
316+++ tests/unit-tests/logging/test_compositor_report.cpp 2015-01-12 04:06:36 +0000
317@@ -82,7 +82,8 @@
318 {
319 report.began_frame(display_id);
320 clock->advance_by(chrono::microseconds(1000000 / target_fps));
321- report.finished_frame(false, display_id);
322+ report.rendered_frame(display_id);
323+ report.finished_frame(display_id);
324 }
325
326 float measured_fps, measured_frame_time;
327@@ -100,7 +101,8 @@
328 {
329 report.began_frame(display_id);
330 clock->advance_by(chrono::microseconds(1000000 / target_fps));
331- report.finished_frame(false, display_id);
332+ report.rendered_frame(display_id);
333+ report.finished_frame(display_id);
334 }
335 ASSERT_TRUE(recorder->scrape(measured_fps, measured_frame_time))
336 << recorder->last_message();
337@@ -117,7 +119,8 @@
338
339 report.began_frame(before);
340 clock->advance_by(chrono::microseconds(12345));
341- report.finished_frame(false, before);
342+ report.rendered_frame(before);
343+ report.finished_frame(before);
344
345 report.stopped();
346 clock->advance_by(chrono::microseconds(12345678));
347@@ -125,13 +128,15 @@
348
349 report.began_frame(after);
350 clock->advance_by(chrono::microseconds(12345));
351- report.finished_frame(false, after);
352+ report.rendered_frame(after);
353+ report.finished_frame(after);
354
355 clock->advance_by(chrono::microseconds(12345678));
356
357 report.began_frame(after);
358 clock->advance_by(chrono::microseconds(12345));
359- report.finished_frame(false, after);
360+ report.rendered_frame(after);
361+ report.finished_frame(after);
362
363 report.stopped();
364 }
365@@ -143,23 +148,44 @@
366 report.started();
367
368 report.began_frame(id);
369- report.finished_frame(false, id);
370+ report.rendered_frame(id);
371+ report.finished_frame(id);
372 EXPECT_TRUE(recorder->last_message_contains("bypass OFF"))
373 << recorder->last_message();
374
375 for (int f = 0; f < 3; ++f)
376 {
377 report.began_frame(id);
378- report.finished_frame(false, id);
379+ report.rendered_frame(id);
380+ report.finished_frame(id);
381 clock->advance_by(chrono::microseconds(12345678));
382 }
383 EXPECT_FALSE(recorder->last_message_contains("bypass "))
384 << recorder->last_message();
385
386 report.began_frame(id);
387- report.finished_frame(true, id);
388+ report.finished_frame(id);
389 EXPECT_TRUE(recorder->last_message_contains("bypass ON"))
390 << recorder->last_message();
391
392 report.stopped();
393 }
394+
395+TEST_F(LoggingCompositorReport, bypass_has_no_render_time)
396+{ // Regression test for LP: #1408906
397+ const void* const id = "My Screen";
398+
399+ report.started();
400+
401+ for (int f = 0; f < 3; ++f)
402+ {
403+ report.began_frame(id);
404+ clock->advance_by(chrono::microseconds(1234));
405+ report.finished_frame(id);
406+ clock->advance_by(chrono::microseconds(12345678));
407+ }
408+ EXPECT_TRUE(recorder->last_message_contains("0.000 ms/frame"))
409+ << recorder->last_message();
410+
411+ report.stopped();
412+}

Subscribers

People subscribed via source and target branches