ascii-chat 0.11.33
Video chat in your terminal
Loading...
Searching...
No Matches
Panic Instrumentation

🚨 Per-statement logging for crash debugging in C programs More...

Files

file  instrument_log.h
 🔍 Debug instrumentation logging runtime for ascii-chat line tracing
 

Macros

#define ASCII_INSTR_SOURCE_PRINT_SIGNAL_HANDLER
 Attribute to mark signal handler functions.
 

Typedefs

typedef struct asciichat_instr_runtime asciichat_instr_runtime_t
 Opaque runtime context for instrumentation logging.
 

Enumerations

enum  { ASCII_INSTR_SOURCE_PRINT_MACRO_NONE = 0u , ASCII_INSTR_SOURCE_PRINT_MACRO_EXPANSION = 1u , ASCII_INSTR_SOURCE_PRINT_MACRO_INVOCATION = 2u }
 Macro expansion indicator values for asciichat_instr_log_line() More...
 

Functions

asciichat_instr_runtime_t * asciichat_instr_runtime_get (void)
 Get or create the thread-local runtime context.
 
void asciichat_instr_runtime_destroy (asciichat_instr_runtime_t *runtime)
 Destroy a runtime context and release resources.
 
void asciichat_instr_runtime_global_destroy (void)
 Global shutdown of the instrumentation system.
 
void asciichat_instr_log_line (const char *file_path, uint32_t line_number, const char *function_name, const char *snippet, uint8_t is_macro_expansion)
 Log a source line execution event.
 
bool asciichat_instr_coverage_enabled (void)
 Check if coverage logging is enabled.
 
void asciichat_instr_log_pc (uintptr_t program_counter)
 Log a program counter for coverage analysis.
 

Detailed Description

🚨 Per-statement logging for crash debugging in C programs

This module provides the runtime logging infrastructure for the source-print instrumentation system. When code is instrumented with ascii-instr-panic, calls to asciichat_instr_log_line() are inserted at each statement to trace execution flow.

Features

Environment Variables

Regex variants (Unix only):

See also
docs/tooling/panic-instrumentation.md for full documentation

Panic Instrumentation

🚨 Overview

Panic instrumentation provides per-statement logging for debugging crashes in C programs. The core idea is simple: the last line printed before a crash is the crashing line (or the line immediately before it in most cases).

Implementation: src/tooling/panic/tool.cpp

Key Features:

  • Per-statement source code logging
  • Multi-threaded support with per-thread log files
  • Environment variable filtering (by file, function, thread, regex, glob patterns)
  • Signal-safe logging using atomic writes
  • Post-mortem analysis with ascii-panic-report tool
  • SanitizerCoverage integration for edge coverage

Background: The Core Idea

The Problem: C programs crash without error messages. When a segfault or other crash occurs, you get no information about which line of code caused it. Traditional debugging approaches have limitations:

  • Manual printf debugging: You have to guess where to add logs, and you might not even be in the right function yet. Hours can be wasted adding printf() calls to the wrong places.
  • Debuggers (gdb/lldb): Great for reproducible crashes, but timing-sensitive bugs (race conditions) may not reproduce under a debugger.
  • Sanitizers (ASan/UBSan): Excellent for memory bugs, but don't help with logic errors or silent hangs.

The Solution: What if we automatically insert a log before every line of code? When the program crashes, the last line printed tells you exactly where it crashed.

If your program crashes without logs:
??? → ??? → ??? → CRASH
With panic instrumentation:
log(line 10) → log(line 11) → log(line 12) → CRASH
↑
Last printed line = crash location!

Why This Works:

  1. We log BEFORE each statement executes
  2. The logging uses atomic writes (survives crashes)
  3. Whatever printed last was the last thing that ran
  4. Therefore, the crash is at or after that line

Why Hasn't This Been Done Before?

Tools like this exist in various forms (SanitizerCoverage, -finstrument-functions, dynamic binary instrumentation), but they typically:

  • Log addresses/PCs that need symbolization, not actual source text
  • Work at function granularity, not per-statement
  • Require post-processing to map back to source

This approach is deliberately simple: print the actual source code text, so the crash location is immediately readable. No symbolization, no post-processing.

Multi-Threaded Programs

With multiple threads, the "last printed line globally" might be from a different thread than the one that crashed. The solution:

  • Each thread writes to its own log file (ascii-instr-<pid>-<tid>.log)
  • Each log line includes the thread ID
  • Use ascii-panic-report to find the last line from each thread
  • Identify the crashing thread from the crash report, then check its log

When to Use

Use panic instrumentation when:

  • You have a crash that's difficult to reproduce
  • Traditional debuggers don't work (e.g., timing-sensitive bugs)
  • You need to know exactly which statement crashed
  • You're debugging multi-threaded code

