utun2/tools/chatgui/rlottie_src/src/vector/vdebug.cpp

/*
 * Copyright (c) 2020 Samsung Electronics Co., Ltd. All rights reserved.

 * Permission is hereby granted, free of charge, to any person obtaining a copy
 * of this software and associated documentation files (the "Software"), to deal
 * in the Software without restriction, including without limitation the rights
 * to use, copy, modify, merge, publish, distribute, sublicense, and/or sell
 * copies of the Software, and to permit persons to whom the Software is
 * furnished to do so, subject to the following conditions:

 * The above copyright notice and this permission notice shall be included in all
 * copies or substantial portions of the Software.

 * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR
 * IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY,
 * FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE
 * AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER
 * LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM,
 * OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE
 * SOFTWARE.
 */

#include "vdebug.h"
#include "rlottie_capi.h"
#include <atomic>
#include <cstdarg>
#include <cstdio>

static std::atomic<Lottie_Warning_Callback> warningCallback{nullptr};

extern "C" void lottie_set_warning_callback(Lottie_Warning_Callback callback) {
    warningCallback.store(callback);
}

void lottieWarning(const char *format, ...) {
    char message[1024];
    va_list args;
    va_start(args, format);
    std::vsnprintf(message, sizeof(message), format, args);
    va_end(args);
    if (auto callback = warningCallback.load()) callback(message);
    else std::fprintf(stderr, "[WARN] rlottie: %s\n", message);
}

#ifdef LOTTIE_LOGGING_SUPPORT

#include <atomic>
#include <chrono>
#include <cstring>
#include <ctime>
#include <fstream>
#include <memory>
#include <queue>
#include <sstream>
#include <thread>
#include <tuple>

namespace {

/* Returns microseconds since epoch */
uint64_t timestamp_now()
{
    return std::chrono::duration_cast<std::chrono::microseconds>(
               std::chrono::high_resolution_clock::now().time_since_epoch())
        .count();
}

/* I want [2016-10-13 00:01:23.528514] */
void format_timestamp(std::ostream& os, uint64_t timestamp)
{
    // The next 3 lines do not work on MSVC!
    // auto duration = std::chrono::microseconds(timestamp);
    // std::chrono::high_resolution_clock::time_point time_point(duration);
    // std::time_t time_t =
    // std::chrono::high_resolution_clock::to_time_t(time_point);
    std::time_t time_t = timestamp / 1000000;
    auto        gmtime = std::gmtime(&time_t);
    char        buffer[32];
    strftime(buffer, 32, "%Y-%m-%d %T.", gmtime);
    char microseconds[7];
    snprintf(microseconds, 7, "%06llu",
             (long long unsigned int)timestamp % 1000000);
    os << '[' << buffer << microseconds << ']';
}

std::thread::id this_thread_id()
{
    static thread_local const std::thread::id id = std::this_thread::get_id();
    return id;
}

template <typename T, typename Tuple>
struct TupleIndex;

template <typename T, typename... Types>
struct TupleIndex<T, std::tuple<T, Types...> > {
    static constexpr const std::size_t value = 0;
};

template <typename T, typename U, typename... Types>
struct TupleIndex<T, std::tuple<U, Types...> > {
    static constexpr const std::size_t value =
        1 + TupleIndex<T, std::tuple<Types...> >::value;
};

}  // anonymous namespace

typedef std::tuple<char, uint32_t, uint64_t, int32_t, int64_t, double,
                   VDebug::string_literal_t, char*>
    SupportedTypes;

char const* to_string(LogLevel loglevel)
{
    switch (loglevel) {
    case LogLevel::OFF:
        return "OFF";
    case LogLevel::INFO:
        return "INFO";
    case LogLevel::WARN:
        return "WARN";
    case LogLevel::CRIT:
        return "CRIT";
    }
    return "XXXX";
}

