Mir

Merge lp:~kdub/mir/report-vsync into lp:mir

report-vsync
Merge into development-branch

Proposed by Kevin DuBois on 2015-03-02

Status:	Merged
Approved by:	Kevin DuBois on 2015-03-04
Approved revision:	2374
Merged at revision:	2361
Proposed branch:	lp:~kdub/mir/report-vsync
Merge into:	lp:mir
Diff against target:	782 lines (+228/-89) 26 files modified src/include/platform/mir/graphics/display_report.h (+2/-0) src/platforms/android/server/display.cpp (+9/-1) src/platforms/android/server/display.h (+2/-0) src/platforms/android/server/fb_device.cpp (+3/-1) src/platforms/android/server/fb_device.h (+3/-1) src/platforms/android/server/hwc_blanking_control.cpp (+4/-3) src/platforms/android/server/hwc_configuration.h (+6/-2) src/platforms/mesa/server/display.cpp (+1/-1) src/platforms/mesa/server/kms_page_flipper.cpp (+19/-10) src/platforms/mesa/server/kms_page_flipper.h (+5/-2) src/server/report/logging/display_report.cpp (+26/-1) src/server/report/logging/display_report.h (+24/-13) src/server/report/logging/logging_report_factory.cpp (+1/-1) src/server/report/lttng/display_report.cpp (+2/-6) src/server/report/lttng/display_report.h (+10/-11) src/server/report/lttng/display_report_tp.h (+9/-0) src/server/report/null/display_report.cpp (+1/-0) src/server/report/null/display_report.h (+1/-0) tests/include/mir_test_doubles/mock_display_report.h (+1/-2) tests/include/mir_test_doubles/stub_display_builder.h (+5/-4) tests/unit-tests/graphics/android/test_display.cpp (+26/-4) tests/unit-tests/graphics/android/test_display_hotplug.cpp (+3/-3) tests/unit-tests/graphics/android/test_hwc_configuration.cpp (+13/-7) tests/unit-tests/graphics/mesa/test_display.cpp (+5/-4) tests/unit-tests/graphics/mesa/test_kms_page_flipper.cpp (+20/-1) tests/unit-tests/logging/test_display_report.cpp (+27/-11)
To merge this branch:	bzr merge lp:~kdub/mir/report-vsync
Related bugs:	Link a bug report

Reviewer	Review Type	Date Requested	Status
PS Jenkins bot	continuous-integration		Approve on 2015-03-04
Robert Carr (community)			Approve on 2015-03-04
Alan Griffiths			Approve on 2015-03-04
Andreas Pokorny (community)			Approve on 2015-03-04
Alexandros Frantzis (community)			Approve on 2015-03-04
Daniel van Vugt		2015-03-02	Abstain on 2015-03-03
Review via email: mp+251532@code.launchpad.net

Commit Message

graphics: add a report_vsync method for android and mesa in mg::DisplayReport with logging, null, and lttng implementations of function.

Description of the Change

graphics: add a report_vsync method for android and mesa in mg::DisplayReport with logging, null, and lttng implementations of function.

PS Jenkins bot (ps-jenkins) wrote on 2015-03-03:

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

review: Approve (continuous-integration)

Daniel van Vugt (vanvugt) wrote on 2015-03-03:

Suggest "needs fixing", but not strictly.

(1) The name arguably needs fixing because "vsync" is not an event. The two events are (a) vblank and then (about 50-60 microseconds later); (b) page flip completed. Although not all platforms will implement it as a "page flip" so the generic term we invented "post" could be used.

(2) These two equivalent reporting points would be less confusing if unified:

180 /* If the page flip we are waiting for has arrived we are done. */
181 if (page_flip_is_done(crtc_id))
182 + {
183 + report->report_vsync(std::to_string(crtc_id));
184 return;
185 + }
186
187 /* ...otherwise we become the worker */
188 worker_tid = std::this_thread::get_id();
189 @@ -140,6 +146,7 @@
190 */
191 pf_cv.notify_all();
192 }
193 + report->report_vsync(std::to_string(crtc_id));

You can do this by making ::page_flip_handler call a new `KMSPageFlipper::page_flip_handler()', as that would have access to the `report' and other private fields. And then you correctly only have to call `report_vsync' in one place.

This is fresh in my mind as I spent much of the past few days hacking this code :)

review: Needs Fixing

Daniel van Vugt (vanvugt) on 2015-03-03:

review: Abstain

Daniel van Vugt (vanvugt) wrote on 2015-03-03:

(1) Whoops, don't call it "post". "post" is the push event at the back of the DisplayBuffer's queue, whereas you're actually measuring the pop from the front. So yeah call it "vsync" if not "scan-out" etc.

Alan Griffiths (alan-griffiths) wrote on 2015-03-03:

45 + display_report->report_vsync(std::to_string(name));

The report interfaces shouldn't force any unnecessary object creation. (Like creating a string here.) In practice we've got an int - so can't we pass that and stream that to output only if reporting?

review: Needs Fixing

lp:~kdub/mir/report-vsync updated on 2015-03-03

2367. By Kevin DuBois on 2015-03-03: improve vsync notification by having the page_flip_handler call the report object
2368. By Kevin DuBois on 2015-03-03: merge mir
2369. By Kevin DuBois on 2015-03-03: small whitespace cleanups
2370. By Kevin DuBois on 2015-03-03: accept an int instead of a string as the report_vsync parameter

Kevin DuBois (kdub) wrote on 2015-03-03:

@Daniel,
1) seems like were keeping report_vsync() then?
2) good idea, we now call the report from the pageflip callback.

@Alan, corrected to take an int as a display id.

PS Jenkins bot (ps-jenkins) wrote on 2015-03-03:

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

review: Needs Fixing (continuous-integration)

lp:~kdub/mir/report-vsync updated on 2015-03-03

2371. By Kevin DuBois on 2015-03-03: correct when the notification happens to correct valgrind error

PS Jenkins bot (ps-jenkins) wrote on 2015-03-03:

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

