29787659139

Committed 20 Jul 2026 11:34PM UTC coverage: 51.578% (-1.1%) from 52.66%

Build # 29787659139

Build Type

Pull #99

github

Committed by

web-flow

Commit Message

Merge ee805adeb into 06bc84ec9

Pull Request Pull Request #99: Support CM time_metric (NS/MS/SEC/US) across reader and viz

Coverage Stats

34832 of 86278 branches covered (40.37%)

Branch coverage included in aggregate %.

1034 of 1319 new or added lines in 30 files covered. (78.39%)

5193 existing lines in 197 files now uncovered.

35349 of 49791 relevant lines covered (70.99%)

9765.54 hits per line

Source File
Press 'n' to go to next uncovered line, 'b' for previous

75.0

/src/dftracer/utils/core/common/logging.cpp

#include <ankerl/unordered_dense.h>
#include <dftracer/utils/core/common/logging.h>
#include <dftracer/utils/core/common/ptr_hash.h>
#include <dftracer/utils/core/common/symbolize.h>
#include <dftracer/utils/core/env.h>
#include <unistd.h>

#include <chrono>
#include <cstdarg>
#include <cstring>
#include <ctime>
#include <optional>
#include <string>
#include <string_view>

namespace dftracer::utils::logger {

namespace detail {
std::atomic<int> g_level{static_cast<int>(Level::Info)};
}  // namespace detail

namespace {

std::FILE* g_sink = stderr;
std::atomic<bool> g_use_color{false};
bool g_show_location = true;

struct LevelStyle {
    const char* name;   // padded to width 5
    const char* color;  // ANSI SGR sequence
};

LevelStyle level_style(Level lvl) {
    switch (lvl) {
        case Level::Trace:
            return {"TRACE", "\x1b[90m"};    // bright black
        case Level::Debug:
            return {"DEBUG", "\x1b[36m"};    // cyan
        case Level::Info:
            return {"INFO ", "\x1b[32m"};    // green
        case Level::Warn:
            return {"WARN ", "\x1b[33m"};    // yellow
        case Level::Error:
            return {"ERROR", "\x1b[1;31m"};  // bold red
        case Level::Off:
            return {"OFF  ", ""};
    }
    return {"?????", ""};
}

Level parse_level(std::optional<std::string_view> env, Level fallback) {
    if (!env) return fallback;
    if (auto lvl = level_from_name(*env)) return *lvl;
    return fallback;
}

ColorMode parse_color_mode(std::optional<std::string_view> env,
                           ColorMode fallback) {
    if (!env) return fallback;
    const std::string_view s = *env;
    if (s == "always" || s == "1" || s == "on") return ColorMode::Always;
    if (s == "never" || s == "0" || s == "off") return ColorMode::Never;
    if (s == "auto") return ColorMode::Auto;
    return fallback;
}

bool resolve_color(ColorMode mode, std::FILE* sink) {
    if (mode == ColorMode::Always) return true;
    if (mode == ColorMode::Never) return false;
    // Auto: honor the common conventions, then fall back to TTY detection.
    if (Env::get<std::string_view>("NO_COLOR")) return false;
    if (Env::get<std::string_view>("FORCE_COLOR") ||
        Env::get<std::string_view>("CLICOLOR_FORCE"))
        return true;
    if (!isatty(fileno(sink))) return false;
    const auto term = Env::get<std::string_view>("TERM");
    if (term && *term == "dumb") return false;
    return true;
}

const char* base_name(const char* path) {
    const char* slash = std::strrchr(path, '/');
    return slash ? slash + 1 : path;
}

void make_timestamp(char* out, std::size_t n) {
    auto now = std::chrono::system_clock::now();
    auto ms = std::chrono::duration_cast<std::chrono::milliseconds>(
                  now.time_since_epoch())
                  .count() %
              1000;
    std::time_t t = std::chrono::system_clock::to_time_t(now);
    std::tm tm;
    localtime_r(&t, &tm);
    std::snprintf(out, n, "%04d-%02d-%02d %02d:%02d:%02d.%03d",
                  tm.tm_year + 1900, tm.tm_mon + 1, tm.tm_mday, tm.tm_hour,
                  tm.tm_min, tm.tm_sec, static_cast<int>(ms));
}

long long steady_now_ns() {
    return std::chrono::duration_cast<std::chrono::nanoseconds>(
               std::chrono::steady_clock::now().time_since_epoch())
        .count();
}

// Per-scope state, heap-allocated so it follows a coroutine across threads.
struct ScopeFrame {
    std::string label;
    const char* file;
    int line;
    long long start_ns;
};

}  // namespace

void init(Config cfg) {
    // Environment overrides the programmatic config.
    cfg.level = parse_level(
        Env::get<std::string_view>("DFTRACER_UTILS_LOG_LEVEL"), cfg.level);
    cfg.color = parse_color_mode(
        Env::get<std::string_view>("DFTRACER_UTILS_LOG_COLOR"), cfg.color);

    std::FILE* sink = cfg.sink ? cfg.sink : stderr;
    if (const auto path = Env::get<std::string_view>("DFTRACER_UTILS_LOG_FILE");
        path && !path->empty()) {
        const std::string p(*path);
        if (std::FILE* fp = std::fopen(p.c_str(), "a")) sink = fp;
    }

    g_sink = sink;
    g_show_location = cfg.show_location;
    g_use_color.store(resolve_color(cfg.color, g_sink),
                      std::memory_order_relaxed);
    detail::g_level.store(static_cast<int>(cfg.level),
                          std::memory_order_relaxed);
}

void set_level(Level level) {
    detail::g_level.store(static_cast<int>(level), std::memory_order_relaxed);
}

Level get_level() {
    return static_cast<Level>(detail::g_level.load(std::memory_order_relaxed));
}

void set_color(ColorMode mode) {
    g_use_color.store(resolve_color(mode, g_sink), std::memory_order_relaxed);
}

std::optional<Level> level_from_name(std::string_view name) {
    if (name == "trace") return Level::Trace;
    if (name == "debug") return Level::Debug;
    if (name == "info") return Level::Info;
    if (name == "warn" || name == "warning") return Level::Warn;
    if (name == "error") return Level::Error;
    if (name == "off" || name == "none") return Level::Off;
    return std::nullopt;
}

const char* level_name(Level level) {
    switch (level) {
        case Level::Trace:
            return "trace";
        case Level::Debug:
            return "debug";
        case Level::Info:
            return "info";
        case Level::Warn:
            return "warn";
        case Level::Error:
            return "error";
        case Level::Off:
            return "off";
    }
    return "unknown";
}

namespace detail {

void write(Level lvl, const char* file, int line, const char* fmt, ...) {
    char msg[1536];
    va_list ap;
    va_start(ap, fmt);
    std::vsnprintf(msg, sizeof(msg), fmt, ap);
    va_end(ap);

    char ts[64];
    make_timestamp(ts, sizeof(ts));

    const LevelStyle style = level_style(lvl);
    const bool color = g_use_color.load(std::memory_order_relaxed);

    // No source location for coroutine traces (file == nullptr).
    const bool loc = g_show_location && file != nullptr;
    char out[2048];
    int n;
    if (color) {
        if (loc) {
            n = std::snprintf(out, sizeof(out),
                              "\x1b[2m[%s]\x1b[0m %s%s\x1b[0m %s "
                              "\x1b[2m(%s:%d)\x1b[0m\n",
                              ts, style.color, style.name, msg, base_name(file),
                              line);
        } else {
            n = std::snprintf(out, sizeof(out),
                              "\x1b[2m[%s]\x1b[0m %s%s\x1b[0m %s\n", ts,
                              style.color, style.name, msg);
        }
    } else {
        if (loc) {
            n = std::snprintf(out, sizeof(out), "[%s] %s %s (%s:%d)\n", ts,
                              style.name, msg, base_name(file), line);
        } else {
            n = std::snprintf(out, sizeof(out), "[%s] %s %s\n", ts, style.name,
                              msg);
        }
    }
    if (n < 0) return;
    std::size_t len = (static_cast<std::size_t>(n) < sizeof(out))
                          ? static_cast<std::size_t>(n)
                          : sizeof(out) - 1;
    std::fwrite(out, 1, len, g_sink);
    if (lvl == Level::Error) std::fflush(g_sink);  // survive a crash
}

void* scope_open(const char* file, int line, const char* label) {
    write(Level::Trace, file, line, "-> %s", label);
    return new ScopeFrame{std::string(label), file, line, steady_now_ns()};
}

void scope_close(void* handle) {
    auto* frame = static_cast<ScopeFrame*>(handle);
    const double ms =
        static_cast<double>(steady_now_ns() - frame->start_ns) / 1e6;
    write(Level::Trace, frame->file, frame->line, "<- %s [%.2f ms]",
          frame->label.c_str(), ms);
    delete frame;
}

namespace {

// Per-thread cache: many coroutine instances share one resume function, so the
// dladdr + demangle runs once per function per thread.
const std::string& ct_name(const void* fn) {
    static thread_local ankerl::unordered_dense::map<const void*, std::string,
                                                     PtrHash>
        cache;
    auto it = cache.find(fn);
    if (it != cache.end()) return it->second;
    return cache.emplace(fn, symbolize_function(fn)).first->second;
}

}  // namespace

void* coro_trace_enter(const void* handle, const char* file, int line) {
    if (!enabled(Level::Trace) || handle == nullptr) return nullptr;
    // The resume-function pointer sits at frame offset 0 (coroutine ABI).
    const void* resume_fn = *reinterpret_cast<const void* const*>(handle);
    return scope_open(file, line, ct_name(resume_fn).c_str());
}

void coro_trace_leave(void* handle) {
    if (handle) scope_close(handle);
}

}  // namespace detail
}  // namespace dftracer::utils::logger

