diff --git a/src/executor.c b/src/executor.c index 5848752..2b4dafc 100644 --- a/src/executor.c +++ b/src/executor.c @@ -149,8 +149,9 @@ void executor_execute_triangle(executor_thread_t *et, char ts_buf[32]; char corr_id[64]; - int64_t signal_received_ms = now_mono_ms(); - int64_t exec_start = signal_received_ms; + int64_t exec_start_rt = now_realtime_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", (unsigned)(uintptr_t)&sig->legs.legs[0] ^ (unsigned)sig->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); + /* ── Timing: leg_order_fired ── */ + if (leg < 6) leg_timings[leg * 2] = (double)(now_mono_ms() - exec_start_mono); + /* ── ORDER output ── */ { - int64_t ref_ms = signal_received_ms; format_ts(ts_buf, sizeof(ts_buf)); executor_write_report( "%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 ── */ format_ts(ts_buf, sizeof(ts_buf)); executor_write_report( @@ -352,25 +358,57 @@ void executor_execute_triangle(executor_thread_t *et, 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) ── */ - int64_t now_rt = now_realtime_ms(); - char timings_str[256] = ""; - if (sig->t_sock_arrive_ms > 0) { - snprintf(timings_str, sizeof(timings_str), - "t-2_book_snapshot=%.1fms " - "book_update_arrived=%.1fms " - "t-1_eval_complete=%.1fms " - "t_signal_created=%.1fms " - "signal_received=0.0ms " - "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)); + /* ── Build timing string ── */ + double exec_complete = (double)(now_mono_ms() - exec_start_mono); + char timings_str[384] = ""; + int tp = 0; + + /* Pipeline timings (relative to signal receive time, realtime clock) */ + if (sig->book_ts_ms > 0 && sig->ts_ms > 0) { + double t2 = (double)((int64_t)sig->book_ts_ms - exec_start_rt); + tp += snprintf(timings_str + tp, sizeof(timings_str) - tp, + "t-2_book_snapshot=%.1fms ", t2); } + 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 ── */ char fills_str[1024] = "";