nicolas
/
triangular_arbitrage_bot
1
0
Fork 0
Code Issues Pull Requests Packages Projects Releases Wiki Activity

fix: timings use correct fields and clocks, match Python format 

- t-2_book_snapshot uses sig->book_ts_ms (not sig->ts_ms)
- All pipeline timings relative to exec_start_rt (realtime clock)
- Leg timings use monotonic clock (leg_timings array)
- execution_complete uses now_mono_ms() - exec_start_mono (not (now - now))
- Only include timing entries for fields that are non-zero
This commit is contained in:
nicolas 2026-05-27 09:39:14 -03:00
parent 8739c871d5
commit 0420d548d5
1 changed files with 58 additions and 20 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

78
src/executor.c
View File

@ -149,8 +149,9 @@ void executor_execute_triangle(executor_thread_t *et,
char ts_buf[32]; char ts_buf[32];
char corr_id[64]; char corr_id[64];
int64_t signal_received_ms = now_mono_ms(); int64_t exec_start_rt = now_realtime_ms();
int64_t exec_start = signal_received_ms; int64_t exec_start_mono = now_mono_ms();
double leg_timings[6] = {0}; /* leg0_order, leg0_fill, leg1_order, leg1_fill, leg2_order, leg2_fill */
snprintf(corr_id, sizeof(corr_id), "%08x%08x%08x%08x", snprintf(corr_id, sizeof(corr_id), "%08x%08x%08x%08x",
(unsigned)(uintptr_t)&sig->legs.legs[0] ^ (unsigned)sig->ts_ms, (unsigned)(uintptr_t)&sig->legs.legs[0] ^ (unsigned)sig->ts_ms,
(unsigned)sig->ts_ms ^ (unsigned)sig->book_ts_ms, (unsigned)sig->ts_ms ^ (unsigned)sig->book_ts_ms,
@ -212,9 +213,11 @@ void executor_execute_triangle(executor_thread_t *et,
fills[leg][5] = (double)(now_mono_ms() - t0); fills[leg][5] = (double)(now_mono_ms() - t0);
/* ── Timing: leg_order_fired ── */
if (leg < 6) leg_timings[leg * 2] = (double)(now_mono_ms() - exec_start_mono);
/* ── ORDER output ── */ /* ── ORDER output ── */
{ {
int64_t ref_ms = signal_received_ms;
format_ts(ts_buf, sizeof(ts_buf)); format_ts(ts_buf, sizeof(ts_buf));
executor_write_report( executor_write_report(
"%s ORDER | corr=%s | leg%d | %s | %s | vol=%.10g | " "%s ORDER | corr=%s | leg%d | %s | %s | vol=%.10g | "
@ -295,6 +298,9 @@ void executor_execute_triangle(executor_thread_t *et,
} }
} }
/* ── Timing: leg_fill_received ── */
if (leg < 6) leg_timings[leg * 2 + 1] = (double)(now_mono_ms() - exec_start_mono);
/* ── FILL output ── */ /* ── FILL output ── */
format_ts(ts_buf, sizeof(ts_buf)); format_ts(ts_buf, sizeof(ts_buf));
executor_write_report( executor_write_report(
@ -352,25 +358,57 @@ void executor_execute_triangle(executor_thread_t *et,
effective_bps = (profit / leg0_in) * 10000.0; effective_bps = (profit / leg0_in) * 10000.0;
} }
int64_t total_ms = now_mono_ms() - exec_start; int64_t total_ms = now_mono_ms() - exec_start_mono;
/* ── Build timing string (relative to signal_arrive realtime) ── */ /* ── Build timing string ── */
int64_t now_rt = now_realtime_ms(); double exec_complete = (double)(now_mono_ms() - exec_start_mono);
char timings_str[256] = ""; char timings_str[384] = "";
if (sig->t_sock_arrive_ms > 0) { int tp = 0;
snprintf(timings_str, sizeof(timings_str),
"t-2_book_snapshot=%.1fms " /* Pipeline timings (relative to signal receive time, realtime clock) */
"book_update_arrived=%.1fms " if (sig->book_ts_ms > 0 && sig->ts_ms > 0) {
"t-1_eval_complete=%.1fms " double t2 = (double)((int64_t)sig->book_ts_ms - exec_start_rt);
"t_signal_created=%.1fms " tp += snprintf(timings_str + tp, sizeof(timings_str) - tp,
"signal_received=0.0ms " "t-2_book_snapshot=%.1fms ", t2);
"execution_complete=%.1fms",
(double)(sig->ts_ms - now_rt),
(double)(sig->t_sock_arrive_ms - now_rt),
(double)(sig->t_arrive_ms - now_rt),
(double)(sig->t_eval_ms - now_rt),
(double)(now_rt - now_rt));
} }
if (sig->t_sock_arrive_ms > 0) {
double sa = (double)((int64_t)sig->t_sock_arrive_ms - exec_start_rt);
tp += snprintf(timings_str + tp, sizeof(timings_str) - tp,
"socket_arrived=%.1fms ", sa);
}
if (sig->t_arrive_ms > 0) {
double ba = (double)((int64_t)sig->t_arrive_ms - exec_start_rt);
tp += snprintf(timings_str + tp, sizeof(timings_str) - tp,
"book_update_arrived=%.1fms ", ba);
}
if (sig->t_eval_ms > 0) {
double te = (double)((int64_t)sig->t_eval_ms - exec_start_rt);
tp += snprintf(timings_str + tp, sizeof(timings_str) - tp,
"t-1_eval_complete=%.1fms ", te);
}
if (sig->ts_ms > 0) {
double sc = (double)((int64_t)sig->ts_ms - exec_start_rt);
tp += snprintf(timings_str + tp, sizeof(timings_str) - tp,
"t_signal_created=%.1fms ", sc);
}
tp += snprintf(timings_str + tp, sizeof(timings_str) - tp,
"signal_received=0.0ms ");
/* Leg execution timings (monotonic, relative to exec start) */
for (int l = 0; l < 3; l++) {
if (leg_timings[l * 2] > 0) {
tp += snprintf(timings_str + tp, sizeof(timings_str) - tp,
"leg%d_order_fired=%.1fms ", l, leg_timings[l * 2]);
}
if (leg_timings[l * 2 + 1] > 0) {
tp += snprintf(timings_str + tp, sizeof(timings_str) - tp,
"leg%d_fill_received=%.1fms ", l, leg_timings[l * 2 + 1]);
}
}
tp += snprintf(timings_str + tp, sizeof(timings_str) - tp,
"execution_complete=%.1fms", exec_complete);
/* ── Build fills string ── */ /* ── Build fills string ── */
char fills_str[1024] = ""; char fills_str[1024] = "";