How It Works

The panic instrumentation tool transforms your C source code to print each statement before executing it:

Original code: Instrumented code:
--------------- -------------------------------------------
int x = 5; log("lib/foo.c:10: int x = 5;");
int x = 5;
int y = x / 0; log("lib/foo.c:11: int y = x / 0;"); // Last printed!
int y = x / 0; // CRASH!
return y; log("lib/foo.c:12: return y;"); // Never reached
return y;

Single-Threaded Programs: The last log line is the crash location.

Multi-Threaded Programs: Each thread writes to its own log file (ascii-instr-<pid>-<tid>.log). Use ascii-panic-report to summarize the last statement executed by each thread.

Usage

Building with Panic Instrumentation

# Build with panic instrumentation
cmake -B build -DASCIICHAT_BUILD_WITH_PANIC=ON
cmake --build build

Debugging Workflow

# 1. Build with panic instrumentation
cmake -B build -DASCIICHAT_BUILD_WITH_PANIC=ON
cmake --build build
# 2. Run the crashing program
export ASCII_PANIC_OUTPUT_DIR=/tmp/crash-logs
./build/bin/ascii-chat server
# ... program crashes ...
# 3. Find the crash location
# Single-threaded: just look at the last line
tail -n1 /tmp/crash-logs/ascii-instr-*.log
# Multi-threaded: use the report tool
./build/bin/ascii-panic-report --log-dir /tmp/crash-logs

The ascii-panic-report Tool

For multi-threaded programs, ascii-panic-report parses all log files and shows the last executed statement per thread:

# Build the report tool
cmake --build build --target ascii-panic-report
# Run it
./build/bin/ascii-panic-report --log-dir /tmp/crash-logs
# Output:
# Latest instrumentation record per thread (3 threads)
# ======================================================================
# tid=1234 seq=42891 pid=5678
# timestamp : 2025-11-07T18:32:01.123456789Z
# elapsed : 12.3ms
# location : lib/network.c:512
# function : socket_send
# macro : none (0)
# snippet : send_packet(queue, payload)
# ----------------------------------------------------------------------
# tid=1235 seq=8901 pid=5678
# location : lib/mixer.c:234
# function : mix_audio_frames
# snippet : buffer[i] = left + right

Report Tool Options

# Filter to specific thread
./build/bin/ascii-panic-report --thread 1234
# Filter by file path
./build/bin/ascii-panic-report --include network.c
# Exclude files
./build/bin/ascii-panic-report --exclude video
# Show raw log lines
./build/bin/ascii-panic-report --raw

Log Record Format

Each log line contains:

pid=12345 tid=678 seq=42 ts=2025-11-07T18:32:01.123456789Z elapsed=12.3ms file=lib/network.c line=512 func=socket_send macro=0 snippet=send_packet(queue, payload)
  • pid: Process ID
  • tid: Thread ID
  • seq: Sequence number for this thread
  • ts: Timestamp (ISO 8601 format)
  • elapsed: Time since runtime initialization
  • file: Source file path
  • line: Line number
  • func: Function name
  • macro: Macro flag (0=normal, 1=from macro expansion, 2=macro invocation)
  • snippet: The source code being executed

Environment Variable Filtering

Reduce log volume by filtering what gets logged. Filters are checked before formatting to minimize overhead.

Basic Filters

Variable Purpose
ASCII_INSTR_SOURCE_PRINT_INCLUDE Only log files matching substring
ASCII_INSTR_SOURCE_PRINT_EXCLUDE Skip files matching substring
ASCII_INSTR_SOURCE_PRINT_THREAD Comma-separated thread IDs to log
ASCII_INSTR_SOURCE_PRINT_FUNCTION_INCLUDE Only log functions matching substring
ASCII_INSTR_SOURCE_PRINT_FUNCTION_EXCLUDE Skip functions matching substring
ASCII_INSTR_SOURCE_PRINT_OUTPUT_DIR Directory for log files
ASCII_INSTR_SOURCE_PRINT_RATE Log every Nth statement (throttle)
ASCII_INSTR_SOURCE_PRINT_ENABLE Set to "0" to disable at runtime

Regex Filters (POSIX platforms only)

Variable Purpose
ASCII_INSTR_SOURCE_PRINT_INCLUDE_REGEX POSIX regex include filter on file path
ASCII_INSTR_SOURCE_PRINT_EXCLUDE_REGEX POSIX regex exclude filter on file path
ASCII_INSTR_SOURCE_PRINT_FUNCTION_INCLUDE_REGEX POSIX regex include filter on function name
ASCII_INSTR_SOURCE_PRINT_FUNCTION_EXCLUDE_REGEX POSIX regex exclude filter on function name

ONLY Selectors (Advanced)

