Merge lp:~vanvugt/mir/logtime into lp:mir

[Daniel van Vugt]

Logging: Add timestamps to log messages and change the prefix format to be
more like that of kernel/Xorg logs:
[seconds.microseconds] (severity) component: your message goes here

Importantly, the timestamps are consistent system-wide so you can compare
them between different processes, concatenate logs from different processes,
and sort the result into meaningful output.

[Andreas Pokorny (andreas-pokorny)]

review: Approve

[Alexandros Frantzis (afrantzis)]

The display of the timestamp can be written more idiomatically and more safely (since we avoid the manual conversion) as:

auto secs = duration_cast<duration<double>>(system_clock::now().time_since_epoch());
auto old_flags = out.flags();
out << std::fixed << secs.count() << std::endl;
out.setf(old_flags);

review: Needs Fixing

[Daniel van Vugt (vanvugt)]

I am intentionally avoiding floating point at every stage due to its lack of precision. Maintaining integers all the way through provides a guarantee that the digits right of the decimal point are accurate. Floating point does not.

[PS Jenkins bot (ps-jenkins)]

PASSED: Continuous integration, rev:1282
http://jenkins.qa.ubuntu.com/job/mir-team-mir-development-branch-ci/520/
Executed test runs:
    SUCCESS: http://jenkins.qa.ubuntu.com/job/mir-android-trusty-i386-build/410
    SUCCESS: http://jenkins.qa.ubuntu.com/job/mir-clang-trusty-amd64-build/406
    SUCCESS: http://jenkins.qa.ubuntu.com/job/mir-mediumtests-trusty-touch/16
    SUCCESS: http://jenkins.qa.ubuntu.com/job/mir-team-mir-development-branch-trusty-amd64-ci/246
        deb: http://jenkins.qa.ubuntu.com/job/mir-team-mir-development-branch-trusty-amd64-ci/246/artifact/work/output/*zip*/output.zip
    SUCCESS: http://jenkins.qa.ubuntu.com/job/mir-team-mir-development-branch-trusty-armhf-ci/249
        deb: http://jenkins.qa.ubuntu.com/job/mir-team-mir-development-branch-trusty-armhf-ci/249/artifact/work/output/*zip*/output.zip
    SUCCESS: http://jenkins.qa.ubuntu.com/job/mir-mediumtests-builder-trusty-armhf/16
        deb: http://jenkins.qa.ubuntu.com/job/mir-mediumtests-builder-trusty-armhf/16/artifact/work/output/*zip*/output.zip
    SUCCESS: http://jenkins.qa.ubuntu.com/job/mir-mediumtests-runner-mako/54
    SUCCESS: http://s-jenkins.ubuntu-ci:8080/job/touch-flash-device/2268

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

review: Approve (continuous-integration)

[Alexandros Frantzis (afrantzis)]

As per the standard, single precision floating point are guaranteed to have a precision of at least 6 decimal digits, and double precision numbers a precision of least 10 decimal digits (in practice, i.e., when using IEEE 754 representation, the precision is actually larger). Double should be more than enough for our purposes. Plus we are just converting to double, not doing any arithmetic with it which could lead to the accumulation of precision errors. Anyway, I am not really fussed over the current approach, so abstaining.

review: Abstain

[Daniel van Vugt (vanvugt)]

According to IEEE754, even a double will not fit enough decimal digits to accurately represent system_clock time in microseconds. A double can represent 15.95 decimal digits. But the system_clock in microseconds is at least 16 digits.

