2
\$\begingroup\$

I am developing (for fun) a Utilities & Logging library

Can someone please help me to improve: Github link

Pros

  • Thread-safe, no mutex. Use lock-free ring buffer (the idea is inherited from FreeBSD lock-free queue: extremely reliable and fast)
  • Support multiple file descriptors
  • Only 2 or 1 header files
  • printf style (user-defined log format)

Cons

  • Please help to figure-out

logger.h

#pragma once

#include <fstream>
#include <vector>
#include <mutex>
#include <chrono>
#include <thread>
#include <sstream>
#include <string>
#include <unordered_set>

#include <cstdarg>
#include <iomanip>

#include <netinet/in.h>
#include <unistd.h> // close
#include <sys/socket.h>
#include <sys/un.h>
#include <functional>
#include "utils.h"

#include <omp.h>

#ifndef STATIC_LIB
#define TLL_INLINE
#else
#define TLL_INLINE inline
#endif


namespace tll {

typedef uint32_t LogType;

namespace logtype { /// logtype
static const LogType kDebug=(1U << 0);
static const LogType kTrace=(1U << 1);
static const LogType kInfo=(1U << 2);
static const LogType kFatal=(1U << 3);
}

typedef std::pair<LogType, std::string> LogInfo;
typedef std::pair<LogType, int> LogFd;

template <size_t const kLogSize, uint32_t max_log_in_queue, uint32_t const kDelayMicro>
class Logger
{
public:
    template < typename ... LFds>
    Logger(LFds ...lfds) : ring_queue_(max_log_in_queue), is_running_(false)
    {
        addFd__(lfds...);
    }

    ~Logger() 
    {
        is_running_.store(false, std::memory_order_relaxed);
        if(broadcast_.joinable()) broadcast_.join();
        for(auto lfd : lfds_)
        {
            close(lfd.second);
        }
    }

    template <LogType type, typename... Args>
    void log(const char *format, Args &&...args)
    {
        ring_queue_.push([](LogInfo &elem, uint32_t size, LogInfo &&log_msg)
        {
            elem = std::move(log_msg);
        }, LogInfo{type, utils::Format(kLogSize, format, std::forward<Args>(args)...)});

        if(!is_running_.load(std::memory_order_relaxed)) start();
    }

    TLL_INLINE void start()
    {
        bool val = false;
        if(!is_running_.compare_exchange_strong(val, true, std::memory_order_relaxed)) return;

        broadcast_ = std::thread([this]()
        {
            while(is_running_.load(std::memory_order_relaxed))
            {
                if(ring_queue_.empty())
                {
                    std::this_thread::sleep_for(std::chrono::microseconds(kDelayMicro));
                    continue;
                }

                LogInfo log_message;
                ring_queue_.pop([&log_message](LogInfo &elem, uint32_t)
                {
                    log_message = std::move(elem);
                });

                // FIXME: parallel is 10 times slower???
                // #pragma omp parallel for
                for(int i=0; i<lfds_.size(); i++)
                {
                    LogFd &lfd = lfds_[i];
                    if(lfd.first & log_message.first)
                    {
                        auto size = write(lfd.second, log_message.second.data(), log_message.second.size());
                    }
                }
            }
        });
    }

    TLL_INLINE void join()
    {
        while(is_running_.load(std::memory_order_relaxed) && !ring_queue_.empty())
            std::this_thread::sleep_for(std::chrono::microseconds(kDelayMicro));
    }

    template < typename ... LFds>
    void addFd(LFds ...lfds)
    {
        if(is_running_.load(std::memory_order_relaxed)) return;
        addFd__(lfds...);
    }

private:
    template <typename ... LFds>
    void addFd__(LogFd lfd, LFds ...lfds)
    {
        lfds_.push_back(lfd);
        addFd__(lfds...);
    }

    TLL_INLINE void addFd__(LogFd lfd)
    {
        lfds_.push_back(lfd);
    }

    utils::BSDLFQ<LogInfo> ring_queue_;
    std::atomic<bool> is_running_;
    std::thread broadcast_;
    std::vector<LogFd> lfds_;
};

} // llt

#define LOG_HEADER__ utils::Format("(%.6f)%s:%s:%d[%s]", utils::timestamp<double>(), __FILE__, __FUNCTION__, __LINE__, utils::tid())