The ASCII_INSTR_SOURCE_PRINT_ONLY variable supports sophisticated allow-list filtering using comma-separated selectors:

Syntax Description
file=<glob> Match files by glob pattern
func=<glob> Match functions by glob pattern
module=<name> Match files under /name/ directory
module=<name>:<glob> Match files under /name/ with basename matching glob
<name>:<glob> Shorthand for module=<name>:<glob>
<substring> Match files containing substring

Examples:

# Only log network-related files
export ASCII_INSTR_SOURCE_PRINT_INCLUDE=network.c
# Skip video processing (too noisy)
export ASCII_INSTR_SOURCE_PRINT_EXCLUDE=video
# Only log specific threads
export ASCII_INSTR_SOURCE_PRINT_THREAD=1234,5678
# Log every 100th statement (reduce volume)
export ASCII_INSTR_SOURCE_PRINT_RATE=100
# Custom output directory
export ASCII_INSTR_SOURCE_PRINT_OUTPUT_DIR=/tmp/crash-logs
# Advanced: Only log server render code
export ASCII_INSTR_SOURCE_PRINT_ONLY="server:render_*"
# Advanced: Multiple selectors
export ASCII_INSTR_SOURCE_PRINT_ONLY="file=lib/network/*,func=socket_*"
# Advanced: Module with glob pattern
export ASCII_INSTR_SOURCE_PRINT_ONLY="module=crypto:handshake*"
# Disable instrumentation at runtime (binary still instrumented)
export ASCII_INSTR_SOURCE_PRINT_ENABLE=0

Custom Log File

For debugging specific issues, you can direct all output to a single file:

# Write to a specific file (allows appending across runs)
export ASCII_CHAT_DEBUG_SELF_SOURCE_CODE_LOG_FILE=/tmp/trace.log
# Also echo to stderr for live viewing
export ASCII_CHAT_DEBUG_SELF_SOURCE_CODE_LOG_STDERR=1

Signal Handler Annotations

Mark functions that must remain async-signal-safe:

ASCII_PANIC_SIGNAL_HANDLER
void handle_sigint(int signum) {
// ... signal handler code ...
}

The panic instrumentation tool skips any function carrying that annotation, ensuring inserted logging calls never appear inside signal handlers.

Safety Guarantees

  • Original sources remain untouched: The tool writes only to new files under build/instrumented/
  • Atomic writes: Each log line is emitted with a single write() call, so concurrent threads cannot interleave records
  • Signal tolerance: Once initialized, the runtime avoids non-signal-safe functions inside the hot path
  • Thread isolation: Separate files per thread prevent interleaving

Limitations and Best Practices

  • Performance cost: Logging every statement carries significant overhead. Use filters to narrow the scope when possible.
  • Timing changes: Heavy I/O can mask race conditions (Heisenbugs). After localizing the failure, confirm with sanitizers or record/replay tools.
  • Binary size: Expect larger binaries because every statement introduces a logging call and associated string literal.
  • Thread IDs differ by platform: Always copy the numeric ID from log headers when using ASCII_PANIC_THREAD.

Build System Details

File Locations

CMake Options

Option Default Description
ASCIICHAT_BUILD_WITH_PANIC OFF Enable panic instrumentation
ASCIICHAT_PANIC_TOOL "" Path to pre-built tool (faster rebuilds)

SanitizerCoverage Mode

For lightweight edge coverage without full statement logging:

# Build with coverage instrumentation
cmake -B build -DCMAKE_C_FLAGS="-fsanitize-coverage=trace-pc-guard"
# Enable coverage logging at runtime
export ASCII_INSTR_SOURCE_PRINT_ENABLE_COVERAGE=1
./build/bin/ascii-chat server

Coverage mode logs compact pc=0x... entries that can be symbolized with llvm-symbolizer or addr2line to map back to source locations.

Tool Command-Line Options

The ascii-instr-panic tool supports:

Option Description
--output-dir <path> Where to write instrumented sources
--input-root <path> Root for computing relative paths
--log-macro-expansions Instrument statements from macro expansions
--log-macro-invocations Emit synthetic log for macro call sites
--filter-file <substring> Only instrument files matching substring
--filter-function <substring> Only instrument functions matching substring
--signal-handler-annotation <name> Annotation to skip (default: ASCII_INSTR_PANIC_SIGNAL_HANDLER)

Troubleshooting

No logs emitted:

  • Check the output directory exists and is writable
  • Verify filters aren't over-restrictive (unset ASCII_INSTR_SOURCE_PRINT_INCLUDE)
  • Check ASCII_INSTR_SOURCE_PRINT_ENABLE isn't set to "0"

**"Refusing to overwrite" errors**:

  • Remove existing build/instrumented/ directory
  • Or specify a fresh output directory

