Skip to content

Commit 8c07fc2

Browse files
emerybergerclaude
andcommitted
Fix MySQL profiling issues: double delays, thundering herd, stale counters, and custom sync API
Address four issues reported when profiling MySQL after the LIEF/macOS port: 1a. Guard progress-point delay check with __APPLE__. On Linux, delays are already applied in the SIGPROF handler; calling add_delays() again at every COZ_PROGRESS hit caused double application and TPS collapse. 1b. Remove per-experiment local_delay sync block added in the macOS port. Forcing all threads to the same baseline caused a thundering herd of nanosleep calls under high concurrency. The existing cool-off period between experiments already naturally syncs threads via add_delays(). 4. Call process_samples() (not just add_delays()) in catch_up() and post_block() on Linux. Samples accumulate in per-thread perf_event buffers between 10ms timer signals; processing them ensures delay counters are current before unblocking other threads (BCOZ fix). 3. Add COZ_PRE_BLOCK, COZ_CATCH_UP, COZ_POST_BLOCK(skip_delays) macros and corresponding _coz_pre_block/_coz_post_block exports for programs using custom synchronization not intercepted by Coz (e.g., MySQL mutexes, RocksDB internal locks). 2. Add linear regression slope and R-squared columns to `coz plot --text` output to help users assess result reliability and optimization impact. Co-Authored-By: Claude Opus 4.6 <noreply@anthropic.com>
1 parent 9546ac1 commit 8c07fc2

5 files changed

Lines changed: 136 additions & 20 deletions

File tree

coz

Lines changed: 29 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -372,13 +372,36 @@ def calculate_speedups(data, min_points=1, min_delta=5):
372372
if len(measurements) >= min_points:
373373
# Calculate max speedup
374374
max_speedup = max(m[1] for m in measurements) if measurements else 0
375+
376+
# Calculate linear regression slope and R-squared
377+
slope = None
378+
r_squared = None
379+
if len(measurements) >= 2:
380+
n = len(measurements)
381+
sum_x = sum(m[0] for m in measurements)
382+
sum_y = sum(m[1] for m in measurements)
383+
sum_xy = sum(m[0] * m[1] for m in measurements)
384+
sum_x2 = sum(m[0] ** 2 for m in measurements)
385+
sum_y2 = sum(m[1] ** 2 for m in measurements)
386+
denom = n * sum_x2 - sum_x ** 2
387+
if denom != 0:
388+
slope = (n * sum_xy - sum_x * sum_y) / denom
389+
# R-squared: coefficient of determination
390+
ss_tot = sum_y2 - (sum_y ** 2) / n
391+
intercept = (sum_y - slope * sum_x) / n
392+
ss_res = sum((y - (intercept + slope * x)) ** 2 for x, y in measurements)
393+
if ss_tot > 0:
394+
r_squared = 1.0 - ss_res / ss_tot
395+
375396
results.append({
376397
'line': selected,
377398
'progress_point': pp_name,
378399
'measurements': measurements,
379400
'max_speedup': max_speedup,
380401
'num_points': len(measurements),
381-
'baseline_speedup': baseline_speedup
402+
'baseline_speedup': baseline_speedup,
403+
'slope': slope,
404+
'r_squared': r_squared
382405
})
383406