#define TLL_LOGD(logger, format, ...) (logger).log<tll::logtype::kDebug>("[D]%s(" format ")\n", LOG_HEADER__ , ##__VA_ARGS__)

#define TLL_LOGTF(logger) (logger).log<tll::logtype::kTrace>("[T]%s", LOG_HEADER__); utils::Timer timer__([&logger](std::string const &str){logger.log<tll::logtype::kTrace>("%s", str.data());}, __FUNCTION__)

#define TLL_LOGT(logger, ID) (logger).log<tll::logtype::kTrace>("[T]%s", LOG_HEADER__); utils::Timer timer_##ID__([&logger](std::string const &str){logger.log<tll::logtype::kTrace>("%s", str.data());}, #ID)

#define TLL_LOGI(logger, format, ...) (logger).log<tll::logtype::kInfo>("[I]%s(" format ")\n", LOG_HEADER__ , ##__VA_ARGS__)

#define TLL_LOGF(logger, format, ...) (logger).log<tll::logtype::kFatal>("[F]%s(" format ")\n", LOG_HEADER__ , ##__VA_ARGS__)

utils.h

#pragma once

#include <vector>
#include <chrono>
#include <thread>
#include <unordered_map>
#include <string>
#include <sstream>
#include <atomic>
#include <cstring>

#include "SimpleSignal.hpp"

#define LOGPD(format, ...) printf("[D](%.6f)%s:%s:%d[%s]:" format "\n", utils::timestamp<double>(), __FILE__, __PRETTY_FUNCTION__, __LINE__, utils::tid().data(), ##__VA_ARGS__)
#define LOGD(format, ...) printf("[D](%.6f)%s:%s:%d[%s]:" format "\n", utils::timestamp<double>(), __FILE__, __FUNCTION__, __LINE__, utils::tid().data(), ##__VA_ARGS__)
#define LOGE(format, ...) printf("[E](%.6f)%s:%s:%d[%s]:" format "%s\n", utils::timestamp<double>(), __FILE__, __FUNCTION__, __LINE__, utils::tid().data(), ##__VA_ARGS__, strerror(errno))

#define TIMER(ID) utils::Timer __timer_##ID(#ID)
#define TRACE() utils::Timer __tracer(std::string(__FUNCTION__) + ":" + std::to_string(__LINE__) + "(" + utils::tid() + ")")


namespace utils {

/// format
template <typename T>
T Argument(T value) noexcept
{
    return value;
}

template <typename T>
T const * Argument(std::basic_string<T> const & value) noexcept
{
    return value.data();
}

template <typename ... Args>
int StringPrint(char * const buffer,
                size_t const bufferCount,
                char const * const format,
                Args const & ... args) noexcept
{
    int const result = snprintf(buffer,
                              bufferCount,
                              format,
                              Argument(args) ...);
    // assert(-1 != result);
    return result;
}

template <typename ... Args>
int StringPrint(wchar_t * const buffer,
                size_t const bufferCount,
                wchar_t const * const format,
                Args const & ... args) noexcept
{
    int const result = swprintf(buffer,
                              bufferCount,
                              format,
                              Argument(args) ...);
    // assert(-1 != result);
    return result;
}

template <typename T, typename ... Args>
std::basic_string<T> Format(
            size_t size,
            T const * const format,
            Args const & ... args)
{
    std::basic_string<T> buffer;
    buffer.resize(size);
    int len = StringPrint(&buffer[0], buffer.size(), format, args ...);
    buffer.resize(len);
    return buffer;
}

template <typename T, typename ... Args>
std::basic_string<T> Format(
            T const * const format,
            Args const & ... args)
{
    std::basic_string<T> buffer;
    // size_t const size = 0x100;
    size_t const size = StringPrint(&buffer[0], 0, format, args ...);
    if (size > 0)
    {
        buffer.resize(size + 1); /// extra for null
        StringPrint(&buffer[0], buffer.size(), format, args ...);
    }

    return buffer;
}

inline uint32_t nextPowerOf2(uint32_t val)
{
    val--;
    val |= val >> 1;
    val |= val >> 2;
    val |= val >> 4;
    val |= val >> 8;
    val |= val >> 16;
    val++;
    return val;
}

inline bool powerOf2(uint32_t val)
{
    return (val & (val - 1)) == 0;
}

template <typename T, size_t const kELemSize=sizeof(T)>
class BSDLFQ
{
public:
    BSDLFQ(uint32_t num_of_elem) : prod_tail_(0), prod_head_(0), cons_tail_(0), cons_head_(0)
    {
        capacity_ = powerOf2(num_of_elem) ? num_of_elem : nextPowerOf2(num_of_elem);
        buffer_.resize(capacity_ * kELemSize);
    }