Partial log files:

  • Ensure disk isn't full
  • Check runtime didn't hit a fatal error before logging

Thread IDs don't match:

  • Thread IDs are platform-specific (pthread vs system TID)
  • Always copy the exact numeric ID from log headers

Related Tools and Alternatives

Tool Approach Pros Cons
Panic instrumentation Source rewriting Readable output, no symbolization High overhead
SanitizerCoverage Edge callbacks Lower overhead Needs symbolization
-finstrument-functions Function entry/exit Very low overhead Function granularity only
rr (record/replay) Deterministic replay Perfect reproduction Linux only, heavyweight
ASan/UBSan Memory/UB detection Catches specific bugs Not for all crash types
gdb/lldb Debugger Full control May perturb timing

Panic instrumentation is best when you need:

  • Immediate, readable crash location without post-processing
  • To debug timing-sensitive code that doesn't reproduce under debuggers
  • Per-statement granularity for complex control flow

References

Macro Definition Documentation

◆ ASCII_INSTR_SOURCE_PRINT_SIGNAL_HANDLER

#define ASCII_INSTR_SOURCE_PRINT_SIGNAL_HANDLER

#include <instrument_log.h>

Attribute to mark signal handler functions.

Functions marked with this attribute are recognized by the instrumentation tool and may receive special handling to avoid signal-unsafe operations.

Definition at line 76 of file instrument_log.h.

Typedef Documentation

◆ asciichat_instr_runtime_t

#include <instrument_log.h>

Opaque runtime context for instrumentation logging.

Each thread has its own runtime context that tracks:

  • File descriptor for the log file
  • Sequence numbers and call counters
  • Filter configuration (compiled regexes, substring patterns)
  • Rate limiting state

Definition at line 88 of file instrument_log.h.

Enumeration Type Documentation

◆ anonymous enum

anonymous enum

#include <instrument_log.h>

Macro expansion indicator values for asciichat_instr_log_line()

These values indicate whether a logged line originates from a macro expansion, the macro invocation site, or regular code.

Enumerator
ASCII_INSTR_SOURCE_PRINT_MACRO_NONE 

Regular code, not from a macro

ASCII_INSTR_SOURCE_PRINT_MACRO_EXPANSION 

Inside macro expansion

ASCII_INSTR_SOURCE_PRINT_MACRO_INVOCATION 

At macro invocation site

Definition at line 61 of file instrument_log.h.

61 {
65};
@ ASCII_INSTR_SOURCE_PRINT_MACRO_INVOCATION
@ ASCII_INSTR_SOURCE_PRINT_MACRO_EXPANSION
@ ASCII_INSTR_SOURCE_PRINT_MACRO_NONE

Function Documentation

◆ asciichat_instr_coverage_enabled()

bool asciichat_instr_coverage_enabled ( void  )

#include <instrument_log.h>

Check if coverage logging is enabled.

Coverage mode logs program counter addresses instead of full source info, useful for generating coverage reports with lower overhead.

Returns
true if ASCII_INSTR_SOURCE_PRINT_ENABLE_COVERAGE is set

Definition at line 431 of file instrument_log.c.

431 {
432 if (g_disable_write) {
433 return false;
434 }
435
436 // Initialize runtime once using lock-free lifecycle API
437 if (!lifecycle_is_initialized(&g_runtime_lc)) {
438 if (lifecycle_init_once(&g_runtime_lc)) {
439 asciichat_instr_runtime_init_once();
440 lifecycle_init_commit(&g_runtime_lc);
441 }
442 }
443
444 return g_coverage_enabled;
445}
bool lifecycle_is_initialized(const lifecycle_t *lc)
Definition lifecycle.c:155
void lifecycle_init_commit(lifecycle_t *lc)
Definition lifecycle.c:90
bool lifecycle_init_once(lifecycle_t *lc)
Definition lifecycle.c:52

References lifecycle_init_commit(), lifecycle_init_once(), and lifecycle_is_initialized().

Referenced by asciichat_instr_log_pc().

◆ asciichat_instr_log_line()

void asciichat_instr_log_line ( const char *  file_path,
uint32_t  line_number,
const char *  function_name,
const char *  snippet,
uint8_t  is_macro_expansion 
)

#include <instrument_log.h>

Log a source line execution event.

Called by instrumented code at each statement to record execution trace. The log entry includes timestamp, thread ID, sequence number, file location, function name, and source code snippet.

Parameters
file_pathSource file path (typically from FILE)
line_numberLine number in the source file
function_nameName of the containing function
snippetSource code snippet for this line
is_macro_expansionOne of ASCII_INSTR_SOURCE_PRINT_MACRO_* values
Note
Filters are applied before logging; entry may be skipped
Thread-safe: uses per-thread runtime context
Reentrant-safe: nested calls are detected and skipped