384407
# Sort by max speedup (highest first)
@@ -402,15 +425,17 @@ def print_text_summary(profile_path, results, experiment_count, runtime, samples
402425
max_line_len = max(max_line_len, 11) # "Source Line" header
403426

404427
# Print header
405-
header = f"{'Source Line':<{max_line_len}} | Max Speedup | Points"
428+
header = f"{'Source Line':<{max_line_len}} | {'Slope':>7} | {'R²':>5} | Max Speedup | Points"
406429
print(header)
407-
print('-' * max_line_len + '-+-------------+-------')
430+
print('-' * max_line_len + '-+---------+-------+-------------+-------')
408431

409432
# Print each result
410433
for r in results:
411434
speedup_pct = r['max_speedup'] * 100
412435
sign = '+' if speedup_pct >= 0 else ''
413-
print(f"{r['line']:<{max_line_len}} | {sign}{speedup_pct:>9.1f}% | {r['num_points']:>5}")
436+
slope_str = f"{r['slope']:>7.3f}" if r.get('slope') is not None else ' N/A'
437+
r2_str = f"{r['r_squared']:>5.2f}" if r.get('r_squared') is not None else ' N/A'
438+
print(f"{r['line']:<{max_line_len}} | {slope_str} | {r2_str} | {sign}{speedup_pct:>9.1f}% | {r['num_points']:>5}")
414439

415440
def print_scatter_plot(result):
416441
"""Print an ASCII scatter plot for a single result."""

include/coz.h

Lines changed: 69 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -43,6 +43,12 @@ typedef coz_counter_t* (*coz_get_counter_t)(int, const char*);
4343
// The type of the _coz_add_delays function
4444
typedef void (*coz_add_delays_t)(void);
4545

46+
// The type of the _coz_pre_block function
47+
typedef void (*coz_pre_block_t)(void);
48+
49+
// The type of the _coz_post_block function
50+
typedef void (*coz_post_block_t)(int);
51+
4652
// Locate and invoke _coz_get_counter
4753
static coz_counter_t* _call_coz_get_counter(int type, const char* name) {
4854
static unsigned char _initialized = 0;
@@ -88,9 +94,50 @@ static void _call_coz_add_delays(void) {
8894
if(fn) fn();
8995
}
9096

97+
// Locate and invoke _coz_pre_block
98+
static void _call_coz_pre_block(void) {
99+
static unsigned char _initialized = 0;
100+
static coz_pre_block_t fn;
101+
102+
if(!_initialized) {
103+
if(dlsym) {
104+
void* p = dlsym(RTLD_DEFAULT, "_coz_pre_block");
105+
memcpy(&fn, &p, sizeof(p));
106+
}
107+
_initialized = 1;
108+
}
109+
110+
if(fn) fn();
111+
}
112+
113+
// Locate and invoke _coz_post_block
114+
static void _call_coz_post_block(int skip_delays) {
115+
static unsigned char _initialized = 0;
116+
static coz_post_block_t fn;
117+
118+
if(!_initialized) {
119+
if(dlsym) {
120+
void* p = dlsym(RTLD_DEFAULT, "_coz_post_block");
121+
memcpy(&fn, &p, sizeof(p));
122+
}
123+
_initialized = 1;
124+
}
125+
126+
if(fn) fn(skip_delays);
127+
}
128+
129+
// On macOS, per-thread timers are not available so worker threads must check
130+
// their delay debt at progress points. On Linux, delays are already applied
131+
// in the SIGPROF handler via process_samples() -> add_delays(), so calling
132+
// add_delays() again at every progress-point hit causes double application
133+
// and TPS collapse under high concurrency.
134+
#ifdef __APPLE__
135+
# define _COZ_CHECK_DELAYS _call_coz_add_delays()
136+
#else
137+
# define _COZ_CHECK_DELAYS ((void)0)
138+
#endif
139+
91140
// Macro to initialize and increment a counter, then check for pending delays.
92-
// The delay check is critical on macOS where per-thread timers are not available,
93-
// ensuring worker threads apply delays at progress points.
94141
#define COZ_INCREMENT_COUNTER(type, name) \
95142
if(1) { \
96143
static unsigned char _initialized = 0; \
@@ -102,7 +149,7 @@ static void _call_coz_add_delays(void) {
102149
} \
103150
if(_counter) { \
104151
__atomic_add_fetch(&_counter->count, 1, __ATOMIC_RELAXED); \
105-
_call_coz_add_delays(); \
152+
_COZ_CHECK_DELAYS; \
106153
} \
107154
}
108155

@@ -115,6 +162,25 @@ static void _call_coz_add_delays(void) {
115162
#define COZ_BEGIN(name) COZ_INCREMENT_COUNTER(COZ_COUNTER_TYPE_BEGIN, name)
116163
#define COZ_END(name) COZ_INCREMENT_COUNTER(COZ_COUNTER_TYPE_END, name)
117164

165+
// Custom synchronization support.
166+
// Use these macros around blocking operations that Coz does not intercept
167+
// (e.g., custom mutexes, futex-based locks, RocksDB internal synchronization).
168+
//
169+
// COZ_PRE_BLOCK; // before blocking
170+
// my_custom_lock_acquire(&lock);
171+
// COZ_POST_BLOCK(1); // after blocking (1 = skip delays)
172+
//
173+
// // Before potentially unblocking another thread:
174+
// COZ_CATCH_UP;
175+
// my_custom_lock_release(&lock);
176+
//
177+
// COZ_POST_BLOCK(skip_delays):
178+
// skip_delays=1 when woken by another thread (e.g., mutex acquired)
179+
// skip_delays=0 when the wake may have been spurious or timed out
180+
#define COZ_PRE_BLOCK _call_coz_pre_block()
181+
#define COZ_CATCH_UP _call_coz_add_delays()
182+
#define COZ_POST_BLOCK(skip_delays) _call_coz_post_block(skip_delays)
183+
118184
#if defined(__cplusplus)
119185
}
120186
#endif

libcoz/libcoz.cpp

Lines changed: 18 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -54,6 +54,24 @@ extern "C" void _coz_add_delays() {
5454
}
5555
}
5656

57+
/**
58+
* Called by the application before a custom blocking operation.
59+
* For use with synchronization primitives not intercepted by Coz
60+
* (e.g., MySQL's custom mutexes, RocksDB internal locks).
61+
*/
62+
extern "C" void _coz_pre_block() {
63+
if(initialized) profiler::get_instance().pre_block();
64+
}
65+
66+
/**
67+
* Called by the application after a custom blocking operation completes.
68+
* If skip_delays is non-zero, delays inserted during the blocked period
69+
* are skipped (use when woken by another thread).
70+
*/
71+
extern "C" void _coz_post_block(int skip_delays) {
72+
if(initialized) profiler::get_instance().post_block(skip_delays != 0);
73+
}
74+
5775
#ifdef __APPLE__
5876
/**
5977
* Helper functions called from mac_interpose.cpp

libcoz/profiler.cpp

Lines changed: 0 additions & 13 deletions
Original file line numberDiff line numberDiff line change
@@ -299,19 +299,6 @@ void profiler::profiler_thread(spinlock& l) {
299299
}
300300
_latency_points_lock.unlock();
301301

302-
// Sync all non-blocked threads' local_delay to global_delay before starting.
303-
// This prevents stale residual from a previous experiment from causing threads
304-
// to skip delays (local > global branch in add_delays).
305-
// Skip blocked threads — their pre_block/post_block mechanism handles accounting.
306-
{
307-
size_t current_global = _global_delay.load();
308-
_thread_states.for_each([current_global](pid_t tid, thread_state* state) {
309-
if(!state->is_blocked.load()) {
310-
state->local_delay.store(current_global);
311-
}
312-
});
313-
}
314-
315302
#ifdef __APPLE__
316303
// Reset overshoot counter for this experiment
317304
g_experiment_overshoot.store(0, std::memory_order_relaxed);

libcoz/profiler.h

Lines changed: 20 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -169,7 +169,16 @@ class profiler {
169169
// Handle all samples and add delays as required
170170
if(_experiment_active) {
171171
state->set_in_use(true);
172+
#ifndef __APPLE__
173+
// On Linux, samples accumulate in the per-thread perf_event buffer between
174+
// timer signals (every 10ms). Process pending samples so the delay counters
175+
// are up-to-date before we potentially unblock another thread.
176+
// process_samples() calls add_delays() at the end.
177+
process_samples(state);
178+
#else
179+
// On macOS, samples are processed centrally by the profiler thread.
172180
add_delays(state);
181+
#endif
173182
state->set_in_use(false);
174183
}
175184
}
@@ -197,7 +206,18 @@ class profiler {
197206
state->local_delay.fetch_add(_global_delay.load() - state->pre_block_time);
198207
}
199208

209+
// Must clear is_blocked before process_samples() because add_delays()
210+
// (called at the end of process_samples()) returns early if is_blocked is true.
200211
state->is_blocked.store(false);
212+
213+
#ifndef __APPLE__
214+
// On Linux, process any samples that accumulated while this thread was
215+
// blocked to bring its delay counters up to date (BCOZ fix).
216+
if(_experiment_active) {
217+
process_samples(state);
218+
}
219+
#endif
220+
201221
state->set_in_use(false);
202222
}
203223

0 commit comments

Comments
 (0)