Merge lp:~vanvugt/mir/compositor-report into lp:mir

[Daniel van Vugt]

Introducing CompositorReport. In its present form it just logs useful
information like composition frame rate, frame time (render + post) and
pause/resume.

Basic usage:
   mir_demo_server_shell --compositor-report=log

[PS Jenkins bot (ps-jenkins)]

FAILED: Continuous integration, rev:1326
http://jenkins.qa.ubuntu.com/job/mir-team-mir-development-branch-ci/576/
Executed test runs:
    SUCCESS: http://jenkins.qa.ubuntu.com/job/mir-android-trusty-i386-build/511
    SUCCESS: http://jenkins.qa.ubuntu.com/job/mir-clang-trusty-amd64-build/507
    SUCCESS: http://jenkins.qa.ubuntu.com/job/mir-mediumtests-trusty-touch/115
    FAILURE: http://jenkins.qa.ubuntu.com/job/mir-team-mir-development-branch-trusty-amd64-ci/302/console
    SUCCESS: http://jenkins.qa.ubuntu.com/job/mir-team-mir-development-branch-trusty-armhf-ci/305
        deb: http://jenkins.qa.ubuntu.com/job/mir-team-mir-development-branch-trusty-armhf-ci/305/artifact/work/output/*zip*/output.zip
    SUCCESS: http://jenkins.qa.ubuntu.com/job/mir-mediumtests-builder-trusty-armhf/115
        deb: http://jenkins.qa.ubuntu.com/job/mir-mediumtests-builder-trusty-armhf/115/artifact/work/output/*zip*/output.zip
    SUCCESS: http://jenkins.qa.ubuntu.com/job/mir-mediumtests-runner-mako/143
    SUCCESS: http://s-jenkins.ubuntu-ci:8080/job/touch-flash-device/2612

Click here to trigger a rebuild:
http://s-jenkins.ubuntu-ci:8080/job/mir-team-mir-development-branch-ci/576/rebuild

review: Needs Fixing (continuous-integration)

[PS Jenkins bot (ps-jenkins)]

PASSED: Continuous integration, rev:1328
http://jenkins.qa.ubuntu.com/job/mir-team-mir-development-branch-ci/578/
Executed test runs:
    SUCCESS: http://jenkins.qa.ubuntu.com/job/mir-android-trusty-i386-build/514
    SUCCESS: http://jenkins.qa.ubuntu.com/job/mir-clang-trusty-amd64-build/510
    SUCCESS: http://jenkins.qa.ubuntu.com/job/mir-mediumtests-trusty-touch/118
    SUCCESS: http://jenkins.qa.ubuntu.com/job/mir-team-mir-development-branch-trusty-amd64-ci/304
        deb: http://jenkins.qa.ubuntu.com/job/mir-team-mir-development-branch-trusty-amd64-ci/304/artifact/work/output/*zip*/output.zip
    SUCCESS: http://jenkins.qa.ubuntu.com/job/mir-team-mir-development-branch-trusty-armhf-ci/307
        deb: http://jenkins.qa.ubuntu.com/job/mir-team-mir-development-branch-trusty-armhf-ci/307/artifact/work/output/*zip*/output.zip
    SUCCESS: http://jenkins.qa.ubuntu.com/job/mir-mediumtests-builder-trusty-armhf/118
        deb: http://jenkins.qa.ubuntu.com/job/mir-mediumtests-builder-trusty-armhf/118/artifact/work/output/*zip*/output.zip
    SUCCESS: http://jenkins.qa.ubuntu.com/job/mir-mediumtests-runner-mako/146
    SUCCESS: http://s-jenkins.ubuntu-ci:8080/job/touch-flash-device/2621

Click here to trigger a rebuild:
http://s-jenkins.ubuntu-ci:8080/job/mir-team-mir-development-branch-ci/578/rebuild

review: Approve (continuous-integration)

[Andreas Pokorny (andreas-pokorny)]

The finished_frame method took me some time to parse - please extract some parts.
Could that be reused in a lttng implementation - then we it might make even more sense to have those calculations not directly in that method.

What is dn?

review: Needs Fixing

[Daniel van Vugt (vanvugt)]

dn is a delta of n as in nframes:
   auto dn = i.nframes - i.last_reported_nframes;
I think the "dX" syntax is acceptable shorthand for any delta value calculus.

I disagree with breaking up finished_frame. In its current form it is highly cohesive.

As for different reporting outputs... The best report design is one with a minimal interface, like you see in CompositorReport. While it's possible LTTNG might use some of the same logic, I think it's unlikely. Because most of the current logic is about doing accurate reports of averages on 1-second intervals. That's not something LTTNG would reuse.

[Andreas Pokorny (andreas-pokorny)]

> I disagree with breaking up finished_frame. In its current form it is highly
> cohesive.

It does two things. it updates one "Instance" and if timeout is big enough it creates reports for each instance and logs them. So the second thing is two things again, calculating and resetting the Riemann sums and formatting and printing the log string.

Why are the "last_reported_*" time values updated even when no report took place?

[Andreas Pokorny (andreas-pokorny)]

Ah that check is like first frame vs. any further frame measured.

review: Approve

[PS Jenkins bot (ps-jenkins)]