template <typename Arg>
void VDebug::encode(Arg arg)
{
    *reinterpret_cast<Arg*>(buffer()) = arg;
    m_bytes_used += sizeof(Arg);
}

template <typename Arg>
void VDebug::encode(Arg arg, uint8_t type_id)
{
    resize_buffer_if_needed(sizeof(Arg) + sizeof(uint8_t));
    encode<uint8_t>(type_id);
    encode<Arg>(arg);
}

VDebug::VDebug(LogLevel level, char const* file, char const* function,
               uint32_t line)
    : m_bytes_used(0), m_buffer_size(sizeof(m_stack_buffer))
{
    encode<uint64_t>(timestamp_now());
    encode<std::thread::id>(this_thread_id());
    encode<string_literal_t>(string_literal_t(file));
    encode<string_literal_t>(string_literal_t(function));
    encode<uint32_t>(line);
    encode<LogLevel>(level);
    if (level == LogLevel::INFO) {
        m_logAll = false;
    } else {
        m_logAll = true;
    }
}

VDebug::~VDebug() = default;

void VDebug::stringify(std::ostream& os)
{
    char*             b = !m_heap_buffer ? m_stack_buffer : m_heap_buffer.get();
    char const* const end = b + m_bytes_used;
    uint64_t          timestamp = *reinterpret_cast<uint64_t*>(b);
    b += sizeof(uint64_t);
    std::thread::id threadid = *reinterpret_cast<std::thread::id*>(b);
    b += sizeof(std::thread::id);
    string_literal_t file = *reinterpret_cast<string_literal_t*>(b);
    b += sizeof(string_literal_t);
    string_literal_t function = *reinterpret_cast<string_literal_t*>(b);
    b += sizeof(string_literal_t);
    uint32_t line = *reinterpret_cast<uint32_t*>(b);
    b += sizeof(uint32_t);
    LogLevel loglevel = *reinterpret_cast<LogLevel*>(b);
    b += sizeof(LogLevel);
    if (m_logAll) {
        format_timestamp(os, timestamp);

        os << '[' << to_string(loglevel) << ']' << '[' << threadid << ']' << '['
           << file.m_s << ':' << function.m_s << ':' << line << "] ";
    }

    stringify(os, b, end);
    os << std::endl;

    if (loglevel >= LogLevel::CRIT) os.flush();
}

template <typename Arg>
char* decode(std::ostream& os, char* b, Arg* /*dummy*/)
{
    Arg arg = *reinterpret_cast<Arg*>(b);
    os << arg;
    return b + sizeof(Arg);
}

template <>
char* decode(std::ostream& os, char* b, VDebug::string_literal_t* /*dummy*/)
{
    VDebug::string_literal_t s =
        *reinterpret_cast<VDebug::string_literal_t*>(b);
    os << s.m_s;
    return b + sizeof(VDebug::string_literal_t);
}

template <>
char* decode(std::ostream& os, char* b, char** /*dummy*/)
{
    while (*b != '\0') {
        os << *b;
        ++b;
    }
    return ++b;
}

void VDebug::stringify(std::ostream& os, char* start, char const* const end)
{
    if (start == end) return;

    int type_id = static_cast<int>(*start);
    start++;

    switch (type_id) {
    case 0:
        stringify(
            os,
            decode(os, start,
                   static_cast<std::tuple_element<0, SupportedTypes>::type*>(
                       nullptr)),
            end);
        return;
    case 1:
        stringify(
            os,
            decode(os, start,
                   static_cast<std::tuple_element<1, SupportedTypes>::type*>(
                       nullptr)),
            end);
        return;
    case 2:
        stringify(
            os,
            decode(os, start,
                   static_cast<std::tuple_element<2, SupportedTypes>::type*>(
                       nullptr)),
            end);
        return;
    case 3:
        stringify(
            os,
            decode(os, start,
                   static_cast<std::tuple_element<3, SupportedTypes>::type*>(
                       nullptr)),
            end);
        return;
    case 4:
        stringify(
            os,
            decode(os, start,
                   static_cast<std::tuple_element<4, SupportedTypes>::type*>(
                       nullptr)),
            end);
        return;
    case 5:
        stringify(
            os,
            decode(os, start,
                   static_cast<std::tuple_element<5, SupportedTypes>::type*>(
                       nullptr)),
            end);
        return;
    case 6:
        stringify(
            os,
            decode(os, start,
                   static_cast<std::tuple_element<6, SupportedTypes>::type*>(
                       nullptr)),
            end);
        return;
    case 7:
        stringify(
            os,
            decode(os, start,
                   static_cast<std::tuple_element<7, SupportedTypes>::type*>(
                       nullptr)),
            end);
        return;
    }
}