Definition at line 281 of file instrument_log.c.

282 {
283 // Instrumentation is enabled by default when the binary is built with Source Print.
284 // Set ASCII_INSTR_SOURCE_PRINT_ENABLE=0 to disable tracing at runtime.
285 if (!g_instrumentation_enabled_checked) {
286 const char *enable_env = SAFE_GETENV("ASCII_INSTR_SOURCE_PRINT_ENABLE");
287 // Default to enabled (true) - only disable if explicitly set to "0", "false", "off", or "no"
288 if (enable_env != NULL && enable_env[0] != '\0') {
289 g_instrumentation_enabled = asciichat_instr_env_is_enabled(enable_env);
290 } else {
291 g_instrumentation_enabled = true; // Default to enabled when instrumented
292 }
293 g_instrumentation_enabled_checked = true;
294 }
295
296 if (!g_instrumentation_enabled) {
297 return;
298 }
299
300 if (g_disable_write) {
301 return;
302 }
303
304 if (g_logging_reentry_guard) {
305 return;
306 }
307
308 g_logging_reentry_guard = true;
309
311 if (runtime == NULL) {
312 goto cleanup;
313 }
314
315 if (!asciichat_instr_should_log(runtime, file_path, line_number, function_name)) {
316 goto cleanup;
317 }
318
319 runtime->call_counter++;
320 if (runtime->rate_enabled) {
321 const uint64_t counter = runtime->call_counter;
322 if (((counter - 1U) % runtime->rate) != 0U) {
323 goto cleanup;
324 }
325 }
326
327 if (runtime->fd < 0) {
328 if (asciichat_instr_open_log_file(runtime) != 0) {
329 runtime->stderr_fallback = true;
330 }
331 }
332
333 const int fd = runtime->stderr_fallback ? STDERR_FILENO : runtime->fd;
335 size_t pos = 0;
336
337 uint64_t realtime_ns = time_get_realtime_ns();
338 time_t sec = (time_t)(realtime_ns / NS_PER_SEC_INT);
339 long nsec = (long)(realtime_ns % NS_PER_SEC_INT);
340 struct tm tm_now;
341 memset(&tm_now, 0, sizeof(tm_now));
342 if (platform_gtime(&sec, &tm_now) != ASCIICHAT_OK) {
343 memset(&tm_now, 0, sizeof(tm_now));
344 }
345
346 char timestamp[32];
347 size_t ts_len = strftime(timestamp, sizeof(timestamp), "%Y-%m-%dT%H:%M:%S", &tm_now);
348 if (ts_len == 0) {
349 SAFE_STRNCPY(timestamp, "1970-01-01T00:00:00", sizeof(timestamp));
350 ts_len = strlen(timestamp);
351 }
352
353 char elapsed_buf[32];
354 elapsed_buf[0] = '\0';
355 if (g_ticks_initialized) {
356 uint64_t now_ns = time_get_ns();
357 uint64_t elapsed_ns = time_elapsed_ns(g_start_ns, now_ns);
358 if (time_pretty((uint64_t)elapsed_ns, -1, elapsed_buf, sizeof(elapsed_buf)) < 0) {
359 elapsed_buf[0] = '\0';
360 }
361 }
362
363 runtime->sequence++;
364
365 const char *elapsed_field = (elapsed_buf[0] != '\0') ? elapsed_buf : "-";
366
367 const char *safe_file_path = (file_path != NULL) ? file_path : "<unknown>";
368 pos += safe_snprintf(buffer + pos, sizeof(buffer) - pos,
369 "pid=%d tid=%llu seq=%llu ts=%.*s.%09ldZ elapsed=%s file=%s line=%u func=%s macro=%u snippet=",
370 runtime->pid, (unsigned long long)runtime->thread_id, (unsigned long long)runtime->sequence,
371 (int)ts_len, timestamp, nsec, elapsed_field, safe_file_path, line_number,
372 function_name ? function_name : "<unknown>", (unsigned)is_macro_expansion);
373
374 if (snippet != NULL) {
375 size_t snippet_len = strnlen(snippet, ASCII_INSTR_SOURCE_PRINT_MAX_SNIPPET);
376 for (size_t i = 0; i < snippet_len && pos < sizeof(buffer) - 2; ++i) {
377 const char ch = snippet[i];
378 switch (ch) {
379 case '\n':
380 buffer[pos++] = '\\';
381 buffer[pos++] = 'n';
382 break;
383 case '\r':
384 buffer[pos++] = '\\';
385 buffer[pos++] = 'r';
386 break;
387 case '\t':
388 buffer[pos++] = '\\';
389 buffer[pos++] = 't';
390 break;
391 default:
392 buffer[pos++] = ch;
393 break;
394 }
395 }
396 }
397
398 if (pos >= sizeof(buffer) - 1) {
399 pos = sizeof(buffer) - 2;
400 }
401
402 buffer[pos++] = '\n';
403 buffer[pos] = '\0';
404
405 asciichat_instr_write_full(fd, buffer, pos);
406
407 // Also echo to stderr if requested via environment variable
408 if (!g_echo_to_stderr_initialized) {
409 const char *echo_env = SAFE_GETENV("ASCII_CHAT_DEBUG_SELF_SOURCE_CODE_LOG_STDERR");
410 g_echo_to_stderr = asciichat_instr_env_is_enabled(echo_env);
411 g_echo_to_stderr_initialized = true;
412 }
413
414 if (g_echo_to_stderr && !runtime->stderr_fallback) {
415 // Write to stderr in addition to the log file
416 // Suppress Windows deprecation warning for POSIX write function
417#ifdef _WIN32
418#pragma clang diagnostic push
419#pragma clang diagnostic ignored "-Wdeprecated-declarations"
420#endif
421 (void)posix_write(STDERR_FILENO, buffer, pos);
422#ifdef _WIN32
423#pragma clang diagnostic pop
424#endif
425 }
426
427cleanup:
428 g_logging_reentry_guard = false;
429}
#define SAFE_STRNCPY(dst, src, size)
Definition common.h:414
#define SAFE_GETENV(name)
Definition common.h:434
unsigned long long uint64_t
Definition common.h:59
@ ASCIICHAT_OK
Definition error_codes.h:51
uint64_t time_get_ns(void)
Get current monotonic time in nanoseconds.
Definition util/time.c:108
uint64_t time_get_realtime_ns(void)
Get current wall-clock (real) time in nanoseconds.
Definition util/time.c:119
#define NS_PER_SEC_INT
Definition time.h:157
int time_pretty(uint64_t nanoseconds, int decimals, char *buffer, size_t buffer_size)
Format nanoseconds as pretty duration with spaces and configurable precision.
Definition util/time.c:424
uint64_t time_elapsed_ns(uint64_t start_ns, uint64_t end_ns)
Calculate elapsed time with wraparound safety.
Definition util/time.c:150
asciichat_instr_runtime_t * asciichat_instr_runtime_get(void)
Get or create the thread-local runtime context.
int safe_snprintf(char *buffer, size_t buffer_size, const char *format,...)
Safe formatted string printing to buffer.
Definition system.c:148
asciichat_error_t platform_gtime(const time_t *timer, struct tm *result)
Platform-safe gmtime wrapper.
#define posix_write
#define ASCII_INSTR_SOURCE_PRINT_MAX_SNIPPET
#define ASCII_INSTR_SOURCE_PRINT_MAX_LINE
char file_path[PLATFORM_MAX_PATH_LENGTH]
Definition mmap.c:39
Per-thread instrumentation runtime state.
uint64_t call_counter
Total number of instrumentation calls.
bool rate_enabled
Whether rate limiting is enabled.
uint64_t sequence
Sequence number for log entries.
uint32_t rate
Rate limiting: log every Nth call.
int fd
Log file descriptor (-1 if not open)
uint64_t thread_id
Thread ID.
bool stderr_fallback
Use stderr if log file can't be opened.