    template <typename F, typename ...Args>
    void pop(F &&doPop, Args &&...elems)
    {
        uint32_t cons_head = cons_head_.load(std::memory_order_relaxed);
        for(;;)
        {
            if (cons_head == prod_tail_.load(std::memory_order_relaxed))
                continue;

            if(cons_head_.compare_exchange_weak(cons_head, cons_head + 1, std::memory_order_acquire, std::memory_order_relaxed))
                break;
        }
        std::forward<F>(doPop)(elemAt(cons_head), kELemSize, std::forward<Args>(elems)...);
        while (cons_tail_.load(std::memory_order_relaxed) != cons_head);

        cons_tail_.fetch_add(1, std::memory_order_release);
    }

    template <typename F, typename ...Args>
    void push(F &&doPush, Args&&...elems)
    {
        uint32_t prod_head = prod_head_.load(std::memory_order_relaxed);
        for(;;)
        {
            if (prod_head == (cons_tail_.load(std::memory_order_relaxed) + capacity_))
                continue;

            if(prod_head_.compare_exchange_weak(prod_head, prod_head + 1, std::memory_order_acquire, std::memory_order_relaxed))
                break;
        }
        std::forward<F>(doPush)(elemAt(prod_head), kELemSize, std::forward<Args>(elems)...);
        while (prod_tail_.load(std::memory_order_relaxed) != prod_head);

        prod_tail_.fetch_add(1, std::memory_order_release);
    }

    inline bool tryPop(uint32_t &cons_head)
    {
        cons_head = cons_head_.load(std::memory_order_relaxed);

        for(;;)
        {
            if (cons_head == prod_tail_.load(std::memory_order_relaxed))
                return false;

            if(cons_head_.compare_exchange_weak(cons_head, cons_head + 1, std::memory_order_acquire, std::memory_order_relaxed))
                return true;
        }

        return false;
    }

    inline bool completePop(uint32_t cons_head)
    {
        while (cons_tail_.load(std::memory_order_relaxed) != cons_head);

        cons_tail_.fetch_add(1, std::memory_order_release);
        return true;
    }

    inline bool tryPush(uint32_t &prod_head)
    {
        prod_head = prod_head_.load(std::memory_order_relaxed);

        for(;;)
        {
            if (prod_head == (cons_tail_.load(std::memory_order_relaxed) + capacity_))
                return false;

            if(prod_head_.compare_exchange_weak(prod_head, prod_head + 1, std::memory_order_acquire, std::memory_order_relaxed))
                return true;
        }
        return false;
    }

    inline bool completePush(uint32_t prod_head)
    {
        while (prod_tail_.load(std::memory_order_relaxed) != prod_head);

        prod_tail_.fetch_add(1, std::memory_order_release);
        return true;
    }

    inline bool empty() const { return size() == 0; }

    inline uint32_t size() const
    {
        return prod_tail_.load(std::memory_order_relaxed) - cons_tail_.load(std::memory_order_relaxed);
    }

    inline uint32_t wrap(uint32_t index) const
    {
        return index & (capacity_ - 1);
    }

    inline uint32_t capacity() const { return capacity_; }

    inline T &elemAt(uint32_t index)
    {
        return buffer_[kELemSize * wrap(index)];
    }

    inline T const &elemAt(uint32_t index) const
    {
        return buffer_[kELemSize * wrap(index)];
    }

    inline size_t elemSize() const
    {
        return kELemSize;
    }

private:

    std::atomic<uint32_t> prod_tail_, prod_head_, cons_tail_, cons_head_;
    uint32_t capacity_;
    std::vector<T> buffer_;
};


inline std::string tid()
{
    std::stringstream ss;
    ss << std::this_thread::get_id();
    return ss.str();
}

template <typename T=size_t, typename D=std::ratio<1,1>, typename C=std::chrono::high_resolution_clock>
T timestamp(typename C::time_point &&t = C::now())
{
    return std::chrono::duration_cast<std::chrono::duration<T,D>>(std::forward<typename C::time_point>(t).time_since_epoch()).count();
}

struct Timer
{
    using clock__= std::chrono::high_resolution_clock;

