Donate to e Foundation | Murena handsets with /e/OS | Own a part of Murena! Learn more

Commit 10b82b68 authored by Mark Salyzyn's avatar Mark Salyzyn
Browse files

logd: isMonotonic improvements 

Use 1972 as a right delineation. Otherwise use half way point
between the monotonic and realtime. Treat correction factor as
unsigned, ensure that any wrapping to a negative value is
dropped or set to EPOCH. Acknowledge that we can get a more
accurate time track by acquiring the time rather than relying on
healthd timestamp.

Bug: 26331432
Change-Id: I09075fca58676a30cf7d87baf2d4b0f53795abaa
parent b5e82131

healthd/BatteryMonitor.cpp

+0 −20
Original line number Diff line number Diff line
@@ -30,7 +30,6 @@ 
#include <batteryservice/BatteryService.h>

#include <cutils/klog.h>

#include <cutils/properties.h>

#include <log/log_read.h>

#include <utils/Errors.h>

#include <utils/String8.h>

#include <utils/Vector.h>
@@ -313,25 +312,6 @@ bool BatteryMonitor::update(void) { 
                 props.chargerUsbOnline ? "u" : "",

                 props.chargerWirelessOnline ? "w" : "");



        log_time realtime(CLOCK_REALTIME);

        time_t t = realtime.tv_sec;

        struct tm *tmp = gmtime(&t);

        if (tmp) {

            static const char fmt[] = " %Y-%m-%d %H:%M:%S.XXXXXXXXX UTC";

            len = strlen(dmesgline);

            if ((len < (sizeof(dmesgline) - sizeof(fmt) - 8)) // margin

                    && strftime(dmesgline + len, sizeof(dmesgline) - len,

                                fmt, tmp)) {

                char *usec = strchr(dmesgline + len, 'X');

                if (usec) {

                    len = usec - dmesgline;

                    snprintf(dmesgline + len, sizeof(dmesgline) - len,

                             "%09u", realtime.tv_nsec);

                    usec[9] = ' ';

                }

            }

        }



        KLOG_WARNING(LOG_TAG, "%s\n", dmesgline);

    }

logd/LogBuffer.h

+31 −5
Original line number Diff line number Diff line
@@ -33,16 +33,42 @@ 
#include "LogWhiteBlackList.h"



//

// We are either in 1970ish (MONOTONIC) or 2015+ish (REALTIME) so to

// differentiate without prejudice, we use 1980 to delineate, earlier

// is monotonic, later is real.

// We are either in 1970ish (MONOTONIC) or 2016+ish (REALTIME) so to

// differentiate without prejudice, we use 1972 to delineate, earlier

// is likely monotonic, later is real. Otherwise we start using a

// dividing line between monotonic and realtime if more than a minute

// difference between them.

//

namespace android {



static bool isMonotonic(const log_time &mono) {

    static const uint32_t EPOCH_PLUS_10_YEARS = 10 * 1461 / 4 * 24 * 60 * 60;

    static const uint32_t EPOCH_PLUS_2_YEARS = 2 * 24 * 60 * 60 * 1461 / 4;

    static const uint32_t EPOCH_PLUS_MINUTE = 60;



    return mono.tv_sec < EPOCH_PLUS_10_YEARS;

    if (mono.tv_sec >= EPOCH_PLUS_2_YEARS) {

        return false;

    }



    log_time now(CLOCK_REALTIME);



    /* Timezone and ntp time setup? */

    if (now.tv_sec >= EPOCH_PLUS_2_YEARS) {

        return true;

    }



    /* no way to differentiate realtime from monotonic time */

    if (now.tv_sec < EPOCH_PLUS_MINUTE) {

        return false;

    }



    log_time cpu(CLOCK_MONOTONIC);

    /* too close to call to differentiate monotonic times from realtime */

    if ((cpu.tv_sec + EPOCH_PLUS_MINUTE) >= now.tv_sec) {

        return false;

    }



    /* dividing line half way between monotonic and realtime */

    return mono.tv_sec < ((cpu.tv_sec + now.tv_sec) / 2);

}



}