review: Needs Fixing (continuous-integration)

Kevin DuBois (kdub) wrote on 2015-03-03:

Looks like a transient error:
subprocess.CalledProcessError: Command 'phablet-network --skip-setup' returned non-zero exit status 124

PS Jenkins bot (ps-jenkins) wrote on 2015-03-03:

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

review: Approve (continuous-integration)

Daniel van Vugt (vanvugt) wrote on 2015-03-04:

(3) You don't need to pass pending_page_flips into the callback any more. Just do the erase in notify_page_flip instead...
156 + page_flip_data->flipper->notify_page_flip(page_flip_data->crtc_id);
157 page_flip_data->pending->erase(page_flip_data->crtc_id);
~~
180 - pending_page_flips[crtc_id] = PageFlipEventData{&pending_page_flips, crtc_id};
181 + pending_page_flips[crtc_id] = PageFlipEventData{&pending_page_flips, crtc_id, this};

(4) The timing is slightly off, but it's probably negligible. The report will be called after the actual page flip happened, because we're calling it from our wait function which could be anything up to a frame later than when the flip "vsync" occurred. To get accurate timings into the report, use the (presently unused) timestamp parameters in the page flip callback (which is a kernel timestamp relative to CLOCK_MONOTONIC). Although the complexity this creates might be worse than any inaccuracies in the current approach. It's also platform-specific unless you convert between clocks. So maybe not...

Alan Griffiths (alan-griffiths) wrote on 2015-03-04:

One thought though...

239 +void mrl::DisplayReport::report_vsync(unsigned int display_id)
240 +{
241 + logger->log(ml::Severity::informational, "vsync event on [" + std::to_string(display_id) + "]", component());
242 +}

...is the raw "vsync event on [...]" log message useful or should the report be collating statistical information?

review: Approve

Alexandros Frantzis (afrantzis) wrote on 2015-03-04:

Looks good.

> (3) You don't need to pass pending_page_flips into the callback any more.

+1 but not a blocker

review: Approve

Andreas Pokorny (andreas-pokorny) wrote on 2015-03-04:

looks good, yes and agree.. that might be to much spam to be interesting. I think it might also be fine to just omit it for now, until we figure out what information might be worth interpreting.

review: Approve

lp:~kdub/mir/report-vsync updated on 2015-03-04

2372. By Kevin DuBois on 2015-03-04: erase the pending_page_flips from within a member function of KMSPageFlipper
2373. By Kevin DuBois on 2015-03-04: collate the incoming vsync data for the DisplayReport

Kevin DuBois (kdub) wrote on 2015-03-04:

(3) is a good improvement, added to this branch
(4) true, although I think it would be neglible as well (I'm interested in hundreds-of-microsecond resolution)

Also collated the vsync data so it would be reported at most once per second.

Kevin DuBois (kdub) wrote on 2015-03-04:

> (3) is a good improvement, added to this branch
> (4) true, although I think it would be neglible as well (I'm interested in
> hundreds-of-microsecond resolution)
>
> Also collated the vsync data so it would be reported at most once per second.

example output:
[1425479039.147480] graphics: 42 vsync events on [0] over 1004ms
[1425479040.148487] graphics: 60 vsync events on [0] over 1001ms
[1425479041.149372] graphics: 60 vsync events on [0] over 1000ms

Alan Griffiths (alan-griffiths) wrote on 2015-03-04:

263 + event_map[display_id]++;
264 + if (now > last_report + report_interval)
265 + {
266 + for(auto const& event : event_map)
267 + logger->log(ml::Severity::informational,
268 + std::to_string(event.second) + " vsync events on [" +
269 + std::to_string(event.first) + "] over " +
270 + std::to_string(duration_cast<milliseconds>(now - last_report).count()) + "ms",
271 + component());
272 + event_map.clear();
273 + last_report = now;
274 + }

Needs a mutex & lock

review: Needs Fixing

lp:~kdub/mir/report-vsync updated on 2015-03-04

2374. By Kevin DuBois on 2015-03-04: guard the collated vsync reporting with a lock

PS Jenkins bot (ps-jenkins) wrote on 2015-03-04:

FAILED: Continuous integration, rev:2373
http://jenkins.qa.ubuntu.com/job/mir-ci/3125/
Executed test runs:
None: http://jenkins.qa.ubuntu.com/job/mir-mediumtests-vivid-touch/1456/console
None: http://jenkins.qa.ubuntu.com/job/mir-mediumtests-builder-vivid-armhf/1456/console

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

review: Needs Fixing (continuous-integration)

Alan Griffiths (alan-griffiths) wrote on 2015-03-04:

LGTM

review: Approve

Kevin DuBois (kdub) wrote on 2015-03-04:

^^manually cancelled

Robert Carr (robertcarr) wrote on 2015-03-04:

LGTM.

review: Approve

PS Jenkins bot (ps-jenkins) wrote on 2015-03-04:

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

review: Approve (continuous-integration)

Preview Diff

[H/L] Next/Prev Comment, [J/K] Next/Prev File, [N/P] Next/Prev Hunk

Subscribers

People subscribed via source and target branches

to all changes:

Emanuele Antonio Faraone

Gerry Boland

Kevin DuBois

Mir development team

 === modified file 'src/include/platform/mir/graphics/display_report.h'
 --- src/include/platform/mir/graphics/display_report.h	2015-01-21 07:34:50 +0000
 +++ src/include/platform/mir/graphics/display_report.h	2015-03-04 14:36:55 +0000
@@ -35,6 +35,8 @@
      virtual void report_successful_egl_buffer_swap_on_construction() = 0;
      virtual void report_successful_display_construction() = 0;
      virtual void report_egl_configuration(EGLDisplay disp, EGLConfig cfg) = 0;
++    virtual void report_vsync(unsigned int display_id) = 0;
++
      /* gbm specific */
      virtual void report_successful_drm_mode_set_crtc_on_construction() = 0;
      virtual void report_drm_master_failure(int error) = 0;
 === modified file 'src/platforms/android/server/display.cpp'
 --- src/platforms/android/server/display.cpp	2015-03-03 06:56:37 +0000
 +++ src/platforms/android/server/display.cpp	2015-03-04 14:36:55 +0000
@@ -135,9 +135,12 @@
      std::shared_ptr<GLConfig> const& gl_config,
      std::shared_ptr<DisplayReport> const& display_report,
      mga::OverlayOptimization overlay_option) :
