bench.cpp 7.88 KB
Newer Older
gabime's avatar
gabime committed
1 2 3 4
//
// Copyright(c) 2015 Gabi Melman.
// Distributed under the MIT License (http://opensource.org/licenses/MIT)
//
gabime's avatar
gabime committed
5

gabi's avatar
gabi committed
6
//
gabime's avatar
gabime committed
7 8
// bench.cpp : spdlog benchmarks
//
gabime's avatar
gabime committed
9
#include "spdlog/spdlog.h"
10
#include "spdlog/async.h"
gabime's avatar
gabime committed
11
#include "spdlog/sinks/basic_file_sink.h"
gabime's avatar
gabime committed
12
#include "spdlog/sinks/daily_file_sink.h"
gabime's avatar
gabime committed
13
#include "spdlog/sinks/null_sink.h"
gabime's avatar
gabime committed
14
#include "spdlog/sinks/rotating_file_sink.h"
gabime's avatar
gabime committed
15

gabime's avatar
gabime committed
16
#include "utils.h"
17 18
#include <atomic>
#include <cstdlib> // EXIT_FAILURE
gabime's avatar
gabime committed
19 20 21
#include <memory>
#include <string>
#include <thread>
22 23

using namespace std;
gabi's avatar
gabi committed
24
using namespace std::chrono;
25
using namespace spdlog;
gabime's avatar
gabime committed
26
using namespace spdlog::sinks;
gabi's avatar
gabi committed
27 28
using namespace utils;

gabi's avatar
gabi committed
29 30
void bench(int howmany, std::shared_ptr<spdlog::logger> log);
void bench_mt(int howmany, std::shared_ptr<spdlog::logger> log, int thread_count);
31
void bench_default_api(int howmany, std::shared_ptr<spdlog::logger> log);
32
void bench_c_string(int howmany, std::shared_ptr<spdlog::logger> log);
gabi's avatar
gabi committed
33