char* VDebug::buffer()
{
    return !m_heap_buffer ? &m_stack_buffer[m_bytes_used]
                          : &(m_heap_buffer.get())[m_bytes_used];
}

void VDebug::resize_buffer_if_needed(size_t additional_bytes)
{
    size_t const required_size = m_bytes_used + additional_bytes;

    if (required_size <= m_buffer_size) return;

    if (!m_heap_buffer) {
        m_buffer_size = std::max(static_cast<size_t>(512), required_size);
        m_heap_buffer = std::make_unique<char[]>(m_buffer_size);
        memcpy(m_heap_buffer.get(), m_stack_buffer, m_bytes_used);
        return;
    } else {
        m_buffer_size =
            std::max(static_cast<size_t>(2 * m_buffer_size), required_size);
        std::unique_ptr<char[]> new_heap_buffer(new char[m_buffer_size]);
        memcpy(new_heap_buffer.get(), m_heap_buffer.get(), m_bytes_used);
        m_heap_buffer.swap(new_heap_buffer);
    }
}

void VDebug::encode(char const* arg)
{
    if (arg != nullptr) encode_c_string(arg, strlen(arg));
}

void VDebug::encode(char* arg)
{
    if (arg != nullptr) encode_c_string(arg, strlen(arg));
}

void VDebug::encode_c_string(char const* arg, size_t length)
{
    if (length == 0) return;

    resize_buffer_if_needed(1 + length + 1);
    char* b = buffer();
    auto  type_id = TupleIndex<char*, SupportedTypes>::value;
    *reinterpret_cast<uint8_t*>(b++) = static_cast<uint8_t>(type_id);
    memcpy(b, arg, length + 1);
    m_bytes_used += 1 + length + 1;
}

void VDebug::encode(string_literal_t arg)
{
    encode<string_literal_t>(
        arg, TupleIndex<string_literal_t, SupportedTypes>::value);
}

VDebug& VDebug::operator<<(std::string const& arg)
{
    encode_c_string(arg.c_str(), arg.length());
    return *this;
}

VDebug& VDebug::operator<<(int32_t arg)
{
    encode<int32_t>(arg, TupleIndex<int32_t, SupportedTypes>::value);
    return *this;
}

VDebug& VDebug::operator<<(uint32_t arg)
{
    encode<uint32_t>(arg, TupleIndex<uint32_t, SupportedTypes>::value);
    return *this;
}

//    VDebug& VDebug::operator<<(int64_t arg)
//    {
//    encode < int64_t >(arg, TupleIndex < int64_t, SupportedTypes >::value);
//    return *this;
//    }

//    VDebug& VDebug::operator<<(uint64_t arg)
//    {
//    encode < uint64_t >(arg, TupleIndex < uint64_t, SupportedTypes >::value);
//    return *this;
//    }
VDebug& VDebug::operator<<(unsigned long arg)
{
    encode<uint64_t>(arg, TupleIndex<uint64_t, SupportedTypes>::value);
    return *this;
}

VDebug& VDebug::operator<<(long arg)
{
    encode<int64_t>(arg, TupleIndex<int64_t, SupportedTypes>::value);
    return *this;
}