PASSED: Continuous integration, rev:1330
http://jenkins.qa.ubuntu.com/job/mir-team-mir-development-branch-ci/593/
Executed test runs:
    SUCCESS: http://jenkins.qa.ubuntu.com/job/mir-android-trusty-i386-build/536
    SUCCESS: http://jenkins.qa.ubuntu.com/job/mir-clang-trusty-amd64-build/532
    SUCCESS: http://jenkins.qa.ubuntu.com/job/mir-mediumtests-trusty-touch/140
    SUCCESS: http://jenkins.qa.ubuntu.com/job/mir-team-mir-development-branch-trusty-amd64-ci/319
        deb: http://jenkins.qa.ubuntu.com/job/mir-team-mir-development-branch-trusty-amd64-ci/319/artifact/work/output/*zip*/output.zip
    SUCCESS: http://jenkins.qa.ubuntu.com/job/mir-team-mir-development-branch-trusty-armhf-ci/322
        deb: http://jenkins.qa.ubuntu.com/job/mir-team-mir-development-branch-trusty-armhf-ci/322/artifact/work/output/*zip*/output.zip
    SUCCESS: http://jenkins.qa.ubuntu.com/job/mir-mediumtests-builder-trusty-armhf/140
        deb: http://jenkins.qa.ubuntu.com/job/mir-mediumtests-builder-trusty-armhf/140/artifact/work/output/*zip*/output.zip
    SUCCESS: http://jenkins.qa.ubuntu.com/job/mir-mediumtests-runner-mako/167
    SUCCESS: http://s-jenkins.ubuntu-ci:8080/job/touch-flash-device/2654

Click here to trigger a rebuild:
http://s-jenkins.ubuntu-ci:8080/job/mir-team-mir-development-branch-ci/593/rebuild

review: Approve (continuous-integration)

[Robert Carr (robertcarr)]

LGTM

review: Approve

=== added file 'include/server/mir/compositor/compositor_report.h'
--- include/server/mir/compositor/compositor_report.h	1970-01-01 00:00:00 +0000
+++ include/server/mir/compositor/compositor_report.h	2014-01-02 09:11:20 +0000
@@ -0,0 +1,58 @@
+/*
+ * Copyright © 2013 Canonical Ltd.
+ *
+ * This program is free software: you can redistribute it and/or modify it
+ * under the terms of the GNU General Public License version 3,
+ * as published by the Free Software Foundation.
+ *
+ * This program is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+ * GNU General Public License for more details.
+ *
+ * You should have received a copy of the GNU General Public License
+ * along with this program.  If not, see <http://www.gnu.org/licenses/>.
+ *
+ * Authored by: Daniel van Vugt <[e-mail]>
+ */
+
+#ifndef MIR_COMPOSITOR_COMPOSITOR_REPORT_H_
+#define MIR_COMPOSITOR_COMPOSITOR_REPORT_H_
+
+namespace mir
+{
+namespace compositor
+{
+
+class CompositorReport
+{
+public:
+    typedef const void* SubCompositorId;  // e.g. thread/display buffer ID
+    virtual void added_display(int width, int height, int x, int y, SubCompositorId id = 0) = 0;
+    virtual void began_frame(SubCompositorId id = 0) = 0;
+    virtual void finished_frame(SubCompositorId id = 0) = 0;
+    virtual void started() = 0;
+    virtual void stopped() = 0;
+    virtual void scheduled() = 0;
+protected:
+    CompositorReport() = default;
+    virtual ~CompositorReport() = default;
+    CompositorReport(CompositorReport const&) = delete;
+    CompositorReport& operator=(CompositorReport const&) = delete;
+};
+
+class NullCompositorReport : public CompositorReport
+{
+public:
+    void added_display(int width, int height, int x, int y, SubCompositorId id);
+    void began_frame(SubCompositorId id);
+    void finished_frame(SubCompositorId id);
+    void started();
+    void stopped();
+    void scheduled();
+};
+
+} // namespace compositor
+} // namespace mir
+
+#endif // MIR_COMPOSITOR_COMPOSITOR_REPORT_H_

=== modified file 'include/server/mir/default_configuration_options.h'
--- include/server/mir/default_configuration_options.h	2013-12-18 02:19:19 +0000
+++ include/server/mir/default_configuration_options.h	2014-01-02 09:11:20 +0000
@@ -32,6 +32,7 @@
     static char const* const no_server_socket_opt;
     static char const* const session_mediator_report_opt;
     static char const* const msg_processor_report_opt;
+    static char const* const compositor_report_opt;
     static char const* const display_report_opt;
     static char const* const legacy_input_report_opt;
     static char const* const connector_report_opt;

=== modified file 'include/server/mir/default_server_configuration.h'
--- include/server/mir/default_server_configuration.h	2013-12-18 02:19:19 +0000
+++ include/server/mir/default_server_configuration.h	2014-01-02 09:11:20 +0000
@@ -36,6 +36,7 @@
 class DisplayBufferCompositorFactory;
 class Compositor;
 class RendererFactory;