References ASCII_INSTR_SOURCE_PRINT_MAX_LINE, ASCII_INSTR_SOURCE_PRINT_MAX_SNIPPET, asciichat_instr_runtime_get(), ASCIICHAT_OK, asciichat_instr_runtime::call_counter, asciichat_instr_runtime::fd, file_path, NS_PER_SEC_INT, asciichat_instr_runtime::pid, platform_gtime(), posix_write, asciichat_instr_runtime::rate, asciichat_instr_runtime::rate_enabled, SAFE_GETENV, safe_snprintf(), SAFE_STRNCPY, asciichat_instr_runtime::sequence, asciichat_instr_runtime::stderr_fallback, asciichat_instr_runtime::thread_id, time_elapsed_ns(), time_get_ns(), time_get_realtime_ns(), and time_pretty().

Referenced by asciichat_instr_log_pc().

◆ asciichat_instr_log_pc()

void asciichat_instr_log_pc ( uintptr_t  program_counter)

#include <instrument_log.h>

Log a program counter for coverage analysis.

Records just the PC address with minimal metadata, intended for post-processing into coverage reports.

Parameters
program_counterThe instruction address to log
Note
Only logs if coverage mode is enabled

Definition at line 447 of file instrument_log.c.

447 {
449 return;
450 }
451
452 char snippet[64];
453 safe_snprintf(snippet, sizeof(snippet), "pc=0x%zx", (size_t)program_counter);
454 asciichat_instr_log_line("__coverage__", 0, "<coverage>", snippet, ASCII_INSTR_SOURCE_PRINT_MACRO_NONE);
455}
bool asciichat_instr_coverage_enabled(void)
Check if coverage logging is enabled.
void asciichat_instr_log_line(const char *file_path, uint32_t line_number, const char *function_name, const char *snippet, uint8_t is_macro_expansion)
Log a source line execution event.