++    display_report{display_report},
      display_buffer_builder{display_buffer_builder},
      hwc_config{display_buffer_builder->create_hwc_configuration()},
--    hotplug_subscription{hwc_config->subscribe_to_config_changes(std::bind(&mga::Display::on_hotplug, this))},
++    hotplug_subscription{hwc_config->subscribe_to_config_changes(
++        std::bind(&mga::Display::on_hotplug, this),
++        std::bind(&mga::Display::on_vsync, this, std::placeholders::_1))},
      primary_attribs(hwc_config->active_attribs_for(mga::DisplayName::primary)),
      external_attribs(hwc_config->active_attribs_for(mga::DisplayName::external)),
      config(
@@ -269,6 +272,11 @@
      display_change_pipe->notify_change();
+ }
++void mga::Display::on_vsync(DisplayName name) const
++{
++    display_report->report_vsync(name);
++}
++
  void mga::Display::register_configuration_change_handler(
      EventHandlerRegister& event_handler,
      DisplayConfigurationChangeHandler const& change_handler)
 === modified file 'src/platforms/android/server/display.h'
 --- src/platforms/android/server/display.h	2015-03-03 06:56:37 +0000
 +++ src/platforms/android/server/display.h	2015-03-04 14:36:55 +0000
@@ -80,7 +80,9 @@
  private:
      void on_hotplug();
++    void on_vsync(DisplayName) const;
++    std::shared_ptr<DisplayReport> const display_report;
      std::shared_ptr<DisplayComponentFactory> const display_buffer_builder;
      std::mutex mutable configuration_mutex;
      bool mutable configuration_dirty{false};
 === modified file 'src/platforms/android/server/fb_device.cpp'
 --- src/platforms/android/server/fb_device.cpp	2015-03-03 06:56:37 +0000
 +++ src/platforms/android/server/fb_device.cpp	2015-03-04 14:36:55 +0000
@@ -68,7 +68,9 @@
        fb_num};
+ }
--mga::ConfigChangeSubscription mga::FbControl::subscribe_to_config_changes(std::function<void()> const&)
++mga::ConfigChangeSubscription mga::FbControl::subscribe_to_config_changes(
++        std::function<void()> const&,
++        std::function<void(DisplayName)> const&)
+ {
      return nullptr;
+ }
 === modified file 'src/platforms/android/server/fb_device.h'
 --- src/platforms/android/server/fb_device.h	2015-03-03 06:56:37 +0000
 +++ src/platforms/android/server/fb_device.h	2015-03-04 14:36:55 +0000
@@ -37,7 +37,9 @@
      FbControl(std::shared_ptr<framebuffer_device_t> const& fbdev);
      void power_mode(DisplayName, MirPowerMode) override;
      DisplayAttribs active_attribs_for(DisplayName) override;
--    ConfigChangeSubscription subscribe_to_config_changes(std::function<void()> const& cb) override;
++    ConfigChangeSubscription subscribe_to_config_changes(
++        std::function<void()> const& hotplug_cb,
++        std::function<void(DisplayName)> const& vsync_cb) override;
  private:
      std::shared_ptr<framebuffer_device_t> const fb_device;
  };
 === modified file 'src/platforms/android/server/hwc_blanking_control.cpp'
 --- src/platforms/android/server/hwc_blanking_control.cpp	2015-03-03 06:56:37 +0000
 +++ src/platforms/android/server/hwc_blanking_control.cpp	2015-03-04 14:36:55 +0000
@@ -146,13 +146,14 @@
+ }
  mga::ConfigChangeSubscription mga::HwcBlankingControl::subscribe_to_config_changes(
--    std::function<void()> const& hotplug)
++    std::function<void()> const& hotplug,
++    std::function<void(DisplayName)> const& vsync)
+ {
      return std::make_shared<
          mir::raii::PairedCalls<std::function<void()>, std::function<void()>>>(
--        [hotplug, this]{
++        [hotplug, vsync, this]{
              hwc_device->subscribe_to_events(this,
--                [](DisplayName, std::chrono::nanoseconds){},
++                [vsync](DisplayName name, std::chrono::nanoseconds){ vsync(name); },
                  [hotplug](DisplayName, bool){ hotplug(); },
                  []{});
          },
 === modified file 'src/platforms/android/server/hwc_configuration.h'
 --- src/platforms/android/server/hwc_configuration.h	2015-02-13 06:12:34 +0000
 +++ src/platforms/android/server/hwc_configuration.h	2015-03-04 14:36:55 +0000
@@ -50,7 +50,9 @@
      virtual ~HwcConfiguration() = default;
      virtual void power_mode(DisplayName, MirPowerMode) = 0;
      virtual DisplayAttribs active_attribs_for(DisplayName) = 0;
--    virtual ConfigChangeSubscription subscribe_to_config_changes(std::function<void()> const& cb) = 0;
++    virtual ConfigChangeSubscription subscribe_to_config_changes(
++        std::function<void()> const& hotplug_cb,
++        std::function<void(DisplayName)> const& vsync_cb) = 0;
  protected:
      HwcConfiguration() = default;
@@ -65,7 +67,9 @@
      HwcBlankingControl(std::shared_ptr<HwcWrapper> const&);
      void power_mode(DisplayName, MirPowerMode) override;
      DisplayAttribs active_attribs_for(DisplayName) override;
--    ConfigChangeSubscription subscribe_to_config_changes(std::function<void()> const& cb) override;
++    ConfigChangeSubscription subscribe_to_config_changes(
++        std::function<void()> const& hotplug_cb,
++        std::function<void(DisplayName)> const& vsync_cb) override;
  private:
      DeviceQuirks quirks{PropertiesOps{}};
 === modified file 'src/platforms/mesa/server/display.cpp'
 --- src/platforms/mesa/server/display.cpp	2015-02-26 03:20:09 +0000
 +++ src/platforms/mesa/server/display.cpp	2015-03-04 14:36:55 +0000
@@ -88,7 +88,7 @@
        monitor(mir::udev::Context()),
        shared_egl{*gl_config},
        output_container{platform->drm->fd,
--                       std::make_shared<KMSPageFlipper>(platform->drm->fd)},
++                       std::make_shared<KMSPageFlipper>(platform->drm->fd, listener)},
        current_display_configuration{platform->drm->fd},
        gl_config{gl_config}
+ {
 === modified file 'src/platforms/mesa/server/kms_page_flipper.cpp'
 --- src/platforms/mesa/server/kms_page_flipper.cpp	2015-01-22 09:00:14 +0000
 +++ src/platforms/mesa/server/kms_page_flipper.cpp	2015-03-04 14:36:55 +0000
@@ -37,15 +37,18 @@
                         void* data)
+ {
      auto page_flip_data = static_cast<mgm::PageFlipEventData*>(data);
--    page_flip_data->pending->erase(page_flip_data->crtc_id);
--}
--
--}
--
--mgm::KMSPageFlipper::KMSPageFlipper(int drm_fd)
--    : drm_fd{drm_fd},
--      pending_page_flips(),
--      worker_tid()
++    page_flip_data->flipper->notify_page_flip(page_flip_data->crtc_id);
++}
++
++}
++
++mgm::KMSPageFlipper::KMSPageFlipper(
++    int drm_fd,
++    std::shared_ptr<DisplayReport> const& report) :
++    drm_fd{drm_fd},
++    report{report},
++    pending_page_flips(),
++    worker_tid()
+ {
+ }
@@ -56,7 +59,7 @@
      if (pending_page_flips.find(crtc_id) != pending_page_flips.end())
          BOOST_THROW_EXCEPTION(std::logic_error("Page flip for crtc_id is already scheduled"));