logd/LogKlog.cpp

+26 −16
Original line number Diff line number Diff line
@@ -206,7 +206,10 @@ char *log_strntok_r(char *s, size_t *len, char **last, size_t *sublen) { 
    // NOTREACHED

}



log_time LogKlog::correction = log_time(CLOCK_REALTIME) - log_time(CLOCK_MONOTONIC);

log_time LogKlog::correction =

    (log_time(CLOCK_REALTIME) < log_time(CLOCK_MONOTONIC))

        ? log_time::EPOCH

        : (log_time(CLOCK_REALTIME) - log_time(CLOCK_MONOTONIC));



LogKlog::LogKlog(LogBuffer *buf, LogReader *reader, int fdWrite, int fdRead, bool auditd) :

        SocketListener(fdRead, false),
@@ -272,7 +275,7 @@ void LogKlog::calculateCorrection(const log_time &monotonic, 
                                  size_t len) {

    log_time real;

    const char *ep = real.strptime(real_string, "%Y-%m-%d %H:%M:%S.%09q UTC");

    if (!ep || (ep > &real_string[len])) {

    if (!ep || (ep > &real_string[len]) || (real > log_time(CLOCK_REALTIME))) {

        return;

    }

    // kernel report UTC, log_time::strptime is localtime from calendar.
@@ -283,9 +286,17 @@ void LogKlog::calculateCorrection(const log_time &monotonic, 
    memset(&tm, 0, sizeof(tm));

    tm.tm_isdst = -1;

    localtime_r(&now, &tm);

    if ((tm.tm_gmtoff < 0) && ((-tm.tm_gmtoff) > real.tv_sec)) {

        real = log_time::EPOCH;

    } else {

        real.tv_sec += tm.tm_gmtoff;

    }

    if (monotonic > real) {

        correction = log_time::EPOCH;

    } else {

        correction = real - monotonic;

    }

}



static const char suspendStr[] = "PM: suspend entry ";

static const char resumeStr[] = "PM: suspend exit ";
@@ -319,11 +330,11 @@ void LogKlog::sniffTime(log_time &now, 
    if (cp && (cp >= &(*buf)[len])) {

        cp = NULL;

    }

    len -= cp - *buf;

    if (cp) {

        static const char healthd[] = "healthd";

        static const char battery[] = ": battery ";



        len -= cp - *buf;

        if (len && isspace(*cp)) {

            ++cp;

            --len;
@@ -347,16 +358,11 @@ void LogKlog::sniffTime(log_time &now, 
                && ((size_t)((b += sizeof(healthd) - 1) - cp) < len)

                && ((b = strnstr(b, len -= b - cp, battery)))

                && ((size_t)((b += sizeof(battery) - 1) - cp) < len)) {

            len -= b - cp;

            // NB: healthd is roughly 150us late, worth the price to deal with

            //     ntp-induced or hardware clock drift.

            // look for " 2???-??-?? ??:??:??.????????? ???"

            for (; len && *b && (*b != '\n'); ++b, --len) {

                if ((b[0] == ' ') && (b[1] == '2') && (b[5] == '-')) {

                    calculateCorrection(now, b + 1, len - 1);

                    break;

                }

            }

            // NB: healthd is roughly 150us late, so we use it instead to

            //     trigger a check for ntp-induced or hardware clock drift.

            log_time real(CLOCK_REALTIME);

            log_time mono(CLOCK_MONOTONIC);

            correction = (real < mono) ? log_time::EPOCH : (real - mono);

        } else if (((b = strnstr(cp, len, suspendedStr)))

                && ((size_t)((b += sizeof(suspendStr) - 1) - cp) < len)) {

            len -= b - cp;
@@ -371,7 +377,11 @@ void LogKlog::sniffTime(log_time &now, 
                    real.tv_nsec += (*endp - '0') * multiplier;

                }

                if (reverse) {

                    if (real > correction) {

                        correction = log_time::EPOCH;

                    } else {

                        correction -= real;

                    }

                } else {

                    correction += real;

                }