+class CompositorReport;
 }
 namespace frontend
 {
@@ -150,6 +151,7 @@
     /** @name compositor configuration - customization
      * configurable interfaces for modifying compositor
      *  @{ */
+    virtual std::shared_ptr<compositor::CompositorReport> the_compositor_report();
     virtual std::shared_ptr<compositor::DisplayBufferCompositorFactory> the_display_buffer_compositor_factory();
     /** @} */
 
@@ -278,6 +280,7 @@
     CachedPtr<shell::SurfaceConfigurator> shell_surface_configurator;
     CachedPtr<compositor::DisplayBufferCompositorFactory> display_buffer_compositor_factory;
     CachedPtr<compositor::Compositor> compositor;
+    CachedPtr<compositor::CompositorReport> compositor_report;
     CachedPtr<logging::Logger> logger;
     CachedPtr<graphics::DisplayReport> display_report;
     CachedPtr<time::TimeSource> time_source;

=== modified file 'src/server/compositor/CMakeLists.txt'
--- src/server/compositor/CMakeLists.txt	2013-12-18 02:19:19 +0000
+++ src/server/compositor/CMakeLists.txt	2014-01-02 09:11:20 +0000
@@ -14,6 +14,7 @@
   bypass.cpp
   occlusion.cpp
   default_configuration.cpp
+  null_compositor_report.cpp
 )
 
 ADD_LIBRARY(

=== modified file 'src/server/compositor/default_configuration.cpp'
--- src/server/compositor/default_configuration.cpp	2013-12-18 02:19:19 +0000
+++ src/server/compositor/default_configuration.cpp	2014-01-02 09:11:20 +0000
@@ -54,7 +54,8 @@
         {
             return std::make_shared<mc::MultiThreadedCompositor>(the_display(),
                                                                  the_scene(),
-                                                                 the_display_buffer_compositor_factory());
+                                                                 the_display_buffer_compositor_factory(),
+                                                                 the_compositor_report());
         });
 }
 

=== modified file 'src/server/compositor/multi_threaded_compositor.cpp'
--- src/server/compositor/multi_threaded_compositor.cpp	2013-12-18 02:19:19 +0000
+++ src/server/compositor/multi_threaded_compositor.cpp	2014-01-02 09:11:20 +0000
@@ -22,6 +22,7 @@
 #include "mir/compositor/display_buffer_compositor.h"
 #include "mir/compositor/display_buffer_compositor_factory.h"
 #include "mir/compositor/scene.h"
+#include "mir/compositor/compositor_report.h"
 
 #include <thread>
 #include <condition_variable>
@@ -56,11 +57,13 @@
 {
 public:
     CompositingFunctor(std::shared_ptr<mc::DisplayBufferCompositorFactory> const& db_compositor_factory,
-                       mg::DisplayBuffer& buffer)
+                       mg::DisplayBuffer& buffer,
+                       std::shared_ptr<CompositorReport> const& report)
         : display_buffer_compositor_factory{db_compositor_factory},
           buffer(buffer),
           running{true},
-          frames_scheduled{0}
+          frames_scheduled{0},
+          report{report}
     {
     }
 
@@ -76,6 +79,14 @@
 
         auto display_buffer_compositor = display_buffer_compositor_factory->create_compositor_for(buffer);
 
+        CompositorReport::SubCompositorId report_id =
+            display_buffer_compositor.get();
+
+        const auto& r = buffer.view_area();
+        report->added_display(r.size.width.as_int(), r.size.height.as_int(),
+                              r.top_left.x.as_int(), r.top_left.y.as_int(),
+                              report_id);
+
         while (running)
         {
             /* Wait until compositing has been scheduled or we are stopped */
@@ -91,7 +102,9 @@
             if (running)
             {
                 lock.unlock();
+                report->began_frame(report_id);
                 display_buffer_compositor->composite();
+                report->finished_frame(report_id);
                 lock.lock();
             }
         }
@@ -127,6 +140,7 @@
     int frames_scheduled;
     std::mutex run_mutex;
     std::condition_variable run_cv;
+    std::shared_ptr<CompositorReport> const report;
 };
 
 }
@@ -135,10 +149,12 @@
 mc::MultiThreadedCompositor::MultiThreadedCompositor(
     std::shared_ptr<mg::Display> const& display,
     std::shared_ptr<mc::Scene> const& scene,
-    std::shared_ptr<DisplayBufferCompositorFactory> const& db_compositor_factory)
+    std::shared_ptr<DisplayBufferCompositorFactory> const& db_compositor_factory,
+    std::shared_ptr<CompositorReport> const& compositor_report)
     : display{display},
       scene{scene},
-      display_buffer_compositor_factory{db_compositor_factory}
+      display_buffer_compositor_factory{db_compositor_factory},
+      report{compositor_report}
 {
 }
 