--    pending_page_flips[crtc_id] = PageFlipEventData{&pending_page_flips, crtc_id};
++    pending_page_flips[crtc_id] = PageFlipEventData{crtc_id, this};
      auto ret = drmModePageFlip(drm_fd, crtc_id, fb_id,
                                 DRM_MODE_PAGE_FLIP_EVENT,
@@ -154,3 +157,9 @@
+ {
      return pending_page_flips.find(crtc_id) == pending_page_flips.end();
+ }
++
++void mgm::KMSPageFlipper::notify_page_flip(uint32_t crtc_id)
++{
++    report->report_vsync(crtc_id);
++    pending_page_flips.erase(crtc_id);
++}
 === modified file 'src/platforms/mesa/server/kms_page_flipper.h'
 --- src/platforms/mesa/server/kms_page_flipper.h	2015-01-22 09:00:14 +0000
 +++ src/platforms/mesa/server/kms_page_flipper.h	2015-03-04 14:36:55 +0000
@@ -39,26 +39,29 @@
  namespace mesa
+ {
++class KMSPageFlipper;
  struct PageFlipEventData
+ {
--    std::unordered_map<uint32_t,PageFlipEventData>* pending;
      uint32_t crtc_id;
++    KMSPageFlipper* flipper;
  };
  class KMSPageFlipper : public PageFlipper
+ {
  public:
--    KMSPageFlipper(int drm_fd);
++    KMSPageFlipper(int drm_fd, std::shared_ptr<DisplayReport> const& report);
      bool schedule_flip(uint32_t crtc_id, uint32_t fb_id);
      void wait_for_flip(uint32_t crtc_id);
      std::thread::id debug_get_worker_tid();
++    void notify_page_flip(uint32_t crtc_id);
  private:
      bool page_flip_is_done(uint32_t crtc_id);
      int const drm_fd;
++    std::shared_ptr<DisplayReport> const report;
      std::unordered_map<uint32_t,PageFlipEventData> pending_page_flips;
      std::mutex pf_mutex;
      std::condition_variable pf_cv;
 === modified file 'src/server/report/logging/display_report.cpp'
 --- src/server/report/logging/display_report.cpp	2015-01-21 07:34:50 +0000
 +++ src/server/report/logging/display_report.cpp	2015-03-04 14:36:55 +0000
@@ -25,7 +25,12 @@
  namespace ml=mir::logging;
  namespace mrl=mir::report::logging;
--mrl::DisplayReport::DisplayReport(const std::shared_ptr<ml::Logger>& logger) : logger(logger)
++mrl::DisplayReport::DisplayReport(
++    std::shared_ptr<ml::Logger> const& logger,
++    std::shared_ptr<time::Clock> const& clock) :
++    logger(logger),
++    clock(clock),
++    last_report(clock->now())
+ {
+ }
@@ -141,3 +146,23 @@
              "    [" + i.name + "] : " + std::to_string(value), component());
+     }
+ }
++
++void mrl::DisplayReport::report_vsync(unsigned int display_id)
++{
++    using namespace std::chrono;
++    seconds const static report_interval{1};
++    std::unique_lock<decltype(vsync_event_mutex)> lk(vsync_event_mutex);
++    auto now = clock->now();
++    event_map[display_id]++;
++    if (now > last_report + report_interval)
++    {
++        for(auto const& event : event_map)
++            logger->log(ml::Severity::informational,
++                std::to_string(event.second) + " vsync events on [" +
++                std::to_string(event.first) + "] over " +
++                std::to_string(duration_cast<milliseconds>(now - last_report).count()) + "ms",
++                component());
++        event_map.clear();
++        last_report = now;
++    }
++}
 === modified file 'src/server/report/logging/display_report.h'
 --- src/server/report/logging/display_report.h	2015-01-21 07:34:50 +0000
 +++ src/server/report/logging/display_report.h	2015-03-04 14:36:55 +0000