References ASCII_INSTR_SOURCE_PRINT_MACRO_NONE, asciichat_instr_coverage_enabled(), asciichat_instr_log_line(), and safe_snprintf().

Referenced by __sanitizer_cov_trace_pc_guard().

◆ asciichat_instr_runtime_destroy()

void asciichat_instr_runtime_destroy ( asciichat_instr_runtime_t *  runtime)

#include <instrument_log.h>

Destroy a runtime context and release resources.

Closes the log file descriptor, frees compiled regexes, and deallocates the runtime structure. Called automatically by TLS destructor on thread exit.

Parameters
runtimeContext to destroy (safe to pass NULL)

Definition at line 224 of file instrument_log.c.

224 {
225 if (runtime == NULL) {
226 return;
227 }
228
229 if (runtime->fd >= 0) {
230 platform_close(runtime->fd);
231 runtime->fd = -1;
232 }
233
234#if ASCII_INSTR_SOURCE_PRINT_HAVE_REGEX
235 if (runtime->include_regex_valid) {
236 regfree(&runtime->include_regex);
237 runtime->include_regex_valid = false;
238 }
239 if (runtime->exclude_regex_valid) {
240 regfree(&runtime->exclude_regex);
241 runtime->exclude_regex_valid = false;
242 }
243 if (runtime->function_include_regex_valid) {
244 regfree(&runtime->function_include_regex);
245 runtime->function_include_regex_valid = false;
246 }
247 if (runtime->function_exclude_regex_valid) {
248 regfree(&runtime->function_exclude_regex);
249 runtime->function_exclude_regex_valid = false;
250 }
251#endif
252
253 asciichat_instr_only_list_destroy(&runtime->only_selectors);
254 SAFE_FREE(runtime);
255}
#define SAFE_FREE(ptr)
Definition common.h:376
int platform_close(int fd)
Safe file close (close replacement)
bool function_exclude_regex_valid
Whether function_exclude_regex was successfully compiled.
asciichat_instr_only_list_t only_selectors
List of "only" selectors for filtering.
regex_t function_exclude_regex
Compiled regex for function name exclusion.
regex_t exclude_regex
Compiled regex for file path exclusion.
bool function_include_regex_valid
Whether function_include_regex was successfully compiled.
regex_t include_regex
Compiled regex for file path inclusion.
regex_t function_include_regex
Compiled regex for function name inclusion.
bool exclude_regex_valid
Whether exclude_regex was successfully compiled.
bool include_regex_valid
Whether include_regex was successfully compiled.

References asciichat_instr_runtime::exclude_regex, asciichat_instr_runtime::exclude_regex_valid, asciichat_instr_runtime::fd, asciichat_instr_runtime::function_exclude_regex, asciichat_instr_runtime::function_exclude_regex_valid, asciichat_instr_runtime::function_include_regex, asciichat_instr_runtime::function_include_regex_valid, asciichat_instr_runtime::include_regex, asciichat_instr_runtime::include_regex_valid, asciichat_instr_runtime::only_selectors, platform_close(), and SAFE_FREE.

Referenced by asciichat_instr_runtime_global_destroy().

◆ asciichat_instr_runtime_get()

asciichat_instr_runtime_t * asciichat_instr_runtime_get ( void  )

#include <instrument_log.h>

Get or create the thread-local runtime context.

Returns the instrumentation runtime for the current thread, creating one if it doesn't exist. The runtime is stored in thread-local storage and cleaned up automatically when the thread exits.

Returns
Runtime context, or NULL if disabled or initialization fails
Note
Thread-safe: each thread gets its own context
Returns NULL if ASCII_INSTR_SOURCE_PRINT_ENABLE=0

Definition at line 177 of file instrument_log.c.