[http://en.wikipedia.org/wiki/IEEE_floating_point]

[Alan Griffiths (alan-griffiths)]

I'm not against changing the output format. But isn't this just replicating what glog already provides?

review: Needs Information

[Alan Griffiths (alan-griffiths)]

this would be easier to test if it used the_time_source() instead of accessing the system clock directly.

And it lacks tests. ;:

[Alexandros Frantzis (afrantzis)]

> According to IEEE754, even a double will not fit enough decimal digits to accurately represent system_clock time in > microseconds. A double can represent 15.95 decimal digits. But the system_clock in microseconds is at least 16
> digits.

OK, convinced. It would be useful to have some tests like Alan suggests, but not a blocker.

review: Approve

[Daniel van Vugt (vanvugt)]

the_time_source() uses std::chrono::high_resolution_clock, which I believe is unsafe to use in this case because there's possibly less guarantee of it having the same epoch between different processes. I did consider that already.

I don't think it's appropriate to write tests for trivial debugging code like this. Although one potential case for tests here would be to verify the format does not change when we have tooling which depends on it...

[Kevin DuBois (kdub)]

i don't know if breaking before every << improves readability, but otherwise good

review: Approve

[Daniel van Vugt (vanvugt)]

> I'm not against changing the output format. But isn't this just replicating
> what glog already provides?

I don't know what glog provides. If it did the formatting for us then great. But I do know that DumbConsoleLogger has no dependencies on glog. You'd have to redesign classes to utilize glog in this case, no?

[PS Jenkins bot (ps-jenkins)]

FAILED: Autolanding.
More details in the following jenkins job:
http://jenkins.qa.ubuntu.com/job/mir-team-mir-development-branch-autolanding/222/
Executed test runs:
    SUCCESS: http://jenkins.qa.ubuntu.com/job/mir-android-trusty-i386-build/424
    SUCCESS: http://jenkins.qa.ubuntu.com/job/mir-clang-trusty-amd64-build/420
    FAILURE: http://jenkins.qa.ubuntu.com/job/mir-mediumtests-trusty-touch/30/console
    SUCCESS: http://jenkins.qa.ubuntu.com/job/mir-team-mir-development-branch-trusty-amd64-autolanding/124
        deb: http://jenkins.qa.ubuntu.com/job/mir-team-mir-development-branch-trusty-amd64-autolanding/124/artifact/work/output/*zip*/output.zip
    SUCCESS: http://jenkins.qa.ubuntu.com/job/mir-team-mir-development-branch-trusty-armhf-autolanding/125
        deb: http://jenkins.qa.ubuntu.com/job/mir-team-mir-development-branch-trusty-armhf-autolanding/125/artifact/work/output/*zip*/output.zip
    SUCCESS: http://jenkins.qa.ubuntu.com/job/mir-mediumtests-builder-trusty-armhf/30
        deb: http://jenkins.qa.ubuntu.com/job/mir-mediumtests-builder-trusty-armhf/30/artifact/work/output/*zip*/output.zip
    FAILURE: http://jenkins.qa.ubuntu.com/job/mir-mediumtests-runner-mako/67/console
    SUCCESS: http://s-jenkins.ubuntu-ci:8080/job/touch-flash-device/2314

review: Needs Fixing (continuous-integration)

[PS Jenkins bot (ps-jenkins)]

FAILED: Autolanding.
More details in the following jenkins job:
http://jenkins.qa.ubuntu.com/job/mir-team-mir-development-branch-autolanding/229/
Executed test runs:
    FAILURE: http://jenkins.qa.ubuntu.com/job/mir-android-trusty-i386-build/440/console
    SUCCESS: http://jenkins.qa.ubuntu.com/job/mir-clang-trusty-amd64-build/436
    SUCCESS: http://jenkins.qa.ubuntu.com/job/mir-mediumtests-trusty-touch/46
    SUCCESS: http://jenkins.qa.ubuntu.com/job/mir-team-mir-development-branch-trusty-amd64-autolanding/131
        deb: http://jenkins.qa.ubuntu.com/job/mir-team-mir-development-branch-trusty-amd64-autolanding/131/artifact/work/output/*zip*/output.zip
    SUCCESS: http://jenkins.qa.ubuntu.com/job/mir-team-mir-development-branch-trusty-armhf-autolanding/132
        deb: http://jenkins.qa.ubuntu.com/job/mir-team-mir-development-branch-trusty-armhf-autolanding/132/artifact/work/output/*zip*/output.zip
    SUCCESS: http://jenkins.qa.ubuntu.com/job/mir-mediumtests-builder-trusty-armhf/46
        deb: http://jenkins.qa.ubuntu.com/job/mir-mediumtests-builder-trusty-armhf/46/artifact/work/output/*zip*/output.zip
    SUCCESS: http://jenkins.qa.ubuntu.com/job/mir-mediumtests-runner-mako/82
    SUCCESS: http://s-jenkins.ubuntu-ci:8080/job/touch-flash-device/2365

review: Needs Fixing (continuous-integration)

[Daniel van Vugt (vanvugt)]

Modified to use CLOCK_REALTIME, so we can accurately calculate the latency between kernel input events and server.

[PS Jenkins bot (ps-jenkins)]

FAILED: Continuous integration, rev:1284
http://jenkins.qa.ubuntu.com/job/mir-team-mir-development-branch-ci/541/
Executed test runs:
    SUCCESS: http://jenkins.qa.ubuntu.com/job/mir-android-trusty-i386-build/445
    SUCCESS: http://jenkins.qa.ubuntu.com/job/mir-clang-trusty-amd64-build/441
    FAILURE: http://jenkins.qa.ubuntu.com/job/mir-mediumtests-trusty-touch/51/console
    SUCCESS: http://jenkins.qa.ubuntu.com/job/mir-team-mir-development-branch-trusty-amd64-ci/267
        deb: http://jenkins.qa.ubuntu.com/job/mir-team-mir-development-branch-trusty-amd64-ci/267/artifact/work/output/*zip*/output.zip
    SUCCESS: http://jenkins.qa.ubuntu.com/job/mir-team-mir-development-branch-trusty-armhf-ci/270
        deb: http://jenkins.qa.ubuntu.com/job/mir-team-mir-development-branch-trusty-armhf-ci/270/artifact/work/output/*zip*/output.zip
    SUCCESS: http://jenkins.qa.ubuntu.com/job/mir-mediumtests-builder-trusty-armhf/51
        deb: http://jenkins.qa.ubuntu.com/job/mir-mediumtests-builder-trusty-armhf/51/artifact/work/output/*zip*/output.zip
    FAILURE: http://jenkins.qa.ubuntu.com/job/mir-mediumtests-runner-mako/86/console
    SUCCESS: http://s-jenkins.ubuntu-ci:8080/job/touch-flash-device/2376

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

review: Needs Fixing (continuous-integration)

[PS Jenkins bot (ps-jenkins)]

FAILED: Autolanding.
More details in the following jenkins job:
http://jenkins.qa.ubuntu.com/job/mir-team-mir-development-branch-autolanding/235/
Executed test runs:
    FAILURE: http://jenkins.qa.ubuntu.com/job/mir-android-trusty-i386-build/452/console
    SUCCESS: http://jenkins.qa.ubuntu.com/job/mir-clang-trusty-amd64-build/448
    FAILURE: http://jenkins.qa.ubuntu.com/job/mir-mediumtests-trusty-touch/58/console
    SUCCESS: http://jenkins.qa.ubuntu.com/job/mir-team-mir-development-branch-trusty-amd64-autolanding/137
        deb: http://jenkins.qa.ubuntu.com/job/mir-team-mir-development-branch-trusty-amd64-autolanding/137/artifact/work/output/*zip*/output.zip
    SUCCESS: http://jenkins.qa.ubuntu.com/job/mir-team-mir-development-branch-trusty-armhf-autolanding/138
        deb: http://jenkins.qa.ubuntu.com/job/mir-team-mir-development-branch-trusty-armhf-autolanding/138/artifact/work/output/*zip*/output.zip
    SUCCESS: http://jenkins.qa.ubuntu.com/job/mir-mediumtests-builder-trusty-armhf/58
        deb: http://jenkins.qa.ubuntu.com/job/mir-mediumtests-builder-trusty-armhf/58/artifact/work/output/*zip*/output.zip
    FAILURE: http://jenkins.qa.ubuntu.com/job/mir-mediumtests-runner-mako/93/console
    SUCCESS: http://s-jenkins.ubuntu-ci:8080/job/touch-flash-device/2401

review: Needs Fixing (continuous-integration)

[PS Jenkins bot (ps-jenkins)]

review: Approve (continuous-integration)

=== modified file 'src/shared/logging/dumb_console_logger.cpp'
--- src/shared/logging/dumb_console_logger.cpp	2013-06-03 08:14:01 +0000
+++ src/shared/logging/dumb_console_logger.cpp	2013-12-16 09:58:03 +0000
@@ -19,6 +19,8 @@
 #include "mir/logging/dumb_console_logger.h"
 
 #include <iostream>
+#include <ctime>
+#include <cstdio>
 
 namespace ml = mir::logging;
 
@@ -38,6 +40,19 @@
 
     std::ostream& out = severity < Logger::informational ? std::cerr : std::cout;
 
-    out << "[" << lut[severity] << ", " << component << "] "
-        << message << "\n";
+    struct timespec ts;
+    clock_gettime(CLOCK_REALTIME, &ts);
+    char now[32];
+    snprintf(now, sizeof(now), "%ld.%06ld",
+             (long)ts.tv_sec, ts.tv_nsec / 1000);
+
+    out << "["
+        << now
+        << "] ("
+        << lut[severity]
+        << ") "
+        << component
+        << ": "
+        << message
+        << "\n";
 }