@@ -21,8 +21,11 @@
  #define MIR_REPORT_LOGGING_DISPLAY_REPORTER_H_
  #include "mir/graphics/display_report.h"
++#include "mir/time/clock.h"
++#include <unordered_map>
  #include <memory>
++#include <mutex>
  namespace mir
+ {
@@ -41,25 +44,33 @@
      static const char* component();
--    DisplayReport(const std::shared_ptr<mir::logging::Logger>& logger);
++    DisplayReport(
++        std::shared_ptr<mir::logging::Logger> const& logger,
++        std::shared_ptr<time::Clock> const& clock);
++
      virtual ~DisplayReport();
--    virtual void report_successful_setup_of_native_resources();
--    virtual void report_successful_egl_make_current_on_construction();
--    virtual void report_successful_egl_buffer_swap_on_construction();
--    virtual void report_successful_drm_mode_set_crtc_on_construction();
--    virtual void report_successful_display_construction();
--    virtual void report_drm_master_failure(int error);
--    virtual void report_vt_switch_away_failure();
--    virtual void report_vt_switch_back_failure();
--    virtual void report_egl_configuration(EGLDisplay disp, EGLConfig cfg);
++    virtual void report_successful_setup_of_native_resources() override;
++    virtual void report_successful_egl_make_current_on_construction() override;
++    virtual void report_successful_egl_buffer_swap_on_construction() override;
++    virtual void report_successful_drm_mode_set_crtc_on_construction() override;
++    virtual void report_successful_display_construction() override;
++    virtual void report_vsync(unsigned int display_id) override;
++    virtual void report_drm_master_failure(int error) override;
++    virtual void report_vt_switch_away_failure() override;
++    virtual void report_vt_switch_back_failure() override;
++    virtual void report_egl_configuration(EGLDisplay disp, EGLConfig cfg) override;
    protected:
--    DisplayReport(const DisplayReport&) = delete;
--    DisplayReport& operator=(const DisplayReport&) = delete;
++    DisplayReport(DisplayReport const&) = delete;
++    DisplayReport& operator=(DisplayReport const&) = delete;
    private:
--    std::shared_ptr<mir::logging::Logger> logger;
++    std::shared_ptr<mir::logging::Logger> const logger;
++    std::shared_ptr<time::Clock> const clock;
++    std::mutex vsync_event_mutex;
++    mir::time::Timestamp last_report;
++    std::unordered_map<unsigned int, unsigned int> event_map;
  };
+ }
+ }
 === modified file 'src/server/report/logging/logging_report_factory.cpp'
 --- src/server/report/logging/logging_report_factory.cpp	2015-02-13 06:12:34 +0000
 +++ src/server/report/logging/logging_report_factory.cpp	2015-03-04 14:36:55 +0000
@@ -45,7 +45,7 @@
  std::shared_ptr<mir::graphics::DisplayReport> mr::LoggingReportFactory::create_display_report()
+ {
--    return std::make_shared<logging::DisplayReport>(logger);
++    return std::make_shared<logging::DisplayReport>(logger, clock);
+ }
  std::shared_ptr<mir::scene::SceneReport> mr::LoggingReportFactory::create_scene_report()
 === modified file 'src/server/report/lttng/display_report.cpp'
 --- src/server/report/lttng/display_report.cpp	2014-02-09 16:18:16 +0000
 +++ src/server/report/lttng/display_report.cpp	2015-03-04 14:36:55 +0000
@@ -35,7 +35,6 @@
  DISPLAY_REPORT_TRACE_CALL(report_successful_drm_mode_set_crtc_on_construction)
  DISPLAY_REPORT_TRACE_CALL(report_vt_switch_away_failure)
  DISPLAY_REPORT_TRACE_CALL(report_vt_switch_back_failure)
--DISPLAY_REPORT_TRACE_CALL(report_gpu_composition_in_use)
  #undef DISPLAY_REPORT_TRACE_CALL
@@ -43,15 +42,12 @@
+ {
+ }
--
  void mir::report::lttng::DisplayReport::report_drm_master_failure(int error)
+ {
      mir_tracepoint(mir_server_display, report_drm_master_failure, strerror(error));
+ }
--
--void mir::report::lttng::DisplayReport::report_hwc_composition_in_use(int major, int minor)
++void mir::report::lttng::DisplayReport::report_vsync(unsigned int display_id)
+ {
--    mir_tracepoint(mir_server_display, report_hwc_composition_in_use, major, minor);
++    mir_tracepoint(mir_server_display, report_vsync, display_id);
+ }
--
 === modified file 'src/server/report/lttng/display_report.h'
 --- src/server/report/lttng/display_report.h	2014-02-17 22:35:23 +0000
 +++ src/server/report/lttng/display_report.h	2015-03-04 14:36:55 +0000
@@ -36,17 +36,16 @@
      DisplayReport() = default;
      virtual ~DisplayReport() noexcept(true) = default;
--    virtual void report_successful_setup_of_native_resources();
--    virtual void report_successful_egl_make_current_on_construction();
--    virtual void report_successful_egl_buffer_swap_on_construction();
--    virtual void report_successful_display_construction();
--    virtual void report_egl_configuration(EGLDisplay disp, EGLConfig cfg);
--    virtual void report_successful_drm_mode_set_crtc_on_construction();
--    virtual void report_drm_master_failure(int error);
--    virtual void report_vt_switch_away_failure();
--    virtual void report_vt_switch_back_failure();
--    virtual void report_hwc_composition_in_use(int major, int minor);
--    virtual void report_gpu_composition_in_use();
++    virtual void report_successful_setup_of_native_resources() override;
++    virtual void report_successful_egl_make_current_on_construction() override;
++    virtual void report_successful_egl_buffer_swap_on_construction() override;
++    virtual void report_successful_display_construction() override;
++    virtual void report_egl_configuration(EGLDisplay disp, EGLConfig cfg) override;
++    virtual void report_successful_drm_mode_set_crtc_on_construction() override;
++    virtual void report_drm_master_failure(int error) override;
++    virtual void report_vt_switch_away_failure() override;
++    virtual void report_vt_switch_back_failure() override;
++    virtual void report_vsync(unsigned int display_id) override;
  private:
      ServerTracepointProvider tp_provider;
 === modified file 'src/server/report/lttng/display_report_tp.h'
 --- src/server/report/lttng/display_report_tp.h	2015-01-21 07:34:50 +0000
 +++ src/server/report/lttng/display_report_tp.h	2015-03-04 14:36:55 +0000