@@ -149,10 +165,12 @@
 
 void mc::MultiThreadedCompositor::start()
 {
+    report->started();
+
     /* Start the compositing threads */
     display->for_each_display_buffer([this](mg::DisplayBuffer& buffer)
     {
-        auto thread_functor_raw = new mc::CompositingFunctor{display_buffer_compositor_factory, buffer};
+        auto thread_functor_raw = new mc::CompositingFunctor{display_buffer_compositor_factory, buffer, report};
         auto thread_functor = std::unique_ptr<mc::CompositingFunctor>(thread_functor_raw);
 
         threads.push_back(std::thread{std::ref(*thread_functor)});
@@ -162,6 +180,7 @@
     /* Recomposite whenever the scene changes */
     scene->set_change_callback([this]()
     {
+        report->scheduled();
         for (auto& f : thread_functors)
             f->schedule_compositing();
     });
@@ -183,4 +202,6 @@
 
     thread_functors.clear();
     threads.clear();
+
+    report->stopped();
 }

=== modified file 'src/server/compositor/multi_threaded_compositor.h'
--- src/server/compositor/multi_threaded_compositor.h	2013-12-18 02:19:19 +0000
+++ src/server/compositor/multi_threaded_compositor.h	2014-01-02 09:11:20 +0000
@@ -39,13 +39,15 @@
 class DisplayBufferCompositorFactory;
 class CompositingFunctor;
 class Scene;
+class CompositorReport;
 
 class MultiThreadedCompositor : public Compositor
 {
 public:
     MultiThreadedCompositor(std::shared_ptr<graphics::Display> const& display,
                             std::shared_ptr<Scene> const& scene,
-                            std::shared_ptr<DisplayBufferCompositorFactory> const& db_compositor_factory);
+                            std::shared_ptr<DisplayBufferCompositorFactory> const& db_compositor_factory,
+                            std::shared_ptr<CompositorReport> const& compositor_report);
     ~MultiThreadedCompositor();
 
     void start();
@@ -55,6 +57,7 @@
     std::shared_ptr<graphics::Display> const display;
     std::shared_ptr<Scene> const scene;
     std::shared_ptr<DisplayBufferCompositorFactory> const display_buffer_compositor_factory;
+    std::shared_ptr<CompositorReport> const report;
 
     std::vector<std::unique_ptr<CompositingFunctor>> thread_functors;
     std::vector<std::thread> threads;

=== added file 'src/server/compositor/null_compositor_report.cpp'
--- src/server/compositor/null_compositor_report.cpp	1970-01-01 00:00:00 +0000
+++ src/server/compositor/null_compositor_report.cpp	2014-01-02 09:11:20 +0000
@@ -0,0 +1,45 @@
+/*
+ * Copyright © 2013 Canonical Ltd.
+ *
+ * This program is free software: you can redistribute it and/or modify it
+ * under the terms of the GNU General Public License version 3,
+ * as published by the Free Software Foundation.
+ *
+ * This program is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+ * GNU General Public License for more details.
+ *
+ * You should have received a copy of the GNU General Public License
+ * along with this program.  If not, see <http://www.gnu.org/licenses/>.
+ *
+ * Authored by: Daniel van Vugt <[e-mail]>
+ */
+
+#include "mir/compositor/compositor_report.h"
+
+using namespace mir::compositor;
+
+void NullCompositorReport::added_display(int, int, int, int, SubCompositorId)
+{
+}
+
+void NullCompositorReport::began_frame(SubCompositorId)
+{
+}
+
+void NullCompositorReport::finished_frame(SubCompositorId)
+{
+}
+
+void NullCompositorReport::started()
+{
+}
+
+void NullCompositorReport::stopped()
+{
+}
+
+void NullCompositorReport::scheduled()
+{
+}

=== modified file 'src/server/default_configuration_options.cpp'
--- src/server/default_configuration_options.cpp	2013-12-18 02:19:19 +0000
+++ src/server/default_configuration_options.cpp	2014-01-02 09:11:20 +0000
@@ -70,6 +70,7 @@
 char const* const mir::ConfigurationOptions::no_server_socket_opt        = "no-file";
 char const* const mir::ConfigurationOptions::session_mediator_report_opt = "session-mediator-report";
 char const* const mir::ConfigurationOptions::msg_processor_report_opt    = "msg-processor-report";
+char const* const mir::ConfigurationOptions::compositor_report_opt       = "compositor-report";
 char const* const mir::ConfigurationOptions::display_report_opt          = "display-report";
 char const* const mir::ConfigurationOptions::legacy_input_report_opt     = "legacy-input-report";
 char const* const mir::ConfigurationOptions::connector_report_opt        = "connector-report";
@@ -120,6 +121,8 @@
             "Library to use for platform graphics support [default=libmirplatformgraphics.so]")
         ("enable-input,i", po::value<bool>(),
             "Enable input. [bool:default=true]")
+        (compositor_report_opt, po::value<std::string>(),
+            "Compositor reporting [{log,off}:default=off]")
         (connector_report_opt, po::value<std::string>(),
             "How to handle the Connector report. [{log,off}:default=off]")
         (display_report_opt, po::value<std::string>(),

=== modified file 'src/server/logging/CMakeLists.txt'
--- src/server/logging/CMakeLists.txt	2013-12-18 02:19:19 +0000
+++ src/server/logging/CMakeLists.txt	2014-01-02 09:11:20 +0000
@@ -8,6 +8,7 @@
   message_processor_report.cpp
   display_report.cpp
   input_report.cpp
+  compositor_report.cpp
 )
 
 add_library(

=== added file 'src/server/logging/compositor_report.cpp'
--- src/server/logging/compositor_report.cpp	1970-01-01 00:00:00 +0000
+++ src/server/logging/compositor_report.cpp	2014-01-02 09:11:20 +0000
@@ -0,0 +1,161 @@
+/*
+ * Copyright © 2013-2014 Canonical Ltd.
+ *
+ * This program is free software: you can redistribute it and/or modify it
+ * under the terms of the GNU General Public License version 3,
+ * as published by the Free Software Foundation.
+ *
+ * This program is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+ * GNU General Public License for more details.
+ *
+ * You should have received a copy of the GNU General Public License
+ * along with this program.  If not, see <http://www.gnu.org/licenses/>.
+ *
+ * Authored by: Daniel van Vugt <[e-mail]>
+ */
+
+#include "compositor_report.h"
+#include "mir/logging/logger.h"
+
+using namespace mir;
+using namespace mir::compositor;
+using namespace mir::time;
+
+namespace
+{
+    const char * const component = "compositor";
+    const auto min_report_interval = std::chrono::seconds(1);
+}
+
+logging::CompositorReport::CompositorReport(
+    std::shared_ptr<Logger> const& logger,
+    std::shared_ptr<TimeSource> const& clock)
+    : logger(logger),
+      clock(clock),
+      last_report(now())
+{
+}
+
+logging::CompositorReport::TimePoint logging::CompositorReport::now() const
+{
+    return clock->sample();
+}
+
+void logging::CompositorReport::added_display(int width, int height,
+                                              int x, int y,
+                                              SubCompositorId id)
+{
+    char msg[128];
+    snprintf(msg, sizeof msg, "Added display %p: %dx%d %+d%+d",
+             id, width, height, x, y);
+    logger->log(Logger::informational, msg, component);
+}
+
+void logging::CompositorReport::began_frame(SubCompositorId id)
+{
+    std::lock_guard<std::mutex> lock(mutex);
+    auto& inst = instance[id];
+
+    auto t = now();
+    inst.start_of_frame = t;
+    inst.latency_sum += t - last_scheduled;
+}
+
+void logging::CompositorReport::Instance::log(
+    Logger& logger, SubCompositorId id)
+{
+    // The first report is a valid sample, but don't log anything because
+    // we need at least two samples for valid deltas.
+    if (last_reported_total_time_sum > TimePoint())
+    {
+        long long dt =
+            std::chrono::duration_cast<std::chrono::microseconds>(
+                total_time_sum - last_reported_total_time_sum
+            ).count();
+        auto dn = nframes - last_reported_nframes;
+        long long df =
+            std::chrono::duration_cast<std::chrono::microseconds>(
+                frame_time_sum - last_reported_frame_time_sum
+            ).count();
+        long long dl =
+            std::chrono::duration_cast<std::chrono::microseconds>(
+                latency_sum - last_reported_latency_sum
+            ).count();
+
+        // Keep everything premultiplied by 1000 to guarantee accuracy
+        // and avoid floating point.
+        long frames_per_1000sec = dt ? dn * 1000000000LL / dt : 0;
+        long avg_frame_time_usec = dn ? df / dn : 0;
+        long avg_latency_usec = dn ? dl / dn : 0;
+        long dt_msec = dt / 1000L;
+
+        char msg[128];
+        snprintf(msg, sizeof msg, "Display %p averaged %ld.%03ld FPS, "
+                 "%ld.%03ld ms/frame, "
+                 "latency %ld.%03ld ms, "
+                 "%ld frames over %ld.%03ld sec",
+                 id,
+                 frames_per_1000sec / 1000,
+                 frames_per_1000sec % 1000,
+                 avg_frame_time_usec / 1000,
+                 avg_frame_time_usec % 1000,
+                 avg_latency_usec / 1000,
+                 avg_latency_usec % 1000,
+                 dn,
+                 dt_msec / 1000,
+                 dt_msec % 1000
+                 );
+
+        logger.log(Logger::informational, msg, component);
+    }
+
+    last_reported_total_time_sum = total_time_sum;
+    last_reported_frame_time_sum = frame_time_sum;
+    last_reported_latency_sum = latency_sum;
+    last_reported_nframes = nframes;
+}
+
+void logging::CompositorReport::finished_frame(SubCompositorId id)
+{
+    std::lock_guard<std::mutex> lock(mutex);
+    auto& inst = instance[id];
+
+    auto t = now();
+    inst.total_time_sum += t - inst.end_of_frame;
+    inst.frame_time_sum += t - inst.start_of_frame;
+    inst.end_of_frame = t;
+    inst.nframes++;
+
+    /*
+     * The exact reporting interval doesn't matter because we count everything
+     * as a Reimann sum. Results will simply be the average over the interval.
+     */
+    if ((t - last_report) >= min_report_interval)
+    {
+        last_report = t;
+
+        for (auto& i : instance)
+            i.second.log(*logger, i.first);
+    }
+}
+
+void logging::CompositorReport::started()
+{
+    logger->log(Logger::informational, "Started", component);
+}
+
+void logging::CompositorReport::stopped()
+{
+    logger->log(Logger::informational, "Stopped", component);
+
+    std::lock_guard<std::mutex> lock(mutex);
+    instance.clear();
+}
+
+void logging::CompositorReport::scheduled()
+{
+    std::lock_guard<std::mutex> lock(mutex);
+    last_scheduled = now();
+}

=== added file 'src/server/logging/compositor_report.h'
--- src/server/logging/compositor_report.h	1970-01-01 00:00:00 +0000
+++ src/server/logging/compositor_report.h	2014-01-02 09:11:20 +0000
@@ -0,0 +1,81 @@
+/*
+ * Copyright © 2013 Canonical Ltd.
+ *
+ * This program is free software: you can redistribute it and/or modify it
+ * under the terms of the GNU General Public License version 3,
+ * as published by the Free Software Foundation.
+ *
+ * This program is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+ * GNU General Public License for more details.
+ *
+ * You should have received a copy of the GNU General Public License
+ * along with this program.  If not, see <http://www.gnu.org/licenses/>.
+ *
+ * Authored by: Daniel van Vugt <[e-mail]>
+ */
+
+#ifndef MIR_LOGGING_COMPOSITOR_REPORT_H_
+#define MIR_LOGGING_COMPOSITOR_REPORT_H_
+
+#include "mir/compositor/compositor_report.h"
+#include "mir/time/time_source.h"
+#include <memory>
+#include <mutex>
+#include <unordered_map>
+#include <chrono>
+
+namespace mir
+{
+namespace logging
+{
+
+class Logger;
+
+class CompositorReport : public mir::compositor::CompositorReport
+{
+public:
+    CompositorReport(std::shared_ptr<Logger> const& logger,
+                     std::shared_ptr<time::TimeSource> const& clock);
+    void added_display(int width, int height, int x, int y, SubCompositorId id);
+    void began_frame(SubCompositorId id);
+    void finished_frame(SubCompositorId id);
+    void started();
+    void stopped();
+    void scheduled();
+
+private:
+    std::shared_ptr<Logger> const logger;
+    std::shared_ptr<time::TimeSource> const clock;
+
+    typedef time::Timestamp TimePoint;
+    TimePoint now() const;
+
+    struct Instance
+    {
+        TimePoint start_of_frame;
+        TimePoint end_of_frame;
+        TimePoint total_time_sum;
+        TimePoint frame_time_sum;
+        TimePoint latency_sum;
+        long nframes = 0;
+
+        TimePoint last_reported_total_time_sum;
+        TimePoint last_reported_frame_time_sum;
+        TimePoint last_reported_latency_sum;
+        long last_reported_nframes = 0;
+
+        void log(Logger& logger, SubCompositorId id);
+    };
+
+    std::mutex mutex; // Protects the following...
+    std::unordered_map<SubCompositorId, Instance> instance;
+    TimePoint last_scheduled;
+    TimePoint last_report;
+};
+
+} // namespace logging
+} // namespace mir
+
+#endif // MIR_LOGGING_COMPOSITOR_REPORT_H_

=== modified file 'src/server/logging/default_configuration.cpp'
--- src/server/logging/default_configuration.cpp	2013-12-18 02:19:19 +0000
+++ src/server/logging/default_configuration.cpp	2014-01-02 09:11:20 +0000
@@ -24,7 +24,9 @@
 #include "session_mediator_report.h"
 
 #include "mir/graphics/null_display_report.h"
+#include "compositor_report.h"
 
+using namespace mir;
 namespace mf = mir::frontend;
 namespace mg = mir::graphics;
 namespace ml = mir::logging;
@@ -70,6 +72,24 @@
         });
 }
 