1	#include <ankerl/unordered_dense.h>
2	#include <dftracer/utils/core/common/logging.h>
3	#include <dftracer/utils/core/common/ptr_hash.h>
4	#include <dftracer/utils/core/common/symbolize.h>
5	#include <dftracer/utils/core/env.h>
6	#include <unistd.h>
7
8	#include <chrono>
9	#include <cstdarg>
10	#include <cstring>
11	#include <ctime>
12	#include <optional>
13	#include <string>
14	#include <string_view>
15
16	namespace dftracer::utils::logger {
17
18	namespace detail {
19	std::atomic<int> g_level{static_cast<int>(Level::Info)};
20	} // namespace detail
21
22	namespace {
23
24	std::FILE* g_sink = stderr;	278✔
25	std::atomic<bool> g_use_color{false};
26	bool g_show_location = true;
27
28	struct LevelStyle {
29	const char* name; // padded to width 5
30	const char* color; // ANSI SGR sequence
31	};
32
33	LevelStyle level_style(Level lvl) {	2,264✔
34	switch (lvl) {	2,264!
35	case Level::Trace:
36	return {"TRACE", "\x1b[90m"}; // bright black	16✔
37	case Level::Debug:
38	return {"DEBUG", "\x1b[36m"}; // cyan	40✔
39	case Level::Info:
40	return {"INFO ", "\x1b[32m"}; // green	2,113✔
41	case Level::Warn:
42	return {"WARN ", "\x1b[33m"}; // yellow	12✔
43	case Level::Error:
44	return {"ERROR", "\x1b[1;31m"}; // bold red	83✔
45	case Level::Off:
46	return {"OFF ", ""};	×
47	}
48	return {"?????", ""};	×
49	}	2,264✔
50
51	Level parse_level(std::optional<std::string_view> env, Level fallback) {	169✔
52	if (!env) return fallback;	169✔
53	if (auto lvl = level_from_name(env)) return lvl;	1!
54	return fallback;	×
55	}	169✔
56
57	ColorMode parse_color_mode(std::optional<std::string_view> env,	169✔
58	ColorMode fallback) {
59	if (!env) return fallback;	169!
60	const std::string_view s = *env;	×
61	if (s == "always" \|\| s == "1" \|\| s == "on") return ColorMode::Always;	×
62	if (s == "never" \|\| s == "0" \|\| s == "off") return ColorMode::Never;	×
63	if (s == "auto") return ColorMode::Auto;	×
64	return fallback;	×
65	}	169✔
66
67	bool resolve_color(ColorMode mode, std::FILE* sink) {	177✔
68	if (mode == ColorMode::Always) return true;	177✔
69	if (mode == ColorMode::Never) return false;	175✔
70	// Auto: honor the common conventions, then fall back to TTY detection.
71	if (Env::get<std::string_view>("NO_COLOR")) return false;	166!
72	if (Env::get<std::string_view>("FORCE_COLOR") \|\|	166!
73	Env::get<std::string_view>("CLICOLOR_FORCE"))	166✔
74	return true;	×
75	if (!isatty(fileno(sink))) return false;	166!
76	const auto term = Env::get<std::string_view>("TERM");	×
77	if (term && *term == "dumb") return false;	×
78	return true;	×
79	}	177✔
80
81	const char* base_name(const char* path) {	2,263✔
82	const char* slash = std::strrchr(path, '/');	2,263✔
83	return slash ? slash + 1 : path;	2,263!
84	}
85
86	void make_timestamp(char* out, std::size_t n) {	2,264✔
87	auto now = std::chrono::system_clock::now();	2,264✔
88	auto ms = std::chrono::duration_cast<std::chrono::milliseconds>(	4,528✔
89	now.time_since_epoch())	2,264✔
90	.count() %	2,264✔
91	1000;
92	std::time_t t = std::chrono::system_clock::to_time_t(now);	2,264✔
93	std::tm tm;
94	localtime_r(&t, &tm);	2,264✔
95	std::snprintf(out, n, "%04d-%02d-%02d %02d:%02d:%02d.%03d",	4,528✔
96	tm.tm_year + 1900, tm.tm_mon + 1, tm.tm_mday, tm.tm_hour,	2,264✔
97	tm.tm_min, tm.tm_sec, static_cast<int>(ms));	2,264✔
98	}	2,264✔
99
100	long long steady_now_ns() {	16✔
101	return std::chrono::duration_cast<std::chrono::nanoseconds>(	32✔
102	std::chrono::steady_clock::now().time_since_epoch())	16✔
103	.count();	16✔
104	}
105
106	// Per-scope state, heap-allocated so it follows a coroutine across threads.
107	struct ScopeFrame {
108	std::string label;
109	const char* file;
110	int line;
111	long long start_ns;
112	};
113
114	} // namespace
115
116	void init(Config cfg) {	169✔
117	// Environment overrides the programmatic config.
118	cfg.level = parse_level(	169✔
119	Env::get<std::string_view>("DFTRACER_UTILS_LOG_LEVEL"), cfg.level);	169✔
120	cfg.color = parse_color_mode(	169✔
121	Env::get<std::string_view>("DFTRACER_UTILS_LOG_COLOR"), cfg.color);	169✔
122
123	std::FILE* sink = cfg.sink ? cfg.sink : stderr;	169✔
124	if (const auto path = Env::get<std::string_view>("DFTRACER_UTILS_LOG_FILE");	169!
125	path && !path->empty()) {	169!
126	const std::string p(*path);	×
127	if (std::FILE* fp = std::fopen(p.c_str(), "a")) sink = fp;	×
128	}	×
129
130	g_sink = sink;	169✔
131	g_show_location = cfg.show_location;	169✔
132	g_use_color.store(resolve_color(cfg.color, g_sink),	169✔
133	std::memory_order_relaxed);
134	detail::g_level.store(static_cast<int>(cfg.level),	169✔
135	std::memory_order_relaxed);
136	}	169✔
137
138	void set_level(Level level) {	16✔
139	detail::g_level.store(static_cast<int>(level), std::memory_order_relaxed);	16✔
140	}	16✔
141
142	Level get_level() {	11✔
143	return static_cast<Level>(detail::g_level.load(std::memory_order_relaxed));	11✔
144	}
145
146	void set_color(ColorMode mode) {	8✔
147	g_use_color.store(resolve_color(mode, g_sink), std::memory_order_relaxed);	8✔
148	}	8✔
149
150	std::optional<Level> level_from_name(std::string_view name) {	15✔
151	if (name == "trace") return Level::Trace;	15✔
152	if (name == "debug") return Level::Debug;	14✔
153	if (name == "info") return Level::Info;	12✔
154	if (name == "warn" \|\| name == "warning") return Level::Warn;	6✔
155	if (name == "error") return Level::Error;	4✔
156	if (name == "off" \|\| name == "none") return Level::Off;	2!
157	return std::nullopt;	1✔
158	}	15✔
159
160	const char* level_name(Level level) {	7✔
161	switch (level) {	7!
162	case Level::Trace:
163	return "trace";	1✔
164	case Level::Debug:
165	return "debug";	1✔
166	case Level::Info:
167	return "info";	1✔
168	case Level::Warn:
169	return "warn";	2✔
170	case Level::Error:
171	return "error";	1✔
172	case Level::Off:
173	return "off";	1✔
174	}
175	return "unknown";	×
176	}	7✔
177
178	namespace detail {
179
180	void write(Level lvl, const char* file, int line, const char* fmt, ...) {	2,264✔
181	char msg[1536];
182	va_list ap;
183	va_start(ap, fmt);	2,264✔
184	std::vsnprintf(msg, sizeof(msg), fmt, ap);	2,264✔
185	va_end(ap);	2,264✔
186
187	char ts[64];
188	make_timestamp(ts, sizeof(ts));	2,264✔
189
190	const LevelStyle style = level_style(lvl);	2,264✔
191	const bool color = g_use_color.load(std::memory_order_relaxed);	2,264✔
192
193	// No source location for coroutine traces (file == nullptr).
194	const bool loc = g_show_location && file != nullptr;	2,264✔
195	char out[2048];
196	int n;
197	if (color) {	2,264✔
198	if (loc) {	1!
199	n = std::snprintf(out, sizeof(out),	2✔
200	"\x1b[2m[%s]\x1b[0m %s%s\x1b[0m %s "
201	"\x1b[2m(%s:%d)\x1b[0m\n",
202	ts, style.color, style.name, msg, base_name(file),	1✔
203	line);	1✔
204	} else {	1✔
205	n = std::snprintf(out, sizeof(out),	×
UNCOV 206	"\x1b[2m[%s]\x1b[0m %s%s\x1b[0m %s\n", ts,	×
207	style.color, style.name, msg);	×
208	}
209	} else {	1✔
210	if (loc) {	2,263✔
211	n = std::snprintf(out, sizeof(out), "[%s] %s %s (%s:%d)\n", ts,	4,524✔
212	style.name, msg, base_name(file), line);	2,262✔
213	} else {	2,262✔
214	n = std::snprintf(out, sizeof(out), "[%s] %s %s\n", ts, style.name,	2✔
215	msg);	1✔
216	}
217	}
218	if (n < 0) return;	2,264!
219	std::size_t len = (static_cast<std::size_t>(n) < sizeof(out))	2,264!
220	? static_cast<std::size_t>(n)	2,264✔
221	: sizeof(out) - 1;
222	std::fwrite(out, 1, len, g_sink);	2,264✔
223	if (lvl == Level::Error) std::fflush(g_sink); // survive a crash	2,264✔
224	}	2,264✔
225
226	void* scope_open(const char* file, int line, const char* label) {	8✔
227	write(Level::Trace, file, line, "-> %s", label);	8✔
228	return new ScopeFrame{std::string(label), file, line, steady_now_ns()};	8!
UNCOV 229	}	×
230
231	void scope_close(void* handle) {	8✔
232	auto* frame = static_cast<ScopeFrame*>(handle);	8✔
233	const double ms =	8✔
234	static_cast<double>(steady_now_ns() - frame->start_ns) / 1e6;	8✔
235	write(Level::Trace, frame->file, frame->line, "<- %s [%.2f ms]",	16✔
236	frame->label.c_str(), ms);	8✔
237	delete frame;	8!
238	}	8✔
239
240	namespace {
241
242	// Per-thread cache: many coroutine instances share one resume function, so the
243	// dladdr + demangle runs once per function per thread.
244	const std::string& ct_name(const void* fn) {	3✔
245	static thread_local ankerl::unordered_dense::map<const void*, std::string,	3✔
246	PtrHash>
247	cache;	1✔
248	auto it = cache.find(fn);	3✔
249	if (it != cache.end()) return it->second;	3✔
250	return cache.emplace(fn, symbolize_function(fn)).first->second;	2!
251	}	3✔
252
253	} // namespace
254
255	void* coro_trace_enter(const void* handle, const char* file, int line) {	3✔
256	if (!enabled(Level::Trace) \|\| handle == nullptr) return nullptr;	3!
257	// The resume-function pointer sits at frame offset 0 (coroutine ABI).
258	const void* resume_fn = reinterpret_cast<const void const*>(handle);	3✔
259	return scope_open(file, line, ct_name(resume_fn).c_str());	3✔
260	}	3✔
261
262	void coro_trace_leave(void* handle) {	3✔
263	if (handle) scope_close(handle);	3!
264	}	3✔
265
266	} // namespace detail
267	} // namespace dftracer::utils::logger

llnl / dftracer-utils / 29787659139

Source File Press 'n' to go to next uncovered line, 'b' for previous

Source File
Press 'n' to go to next uncovered line, 'b' for previous