@@ -62,6 +62,15 @@
+     )
+ )
++TRACEPOINT_EVENT(
++    mir_server_display,
++    report_vsync,
++    TP_ARGS(int, id),
++    TP_FIELDS(
++        ctf_integer(int, id, id)
++     )
++)
++
  #endif /* MIR_LTTNG_DISPLAY_REPORT_TP_H_ */
  #include <lttng/tracepoint-event.h>
 === modified file 'src/server/report/null/display_report.cpp'
 --- src/server/report/null/display_report.cpp	2015-01-21 07:34:50 +0000
 +++ src/server/report/null/display_report.cpp	2015-03-04 14:36:55 +0000
@@ -29,3 +29,4 @@
  void mrn::DisplayReport::report_vt_switch_away_failure() {}
  void mrn::DisplayReport::report_vt_switch_back_failure() {}
  void mrn::DisplayReport::report_egl_configuration(EGLDisplay, EGLConfig) {}
++void mrn::DisplayReport::report_vsync(unsigned int) {}
 === modified file 'src/server/report/null/display_report.h'
 --- src/server/report/null/display_report.h	2015-01-21 07:34:50 +0000
 +++ src/server/report/null/display_report.h	2015-03-04 14:36:55 +0000
@@ -43,6 +43,7 @@
      void report_vt_switch_away_failure() override;
      void report_vt_switch_back_failure() override;
      void report_egl_configuration(EGLDisplay disp, EGLConfig cfg) override;
++    void report_vsync(unsigned int display_id) override;
  };
+ }
+ }
 === modified file 'tests/include/mir_test_doubles/mock_display_report.h'
 --- tests/include/mir_test_doubles/mock_display_report.h	2013-05-10 18:16:51 +0000
 +++ tests/include/mir_test_doubles/mock_display_report.h	2015-03-04 14:36:55 +0000
@@ -41,9 +41,8 @@
      MOCK_METHOD1(report_drm_master_failure, void(int));
      MOCK_METHOD0(report_vt_switch_away_failure, void());
      MOCK_METHOD0(report_vt_switch_back_failure, void());
--    MOCK_METHOD2(report_hwc_composition_in_use, void(int,int));
--    MOCK_METHOD0(report_gpu_composition_in_use, void());
      MOCK_METHOD2(report_egl_configuration, void(EGLDisplay,EGLConfig));
++    MOCK_METHOD1(report_vsync, void(unsigned int));
  };
+ }
 === modified file 'tests/include/mir_test_doubles/stub_display_builder.h'
 --- tests/include/mir_test_doubles/stub_display_builder.h	2015-02-26 03:20:09 +0000
 +++ tests/include/mir_test_doubles/stub_display_builder.h	2015-03-04 14:36:55 +0000
@@ -47,7 +47,7 @@
      MockHwcConfiguration()
+     {
          using namespace testing;
--        ON_CALL(*this, subscribe_to_config_changes(_)).WillByDefault(Return(nullptr));
++        ON_CALL(*this, subscribe_to_config_changes(_,_)).WillByDefault(Return(nullptr));
          ON_CALL(*this, active_attribs_for(graphics::android::DisplayName::primary))
              .WillByDefault(testing::Return(graphics::android::DisplayAttribs{
                  {0,0},{0,0}, 0.0, true, mir_pixel_format_abgr_8888, 2}));
@@ -57,8 +57,9 @@
+     }
      MOCK_METHOD2(power_mode, void(graphics::android::DisplayName, MirPowerMode));
      MOCK_METHOD1(active_attribs_for, graphics::android::DisplayAttribs(graphics::android::DisplayName));
--    MOCK_METHOD1(subscribe_to_config_changes,
--        graphics::android::ConfigChangeSubscription(std::function<void()> const&));
++    MOCK_METHOD2(subscribe_to_config_changes,
++        graphics::android::ConfigChangeSubscription(
++            std::function<void()> const&, std::function<void(graphics::android::DisplayName)> const&));
  };
  struct StubHwcConfiguration : public graphics::android::HwcConfiguration
@@ -77,7 +78,7 @@
      graphics::android::ConfigChangeSubscription subscribe_to_config_changes(
--        std::function<void()> const&) override
++        std::function<void()> const&, std::function<void(graphics::android::DisplayName)> const&) override
+     {
          return nullptr;
+     }
 === modified file 'tests/unit-tests/graphics/android/test_display.cpp'
 --- tests/unit-tests/graphics/android/test_display.cpp	2015-03-03 06:56:37 +0000
 +++ tests/unit-tests/graphics/android/test_display.cpp	2015-03-04 14:36:55 +0000
@@ -554,7 +554,7 @@
      auto use_count_before = subscription.use_count();
      stub_db_factory->with_next_config([&](mtd::MockHwcConfiguration& mock_config)
+     {
--        EXPECT_CALL(mock_config, subscribe_to_config_changes(_))
++        EXPECT_CALL(mock_config, subscribe_to_config_changes(_,_))
              .WillOnce(Return(subscription));
      });
+     {
@@ -596,7 +596,7 @@
      stub_db_factory->with_next_config([&](mtd::MockHwcConfiguration& mock_config)
+     {
--        EXPECT_CALL(mock_config, subscribe_to_config_changes(_))
++        EXPECT_CALL(mock_config, subscribe_to_config_changes(_,_))
              .WillOnce(DoAll(SaveArg<0>(&hotplug_fn), Return(subscription)));
          EXPECT_CALL(mock_config, active_attribs_for(mga::DisplayName::primary))
              .Times(2)
@@ -645,7 +645,7 @@
                  return mga::DisplayAttribs{
                      {20,20}, {4,4}, 50.0f, external_connected, mir_pixel_format_abgr_8888, 2};
              }));