+std::shared_ptr<compositor::CompositorReport>
+DefaultServerConfiguration::the_compositor_report()
+{
+    return compositor_report(
+        [this]() -> std::shared_ptr<compositor::CompositorReport>
+        {
+            if (the_options()->get(compositor_report_opt, off_opt_value) == log_opt_value)
+            {
+                return std::make_shared<ml::CompositorReport>(
+                    the_logger(), the_time_source());
+            }
+            else
+            {
+                return std::make_shared<compositor::NullCompositorReport>();
+            }
+        });
+}
+
 std::shared_ptr<mf::SessionMediatorReport>
 mir::DefaultServerConfiguration::the_session_mediator_report()
 {

=== modified file 'tests/unit-tests/compositor/test_multi_threaded_compositor.cpp'
--- tests/unit-tests/compositor/test_multi_threaded_compositor.cpp	2013-12-18 02:19:19 +0000
+++ tests/unit-tests/compositor/test_multi_threaded_compositor.cpp	2014-01-02 09:11:20 +0000
@@ -20,6 +20,7 @@
 #include "mir/compositor/display_buffer_compositor.h"
 #include "mir/compositor/scene.h"
 #include "mir/compositor/display_buffer_compositor_factory.h"
+#include "mir/compositor/compositor_report.h"
 #include "mir_test_doubles/null_display.h"
 #include "mir_test_doubles/null_display_buffer.h"
 #include "mir_test_doubles/mock_display_buffer.h"
@@ -296,6 +297,20 @@
     }
 };
 
