trace.hpp

// Copyright 2019 Pokitec
// All rights reserved.
 
#include "TTauri/Foundation/counters.hpp"
#include "TTauri/Foundation/datum.hpp"
#include "TTauri/Foundation/logger.hpp"
#include "TTauri/Foundation/cpu_utc_clock.hpp"
#include "TTauri/Foundation/required.hpp"
#include "TTauri/Foundation/tagged_map.hpp"
#include "TTauri/Foundation/wfree_message_queue.hpp"
#include <fmt/ostream.h>
#include <fmt/format.h>
#include <atomic>
#include <array>
#include <utility>
#include <ostream>
#include <typeinfo>
#include <typeindex>
 
#pragma once
 
namespace tt {
 
constexpr int MAX_NR_TRACES = 1024;
 
 
inline std::atomic<int64_t> trace_id = 0;
 
struct trace_stack_type {
    int64_t top_trace_id = 0;
 
    int8_t depth = 0;
 
    int8_t record_depth = 0;
 
    inline int64_t push() noexcept {
        ttlet parent_id = top_trace_id;
        top_trace_id = trace_id.fetch_add(1, std::memory_order_relaxed) + 1;
        depth++;
        return parent_id;
    }
 
    inline std::pair<int64_t, bool> pop(int64_t parent_id) noexcept {
        bool is_recording = record_depth > --depth;
        if (is_recording) {
            record_depth = depth;
        }
 
        ttlet id = top_trace_id;
        top_trace_id = parent_id;
        return {id, is_recording};
    }
};
 
inline thread_local trace_stack_type trace_stack;
 
void trace_record() noexcept;
 
template<typename Tag, typename... InfoTags>
struct trace_data {
    int64_t parent_id;
 
    typename cpu_counter_clock::time_point timestamp;
 
    tagged_map<sdatum, InfoTags...> info;
 
    trace_data(typename cpu_counter_clock::time_point timestamp) :
        timestamp(timestamp) {}
 
    trace_data() = default;
    ~trace_data() = default;
    trace_data(trace_data const &other) = default;
    trace_data &operator=(trace_data const &other) = default;
    trace_data(trace_data &&other) = default;
    trace_data &operator=(trace_data &&other) = default;
 
    template<typename InfoTag>
    sdatum &get() noexcept {
        return info.template get<InfoTag>();
    }
 
    template<typename InfoTag>
    sdatum const &get() const noexcept {
        return info.template get<InfoTag>();
    }
};
 
template<typename Tag, typename... InfoTags>
std::ostream &operator<<(std::ostream &lhs, trace_data<Tag, InfoTags...> const &rhs) {
    auto info_string = std::string{};
 
    auto counter = 0;
    for (size_t i = 0; i < rhs.info.size(); i++) {
        if (counter++ > 0) {
            info_string += ", ";
        }
        info_string += rhs.info.get_tag(i).name();
        info_string += "=";
        info_string += static_cast<std::string>(rhs.info[i]);
    }
 
    lhs << fmt::format("parent={} tag={} start={} {}",
        rhs.parent_id,
        std::type_index(typeid(Tag)).name(),
        format_iso8601(cpu_utc_clock::convert(rhs.timestamp)),
        info_string
    );
    return lhs;
}
 
class trace_statistics_type {
private:
    std::atomic<int64_t> count = 0;
    std::atomic<typename cpu_counter_clock::rep> duration = 0;
    std::atomic<typename cpu_counter_clock::rep> peak_duration = 0;
    std::atomic<int64_t> version = 0;
 
    // Variables used by logger.
    int64_t prev_count = 0;
    typename cpu_counter_clock::duration prev_duration = {};
 
public:
    bool write(cpu_counter_clock::duration const &d) {
        // In the logging thread we can check if count and version are equal
        // to read the statistics.
        ttlet current_count = count.fetch_add(1, std::memory_order_acquire);
 
        duration.fetch_add(d.count(), std::memory_order_relaxed);
 
        auto prev_peak = peak_duration.load(std::memory_order_relaxed);
        decltype(prev_peak) new_peak;
        do {
            new_peak = d.count() > prev_peak ? d.count() : prev_peak;
        } while (!peak_duration.compare_exchange_weak(prev_peak, new_peak, std::memory_order_relaxed));
 
        version.store(current_count + 1, std::memory_order_release);
        
        return current_count == 0;
    }
 
    struct read_result {
        int64_t count;
        int64_t last_count;
 
        typename cpu_counter_clock::duration duration;
        typename cpu_counter_clock::duration last_duration;
        typename cpu_counter_clock::duration peak_duration;
    };
 
    read_result read() {
        read_result r;
 
        r.peak_duration = {};
        do {
            r.count = count.load(std::memory_order_acquire);
 
            r.duration = decltype(r.duration){duration.load(std::memory_order_relaxed)};
 
            auto tmp = peak_duration.exchange(0, std::memory_order_relaxed);
            if (tmp > r.peak_duration.count()) {
                r.peak_duration = decltype(r.duration){tmp};
            }
 
            std::atomic_thread_fence(std::memory_order_release);
        } while (r.count != version.load(std::memory_order_relaxed));
 
        r.last_count = r.count - prev_count;
        r.last_duration = r.duration - prev_duration;
 
        prev_count = r.count;
        prev_duration = r.duration;
        return r;
    }
};
 
template<typename Tag>
inline trace_statistics_type trace_statistics;
 
inline wfree_unordered_map<std::type_index,trace_statistics_type *,MAX_NR_TRACES> trace_statistics_map;
 
 
template<typename Tag, typename... InfoTags>
class trace final {
    // If this pointer is not an volatile, clang will optimize it away and replacing it
    // with direct access to the trace_stack variable. This trace_stack variable is in local storage,
    // so a lot of instructions and memory accesses are emitted by the compiler multiple times.
    trace_stack_type * volatile stack;
 
    trace_data<Tag, InfoTags...> data;
 
    tt_no_inline static void add_to_map() {
        trace_statistics_map.insert(std::type_index(typeid(Tag)), &trace_statistics<Tag>);
    }
 
public:
    trace() :
        stack(&trace_stack), data(cpu_counter_clock::now())
    {
        // We don't need to know our own id, until the destructor is called.
        // Our id will be at the top of the stack.
        data.parent_id = stack->push();
    }
 
    tt_force_inline ~trace() {
        ttlet end_timestamp = cpu_counter_clock::now();
 
        if(tt_unlikely(trace_statistics<Tag>.write(end_timestamp - data.timestamp))) {
            add_to_map();
        }
 
        ttlet [id, is_recording] = stack->pop(data.parent_id);
 
        // Send the log to the log thread.
        if (tt_unlikely(is_recording)) {
            logger.log<log_level::Trace>(end_timestamp, "id={} {}", id, std::move(data));
        }
    }
 
    trace(trace const &) = delete;
    trace(trace &&) = delete;
    trace &operator=(trace const &) = delete;
    trace &operator=(trace &&) = delete;
 
    template<typename InfoTag, typename T>
    trace &set(T &&value) {
        data.template get<InfoTag>() = std::forward<T>(value);
        return *this;
    }
};
 
 
}