--        EXPECT_CALL(mock_config, subscribe_to_config_changes(_))
++        EXPECT_CALL(mock_config, subscribe_to_config_changes(_,_))
              .WillOnce(DoAll(SaveArg<0>(&hotplug_fn), Return(std::make_shared<char>('2'))));
      });
@@ -694,7 +694,7 @@
      bool external_connected = true;
      stub_db_factory->with_next_config([&](mtd::MockHwcConfiguration& mock_config)
+     {
--        EXPECT_CALL(mock_config, subscribe_to_config_changes(_))
++        EXPECT_CALL(mock_config, subscribe_to_config_changes(_,_))
              .WillOnce(DoAll(SaveArg<0>(&hotplug_fn), Return(std::make_shared<char>('2'))));
          ON_CALL(mock_config, active_attribs_for(mga::DisplayName::primary))
              .WillByDefault(Return(
@@ -779,3 +779,25 @@
      });
      display.configure(*configuration);
+ }
++
++TEST_F(Display, reports_vsync)
++{
++    using namespace testing;
++    std::function<void(mga::DisplayName)> vsync_fn = [](mga::DisplayName){};
++    auto report = std::make_shared<NiceMock<mtd::MockDisplayReport>>();
++    EXPECT_CALL(*report, report_vsync(_));
++    stub_db_factory->with_next_config([&](mtd::MockHwcConfiguration& mock_config)
++    {
++        EXPECT_CALL(mock_config, subscribe_to_config_changes(_,_))
++            .WillOnce(DoAll(SaveArg<1>(&vsync_fn), Return(std::make_shared<char>('2'))));
++    });
++
++    mga::Display display(
++        stub_db_factory,
++        stub_gl_program_factory,
++        stub_gl_config,
++        report,
++        mga::OverlayOptimization::enabled);
++
++    vsync_fn(mga::DisplayName::primary);
++}
 === modified file 'tests/unit-tests/graphics/android/test_display_hotplug.cpp'
 --- tests/unit-tests/graphics/android/test_display_hotplug.cpp	2015-02-13 06:12:34 +0000
 +++ tests/unit-tests/graphics/android/test_display_hotplug.cpp	2015-03-04 14:36:55 +0000
@@ -47,7 +47,7 @@
              return mga::DisplayAttribs{{0,0}, {0,0}, 0.0, true, mir_pixel_format_abgr_8888, 2};
+         }
          mga::ConfigChangeSubscription subscribe_to_config_changes(
--            std::function<void()> const& cb) override
++            std::function<void()> const& cb, std::function<void(mga::DisplayName)> const&) override
+         {
              hotplug_fn = cb;
              return {};
@@ -72,9 +72,9 @@
              return wrapped.active_attribs_for(d);
+         }
          mga::ConfigChangeSubscription subscribe_to_config_changes(
--            std::function<void()> const& cb) override
++            std::function<void()> const& hotplug, std::function<void(mga::DisplayName)> const& vsync) override
+         {
--            return wrapped.subscribe_to_config_changes(cb);
++            return wrapped.subscribe_to_config_changes(hotplug, vsync);
+         }
          mga::HwcConfiguration& wrapped;
      };
 === modified file 'tests/unit-tests/graphics/android/test_hwc_configuration.cpp'
 --- tests/unit-tests/graphics/android/test_hwc_configuration.cpp	2015-03-03 06:56:37 +0000
 +++ tests/unit-tests/graphics/android/test_hwc_configuration.cpp	2015-03-04 14:36:55 +0000
@@ -228,17 +228,23 @@
      EXPECT_THAT(attribs.vrefresh_hz, Eq(0.0f));
+ }
--TEST_F(HwcConfiguration, subscribes_to_hotplug)
++TEST_F(HwcConfiguration, subscribes_to_hotplug_and_vsync)
+ {
      using namespace testing;
      std::function<void(mga::DisplayName, bool)> hotplug_fn([](mga::DisplayName, bool){});
++    std::function<void(mga::DisplayName, std::chrono::nanoseconds)> vsync_fn(
++        [](mga::DisplayName, std::chrono::nanoseconds){});
      EXPECT_CALL(*mock_hwc_wrapper, subscribe_to_events(_,_,_,_))
--        .WillOnce(SaveArg<2>(&hotplug_fn));
++        .WillOnce(DoAll(SaveArg<1>(&vsync_fn), SaveArg<2>(&hotplug_fn)));
      EXPECT_CALL(*mock_hwc_wrapper, unsubscribe_from_events_(_));
--    unsigned int call_count{0};
--    auto subscription = config.subscribe_to_config_changes([&]{ call_count++; });
--    hotplug_fn(mga::DisplayName::primary, true);
--    hotplug_fn(mga::DisplayName::primary, true);
--    EXPECT_THAT(call_count, Eq(2));
++    unsigned int hotplug_call_count{0};
++    unsigned int vsync_call_count{0};
++    auto subscription = config.subscribe_to_config_changes(
++        [&]{ hotplug_call_count++; }, [&](mga::DisplayName){ vsync_call_count++; });
++    hotplug_fn(mga::DisplayName::primary, true);
++    hotplug_fn(mga::DisplayName::primary, true);
++    vsync_fn(mga::DisplayName::primary, std::chrono::nanoseconds(33));
++    EXPECT_THAT(hotplug_call_count, Eq(2));
++    EXPECT_THAT(vsync_call_count, Eq(1));
+ }
 === modified file 'tests/unit-tests/graphics/mesa/test_display.cpp'
 --- tests/unit-tests/graphics/mesa/test_display.cpp	2015-02-26 03:20:09 +0000
 +++ tests/unit-tests/graphics/mesa/test_display.cpp	2015-03-04 14:36:55 +0000
@@ -28,6 +28,7 @@
  #include "mir_test_doubles/mock_egl.h"
  #include "mir_test_doubles/mock_gl.h"