gabime's avatar
gabime committed
34
int main(int argc, char *argv[])
gabi's avatar
gabi committed
35
{
gabi's avatar
gabi committed
36

gabime's avatar
gabime committed
37
    spdlog::default_logger()->set_pattern("[%^%l%$] %v");
Gabi Melman's avatar
Gabi Melman committed
38
    int howmany = 1000000;
39
    int queue_size = 8192;
40
    int threads = 10;
41 42
    size_t file_size = 30 * 1024 * 1024;
    size_t rotating_files = 5;
gabime's avatar
gabime committed
43 44 45 46

    try
    {

gabime's avatar
gabime committed
47
        if (argc > 1)
gabime's avatar
gabime committed
48 49
            howmany = atoi(argv[1]);
        if (argc > 2)
gabime's avatar
gabime committed
50
            threads = atoi(argv[2]);
51 52
        if (argc > 3)
            queue_size = atoi(argv[3]);
gabime's avatar
gabime committed
53

gabime's avatar
gabime committed
54 55 56 57
        spdlog::info("**************************************************************");
        spdlog::info("Single thread, {:n} iterations", howmany);
        spdlog::info("**************************************************************");

58
        auto basic_st = spdlog::basic_logger_st("basic_st", "logs/basic_st.log", true);
59
        bench(howmany, std::move(basic_st));
60

61
        basic_st.reset();
Gabi Melman's avatar
Gabi Melman committed
62
        auto rotating_st = spdlog::rotating_logger_st("rotating_st", "logs/rotating_st.log", file_size, rotating_files);
63
        bench(howmany, std::move(rotating_st));
64

65
        auto daily_st = spdlog::daily_logger_st("daily_st", "logs/daily_st.log");
66
        bench(howmany, std::move(daily_st));
gabime's avatar
gabime committed
67

gabime's avatar
gabime committed
68
        bench(howmany, std::make_shared<spdlog::logger>("empty_logger"));
gabime's avatar
gabime committed
69

70
        spdlog::info("**************************************************************");
gabime's avatar
gabime committed
71
        spdlog::info("C-string (400 bytes). Single thread, {:n} iterations", howmany);
72 73 74 75 76 77 78 79 80 81 82 83 84
        spdlog::info("**************************************************************");

        basic_st = spdlog::basic_logger_st("basic_st", "logs/basic_cs.log", true);
        bench_c_string(howmany, std::move(basic_st));

        rotating_st = spdlog::rotating_logger_st("rotating_st", "logs/rotating_cs.log", file_size, rotating_files);
        bench_c_string(howmany, std::move(rotating_st));

        daily_st = spdlog::daily_logger_st("daily_st", "logs/daily_cs.log");
        bench_c_string(howmany, std::move(daily_st));

        bench_c_string(howmany, spdlog::create<null_sink_st>("null_st"));

gabime's avatar
gabime committed
85 86 87
        spdlog::info("**************************************************************");
        spdlog::info("{:n} threads sharing same logger, {:n} iterations", threads, howmany);
        spdlog::info("**************************************************************");
gabime's avatar
gabime committed
88

gabime's avatar
gabime committed
89
        auto basic_mt = spdlog::basic_logger_mt("basic_mt", "logs/basic_mt.log", true);
90
        bench_mt(howmany, std::move(basic_mt), threads);
gabime's avatar
gabime committed
91

92
        auto rotating_mt = spdlog::rotating_logger_mt("rotating_mt", "logs/rotating_mt.log", file_size, rotating_files);
93
        bench_mt(howmany, std::move(rotating_mt), threads);
gabime's avatar
gabime committed
94

95
        auto daily_mt = spdlog::daily_logger_mt("daily_mt", "logs/daily_mt.log");
96
        bench_mt(howmany, std::move(daily_mt), threads);
gabime's avatar
gabime committed
97
        bench_mt(howmany, spdlog::create<null_sink_mt>("null_mt"), threads);
98

99
        int iters = 3;
gabime's avatar
gabime committed
100
        spdlog::info("**************************************************************");
101 102 103 104
        spdlog::info("Asyncronous bench {:n} threads sharing same logger", threads);
        spdlog::info("Messages: {:n}", howmany);
        spdlog::info("Queue size: {:n} slots", queue_size);
        auto slot_size = sizeof(spdlog::details::async_msg);
gabime's avatar
gabime committed
105
        spdlog::info("Total queue memory: {}x{} bytes per slot = {:n} Kb ", queue_size, slot_size, (queue_size * slot_size) / 1024);
gabime's avatar
gabime committed
106
        spdlog::info("**************************************************************");
gabime's avatar
gabime committed
107

108
        for (int i = 0; i < iters; ++i)
gabime's avatar
gabime committed
109
        {
110
            spdlog::init_thread_pool(static_cast<size_t>(queue_size), 1);
gabime's avatar
gabime committed
111
            auto as = spdlog::basic_logger_mt<spdlog::async_factory>("async", "logs/basic_async.log", true);
112
            bench_mt(howmany, std::move(as), threads);
gabime's avatar
gabime committed
113 114 115 116
        }
    }
    catch (std::exception &ex)
    {
gabime's avatar
gabime committed
117
        spdlog::error(ex.what());
118
        return EXIT_FAILURE;
gabime's avatar
gabime committed
119
    }
120
    return EXIT_SUCCESS;
gabi's avatar
gabi committed
121 122
}

gabi's avatar
gabi committed
123 124
void bench(int howmany, std::shared_ptr<spdlog::logger> log)
{
gabime's avatar
gabime committed
125 126
    using std::chrono::high_resolution_clock;
    auto start = high_resolution_clock::now();
gabime's avatar
gabime committed
127 128
    for (auto i = 0; i < howmany; ++i)
    {
Gabi Melman's avatar
Gabi Melman committed
129
        log->info("Hello logger: msg number {}", i);
gabime's avatar
gabime committed
130
    }
gabi's avatar
gabi committed
131

gabime's avatar
gabime committed
132
    auto delta = high_resolution_clock::now() - start;
gabime's avatar
gabime committed
133
    auto delta_d = duration_cast<duration<double>>(delta).count();
134

gabime's avatar
gabime committed
135 136
    spdlog::info("{:<16} Elapsed: {:0.2f} secs {:>16n}/sec", log->name(), delta_d, int(howmany / delta_d));
    spdlog::drop(log->name());
gabi's avatar
gabi committed
137 138 139 140
}