+class MockCompositorReport : public mc::CompositorReport
+{
+public:
+    MOCK_METHOD5(added_display,
+                 void(int,int,int,int,mc::CompositorReport::SubCompositorId));
+    MOCK_METHOD1(began_frame, void(mc::CompositorReport::SubCompositorId));
+    MOCK_METHOD1(finished_frame, void(mc::CompositorReport::SubCompositorId));
+    MOCK_METHOD0(started, void());
+    MOCK_METHOD0(stopped, void());
+    MOCK_METHOD0(scheduled, void());
+};
+
+auto const null_report = std::make_shared<mc::NullCompositorReport>();
+
 }
 
 TEST(MultiThreadedCompositor, compositing_happens_in_different_threads)
@@ -307,7 +322,7 @@
     auto display = std::make_shared<StubDisplay>(nbuffers);
     auto scene = std::make_shared<StubScene>();
     auto db_compositor_factory = std::make_shared<RecordingDisplayBufferCompositorFactory>();
-    mc::MultiThreadedCompositor compositor{display, scene, db_compositor_factory};
+    mc::MultiThreadedCompositor compositor{display, scene, db_compositor_factory, null_report};
 
     compositor.start();
 
@@ -320,6 +335,53 @@
     EXPECT_TRUE(db_compositor_factory->buffers_rendered_in_different_threads());
 }
 