++#include "mir_test_doubles/advanceable_clock.h"
  #include "src/server/report/null_report_factory.h"
  #include "mir_test_doubles/mock_display_report.h"
  #include "mir_test_doubles/null_virtual_terminal.h"
@@ -525,7 +526,7 @@
      using namespace ::testing;
      auto logger = std::make_shared<MockLogger>();
--    auto reporter = std::make_shared<mrl::DisplayReport>(logger);
++    auto reporter = std::make_shared<mrl::DisplayReport>(logger, std::make_shared<mtd::AdvanceableClock>());
      EXPECT_CALL(
          *logger,
@@ -541,7 +542,7 @@
      using namespace ::testing;
      auto logger = std::make_shared<MockLogger>();
--    auto reporter = std::make_shared<mrl::DisplayReport>(logger);
++    auto reporter = std::make_shared<mrl::DisplayReport>(logger, std::make_shared<mtd::AdvanceableClock>());
      EXPECT_CALL(
          *logger,
@@ -557,7 +558,7 @@
      using namespace ::testing;
      auto logger = std::make_shared<MockLogger>();
--    auto reporter = std::make_shared<mrl::DisplayReport>(logger);
++    auto reporter = std::make_shared<mrl::DisplayReport>(logger, std::make_shared<mtd::AdvanceableClock>());
      EXPECT_CALL(
          *logger,
@@ -573,7 +574,7 @@
      using namespace ::testing;
      auto logger = std::make_shared<MockLogger>();
--    auto reporter = std::make_shared<mrl::DisplayReport>(logger);
++    auto reporter = std::make_shared<mrl::DisplayReport>(logger, std::make_shared<mtd::AdvanceableClock>());
      EXPECT_CALL(
          *logger,
 === modified file 'tests/unit-tests/graphics/mesa/test_kms_page_flipper.cpp'
 --- tests/unit-tests/graphics/mesa/test_kms_page_flipper.cpp	2015-01-22 09:00:14 +0000
 +++ tests/unit-tests/graphics/mesa/test_kms_page_flipper.cpp	2015-03-04 14:36:55 +0000
@@ -45,10 +45,11 @@
+ {
  public:
      KMSPageFlipperTest()
--        : page_flipper{mock_drm.fake_drm.fd()}
++        : page_flipper{mock_drm.fake_drm.fd(), mt::fake_shared(report)}
+     {
+     }
++    testing::NiceMock<mtd::MockDisplayReport> report;
      testing::NiceMock<mtd::MockDRM> mock_drm;
      mgm::KMSPageFlipper page_flipper;
  };
@@ -121,6 +122,24 @@
      page_flipper.wait_for_flip(crtc_id);
+ }
++TEST_F(KMSPageFlipperTest, wait_for_flip_reports_vsync)
++{
++    using namespace testing;
++    uint32_t const crtc_id{10};
++    uint32_t const fb_id{101};
++    void* user_data{nullptr};
++    ON_CALL(mock_drm, drmModePageFlip(_, _, _, _, _))
++        .WillByDefault(DoAll(SaveArg<4>(&user_data), Return(0)));
++    ON_CALL(mock_drm, drmHandleEvent(_, _))
++        .WillByDefault(DoAll(InvokePageFlipHandler(&user_data), Return(0)));
++
++    EXPECT_CALL(report, report_vsync(crtc_id));
++
++    page_flipper.schedule_flip(crtc_id, fb_id);
++    EXPECT_EQ(1, write(mock_drm.fake_drm.write_fd(), "a", 1));
++    page_flipper.wait_for_flip(crtc_id);
++}
++
  TEST_F(KMSPageFlipperTest, wait_for_non_scheduled_page_flip_doesnt_block)
+ {
      using namespace testing;
 === modified file 'tests/unit-tests/logging/test_display_report.cpp'
 --- tests/unit-tests/logging/test_display_report.cpp	2015-01-21 07:34:50 +0000
 +++ tests/unit-tests/logging/test_display_report.cpp	2015-03-04 14:36:55 +0000
@@ -19,6 +19,7 @@
  #include "src/server/report/logging/display_report.h"
  #include "mir/logging/logger.h"
  #include "mir_test_doubles/mock_egl.h"
++#include "mir_test_doubles/advanceable_clock.h"
  #include <gtest/gtest.h>
  #include <gmock/gmock.h>
@@ -39,16 +40,8 @@
  struct DisplayReport : public testing::Test
+ {
--    DisplayReport()
--    {
--    }
--
--    void SetUp()
--    {
--        logger = std::make_shared<MockLogger>();
--    }
--
--    std::shared_ptr<MockLogger> logger;
++    std::shared_ptr<mtd::AdvanceableClock> const clock{std::make_shared<mtd::AdvanceableClock>()};
++    std::shared_ptr<MockLogger> logger{std::make_shared<MockLogger>()};
      mtd::MockEGL mock_egl;
  };
@@ -123,6 +116,29 @@
              component));
+     }
--    mrl::DisplayReport report(logger);
++    mrl::DisplayReport report(logger, clock);
      report.report_egl_configuration(disp, config);
+ }
++
++TEST_F(DisplayReport, reports_vsync)
++{
++    std::chrono::milliseconds interval(1500);
++    unsigned int display1_id {1223};
++    unsigned int display2_id {4492};
++    std::string display1_name(std::to_string(display1_id));
++    std::string display2_name(std::to_string(display2_id));
++    EXPECT_CALL(*logger, log(
++        ml::Severity::informational,
++        "2 vsync events on [" + display1_name + "] over " + std::to_string(interval.count()) + "ms",
++        component));
++    EXPECT_CALL(*logger, log(
++        ml::Severity::informational,
++        "1 vsync events on [" + display2_name + "] over " + std::to_string(interval.count()) + "ms",
++        component));
++    mrl::DisplayReport report(logger, clock);
++
++    report.report_vsync(display1_id);
++    report.report_vsync(display2_id);
++    clock->advance_by(interval);
++    report.report_vsync(display1_id);
++}