gl-host-common/opengl/logger.cpp

// Copyright 2020 The Android Open Source Project
//
// Licensed under the Apache License, Version 2.0 (the "License");
// you may not use this file except in compliance with the License.
// You may obtain a copy of the License at
//
// http://www.apache.org/licenses/LICENSE-2.0
//
// Unless required by applicable law or agreed to in writing, software
// distributed under the License is distributed on an "AS IS" BASIS,
// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
// See the License for the specific language governing permissions and
// limitations under the License.

#include "host-common/opengl/logger.h"

#include "aemu/base/files/PathUtils.h"
#include "aemu/base/synchronization/Lock.h"

#include <algorithm>
#include <fstream>
#include <inttypes.h>
#include <stdarg.h>
#include <stdio.h>
#include <string>

#include "aemu/base/msvc.h"

#ifndef _MSC_VER
#include <sys/time.h>
#endif
#include <vector>

using android::base::AutoLock;
using android::base::Lock;
using android::base::PathUtils;

// The purpose of the OpenGL logger is to log
// information about such things as EGL initialization
// and possibly miscellanous OpenGL commands,
// in order to get a better idea of what is going on
// in crash reports.

// The OpenGLLogger implementation's initialization method
// by default uses the crash reporter's data directory.

static const int kBufferLen = 2048;

typedef std::pair<uint64_t, std::string> TimestampedLogEntry;

class OpenGLLogger {
public:
    OpenGLLogger();
    OpenGLLogger(const char* filename);
    void stop();

    // Coarse log: Call this infrequently.
    void writeCoarse(const char* str);

    // Fine log: When we want to log very frequent events.
    // Fine logs can be toggled on/off.
    void writeFineTimestamped(const char* str);

    void setLoggerFlags(AndroidOpenglLoggerFlags flags);
    bool isFineLogging() const;

    static OpenGLLogger* get();

private:

    void writeFineLocked(uint64_t time, const char* str);
    void stopFineLogLocked();

    Lock mLock;
    AndroidOpenglLoggerFlags mLoggerFlags = OPENGL_LOGGER_NONE;
    uint64_t mPrevTimeUs = 0;
    std::string mFileName;
    std::ofstream mFileHandle;
    std::string mFineLogFileName;
    std::ofstream mFineLogFileHandle;
    std::vector<TimestampedLogEntry> mFineLog;
    DISALLOW_COPY_ASSIGN_AND_MOVE(OpenGLLogger);
};

static OpenGLLogger* sOpenGLLogger() {
    static OpenGLLogger* g = new OpenGLLogger;
    return g;
}

OpenGLLogger* OpenGLLogger::get() {
    return sOpenGLLogger();
}

OpenGLLogger::OpenGLLogger() {
// #ifdef AEMU_MIN
    return;
// #else
//     const std::string& data_dir =
//         CrashReporter::get()->getDataExchangeDir();
//     mFileName = PathUtils::join(data_dir,
//                                 "opengl_log.txt");
//     mFileHandle.open(mFileName, std::ios::app);
//     mFineLogFileName = PathUtils::join(data_dir,
//                                        "opengl_cxt_log.txt");
//     mFineLogFileHandle.open(mFineLogFileName, std::ios::app);
// #endif
}

OpenGLLogger::OpenGLLogger(const char* filename) :
    mFileName(filename) {
    mFileHandle.open(mFileName, std::ios::app);
}

void OpenGLLogger::writeCoarse(const char* str) {
    AutoLock lock(mLock);
    if (mLoggerFlags & OPENGL_LOGGER_PRINT_TO_STDOUT) {
        printf("%s\n", str);
    }
    if (mFileHandle) {
        mFileHandle << str << std::endl;
    }
}

void OpenGLLogger::stop() {
    AutoLock lock(mLock);
    stopFineLogLocked();
    mFileHandle.close();
}

void OpenGLLogger::writeFineLocked(uint64_t time, const char* str) {
    if (mLoggerFlags & OPENGL_LOGGER_PRINT_TO_STDOUT) {
        printf("%s", str);
    } else {
        mFineLog.emplace_back(time, str);
    }
}