+TEST(MultiThreadedCompositor, reports_in_the_right_places)
+{
+    using namespace testing;
+
+    auto display = std::make_shared<StubDisplayWithMockBuffers>(1);
+    auto scene = std::make_shared<StubScene>();
+    auto db_compositor_factory =
+        std::make_shared<RecordingDisplayBufferCompositorFactory>();
+    auto mock_report = std::make_shared<MockCompositorReport>();
+    mc::MultiThreadedCompositor compositor{display, scene,
+                                           db_compositor_factory,
+                                           mock_report};
+
+    EXPECT_CALL(*mock_report, started())
+        .Times(1);
+
+    display->for_each_mock_buffer([](mtd::MockDisplayBuffer& mock_buf)
+    {
+        EXPECT_CALL(mock_buf, make_current()).Times(1);
+        EXPECT_CALL(mock_buf, view_area())
+            .WillOnce(Return(geom::Rectangle()));
+    });
+
+    EXPECT_CALL(*mock_report, added_display(_,_,_,_,_))
+        .Times(1);
+    EXPECT_CALL(*mock_report, scheduled())
+        .Times(1);
+    EXPECT_CALL(*mock_report, began_frame(_))
+        .Times(mc::max_client_buffers);
+    EXPECT_CALL(*mock_report, finished_frame(_))
+        .Times(mc::max_client_buffers);
+
+    display->for_each_mock_buffer([](mtd::MockDisplayBuffer& mock_buf)
+    {
+        EXPECT_CALL(mock_buf, release_current()).Times(1);
+    });
+
+    EXPECT_CALL(*mock_report, stopped())
+        .Times(AtLeast(1));
+
+    compositor.start();
+    scene->emit_change_event();
+    while (!db_compositor_factory->check_record_count_for_each_buffer(1, mc::max_client_buffers))
+        std::this_thread::yield();
+    compositor.stop();
+}
+
 /*
  * It's difficult to test that a render won't happen, without some further
  * introspective capabilities that would complicate the code. This test will
@@ -338,7 +400,7 @@
     auto display = std::make_shared<StubDisplay>(nbuffers);
     auto scene = std::make_shared<StubScene>();
     auto db_compositor_factory = std::make_shared<RecordingDisplayBufferCompositorFactory>();
-    mc::MultiThreadedCompositor compositor{display, scene, db_compositor_factory};
+    mc::MultiThreadedCompositor compositor{display, scene, db_compositor_factory, null_report};
 
     // Verify we're actually starting at zero frames
     EXPECT_TRUE(db_compositor_factory->check_record_count_for_each_buffer(nbuffers, 0, 0));
@@ -398,7 +460,7 @@
     auto display = std::make_shared<StubDisplay>(nbuffers);
     auto scene = std::make_shared<StubScene>();
     auto db_compositor_factory = std::make_shared<SurfaceUpdatingDisplayBufferCompositorFactory>(scene);
-    mc::MultiThreadedCompositor compositor{display, scene, db_compositor_factory};
+    mc::MultiThreadedCompositor compositor{display, scene, db_compositor_factory, null_report};
 
     compositor.start();
 
@@ -417,10 +479,12 @@
     auto display = std::make_shared<StubDisplayWithMockBuffers>(nbuffers);
     auto scene = std::make_shared<StubScene>();
     auto db_compositor_factory = std::make_shared<NullDisplayBufferCompositorFactory>();
-    mc::MultiThreadedCompositor compositor{display, scene, db_compositor_factory};
+    mc::MultiThreadedCompositor compositor{display, scene, db_compositor_factory, null_report};
 
     display->for_each_mock_buffer([](mtd::MockDisplayBuffer& mock_buf)
     {
+        EXPECT_CALL(mock_buf, view_area())
+            .WillOnce(Return(geom::Rectangle()));
         EXPECT_CALL(mock_buf, make_current()).Times(1);
         EXPECT_CALL(mock_buf, release_current()).Times(1);
     });

=== modified file 'tests/unit-tests/logging/CMakeLists.txt'
--- tests/unit-tests/logging/CMakeLists.txt	2013-05-28 17:55:26 +0000
+++ tests/unit-tests/logging/CMakeLists.txt	2014-01-02 09:11:20 +0000
@@ -2,6 +2,7 @@
   ${CMAKE_CURRENT_SOURCE_DIR}/message_processor_report.cpp
   ${CMAKE_CURRENT_SOURCE_DIR}/test_legacy_input_report.cpp
   ${CMAKE_CURRENT_SOURCE_DIR}/test_display_report.cpp
+  ${CMAKE_CURRENT_SOURCE_DIR}/test_compositor_report.cpp
 )
 
 set(UNIT_TEST_SOURCES ${UNIT_TEST_SOURCES} PARENT_SCOPE)

=== added file 'tests/unit-tests/logging/test_compositor_report.cpp'
--- tests/unit-tests/logging/test_compositor_report.cpp	1970-01-01 00:00:00 +0000
+++ tests/unit-tests/logging/test_compositor_report.cpp	2014-01-02 09:11:20 +0000
@@ -0,0 +1,142 @@
+/*
+ * Copyright © 2013 Canonical Ltd.
+ *
+ * This program is free software: you can redistribute it and/or modify it
+ * under the terms of the GNU General Public License version 3,
+ * as published by the Free Software Foundation.
+ *
+ * This program is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+ * GNU General Public License for more details.
+ *
+ * You should have received a copy of the GNU General Public License
+ * along with this program.  If not, see <http://www.gnu.org/licenses/>.
+ *
+ * Authored by: Daniel van Vugt <[e-mail]>
+ */
+
+#include "src/server/logging/compositor_report.h"
+#include "mir/logging/logger.h"
+#include <gtest/gtest.h>
+#include <string>
+#include <cstdio>
+
+using namespace mir;
+using namespace std;
+
+namespace
+{
+
+class FakeClock : public time::TimeSource
+{
+public:
+    void elapse(chrono::microseconds delta)
+    {
+        now += delta;
+    }
+    time::Timestamp sample() const
+    {
+        return now;
+    }
+private:
+    time::Timestamp now;
+};
+
+class Recorder : public logging::Logger
+{
+public:
+    void log(Severity, string const& message, string const&)
+    {
+        last = message;
+    }
+    string const& last_message() const
+    {
+        return last;
+    }
+    bool scrape(float& fps, float& frame_time) const
+    {
+        return sscanf(last.c_str(), "Display %*s averaged %f FPS, %f ms/frame",
+                      &fps, &frame_time) == 2;
+    }
+private:
+    string last;
+};
+
+} // namespace
+
+TEST(LoggingCompositorReport, calculates_accurate_stats)
+{
+    /*
+     * This test just verifies the important stats; FPS and frame time.
+     * We don't need to validate all the numbers because maintaining low
+     * coupling to log formats is more important.
+     */
+    auto clock = make_shared<FakeClock>();
+    auto recorder = make_shared<Recorder>();
+    const void* const display_id = nullptr;
+
+    logging::CompositorReport report(recorder, clock);
+
+    int target_fps = 60;
+    for (int frame = 0; frame < target_fps*3; frame++)
+    {
+        report.began_frame(display_id);
+        clock->elapse(chrono::microseconds(1000000 / target_fps));
+        report.finished_frame(display_id);
+    }
+
+    float measured_fps, measured_frame_time;
+    ASSERT_TRUE(recorder->scrape(measured_fps, measured_frame_time))
+        << recorder->last_message();
+    EXPECT_LE(59.9f, measured_fps);
+    EXPECT_GE(60.1f, measured_fps);
+    EXPECT_LE(16.5f, measured_frame_time);
+    EXPECT_GE(16.7f, measured_frame_time);
+
+    clock->elapse(chrono::microseconds(5000000));
+
+    target_fps = 100;
+    for (int frame = 0; frame < target_fps*3; frame++)
+    {
+        report.began_frame(display_id);
+        clock->elapse(chrono::microseconds(1000000 / target_fps));
+        report.finished_frame(display_id);
+    }
+    ASSERT_TRUE(recorder->scrape(measured_fps, measured_frame_time))
+        << recorder->last_message();
+    EXPECT_FLOAT_EQ(100.0f, measured_fps);
+    EXPECT_FLOAT_EQ(10.0f, measured_frame_time);
+}
+
+TEST(LoggingCompositorReport, survives_pause_resume)
+{
+    auto clock = make_shared<FakeClock>();
+    auto logger = make_shared<Recorder>();
+    const void* const before = "before";
+    const void* const after = "after";
+
+    logging::CompositorReport report(logger, clock);
+
+    report.started();
+
+    report.began_frame(before);
+    clock->elapse(chrono::microseconds(12345));
+    report.finished_frame(before);
+
+    report.stopped();
+    clock->elapse(chrono::microseconds(12345678));
+    report.started();
+
+    report.began_frame(after);
+    clock->elapse(chrono::microseconds(12345));
+    report.finished_frame(after);
+
+    clock->elapse(chrono::microseconds(12345678));
+
+    report.began_frame(after);
+    clock->elapse(chrono::microseconds(12345));
+    report.finished_frame(after);
+
+    report.stopped();
+}