Skip to content

Introduces self stopping profiler macros. #166

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
LiquidityC merged 1 commit into from
Apr 11, 2026
Merged

Introduces self stopping profiler macros. #166

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
37 changes: 20 additions & 17 deletions lib/profiler/include/macros.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -6,42 +6,45 @@

#ifdef PROFILER

#define PROFILER_SETUP() \
prof_start();
#define PROFILER_SETUP() prof_start();

#define PROFILER_STOP(fp) \
prof_stop(); \
prof_print(fp);
#define PROFILER_STOP(fp) \
prof_stop(); \
prof_print(fp);

#define _NameConcat(A, B) A##B
#define NameConcat(A, B) _NameConcat(A, B)

#define TIME_BANDWIDTH_BEGIN(label, bytes) \
AnchorBlock NameConcat(Block, label) = make_anchor_block(#label, bytes);

#define TIME_BANDWIDTH_END(label) \
read_anchor_block( &Block##label );
#define TIME_BANDWIDTH_BEGIN(label, bytes) AnchorBlock NameConcat(Block, label) = make_anchor_block(#label, bytes)
#define TIME_BANDWIDTH_END(label) read_anchor_block(&Block##label)
#define TIME_BANDWIDTH(label, bytes) \
AnchorBlock NameConcat(Block, label) __attribute__((cleanup(read_anchor_block))); \
NameConcat(Block, label) = make_anchor_block(#label, bytes)

#define TIME_BLOCK_BEGIN(label) TIME_BANDWIDTH_BEGIN(label, 0)
#define TIME_BLOCK_END(label) TIME_BANDWIDTH_END(label)
#define TIME_BLOCK(label) \
AnchorBlock NameConcat(Block, label) __attribute__((cleanup(read_anchor_block))); \
NameConcat(Block, label) = make_anchor_block(#label, 0)

#define TIME_FUNC_BEGIN() \
AnchorBlock NameConcat(Block, __func__) = make_anchor_block(__func__, 0);

#define TIME_FUNC_END() \
read_anchor_block( &Block##__func__ );
#define TIME_FUNC_BEGIN() AnchorBlock NameConcat(Block, __func__) = make_anchor_block(__func__, 0)
#define TIME_FUNC_END() read_anchor_block(&Block##__func__)
#define TIME_FUNC() \
AnchorBlock NameConcat(Block, __func__) __attribute__((cleanup(read_anchor_block))); \
NameConcat(Block, __func__) = make_anchor_block(__func__, 0)

#else
#define PROFILER_SETUP()
#define PROFILER_STOP(fp)
#define TIME_BLOCK_BEGIN(label)
#define TIME_BLOCK_END(label)
#define TIME_BLOCK(label)
#define TIME_BANDWIDTH_BEGIN(label, bytes)
#define TIME_BANDWIDTH_END(label)
#define TIME_BANDWIDTH(label, bytes)
#define TIME_FUNC_BEGIN()
#define TIME_FUNC_END()
#define TIME_FUNC()
#endif


#endif // __MACROS_H_

278 changes: 146 additions & 132 deletions lib/profiler/src/profiler.c
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -14,177 +14,191 @@
static Profiler _Prof;
static char *CurrentAnchorLabel = NULL;

inline static uint64_t hash_key(const char *key)
inline static uint64_t
hash_key(const char *key)
{
uint64_t hash = FNV_OFFSET;
for (const char *p = key; *p; ++p) {
hash ^= (uint64_t)(unsigned char)(*p);
hash *= FNV_PRIME;
}
return hash;
uint64_t hash = FNV_OFFSET;
for (const char *p = key; *p; ++p) {
hash ^= (uint64_t)(unsigned char)(*p);
hash *= FNV_PRIME;
}
return hash;
}

inline static size_t hash_index(const char *key)
inline static size_t
hash_index(const char *key)
{
uint64_t hash = hash_key(key);
size_t index = (size_t)(hash & (ANCHOR_CAPACITY - 1));
return index;
uint64_t hash = hash_key(key);
size_t index = (size_t)(hash & (ANCHOR_CAPACITY - 1));
return index;
}

inline static ProfileAnchor* get_anchor(const char *label)
inline static ProfileAnchor *
get_anchor(const char *label)
{
size_t index = hash_index(label);
ProfileAnchor *cp = _Prof.anchors + index;

while (cp->label != NULL && strcmp(cp->label, label) != 0) {
cp++;
}

if (cp->label == NULL) {
cp->label = label;
cp->elapsed_inclusive = 0;
cp->elapsed_exclusive = 0;
_Prof.len++;
}
return cp;
size_t index = hash_index(label);
ProfileAnchor *cp = _Prof.anchors + index;

while (cp->label != NULL && strcmp(cp->label, label) != 0) {
cp++;
}

if (cp->label == NULL) {
cp->label = label;
cp->elapsed_inclusive = 0;
cp->elapsed_exclusive = 0;
_Prof.len++;
}
return cp;
}

void prof_start(void)
void
prof_start(void)
{
_Prof.start = read_cpu_timer();
_Prof.start = read_cpu_timer();
}

void prof_stop(void)
void
prof_stop(void)
{
_Prof.stop = read_cpu_timer();
_Prof.stop = read_cpu_timer();
}

static void prof_add_child_anchor(const char *label, uint64_t elapsed)
static void
prof_add_child_anchor(const char *label, uint64_t elapsed)
{
ProfileAnchor *cp = get_anchor(label);
ProfileAnchor *cp = get_anchor(label);

cp->elapsed_exclusive -= elapsed;
cp->elapsed_exclusive -= elapsed;
}

void prof_add_anchor(const AnchorBlock *anchor, uint64_t elapsed)
void
prof_add_anchor(const AnchorBlock *anchor, uint64_t elapsed)
{
ProfileAnchor *cp = get_anchor(anchor->label);
ProfileAnchor *cp = get_anchor(anchor->label);

if (anchor->parent_anchor != NULL) {
prof_add_child_anchor(anchor->parent_anchor, elapsed);
}
if (anchor->parent_anchor != NULL) {
prof_add_child_anchor(anchor->parent_anchor, elapsed);
}

cp->elapsed_exclusive += elapsed;
cp->elapsed_inclusive = anchor->old_elapsed_inclusive + elapsed;
cp->processed_byte_count += anchor->processed_byte_count;
cp->hits++;
cp->elapsed_exclusive += elapsed;
cp->elapsed_inclusive = anchor->old_elapsed_inclusive + elapsed;
cp->processed_byte_count += anchor->processed_byte_count;
cp->hits++;

if (_Prof.len > ANCHOR_CAPACITY / 2) {
fprintf(stderr, "%s: Profile anchors beyond optimal count: %zu > %d\n", __func__, _Prof.len, ANCHOR_CAPACITY);
}
if (_Prof.len > ANCHOR_CAPACITY / 2) {
fprintf(stderr, "%s: Profile anchors beyond optimal count: %zu > %d\n", __func__, _Prof.len,
ANCHOR_CAPACITY);
}
}

static void print_header(FILE *fp, int indent, const char *time_label, uint64_t elapsed, uint64_t cpu_freq)
static void
print_header(FILE *fp, int indent, const char *time_label, uint64_t elapsed, uint64_t cpu_freq)
{
if (isatty(fileno(fp))) {
fprintf(fp, C_BLUE "\n%*s : =====\n" C_RESET, indent, "===== Benchmarks");
fprintf(fp, C_RED "%*s" C_RESET " : %lu " C_WHITE "(%.4fs with freq %lu)" C_RESET "\n",
indent, time_label, elapsed, (float)elapsed/cpu_freq, cpu_freq);
} else {
fprintf(fp, "\n%*s : =====\n", indent, "===== Benchmarks");
fprintf(fp, "%*s : %lu (%.4f s)\n", indent, time_label, elapsed, (float)elapsed/cpu_freq);
}
if (isatty(fileno(fp))) {
fprintf(fp, C_BLUE "\n%*s : =====\n" C_RESET, indent, "===== Benchmarks");
fprintf(fp, C_RED "%*s" C_RESET " : %lu " C_WHITE "(%.4fs with freq %lu)" C_RESET "\n", indent,
time_label, elapsed, (float)elapsed / cpu_freq, cpu_freq);
} else {
fprintf(fp, "\n%*s : =====\n", indent, "===== Benchmarks");
fprintf(fp, "%*s : %lu (%.4f s)\n", indent, time_label, elapsed, (float)elapsed / cpu_freq);
}
}

static void print_cp(int indent, const char *label, uint64_t elapsed, double perc, FILE *fp)
static void
print_cp(int indent, const char *label, uint64_t elapsed, double perc, FILE *fp)
{
if (isatty(fileno(fp))) {
fprintf(fp, C_GREEN "%*s" C_RESET " : %-11lu " C_YELLOW "%6.02f%%" C_RESET,
indent, label, elapsed, perc);
} else {
fprintf(fp, "%*s : %-10lu %6.02f%%", indent, label, elapsed, perc);
}
if (isatty(fileno(fp))) {
fprintf(fp, C_GREEN "%*s" C_RESET " : %-11lu " C_YELLOW "%6.02f%%" C_RESET, indent, label, elapsed,
perc);
} else {
fprintf(fp, "%*s : %-10lu %6.02f%%", indent, label, elapsed, perc);
}
}

static void print_cp_child(int indent, const char *label, uint64_t elapsed, double perc, double total_perc, FILE *fp)
static void
print_cp_child(int indent, const char *label, uint64_t elapsed, double perc, double total_perc, FILE *fp)
{
if (isatty(fileno(fp))) {
fprintf(fp, C_GREEN "%*s" C_RESET " : %-11lu " C_YELLOW "%6.02f%% (%.02f%% w/children)" C_RESET,
indent, label, elapsed, perc, total_perc);
} else {
fprintf(fp, "%*s : %-10lu %6.02f%% (%.02f%% w/children)", indent, label, elapsed, perc, total_perc);
}
if (isatty(fileno(fp))) {
fprintf(fp, C_GREEN "%*s" C_RESET " : %-11lu " C_YELLOW "%6.02f%% (%.02f%% w/children)" C_RESET, indent,
label, elapsed, perc, total_perc);
} else {
fprintf(fp, "%*s : %-10lu %6.02f%% (%.02f%% w/children)", indent, label, elapsed, perc, total_perc);
}
}

void prof_print(FILE *fp)
void
prof_print(FILE *fp)
{
char label[256];
uint64_t total_elapsed = 0;
uint64_t total = _Prof.stop - _Prof.start;
double share, total_share;
ProfileAnchor *cp;
uint64_t cpu_freq = estimate_cpu_freq(300);
char *time_label = "Total time";

int indent = strlen(time_label);
for (size_t i = 0; i < ANCHOR_CAPACITY; ++i) {
cp = _Prof.anchors + i;
if (cp->hits == 0) {
continue;
}
sprintf(label, "%s[%zu]", cp->label, cp->hits);
int len = strlen(label);
indent = len > indent ? len : indent;
}
indent += 5;

total_elapsed = _Prof.stop - _Prof.start;
print_header(fp, indent, time_label, total_elapsed, cpu_freq);

for (size_t i = 0; i < ANCHOR_CAPACITY; ++i) {
cp = _Prof.anchors + i;
if (cp->hits == 0) {
continue;
}
sprintf(label, "%s[%zu]", cp->label, cp->hits);
share = ((double) cp->elapsed_exclusive/(double) total) * 100;
if (cp->elapsed_inclusive == cp->elapsed_exclusive) {
print_cp(indent, label, cp->elapsed_exclusive, share, fp);
} else {
total_share = ((double) cp->elapsed_inclusive/(double) total) * 100;
print_cp_child(indent, label, cp->elapsed_exclusive, share, total_share, fp);
}
if (cp->processed_byte_count) {
static const double mb = 1024.0*1024.0;
static const double gb = mb*1024.0;

double seconds = (double) cp->elapsed_inclusive / cpu_freq;
double bytes_per_second = cp->processed_byte_count / seconds;
double mbs = cp->processed_byte_count / mb;
double gb_per_second = bytes_per_second / gb;

if (isatty(fileno(fp))) {
printf(C_CYAN " %.3fmb" C_RESET " at " C_MAGENTA "%.2fgb/s" C_RESET, mbs, gb_per_second);
} else {
printf(" %.3fmb at %.2fgb/s", mbs, gb_per_second);
}
}
fprintf(fp, "\n");
}
char label[256];
uint64_t total_elapsed = 0;
uint64_t total = _Prof.stop - _Prof.start;
double share, total_share;
ProfileAnchor *cp;
uint64_t cpu_freq = estimate_cpu_freq(300);
char *time_label = "Total time";

int indent = strlen(time_label);
for (size_t i = 0; i < ANCHOR_CAPACITY; ++i) {
cp = _Prof.anchors + i;
if (cp->hits == 0) {
continue;
}
sprintf(label, "%s[%zu]", cp->label, cp->hits);
int len = strlen(label);
indent = len > indent ? len : indent;
}
indent += 5;

total_elapsed = _Prof.stop - _Prof.start;
print_header(fp, indent, time_label, total_elapsed, cpu_freq);

for (size_t i = 0; i < ANCHOR_CAPACITY; ++i) {
cp = _Prof.anchors + i;
if (cp->hits == 0) {
continue;
}
sprintf(label, "%s[%zu]", cp->label, cp->hits);
share = ((double)cp->elapsed_exclusive / (double)total) * 100;
if (cp->elapsed_inclusive == cp->elapsed_exclusive) {
print_cp(indent, label, cp->elapsed_exclusive, share, fp);
} else {
total_share = ((double)cp->elapsed_inclusive / (double)total) * 100;
print_cp_child(indent, label, cp->elapsed_exclusive, share, total_share, fp);
}
if (cp->processed_byte_count) {
static const double mb = 1024.0 * 1024.0;
static const double gb = mb * 1024.0;

double seconds = (double)cp->elapsed_inclusive / cpu_freq;
double bytes_per_second = cp->processed_byte_count / seconds;
double mbs = cp->processed_byte_count / mb;
double gb_per_second = bytes_per_second / gb;

if (isatty(fileno(fp))) {
printf(C_CYAN " %.3fmb" C_RESET " at " C_MAGENTA "%.2fgb/s" C_RESET, mbs,
gb_per_second);
} else {
printf(" %.3fmb at %.2fgb/s", mbs, gb_per_second);
}
}
fprintf(fp, "\n");
}
}

AnchorBlock make_anchor_block(const char *label, size_t used_bytes)
AnchorBlock
make_anchor_block(const char *label, size_t used_bytes)
{
ProfileAnchor *cp = get_anchor(label);
AnchorBlock anchor = { label, read_cpu_timer(), cp->elapsed_inclusive, used_bytes, CurrentAnchorLabel };
CurrentAnchorLabel = (char*) label;
return anchor;
ProfileAnchor *cp = get_anchor(label);
AnchorBlock anchor = {label, read_cpu_timer(), cp->elapsed_inclusive, used_bytes, CurrentAnchorLabel};
CurrentAnchorLabel = (char *)label;
return anchor;
}

void read_anchor_block(const AnchorBlock *anchor)
void
read_anchor_block(const AnchorBlock *anchor)
{
uint64_t elapsed = read_cpu_timer() - anchor->start;
prof_add_anchor(anchor, elapsed);
CurrentAnchorLabel = anchor->parent_anchor;
uint64_t elapsed = read_cpu_timer() - anchor->start;
prof_add_anchor(anchor, elapsed);
CurrentAnchorLabel = anchor->parent_anchor;
}

Loading