VDebug& VDebug::operator<<(double arg)
{
    encode<double>(arg, TupleIndex<double, SupportedTypes>::value);
    return *this;
}

VDebug& VDebug::operator<<(char arg)
{
    encode<char>(arg, TupleIndex<char, SupportedTypes>::value);
    return *this;
}

struct BufferBase {
    virtual ~BufferBase() = default;
    virtual void push(VDebug&& logline) = 0;
    virtual bool try_pop(VDebug& logline) = 0;
};

struct SpinLock {
    SpinLock(std::atomic_flag& flag) : m_flag(flag)
    {
        while (m_flag.test_and_set(std::memory_order_acquire))
            ;
    }

    ~SpinLock() { m_flag.clear(std::memory_order_release); }

private:
    std::atomic_flag& m_flag;
};

/* Multi Producer Single Consumer Ring Buffer */
class RingBuffer : public BufferBase {
public:
    struct alignas(64) Item {
        Item()
            : flag(), written(0), logline(LogLevel::INFO, nullptr, nullptr, 0)
        {
        }

        std::atomic_flag flag;
        char             written;
        char             padding[256 - sizeof(std::atomic_flag) - sizeof(char) -
                     sizeof(VDebug)];
        VDebug           logline;
    };

    RingBuffer(size_t const size)
        : m_size(size),
          m_ring(static_cast<Item*>(std::malloc(size * sizeof(Item)))),
          m_write_index(0),
          m_read_index(0)
    {
        for (size_t i = 0; i < m_size; ++i) {
            new (&m_ring[i]) Item();
        }
        static_assert(sizeof(Item) == 256, "Unexpected size != 256");
    }

    ~RingBuffer() override
    {
        for (size_t i = 0; i < m_size; ++i) {
            m_ring[i].~Item();
        }
        std::free(m_ring);
    }

    void push(VDebug&& logline) override
    {
        unsigned int write_index =
            m_write_index.fetch_add(1, std::memory_order_relaxed) % m_size;
        Item&    item = m_ring[write_index];
        SpinLock spinlock(item.flag);
        item.logline = std::move(logline);
        item.written = 1;
    }

    bool try_pop(VDebug& logline) override
    {
        Item&    item = m_ring[m_read_index % m_size];
        SpinLock spinlock(item.flag);
        if (item.written == 1) {
            logline = std::move(item.logline);
            item.written = 0;
            ++m_read_index;
            return true;
        }
        return false;
    }

    RingBuffer(RingBuffer const&) = delete;
    RingBuffer& operator=(RingBuffer const&) = delete;

private:
    size_t const              m_size;
    Item*                     m_ring;
    std::atomic<unsigned int> m_write_index;

public:
    char pad[64];

private:
    unsigned int m_read_index;
};

class Buffer {
public:
    struct Item {
        Item(VDebug&& logline) : logline(std::move(logline)) {}
        char   padding[256 - sizeof(VDebug)];
        VDebug logline;
    };

    static constexpr const size_t size =
        32768;  // 8MB. Helps reduce memory fragmentation

    Buffer() : m_buffer(static_cast<Item*>(std::malloc(size * sizeof(Item))))
    {
        for (size_t i = 0; i <= size; ++i) {
            m_write_state[i].store(0, std::memory_order_relaxed);
        }
        static_assert(sizeof(Item) == 256, "Unexpected size != 256");
    }

    ~Buffer()
    {
        unsigned int write_count = m_write_state[size].load();
        for (size_t i = 0; i < write_count; ++i) {
            m_buffer[i].~Item();
        }
        std::free(m_buffer);
    }

    // Returns true if we need to switch to next buffer
    bool push(VDebug&& logline, unsigned int const write_index)
    {
        new (&m_buffer[write_index]) Item(std::move(logline));
        m_write_state[write_index].store(1, std::memory_order_release);
        return m_write_state[size].fetch_add(1, std::memory_order_acquire) +
                   1 ==
               size;
    }