177 {
178 if (g_disable_write) {
179 return NULL;
180 }
181
182 // Initialize runtime once using lock-free lifecycle API
183 if (!lifecycle_is_initialized(&g_runtime_lc)) {
184 if (lifecycle_init_once(&g_runtime_lc)) {
185 asciichat_instr_runtime_init_once();
186 lifecycle_init_commit(&g_runtime_lc);
187 }
188 }
189
190 asciichat_instr_runtime_t *runtime = ascii_tls_get(g_runtime_key);
191 if (runtime != NULL) {
192 return runtime;
193 }
194
195 runtime = SAFE_CALLOC(1, sizeof(*runtime), asciichat_instr_runtime_t *);
196 if (runtime == NULL) {
197 return NULL;
198 }
199
200 runtime->pid = platform_get_pid();
202 runtime->sequence = 0;
203 runtime->call_counter = 0;
204 runtime->fd = -1;
205 runtime->filter_include = SAFE_GETENV("ASCII_INSTR_SOURCE_PRINT_INCLUDE");
206 runtime->filter_exclude = SAFE_GETENV("ASCII_INSTR_SOURCE_PRINT_EXCLUDE");
207 runtime->filter_thread = SAFE_GETENV("ASCII_INSTR_SOURCE_PRINT_THREAD");
208 runtime->filter_function_include = NULL;
209 runtime->filter_function_exclude = NULL;
210 runtime->filters_enabled = false;
211 runtime->rate = 1;
212 runtime->rate_enabled = false;
213
214 asciichat_instr_runtime_configure(runtime);
215
216 if (ascii_tls_set(g_runtime_key, runtime) != 0) {
217 SAFE_FREE(runtime);
218 return NULL;
219 }
220
221 return runtime;
222}
#define SAFE_CALLOC(count, size, cast)
Definition common.h:274
int ascii_tls_set(tls_key_t key, void *value)
Set thread-local value for a key.
Definition threading.c:109
pid_t platform_get_pid(void)
Get the current process ID.
Definition wasm/system.c:61
void * ascii_tls_get(tls_key_t key)
Get thread-local value for a key.
Definition threading.c:105
uint64_t asciichat_thread_current_id(void)
Get the current thread's unique numeric ID.
Definition threading.c:92
const char * filter_exclude
File path substring to exclude (from env var)
const char * filter_include
File path substring to include (from env var)
const char * filter_function_exclude
Function name substring to exclude (from env var)
const char * filter_function_include
Function name substring to include (from env var)
const char * filter_thread
Thread ID filter (from env var)
bool filters_enabled
Whether any filters are active.

References ascii_tls_get(), ascii_tls_set(), asciichat_thread_current_id(), asciichat_instr_runtime::call_counter, asciichat_instr_runtime::fd, asciichat_instr_runtime::filter_exclude, asciichat_instr_runtime::filter_function_exclude, asciichat_instr_runtime::filter_function_include, asciichat_instr_runtime::filter_include, asciichat_instr_runtime::filter_thread, asciichat_instr_runtime::filters_enabled, lifecycle_init_commit(), lifecycle_init_once(), lifecycle_is_initialized(), asciichat_instr_runtime::pid, platform_get_pid(), asciichat_instr_runtime::rate, asciichat_instr_runtime::rate_enabled, SAFE_CALLOC, SAFE_FREE, SAFE_GETENV, asciichat_instr_runtime::sequence, and asciichat_instr_runtime::thread_id.

Referenced by asciichat_instr_log_line().

◆ asciichat_instr_runtime_global_destroy()

void asciichat_instr_runtime_global_destroy ( void  )

#include <instrument_log.h>

Global shutdown of the instrumentation system.

Disables all logging, cleans up the TLS key, and resets global state. Should be called at program exit to ensure clean shutdown.

Note
After calling this, logging can be re-enabled by resetting env vars
Thread-safe: acquires global mutex during shutdown

Definition at line 257 of file instrument_log.c.

257 {
258 if (lifecycle_shutdown(&g_runtime_lc)) {
259 g_disable_write = true;
260 asciichat_instr_runtime_t *runtime = ascii_tls_get(g_runtime_key);
261 if (runtime != NULL) {
262 ascii_tls_set(g_runtime_key, NULL);
264 }
265 ascii_tls_key_delete(g_runtime_key);
266 g_ticks_initialized = false;
267 g_start_ns = 0;
268 g_coverage_enabled = false;
269 g_output_dir_set = false;
270 g_output_dir[0] = '\0';
271 g_instrumentation_enabled_checked = false;
272 g_instrumentation_enabled = false;
273 g_echo_to_stderr_initialized = false;
274 g_echo_to_stderr = false;
275 }
276
277 // Reset g_disable_write so instrumentation can be re-enabled in subsequent tests
278 g_disable_write = false;
279}
void asciichat_instr_runtime_destroy(asciichat_instr_runtime_t *runtime)
Destroy a runtime context and release resources.
int ascii_tls_key_delete(tls_key_t key)
Delete a thread-local storage key.
Definition threading.c:101
bool lifecycle_shutdown(lifecycle_t *lc)
Definition lifecycle.c:108

References ascii_tls_get(), ascii_tls_key_delete(), ascii_tls_set(), asciichat_instr_runtime_destroy(), and lifecycle_shutdown().