Coverage Report

Created: 2026-07-08 14:14

next uncovered line (L), next uncovered region (R), next uncovered branch (B)
/tmp/bitcoin/src/logging/timer.h
Line
Count
Source
1
// Copyright (c) 2009-2010 Satoshi Nakamoto
2
// Copyright (c) 2009-present The Bitcoin Core developers
3
// Distributed under the MIT software license, see the accompanying
4
// file COPYING or http://www.opensource.org/licenses/mit-license.php.
5
6
#ifndef BITCOIN_LOGGING_TIMER_H
7
#define BITCOIN_LOGGING_TIMER_H
8
9
#include <util/log.h>
10
#include <util/macros.h>
11
#include <util/time.h>
12
#include <util/types.h>
13
14
#include <chrono>
15
#include <optional>
16
#include <string>
17
18
19
namespace BCLog {
20
21
//! RAII-style object that outputs timing information to logs.
22
template <typename TimeType>
23
class Timer
24
{
25
public:
26
    //! If log_category is left as the default, end_msg will log unconditionally
27
    //! (instead of being filtered by category).
28
    Timer(
29
        std::string prefix,
30
        std::string end_msg,
31
        BCLog::LogFlags log_category = BCLog::LogFlags::ALL,
32
        bool msg_on_completion = true)
33
1.08M
        : m_prefix(std::move(prefix)),
34
1.08M
          m_title(std::move(end_msg)),
35
1.08M
          m_log_category(log_category),
36
1.08M
          m_message_on_completion(msg_on_completion)
37
1.08M
    {
38
1.08M
        this->Log(strprintf("%s started", m_title));
39
1.08M
        m_start_t = std::chrono::steady_clock::now();
40
1.08M
    }
BCLog::Timer<std::chrono::duration<long, std::ratio<1l, 1000000l>>>::Timer(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char>>, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char>>, BCLog::LogFlags, bool)
Line
Count
Source
33
1.07M
        : m_prefix(std::move(prefix)),
34
1.07M
          m_title(std::move(end_msg)),
35
1.07M
          m_log_category(log_category),
36
1.07M
          m_message_on_completion(msg_on_completion)
37
1.07M
    {
38
1.07M
        this->Log(strprintf("%s started", m_title));
39
1.07M
        m_start_t = std::chrono::steady_clock::now();
40
1.07M
    }
BCLog::Timer<std::chrono::duration<long, std::ratio<1l, 1l>>>::Timer(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char>>, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char>>, BCLog::LogFlags, bool)
Line
Count
Source
33
78
        : m_prefix(std::move(prefix)),
34
78
          m_title(std::move(end_msg)),
35
78
          m_log_category(log_category),
36
78
          m_message_on_completion(msg_on_completion)
37
78
    {
38
78
        this->Log(strprintf("%s started", m_title));
39
78
        m_start_t = std::chrono::steady_clock::now();
40
78
    }
BCLog::Timer<std::chrono::duration<long, std::ratio<1l, 1000l>>>::Timer(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char>>, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char>>, BCLog::LogFlags, bool)
Line
Count
Source
33
11.7k
        : m_prefix(std::move(prefix)),
34
11.7k
          m_title(std::move(end_msg)),
35
11.7k
          m_log_category(log_category),
36
11.7k
          m_message_on_completion(msg_on_completion)
37
11.7k
    {
38
11.7k
        this->Log(strprintf("%s started", m_title));
39
11.7k
        m_start_t = std::chrono::steady_clock::now();
40
11.7k
    }
41
42
    ~Timer()
43
1.08M
    {
44
1.08M
        if (m_message_on_completion) {
45
1.08M
            this->Log(strprintf("%s completed", m_title));
46
1.08M
        } else {
47
942
            this->Log("completed");
48
942
        }
49
1.08M
    }
BCLog::Timer<std::chrono::duration<long, std::ratio<1l, 1000000l>>>::~Timer()
Line
Count
Source
43
1.07M
    {
44
1.07M
        if (m_message_on_completion) {
45
1.07M
            this->Log(strprintf("%s completed", m_title));
46
1.07M
        } else {
47
0
            this->Log("completed");
48
0
        }
49
1.07M
    }
BCLog::Timer<std::chrono::duration<long, std::ratio<1l, 1l>>>::~Timer()
Line
Count
Source
43
78
    {
44
78
        if (m_message_on_completion) {
45
78
            this->Log(strprintf("%s completed", m_title));
46
78
        } else {
47
0
            this->Log("completed");
48
0
        }
49
78
    }
BCLog::Timer<std::chrono::duration<long, std::ratio<1l, 1000l>>>::~Timer()
Line
Count
Source
43
11.7k
    {
44
11.7k
        if (m_message_on_completion) {
45
10.7k
            this->Log(strprintf("%s completed", m_title));
46
10.7k
        } else {
47
942
            this->Log("completed");
48
942
        }
49
11.7k
    }
50
51
    void Log(const std::string& msg)
52
2.17M
    {
53
2.17M
        const std::string full_msg = this->LogMsg(msg);
54
55
2.17M
        if (m_log_category == BCLog::LogFlags::ALL) {
56
202
            LogInfo("%s\n", full_msg);
57
2.17M
        } else {
58
2.17M
            LogDebug(m_log_category, "%s\n", full_msg);
59
2.17M
        }
60
2.17M
    }
BCLog::Timer<std::chrono::duration<long, std::ratio<1l, 1000000l>>>::Log(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char>> const&)
Line
Count
Source
52
2.15M
    {
53
2.15M
        const std::string full_msg = this->LogMsg(msg);
54
55
2.15M
        if (m_log_category == BCLog::LogFlags::ALL) {
56
2
            LogInfo("%s\n", full_msg);
57
2.15M
        } else {
58
2.15M
            LogDebug(m_log_category, "%s\n", full_msg);
59
2.15M
        }
60
2.15M
    }
BCLog::Timer<std::chrono::duration<long, std::ratio<1l, 1l>>>::Log(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char>> const&)
Line
Count
Source
52
156
    {
53
156
        const std::string full_msg = this->LogMsg(msg);
54
55
156
        if (m_log_category == BCLog::LogFlags::ALL) {
56
156
            LogInfo("%s\n", full_msg);
57
156
        } else {
58
0
            LogDebug(m_log_category, "%s\n", full_msg);
59
0
        }
60
156
    }
BCLog::Timer<std::chrono::duration<long, std::ratio<1l, 1000l>>>::Log(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char>> const&)
Line
Count
Source
52
23.4k
    {
53
23.4k
        const std::string full_msg = this->LogMsg(msg);
54
55
23.4k
        if (m_log_category == BCLog::LogFlags::ALL) {
56
44
            LogInfo("%s\n", full_msg);
57
23.3k
        } else {
58
23.3k
            LogDebug(m_log_category, "%s\n", full_msg);
59
23.3k
        }
60
23.4k
    }
61
62
    std::string LogMsg(const std::string& msg)
63
2.17M
    {
64
2.17M
        const auto end_time{std::chrono::steady_clock::now()};
65
2.17M
        if (!m_start_t) {
66
1.08M
            return strprintf("%s: %s", m_prefix, msg);
67
1.08M
        }
68
1.08M
        const auto duration{end_time - *m_start_t};
69
70
1.08M
        if constexpr (std::is_same_v<TimeType, std::chrono::microseconds>) {
71
1.07M
            return strprintf("%s: %s (%iμs)", m_prefix, msg, Ticks<std::chrono::microseconds>(duration));
72
1.07M
        } else if constexpr (std::is_same_v<TimeType, std::chrono::milliseconds>) {
73
11.7k
            return strprintf("%s: %s (%.2fms)", m_prefix, msg, Ticks<MillisecondsDouble>(duration));
74
11.7k
        } else if constexpr (std::is_same_v<TimeType, std::chrono::seconds>) {
75
78
            return strprintf("%s: %s (%.2fs)", m_prefix, msg, Ticks<SecondsDouble>(duration));
76
        } else {
77
            static_assert(ALWAYS_FALSE<TimeType>, "Error: unexpected time type");
78
        }
79
1.08M
    }
BCLog::Timer<std::chrono::duration<long, std::ratio<1l, 1000000l>>>::LogMsg(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char>> const&)
Line
Count
Source
63
2.15M
    {
64
2.15M
        const auto end_time{std::chrono::steady_clock::now()};
65
2.15M
        if (!m_start_t) {
66
1.07M
            return strprintf("%s: %s", m_prefix, msg);
67
1.07M
        }
68
1.07M
        const auto duration{end_time - *m_start_t};
69
70
1.07M
        if constexpr (std::is_same_v<TimeType, std::chrono::microseconds>) {
71
1.07M
            return strprintf("%s: %s (%iμs)", m_prefix, msg, Ticks<std::chrono::microseconds>(duration));
72
        } else if constexpr (std::is_same_v<TimeType, std::chrono::milliseconds>) {
73
            return strprintf("%s: %s (%.2fms)", m_prefix, msg, Ticks<MillisecondsDouble>(duration));
74
        } else if constexpr (std::is_same_v<TimeType, std::chrono::seconds>) {
75
            return strprintf("%s: %s (%.2fs)", m_prefix, msg, Ticks<SecondsDouble>(duration));
76
        } else {
77
            static_assert(ALWAYS_FALSE<TimeType>, "Error: unexpected time type");
78
        }
79
1.07M
    }
BCLog::Timer<std::chrono::duration<long, std::ratio<1l, 1l>>>::LogMsg(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char>> const&)
Line
Count
Source
63
156
    {
64
156
        const auto end_time{std::chrono::steady_clock::now()};
65
156
        if (!m_start_t) {
66
78
            return strprintf("%s: %s", m_prefix, msg);
67
78
        }
68
78
        const auto duration{end_time - *m_start_t};
69
70
        if constexpr (std::is_same_v<TimeType, std::chrono::microseconds>) {
71
            return strprintf("%s: %s (%iμs)", m_prefix, msg, Ticks<std::chrono::microseconds>(duration));
72
        } else if constexpr (std::is_same_v<TimeType, std::chrono::milliseconds>) {
73
            return strprintf("%s: %s (%.2fms)", m_prefix, msg, Ticks<MillisecondsDouble>(duration));
74
78
        } else if constexpr (std::is_same_v<TimeType, std::chrono::seconds>) {
75
78
            return strprintf("%s: %s (%.2fs)", m_prefix, msg, Ticks<SecondsDouble>(duration));
76
        } else {
77
            static_assert(ALWAYS_FALSE<TimeType>, "Error: unexpected time type");
78
        }
79
78
    }
BCLog::Timer<std::chrono::duration<long, std::ratio<1l, 1000l>>>::LogMsg(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char>> const&)
Line
Count
Source
63
23.4k
    {
64
23.4k
        const auto end_time{std::chrono::steady_clock::now()};
65
23.4k
        if (!m_start_t) {
66
11.7k
            return strprintf("%s: %s", m_prefix, msg);
67
11.7k
        }
68
11.7k
        const auto duration{end_time - *m_start_t};
69
70
        if constexpr (std::is_same_v<TimeType, std::chrono::microseconds>) {
71
            return strprintf("%s: %s (%iμs)", m_prefix, msg, Ticks<std::chrono::microseconds>(duration));
72
11.7k
        } else if constexpr (std::is_same_v<TimeType, std::chrono::milliseconds>) {
73
11.7k
            return strprintf("%s: %s (%.2fms)", m_prefix, msg, Ticks<MillisecondsDouble>(duration));
74
        } else if constexpr (std::is_same_v<TimeType, std::chrono::seconds>) {
75
            return strprintf("%s: %s (%.2fs)", m_prefix, msg, Ticks<SecondsDouble>(duration));
76
        } else {
77
            static_assert(ALWAYS_FALSE<TimeType>, "Error: unexpected time type");
78
        }
79
11.7k
    }
80
81
private:
82
    std::optional<std::chrono::steady_clock::time_point> m_start_t{};
83
84
    //! Log prefix; usually the name of the function this was created in.
85
    const std::string m_prefix;
86
87
    //! A descriptive message of what is being timed.
88
    const std::string m_title;
89
90
    //! Forwarded on to LogDebug if specified - has the effect of only
91
    //! outputting the timing log when a particular debug= category is specified.
92
    const BCLog::LogFlags m_log_category;
93
94
    //! Whether to output the message again on completion.
95
    const bool m_message_on_completion;
96
};
97
98
} // namespace BCLog
99
100
101
#define LOG_TIME_MICROS_WITH_CATEGORY(end_msg, log_category) \
102
1.07M
    BCLog::Timer<std::chrono::microseconds> BITCOIN_UNIQUE_NAME(logging_timer)(__func__, end_msg, log_category)
103
#define LOG_TIME_MILLIS_WITH_CATEGORY(end_msg, log_category) \
104
10.7k
    BCLog::Timer<std::chrono::milliseconds> BITCOIN_UNIQUE_NAME(logging_timer)(__func__, end_msg, log_category)
105
#define LOG_TIME_MILLIS_WITH_CATEGORY_MSG_ONCE(end_msg, log_category) \
106
942
    BCLog::Timer<std::chrono::milliseconds> BITCOIN_UNIQUE_NAME(logging_timer)(__func__, end_msg, log_category, /* msg_on_completion=*/false)
107
#define LOG_TIME_SECONDS(end_msg) \
108
78
    BCLog::Timer<std::chrono::seconds> BITCOIN_UNIQUE_NAME(logging_timer)(__func__, end_msg)
109
110
111
#endif // BITCOIN_LOGGING_TIMER_H