    bool try_pop(VDebug& logline, unsigned int const read_index)
    {
        if (m_write_state[read_index].load(std::memory_order_acquire)) {
            Item& item = m_buffer[read_index];
            logline = std::move(item.logline);
            return true;
        }
        return false;
    }

    Buffer(Buffer const&) = delete;
    Buffer& operator=(Buffer const&) = delete;

private:
    Item*                     m_buffer;
    std::atomic<unsigned int> m_write_state[size + 1];
};

class QueueBuffer : public BufferBase {
public:
    QueueBuffer(QueueBuffer const&) = delete;
    QueueBuffer& operator=(QueueBuffer const&) = delete;

    QueueBuffer()
        : m_current_read_buffer{nullptr},
          m_write_index(0),
          m_flag(),
          m_read_index(0)
    {
        setup_next_write_buffer();
    }

    void push(VDebug&& logline) override
    {
        unsigned int write_index =
            m_write_index.fetch_add(1, std::memory_order_relaxed);
        if (write_index < Buffer::size) {
            if (m_current_write_buffer.load(std::memory_order_acquire)
                    ->push(std::move(logline), write_index)) {
                setup_next_write_buffer();
            }
        } else {
            while (m_write_index.load(std::memory_order_acquire) >=
                   Buffer::size)
                ;
            push(std::move(logline));
        }
    }

    bool try_pop(VDebug& logline) override
    {
        if (m_current_read_buffer == nullptr)
            m_current_read_buffer = get_next_read_buffer();

        Buffer* read_buffer = m_current_read_buffer;

        if (read_buffer == nullptr) return false;

        if (read_buffer->try_pop(logline, m_read_index)) {
            m_read_index++;
            if (m_read_index == Buffer::size) {
                m_read_index = 0;
                m_current_read_buffer = nullptr;
                SpinLock spinlock(m_flag);
                m_buffers.pop();
            }
            return true;
        }

        return false;
    }

private:
    void setup_next_write_buffer()
    {
        std::unique_ptr<Buffer> next_write_buffer(new Buffer());
        m_current_write_buffer.store(next_write_buffer.get(),
                                     std::memory_order_release);
        SpinLock spinlock(m_flag);
        m_buffers.push(std::move(next_write_buffer));
        m_write_index.store(0, std::memory_order_relaxed);
    }

    Buffer* get_next_read_buffer()
    {
        SpinLock spinlock(m_flag);
        return m_buffers.empty() ? nullptr : m_buffers.front().get();
    }

private:
    std::queue<std::unique_ptr<Buffer> > m_buffers;
    std::atomic<Buffer*>                 m_current_write_buffer;
    Buffer*                              m_current_read_buffer;
    std::atomic<unsigned int>            m_write_index;
    std::atomic_flag                     m_flag;
    unsigned int                         m_read_index;
};

class FileWriter {
public:
    FileWriter(std::string const& log_directory,
               std::string const& log_file_name, uint32_t log_file_roll_size_mb)
        : m_log_file_roll_size_bytes(log_file_roll_size_mb * 1024 * 1024),
          m_name(log_directory + log_file_name)
    {
        roll_file();
    }

    void write(VDebug& logline)
    {
        auto pos = m_os->tellp();
        logline.stringify(*m_os);
        m_bytes_written += m_os->tellp() - pos;
        if (m_bytes_written > m_log_file_roll_size_bytes) {
            roll_file();
        }
    }

private:
    void roll_file()
    {
        if (m_os) {
            m_os->flush();
            m_os->close();
        }

        m_bytes_written = 0;
        m_os = std::make_unique<std::ofstream>();
        // TODO Optimize this part. Does it even matter ?
        std::string log_file_name = m_name;
        log_file_name.append(".");
        log_file_name.append(std::to_string(++m_file_number));
        log_file_name.append(".txt");
        m_os->open(log_file_name, std::ofstream::out | std::ofstream::trunc);
    }

private:
    uint32_t                       m_file_number = 0;
    std::streamoff                 m_bytes_written = 0;
    uint32_t const                 m_log_file_roll_size_bytes;
    std::string const              m_name;
    std::unique_ptr<std::ofstream> m_os;
};

