29118766082

Committed 10 Jul 2026 07:39PM UTC coverage: 52.688% (+0.2%) from 52.475%

Build # 29118766082

Build Type

push

github

Committed by

hariharan-devarajan

Commit Message

fix(io): finish scatter-gather writes past IOV_MAX

writev(2) accepts at most IOV_MAX entries and may write fewer bytes than asked.
The streaming HTTP path builds two iovec entries per event, so a chunk over ~511
events overflowed the limit, writev failed, and the connection still sent the
terminating chunk: clients saw 200 OK with an empty body. Bulk export of any
sizeable trace returned nothing.

Add io::writev_all(), which splits runs longer than IOV_MAX and resumes after
short writes, and use it for streamed responses. The limit is read via
sysconf(_SC_IOV_MAX), since glibc gates IOV_MAX behind feature macros and
spells it UIO_MAXIOV; io_uring's IORING_OP_WRITEV is bounded the same way.

Coverage Stats

39269 of 96697 branches covered (40.61%)

Branch coverage included in aggregate %.

26 of 27 new or added lines in 2 files covered. (96.3%)

428 existing lines in 11 files now uncovered.

35017 of 44296 relevant lines covered (79.05%)

21293.65 hits per line

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

73.8

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

llnl / dftracer-utils / 29118766082

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