void OpenGLLogger::writeFineTimestamped(const char* str) {
    if (mLoggerFlags & OPENGL_LOGGER_DO_FINE_LOGGING) {
        char buf[kBufferLen] = {};
        struct timeval tv;
        gettimeofday(&tv, NULL);

        uint64_t curr_micros = (tv.tv_usec) % 1000;
        uint64_t curr_millis = (tv.tv_usec / 1000) % 1000;
        uint64_t curr_secs = tv.tv_sec;
        uint64_t curr_us = tv.tv_sec * 1000000ULL + tv.tv_usec;
        snprintf(buf, sizeof(buf) - 1,
                "time_us="
                "%" PRIu64 " s "
                "%" PRIu64 " ms "
                "%" PRIu64 " us deltaUs "
                "%" PRIu64 " | %s",
                curr_secs,
                curr_millis,
                curr_micros,
                curr_us - mPrevTimeUs,
                str);
        AutoLock lock(mLock);
        writeFineLocked(curr_micros + 1000ULL * curr_millis +
                  1000ULL * 1000ULL * curr_secs, buf);
        mPrevTimeUs = curr_us;
    }
}

void OpenGLLogger::setLoggerFlags(AndroidOpenglLoggerFlags flags) {
    AutoLock lock(mLock);
    bool needStopFineLog =
        (mLoggerFlags & OPENGL_LOGGER_DO_FINE_LOGGING) &&
        (!(flags & OPENGL_LOGGER_DO_FINE_LOGGING));

    if (needStopFineLog) {
        stopFineLogLocked();
    }

    mLoggerFlags = flags;
}

bool OpenGLLogger::isFineLogging() const {
    // For speed, we'll just let this read of mLoggerFlags race.
    return (mLoggerFlags & OPENGL_LOGGER_DO_FINE_LOGGING);
}

void OpenGLLogger::stopFineLogLocked() {
    // Only print message when fine-grained
    // logging is turned on.
    if (!mFineLog.empty()) {
        fprintf(stderr,
                "Writing fine-grained GL log to %s...",
                mFineLogFileName.c_str());
    }

    // Sort log entries according to their timestamps.
    // This is because the log entries might arrive
    // out of order.
    std::sort(mFineLog.begin(), mFineLog.end(),
              [](const TimestampedLogEntry& x,
                 const TimestampedLogEntry& y) {
                  return x.first < y.first;
              });

    if (mFineLogFileHandle) {
        for (const auto& entry : mFineLog) {
            // The fine log does not print newlines
            // as it is used with the opengl debug
            // printout in emugl, which adds
            // newlines of its own.
            mFineLogFileHandle << entry.second;
        }
        mFineLogFileHandle.close();
        if (!mFineLog.empty()) {
            fprintf(stderr, "done\n");
        }
    }
    mFineLog.clear();
}

// C interface

void android_init_opengl_logger() {
    OpenGLLogger::get();
}

void android_opengl_logger_set_flags(AndroidOpenglLoggerFlags flags) {
    OpenGLLogger::get()->setLoggerFlags(flags);
}

void android_opengl_logger_write(const char* fmt, ...) {
    char buf[kBufferLen] = {};
    va_list ap;
    va_start(ap, fmt);
    vsnprintf(buf, sizeof(buf) - 1, fmt, ap);
    va_end(ap);
    OpenGLLogger::get()->writeCoarse(buf);
}

void android_opengl_cxt_logger_write(const char* fmt, ...) {
    auto gl_log = OpenGLLogger::get();

    if (!gl_log->isFineLogging()) return;

    char buf[kBufferLen] = {};
    va_list ap;
    va_start(ap, fmt);
    vsnprintf(buf, sizeof(buf) - 1, fmt, ap);
    va_end(ap);

    gl_log->writeFineTimestamped(buf);
}

void android_stop_opengl_logger() {
    OpenGLLogger* gl_log = OpenGLLogger::get();
    gl_log->stop();
}