class NanoLogger {
public:
    NanoLogger(NonGuaranteedLogger ngl, std::string const& log_directory,
               std::string const& log_file_name, uint32_t log_file_roll_size_mb)
        : m_state(State::INIT),
          m_buffer_base(
              new RingBuffer(std::max(1u, ngl.ring_buffer_size_mb) * 1024 * 4)),
          m_file_writer(log_directory, log_file_name,
                        std::max(1u, log_file_roll_size_mb)),
          m_thread(&NanoLogger::pop, this)
    {
        m_state.store(State::READY, std::memory_order_release);
    }

    NanoLogger(GuaranteedLogger /*gl*/, std::string const& log_directory,
               std::string const& log_file_name, uint32_t log_file_roll_size_mb)
        : m_state(State::INIT),
          m_buffer_base(new QueueBuffer()),
          m_file_writer(log_directory, log_file_name,
                        std::max(1u, log_file_roll_size_mb)),
          m_thread(&NanoLogger::pop, this)
    {
        m_state.store(State::READY, std::memory_order_release);
    }

    ~NanoLogger()
    {
        m_state.store(State::SHUTDOWN);
        m_thread.join();
    }

    void add(VDebug&& logline) { m_buffer_base->push(std::move(logline)); }

    void pop()
    {
        // Wait for constructor to complete and pull all stores done there to
        // this thread / core.
        while (m_state.load(std::memory_order_acquire) == State::INIT)
            std::this_thread::sleep_for(std::chrono::microseconds(50));

        VDebug logline(LogLevel::INFO, nullptr, nullptr, 0);

        while (m_state.load() == State::READY) {
            if (m_buffer_base->try_pop(logline))
                m_file_writer.write(logline);
            else
                std::this_thread::sleep_for(std::chrono::microseconds(50));
        }

        // Pop and log all remaining entries
        while (m_buffer_base->try_pop(logline)) {
            m_file_writer.write(logline);
        }
    }

private:
    enum class State { INIT, READY, SHUTDOWN };

    std::atomic<State>          m_state;
    std::unique_ptr<BufferBase> m_buffer_base;
    FileWriter                  m_file_writer;
    std::thread                 m_thread;
};

std::unique_ptr<NanoLogger> nanologger;
std::atomic<NanoLogger*>    atomic_nanologger;

bool VDebugServer::operator==(VDebug& logline)
{
    atomic_nanologger.load(std::memory_order_acquire)->add(std::move(logline));
    return true;
}

void initialize(NonGuaranteedLogger ngl, std::string const& log_directory,
                std::string const& log_file_name,
                uint32_t           log_file_roll_size_mb)
{
    nanologger = std::make_unique<NanoLogger>(ngl, log_directory, log_file_name,
                                              log_file_roll_size_mb);
    atomic_nanologger.store(nanologger.get(), std::memory_order_seq_cst);
}

void initialize(GuaranteedLogger gl, std::string const& log_directory,
                std::string const& log_file_name,
                uint32_t           log_file_roll_size_mb)
{
    nanologger = std::make_unique<NanoLogger>(gl, log_directory, log_file_name,
                                              log_file_roll_size_mb);
    atomic_nanologger.store(nanologger.get(), std::memory_order_seq_cst);
}

std::atomic<unsigned int> loglevel = {0};

void set_log_level(LogLevel level)
{
    loglevel.store(static_cast<unsigned int>(level), std::memory_order_release);
}

bool is_logged(LogLevel level)
{
    return static_cast<unsigned int>(level) >=
           loglevel.load(std::memory_order_relaxed);
}

#endif  // LOTTIE_LOGGING_SUPPORT