void bench_mt(int howmany, std::shared_ptr<spdlog::logger> log, int thread_count)
{
gabime's avatar
gabime committed
141
    using std::chrono::high_resolution_clock;
gabime's avatar
gabime committed
142
    vector<thread> threads;
gabime's avatar
gabime committed
143
    auto start = high_resolution_clock::now();
gabime's avatar
gabime committed
144 145
    for (int t = 0; t < thread_count; ++t)
    {
gabime's avatar
gabime committed
146
        threads.push_back(std::thread([&]() {
gabime's avatar
gabime committed
147
            for (int j = 0; j < howmany / thread_count; j++)
gabime's avatar
gabime committed
148
            {
gabime's avatar
gabime committed
149
                log->info("Hello logger: msg number {}", j);
gabime's avatar
gabime committed
150 151 152 153
            }
        }));
    }

gabime's avatar
gabime committed
154
    for (auto &t : threads)
gabime's avatar
gabime committed
155 156 157 158
    {
        t.join();
    };

gabime's avatar
gabime committed
159
    auto delta = high_resolution_clock::now() - start;
gabime's avatar
gabime committed
160
    auto delta_d = duration_cast<duration<double>>(delta).count();
gabime's avatar
gabime committed
161 162
    spdlog::info("{:<16} Elapsed: {:0.2f} secs {:>16n}/sec", log->name(), delta_d, int(howmany / delta_d));
    spdlog::drop(log->name());
163 164 165 166 167
}

void bench_default_api(int howmany, std::shared_ptr<spdlog::logger> log)
{
    using std::chrono::high_resolution_clock;
gabime's avatar
gabime committed
168
    auto orig_default = spdlog::default_logger();
169 170 171 172 173 174 175 176 177
    spdlog::set_default_logger(log);
    auto start = high_resolution_clock::now();
    for (auto i = 0; i < howmany; ++i)
    {
        spdlog::info("Hello logger: msg number {}", i);
    }

    auto delta = high_resolution_clock::now() - start;
    auto delta_d = duration_cast<duration<double>>(delta).count();
gabime's avatar
gabime committed
178 179 180
    spdlog::drop(log->name());
    spdlog::set_default_logger(std::move(orig_default));
    spdlog::info("{:<16} Elapsed: {:0.2f} secs {:>16n}/sec", log->name(), delta_d, int(howmany / delta_d));
gabi's avatar
gabi committed
181
}
182 183 184

void bench_c_string(int howmany, std::shared_ptr<spdlog::logger> log)
{
gabime's avatar
gabime committed
185 186 187 188 189
    const char *msg = "Lorem ipsum dolor sit amet, consectetur adipiscing elit. Vestibulum pharetra metus cursus "
                      "lacus placerat congue. Nulla egestas, mauris a tincidunt tempus, enim lectus volutpat mi, eu consequat sem "
                      "libero nec massa. In dapibus ipsum a diam rhoncus gravida. Etiam non dapibus eros. Donec fringilla dui sed "
                      "augue pretium, nec scelerisque est maximus. Nullam convallis, sem nec blandit maximus, nisi turpis ornare "
                      "nisl, sit amet volutpat neque massa eu odio. Maecenas malesuada quam ex, posuere congue nibh turpis duis.";
190 191 192 193 194 195 196 197 198 199 200 201 202 203 204
    using std::chrono::high_resolution_clock;
    auto orig_default = spdlog::default_logger();
    spdlog::set_default_logger(log);
    auto start = high_resolution_clock::now();
    for (auto i = 0; i < howmany; ++i)
    {
        spdlog::log(level::info, msg);
    }

    auto delta = high_resolution_clock::now() - start;
    auto delta_d = duration_cast<duration<double>>(delta).count();
    spdlog::drop(log->name());
    spdlog::set_default_logger(std::move(orig_default));
    spdlog::info("{:<16} Elapsed: {:0.2f} secs {:>16n}/sec", log->name(), delta_d, int(howmany / delta_d));
}