    Timer() : name_(""), begin_(clock__::now()) {}
    Timer(std::string id) : name_(std::move(id)), begin_(clock__::now()) 
    {
        printf(" (%.6f)%s\n", utils::timestamp<double>(), name_.data());
    }

    Timer(std::function<void(std::string const&)> logf, std::string id="") : name_(std::move(id)), begin_(clock__::now()) 
    {
        sig_log_.connect(logf);
        sig_log_.emit(Format("(%s)\n", utils::timestamp<double>(), name_.data()));
    }

    ~Timer()
    {
        if(sig_log_)
            sig_log_.emit(Format("   (%.6f)[%s](~%s) %.3f (ms)\n", utils::timestamp<double>(), utils::tid(), name_.data(), elapse<double,std::milli>()));
        else if(!name_.empty())
            printf(" (%.6f)~%s: %.3f (ms)\n", utils::timestamp<double>(), name_.data(), elapse<double,std::milli>());
    }

    template <typename T=double, typename D=std::milli>
    T reset()
    {
        T ret = elapse<T,D>();
        begin_ = clock__::now();
        return ret;
    }

    template <typename T=double, typename D=std::milli>
    T elapse() const
    {
        using namespace std::chrono;
        return duration_cast<std::chrono::duration<T,D>>(clock__::now() - begin_).count();
    }

    template <typename T=double, typename D=std::milli>
    std::chrono::duration<T,D> duration() const
    {
        using namespace std::chrono;
        auto ret = duration_cast<std::chrono::duration<T,D>>(clock__::now() - begin_);
        return ret;
    }

    clock__::time_point begin_;
    std::string name_;

    Simple::Signal<void(std::string const&)> sig_log_;
};

} /// utils

logtest.cc

#include <fstream>
#include <iostream>
#include <fcntl.h>    /* For O_RDWR */
#include <unistd.h>   /* For open(), creat() */

#include "../libs/SimpleSignal.hpp"
#include "../libs/utils.h"
#include "../libs/logger.h"
// #include "../libs/exporterudp.h"



namespace {
    int const fd_terminal = 0;
}

int main(int argc, char const *argv[])
{
    tll::Logger<0x400, 0x1000, 5> lg
        (
            tll::LogFd{tll::logtype::kDebug | tll::logtype::kInfo | tll::logtype::kFatal, fd_terminal},
            tll::LogFd{tll::logtype::kTrace | tll::logtype::kDebug, open("fd_t.log", O_WRONLY | O_TRUNC | O_CREAT , 0644)},
            tll::LogFd{tll::logtype::kInfo, open("fd_i.log", O_WRONLY | O_TRUNC | O_CREAT , 0644)},
            tll::LogFd{tll::logtype::kFatal, open("fd_f.log", O_WRONLY | O_TRUNC | O_CREAT , 0644)}
        );

    TLL_LOGTF(lg);
    if(argc == 2)
    {
        TIMER(logger);

        for(int i=0; i<std::stoi(argv[1]); i++)
        {
            TLL_LOGD(lg, "%d %s", 10, "oi troi oi");
            TLL_LOGT(lg, loop);
            TLL_LOGI(lg, "%d %s", 10, "oi troi oi");
            TLL_LOGF(lg, "%d %s", 10, "oi troi oi");
        }
        lg.join();
    }
    else
    {
        TIMER(rawlog);
        for(int i=0; i<std::stoi(argv[1]); i++)
            printf("[%d]%ld:%s:%s:%d[%s](%d %s)\n", (int)tll::logtype::kInfo, utils::timestamp(), __FILE__, __FUNCTION__, __LINE__, utils::tid().data(), 10, "oi troi oi");
    }

    return 0;
}

Command-line to compile

cd util/tests; g++ logtest.cc -std=c++11 -lpthread -fopenmp -O3 && ./a.out 100

Any advice would be valuable for me

Thanks in advance

\$\endgroup\$
2
\$\begingroup\$

The following are only a few quick notes on the C++ language usage from a first reading. I didn't have enough time to fully get through the whole code (might revisit later) and make suggestions on the overall design. I hope this is still considered an ok answer:


TTL_INLINE is pointless. It is used only on declarations of member functions which are defined in the class itself. Member functions defined in a class are inline automatically. Especially in a (class) template definition there is no point to inline at all, because being a template already imparts the same semantics as inline does.


static const LogType kDebug=(1U << 0);

It doesn't matter so much for variables of integral type, but if you want to declare a compile-time constant it is advisable to always declare it constexpr. This guarantees that the variable is indeed a compile-time constant (and you will get an error message if it isn't.

static is pointless for global const (or constexpr) variables, because they have internal linkage in C++ anyway (but not in C!).

So, better:

constexpr LogType kDebug=(1U << 0);

Similarly there is no point in having the unnamed namespace in

namespace {
    int const fd_terminal = 0;
}

template <size_t const kLogSize, uint32_t max_log_in_queue, uint32_t const kDelayMicro>

const-qualifying a template parameter is pointless. They cannot be modified anyway.


addFd__, LOG_HEADER__, clock__, timer__: Identifiers containing a double underscore in any place are reserved for the C++ compiler/standard library in all contexts.

You are not allowed to define them as macro or declare them in any way. Doing so causes the program to technically have undefined behavior and will definitively get you in trouble if the compiler/standard library actually uses one of the reserved names.

Note that the same is true for identifiers starting with a single underscore followed by an upper case letter. Identifiers starting with a single underscore are always reserved in the global scope.

Use a different naming scheme instead.


Your Logger class has a custom destructor, but you are not defining a copy constructor and copy assignment operator. This is by itself is a violation of the rule of 0/3/5. Violating this rule in most cases causes undefined behavior when the copies of objects of the class are made.

However, in your particular case the class is non-copyable because it contains a non-copyable type (std::thread) and is also non-movable because of the user-declared destructor. Therefore you won't be able to copy class objects anyway.

You might still want to be explicit about it though and delete the copy operations:

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

The Timer class has a similar issue.


template <typename T>
T Argument(T value) noexcept
{
    return value;
}

This seems dangerous, because there is no guarantee that the copy constructors involved in this are actually noexcept. Instead you can simply pass-on the a reference:

template <typename T>
const T& Argument(const T& value) noexcept
{
    return value;
}

which is guaranteed to not throw and also never requires copy constructor calls.

However StringPrint itself also has the same problem. It is however only a symptom of the much larger issue that you are not checking the types passed to your logger functions at all. In reality you should only accept types matching the format specification. Everything else will, silently, lead to undefined behavior.

In general, I'd suggest not using the C IO library which fundamentally has this type-safety problem. Instead have a look at e.g. the fmt library, which also inspires the upcoming C++20 std::format.


(This one might be a bit pedantic, I think it is not a problem in practice.)

uint32_t, size_t, snprintf and all the other C type aliases and functions are not guaranteed to be introduced into the global namespace when you include the <c...> header versions.

From what I can tell the POSIX header unistd.h guarantees that size_t and all the symbols from stdio.h are introduced in the global namespace and the POSIX header netinet/in.h guarantees that uint32_t is introduced, but you might want to just always prefix std:: (or add a using declaration), just to be sure.

| improve this answer | |
\$\endgroup\$
  • \$\begingroup\$ Thank you to pointed out, all your comments are correct. They are caused by copy-pasted mistake. I will clean them in later commits. But how about the design architecture, any points to make it easier to be used or re-used? How about performance, any idea to make it faster? \$\endgroup\$ – LongLT Mar 12 at 15:30
  • \$\begingroup\$ BTW, I am very interested in (proud of) my BSDLFQ (lol!) \$\endgroup\$ – LongLT Mar 12 at 15:36
  • \$\begingroup\$ Thanks about "Identifiers containing a double underscore in any place are reserved for the C++ compiler/standard library in all contexts." I saw stdlib usually uses __<previx>, so I decided to use <posfix>__ instead. Seems better to avoid __ in any situation \$\endgroup\$ – LongLT Mar 12 at 20:08
1
\$\begingroup\$

Not that it is important, but pop and push both use unbounded loops to wait for other operations to finish. So strictly speaking your queue implementation is not lock-free. This can be a performance problem in case of oversubscription (i.e., when you use more threads than you have cores).

However, with regards to performance improvements you should first run some profiling tests. If you come back with some results where most of the time is spent, we might be able to give a few pointers.

| improve this answer | |
\$\endgroup\$

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.