Skip to content

Commit 6bee76e

Browse files
LiquidityCLiquidityC
authored
Introduces self stopping profiler macros. (#166)
Leverages __attribute__((cleanup(func))) to make profiler anchors self clean after leaving scope. Should function on both GCC and Clang. Also formats the impacted files.
1 parent fa72667 commit 6bee76e

2 files changed

Lines changed: 166 additions & 149 deletions

File tree

‎lib/profiler/include/macros.h‎

Lines changed: 20 additions & 17 deletions
Original file line numberDiff line numberDiff line change
@@ -6,42 +6,45 @@
66

77
#ifdef PROFILER
88

9-
#define PROFILER_SETUP() \
10-
prof_start();
9+
#define PROFILER_SETUP() prof_start();
1110

12-
#define PROFILER_STOP(fp) \
13-
prof_stop(); \
14-
prof_print(fp);
11+
#define PROFILER_STOP(fp) \
12+
prof_stop(); \
13+
prof_print(fp);
1514

1615
#define _NameConcat(A, B) A##B
1716
#define NameConcat(A, B) _NameConcat(A, B)
1817

19-
#define TIME_BANDWIDTH_BEGIN(label, bytes) \
20-
AnchorBlock NameConcat(Block, label) = make_anchor_block(#label, bytes);
21-
22-
#define TIME_BANDWIDTH_END(label) \
23-
read_anchor_block( &Block##label );
18+
#define TIME_BANDWIDTH_BEGIN(label, bytes) AnchorBlock NameConcat(Block, label) = make_anchor_block(#label, bytes)
19+
#define TIME_BANDWIDTH_END(label) read_anchor_block(&Block##label)
20+
#define TIME_BANDWIDTH(label, bytes) \
21+
AnchorBlock NameConcat(Block, label) __attribute__((cleanup(read_anchor_block))); \
22+
NameConcat(Block, label) = make_anchor_block(#label, bytes)
2423

2524
#define TIME_BLOCK_BEGIN(label) TIME_BANDWIDTH_BEGIN(label, 0)
2625
#define TIME_BLOCK_END(label) TIME_BANDWIDTH_END(label)
26+
#define TIME_BLOCK(label) \
27+
AnchorBlock NameConcat(Block, label) __attribute__((cleanup(read_anchor_block))); \
28+
NameConcat(Block, label) = make_anchor_block(#label, 0)
2729

28-
#define TIME_FUNC_BEGIN() \
29-
AnchorBlock NameConcat(Block, __func__) = make_anchor_block(__func__, 0);
30-
31-
#define TIME_FUNC_END() \
32-
read_anchor_block( &Block##__func__ );
30+
#define TIME_FUNC_BEGIN() AnchorBlock NameConcat(Block, __func__) = make_anchor_block(__func__, 0)
31+
#define TIME_FUNC_END() read_anchor_block(&Block##__func__)
32+
#define TIME_FUNC() \
33+
AnchorBlock NameConcat(Block, __func__) __attribute__((cleanup(read_anchor_block))); \
34+
NameConcat(Block, __func__) = make_anchor_block(__func__, 0)
3335

3436
#else
3537
#define PROFILER_SETUP()
3638
#define PROFILER_STOP(fp)
3739
#define TIME_BLOCK_BEGIN(label)
3840
#define TIME_BLOCK_END(label)
41+
#define TIME_BLOCK(label)
3942
#define TIME_BANDWIDTH_BEGIN(label, bytes)
4043
#define TIME_BANDWIDTH_END(label)
44+
#define TIME_BANDWIDTH(label, bytes)
4145
#define TIME_FUNC_BEGIN()
4246
#define TIME_FUNC_END()
47+
#define TIME_FUNC()
4348
#endif
4449

45-
4650
#endif // __MACROS_H_
47-

‎lib/profiler/src/profiler.c‎

Lines changed: 146 additions & 132 deletions
Original file line numberDiff line numberDiff line change
@@ -14,177 +14,191 @@
1414
static Profiler _Prof;
1515
static char *CurrentAnchorLabel = NULL;
1616

17-
inline static uint64_t hash_key(const char *key)
17+
inline static uint64_t
18+
hash_key(const char *key)
1819
{
19-
uint64_t hash = FNV_OFFSET;
20-
for (const char *p = key; *p; ++p) {
21-
hash ^= (uint64_t)(unsigned char)(*p);
22-
hash *= FNV_PRIME;
23-
}
24-
return hash;
20+
uint64_t hash = FNV_OFFSET;
21+
for (const char *p = key; *p; ++p) {
22+
hash ^= (uint64_t)(unsigned char)(*p);
23+
hash *= FNV_PRIME;
24+
}
25+
return hash;
2526
}
2627

27-
inline static size_t hash_index(const char *key)
28+
inline static size_t
29+
hash_index(const char *key)
2830
{
29-
uint64_t hash = hash_key(key);
30-
size_t index = (size_t)(hash & (ANCHOR_CAPACITY - 1));
31-
return index;
31+
uint64_t hash = hash_key(key);
32+
size_t index = (size_t)(hash & (ANCHOR_CAPACITY - 1));
33+
return index;
3234
}
3335

34-
inline static ProfileAnchor* get_anchor(const char *label)
36+
inline static ProfileAnchor *
37+
get_anchor(const char *label)
3538
{
36-
size_t index = hash_index(label);
37-
ProfileAnchor *cp = _Prof.anchors + index;
38-
39-
while (cp->label != NULL && strcmp(cp->label, label) != 0) {
40-
cp++;
41-
}
42-
43-
if (cp->label == NULL) {
44-
cp->label = label;
45-
cp->elapsed_inclusive = 0;
46-
cp->elapsed_exclusive = 0;
47-
_Prof.len++;
48-
}
49-
return cp;
39+
size_t index = hash_index(label);
40+
ProfileAnchor *cp = _Prof.anchors + index;
41+
42+
while (cp->label != NULL && strcmp(cp->label, label) != 0) {
43+
cp++;
44+
}
45+
46+
if (cp->label == NULL) {
47+
cp->label = label;
48+
cp->elapsed_inclusive = 0;
49+
cp->elapsed_exclusive = 0;
50+
_Prof.len++;
51+
}
52+
return cp;
5053
}
5154

52-
void prof_start(void)
55+
void
56+
prof_start(void)
5357
{
54-
_Prof.start = read_cpu_timer();
58+
_Prof.start = read_cpu_timer();
5559
}
5660

57-
void prof_stop(void)
61+
void
62+
prof_stop(void)
5863
{
59-
_Prof.stop = read_cpu_timer();
64+
_Prof.stop = read_cpu_timer();
6065
}
6166

62-
static void prof_add_child_anchor(const char *label, uint64_t elapsed)
67+
static void
68+
prof_add_child_anchor(const char *label, uint64_t elapsed)
6369
{
64-
ProfileAnchor *cp = get_anchor(label);
70+
ProfileAnchor *cp = get_anchor(label);
6571

66-
cp->elapsed_exclusive -= elapsed;
72+
cp->elapsed_exclusive -= elapsed;
6773
}
6874

69-
void prof_add_anchor(const AnchorBlock *anchor, uint64_t elapsed)
75+
void
76+
prof_add_anchor(const AnchorBlock *anchor, uint64_t elapsed)
7077
{
71-
ProfileAnchor *cp = get_anchor(anchor->label);
78+
ProfileAnchor *cp = get_anchor(anchor->label);
7279

73-
if (anchor->parent_anchor != NULL) {
74-
prof_add_child_anchor(anchor->parent_anchor, elapsed);
75-
}
80+
if (anchor->parent_anchor != NULL) {
81+
prof_add_child_anchor(anchor->parent_anchor, elapsed);
82+
}
7683

77-
cp->elapsed_exclusive += elapsed;
78-
cp->elapsed_inclusive = anchor->old_elapsed_inclusive + elapsed;
79-
cp->processed_byte_count += anchor->processed_byte_count;
80-
cp->hits++;
84+
cp->elapsed_exclusive += elapsed;
85+
cp->elapsed_inclusive = anchor->old_elapsed_inclusive + elapsed;
86+
cp->processed_byte_count += anchor->processed_byte_count;
87+
cp->hits++;
8188

82-
if (_Prof.len > ANCHOR_CAPACITY / 2) {
83-
fprintf(stderr, "%s: Profile anchors beyond optimal count: %zu > %d\n", __func__, _Prof.len, ANCHOR_CAPACITY);
84-
}
89+
if (_Prof.len > ANCHOR_CAPACITY / 2) {
90+
fprintf(stderr, "%s: Profile anchors beyond optimal count: %zu > %d\n", __func__, _Prof.len,
91+
ANCHOR_CAPACITY);
92+
}
8593
}
8694

87-
static void print_header(FILE *fp, int indent, const char *time_label, uint64_t elapsed, uint64_t cpu_freq)
95+
static void
96+
print_header(FILE *fp, int indent, const char *time_label, uint64_t elapsed, uint64_t cpu_freq)
8897
{
89-
if (isatty(fileno(fp))) {
90-
fprintf(fp, C_BLUE "\n%*s : =====\n" C_RESET, indent, "===== Benchmarks");
91-
fprintf(fp, C_RED "%*s" C_RESET " : %lu " C_WHITE "(%.4fs with freq %lu)" C_RESET "\n",
92-
indent, time_label, elapsed, (float)elapsed/cpu_freq, cpu_freq);
93-
} else {
94-
fprintf(fp, "\n%*s : =====\n", indent, "===== Benchmarks");
95-
fprintf(fp, "%*s : %lu (%.4f s)\n", indent, time_label, elapsed, (float)elapsed/cpu_freq);
96-
}
98+
if (isatty(fileno(fp))) {
99+
fprintf(fp, C_BLUE "\n%*s : =====\n" C_RESET, indent, "===== Benchmarks");
100+
fprintf(fp, C_RED "%*s" C_RESET " : %lu " C_WHITE "(%.4fs with freq %lu)" C_RESET "\n", indent,
101+
time_label, elapsed, (float)elapsed / cpu_freq, cpu_freq);
102+
} else {
103+
fprintf(fp, "\n%*s : =====\n", indent, "===== Benchmarks");
104+
fprintf(fp, "%*s : %lu (%.4f s)\n", indent, time_label, elapsed, (float)elapsed / cpu_freq);
105+
}
97106
}
98107

99-
static void print_cp(int indent, const char *label, uint64_t elapsed, double perc, FILE *fp)
108+
static void
109+
print_cp(int indent, const char *label, uint64_t elapsed, double perc, FILE *fp)
100110
{
101-
if (isatty(fileno(fp))) {
102-
fprintf(fp, C_GREEN "%*s" C_RESET " : %-11lu " C_YELLOW "%6.02f%%" C_RESET,
103-
indent, label, elapsed, perc);
104-
} else {
105-
fprintf(fp, "%*s : %-10lu %6.02f%%", indent, label, elapsed, perc);
106-
}
111+
if (isatty(fileno(fp))) {
112+
fprintf(fp, C_GREEN "%*s" C_RESET " : %-11lu " C_YELLOW "%6.02f%%" C_RESET, indent, label, elapsed,
113+
perc);
114+
} else {
115+
fprintf(fp, "%*s : %-10lu %6.02f%%", indent, label, elapsed, perc);
116+
}
107117
}
108118

109-
static void print_cp_child(int indent, const char *label, uint64_t elapsed, double perc, double total_perc, FILE *fp)
119+
static void
120+
print_cp_child(int indent, const char *label, uint64_t elapsed, double perc, double total_perc, FILE *fp)
110121
{
111-
if (isatty(fileno(fp))) {
112-
fprintf(fp, C_GREEN "%*s" C_RESET " : %-11lu " C_YELLOW "%6.02f%% (%.02f%% w/children)" C_RESET,
113-
indent, label, elapsed, perc, total_perc);
114-
} else {
115-
fprintf(fp, "%*s : %-10lu %6.02f%% (%.02f%% w/children)", indent, label, elapsed, perc, total_perc);
116-
}
122+
if (isatty(fileno(fp))) {
123+
fprintf(fp, C_GREEN "%*s" C_RESET " : %-11lu " C_YELLOW "%6.02f%% (%.02f%% w/children)" C_RESET, indent,
124+
label, elapsed, perc, total_perc);
125+
} else {
126+
fprintf(fp, "%*s : %-10lu %6.02f%% (%.02f%% w/children)", indent, label, elapsed, perc, total_perc);
127+
}
117128
}
118129

119-
void prof_print(FILE *fp)
130+
void
131+
prof_print(FILE *fp)
120132
{
121-
char label[256];
122-
uint64_t total_elapsed = 0;
123-
uint64_t total = _Prof.stop - _Prof.start;
124-
double share, total_share;
125-
ProfileAnchor *cp;
126-
uint64_t cpu_freq = estimate_cpu_freq(300);
127-
char *time_label = "Total time";
128-
129-
int indent = strlen(time_label);
130-
for (size_t i = 0; i < ANCHOR_CAPACITY; ++i) {
131-
cp = _Prof.anchors + i;
132-
if (cp->hits == 0) {
133-
continue;
134-
}
135-
sprintf(label, "%s[%zu]", cp->label, cp->hits);
136-
int len = strlen(label);
137-
indent = len > indent ? len : indent;
138-
}
139-
indent += 5;
140-
141-
total_elapsed = _Prof.stop - _Prof.start;
142-
print_header(fp, indent, time_label, total_elapsed, cpu_freq);
143-
144-
for (size_t i = 0; i < ANCHOR_CAPACITY; ++i) {
145-
cp = _Prof.anchors + i;
146-
if (cp->hits == 0) {
147-
continue;
148-
}
149-
sprintf(label, "%s[%zu]", cp->label, cp->hits);
150-
share = ((double) cp->elapsed_exclusive/(double) total) * 100;
151-
if (cp->elapsed_inclusive == cp->elapsed_exclusive) {
152-
print_cp(indent, label, cp->elapsed_exclusive, share, fp);
153-
} else {
154-
total_share = ((double) cp->elapsed_inclusive/(double) total) * 100;
155-
print_cp_child(indent, label, cp->elapsed_exclusive, share, total_share, fp);
156-
}
157-
if (cp->processed_byte_count) {
158-
static const double mb = 1024.0*1024.0;
159-
static const double gb = mb*1024.0;
160-
161-
double seconds = (double) cp->elapsed_inclusive / cpu_freq;
162-
double bytes_per_second = cp->processed_byte_count / seconds;
163-
double mbs = cp->processed_byte_count / mb;
164-
double gb_per_second = bytes_per_second / gb;
165-
166-
if (isatty(fileno(fp))) {
167-
printf(C_CYAN " %.3fmb" C_RESET " at " C_MAGENTA "%.2fgb/s" C_RESET, mbs, gb_per_second);
168-
} else {
169-
printf(" %.3fmb at %.2fgb/s", mbs, gb_per_second);
170-
}
171-
}
172-
fprintf(fp, "\n");
173-
}
133+
char label[256];
134+
uint64_t total_elapsed = 0;
135+
uint64_t total = _Prof.stop - _Prof.start;
136+
double share, total_share;
137+
ProfileAnchor *cp;
138+
uint64_t cpu_freq = estimate_cpu_freq(300);
139+
char *time_label = "Total time";
140+
141+
int indent = strlen(time_label);
142+
for (size_t i = 0; i < ANCHOR_CAPACITY; ++i) {
143+
cp = _Prof.anchors + i;
144+
if (cp->hits == 0) {
145+
continue;
146+
}
147+
sprintf(label, "%s[%zu]", cp->label, cp->hits);
148+
int len = strlen(label);
149+
indent = len > indent ? len : indent;
150+
}
151+
indent += 5;
152+
153+
total_elapsed = _Prof.stop - _Prof.start;
154+
print_header(fp, indent, time_label, total_elapsed, cpu_freq);
155+
156+
for (size_t i = 0; i < ANCHOR_CAPACITY; ++i) {
157+
cp = _Prof.anchors + i;
158+
if (cp->hits == 0) {
159+
continue;
160+
}
161+
sprintf(label, "%s[%zu]", cp->label, cp->hits);
162+
share = ((double)cp->elapsed_exclusive / (double)total) * 100;
163+
if (cp->elapsed_inclusive == cp->elapsed_exclusive) {
164+
print_cp(indent, label, cp->elapsed_exclusive, share, fp);
165+
} else {
166+
total_share = ((double)cp->elapsed_inclusive / (double)total) * 100;
167+
print_cp_child(indent, label, cp->elapsed_exclusive, share, total_share, fp);
168+
}
169+
if (cp->processed_byte_count) {
170+
static const double mb = 1024.0 * 1024.0;
171+
static const double gb = mb * 1024.0;
172+
173+
double seconds = (double)cp->elapsed_inclusive / cpu_freq;
174+
double bytes_per_second = cp->processed_byte_count / seconds;
175+
double mbs = cp->processed_byte_count / mb;
176+
double gb_per_second = bytes_per_second / gb;
177+
178+
if (isatty(fileno(fp))) {
179+
printf(C_CYAN " %.3fmb" C_RESET " at " C_MAGENTA "%.2fgb/s" C_RESET, mbs,
180+
gb_per_second);
181+
} else {
182+
printf(" %.3fmb at %.2fgb/s", mbs, gb_per_second);
183+
}
184+
}
185+
fprintf(fp, "\n");
186+
}
174187
}
175188

176-
AnchorBlock make_anchor_block(const char *label, size_t used_bytes)
189+
AnchorBlock
190+
make_anchor_block(const char *label, size_t used_bytes)
177191
{
178-
ProfileAnchor *cp = get_anchor(label);
179-
AnchorBlock anchor = { label, read_cpu_timer(), cp->elapsed_inclusive, used_bytes, CurrentAnchorLabel };
180-
CurrentAnchorLabel = (char*) label;
181-
return anchor;
192+
ProfileAnchor *cp = get_anchor(label);
193+
AnchorBlock anchor = {label, read_cpu_timer(), cp->elapsed_inclusive, used_bytes, CurrentAnchorLabel};
194+
CurrentAnchorLabel = (char *)label;
195+
return anchor;
182196
}
183197

184-
void read_anchor_block(const AnchorBlock *anchor)
198+
void
199+
read_anchor_block(const AnchorBlock *anchor)
185200
{
186-
uint64_t elapsed = read_cpu_timer() - anchor->start;
187-
prof_add_anchor(anchor, elapsed);
188-
CurrentAnchorLabel = anchor->parent_anchor;
201+
uint64_t elapsed = read_cpu_timer() - anchor->start;
202+
prof_add_anchor(anchor, elapsed);
203+
CurrentAnchorLabel = anchor->parent_anchor;
189204
}
190-

0 commit comments

Comments
 (0)