From 36394bc3176671cc87cf0280ca6502ff30587be0 Mon Sep 17 00:00:00 2001 From: Claude Date: Wed, 15 Jul 2026 01:17:52 +0000 Subject: [PATCH] Profiling: fix the phase accounting so 'Other' stops swallowing the disk stall MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The dashboard's wall-time stack assumed ewait = felt I/O stall and edisk = overlapped read service, but the engine measured neither: t_ewait was declared and reported yet never incremented (the blue 'I/O wait' segment always read 0.00s), while t_edisk accumulated on the COMPUTE thread — blocking OMP loads, PIPE dispatch, pipe_wait spins — i.e. exactly the felt stall. The UI excluded it from the stack as 'overlapped', so the whole disk stall landed in 'Other' (e.g. 46.9s Other vs 45.3s disk on a 54.1s turn). Now the semantics match the contract: - t_ewait accumulates the compute-thread stall (blocking loads, PIPE dispatch, pipe_wait spins) and feeds the in-stack I/O wait. - Disk service is real: expert_load is timed on whichever thread runs the read (PIPE workers, OMP loaders, pilot) into an atomic ns counter (g_edisk_ns) — thread-seconds, overlapped with compute. - prof_report's I/O share and verdict use the felt wait only, and the expert I/O line prints 'read service / felt wait' so the wait:service gap shows how well PIPE is hiding the reads. PROF wire format, /profile JSON and the web UI are unchanged — the dashboard's existing assumptions are simply true now. Co-Authored-By: Claude Fable 5 Claude-Session: https://claude.ai/code/session_01Dd4hHD2Dsvgr7VAwEVFqWK --- c/glm.c | 62 +++++++++++++++++++++++++++++++++++++++------------------ 1 file changed, 43 insertions(+), 19 deletions(-) diff --git a/c/glm.c b/c/glm.c index 5412cce..8f67b05 100644 --- a/c/glm.c +++ b/c/glm.c @@ -195,7 +195,9 @@ typedef struct { uint64_t route_slots, route_swaps; /* CACHE_ROUTE: slots chosen / substituted vs true top-K */ uint64_t route_agree_hit, route_agree_tot; /* ROUTE_AGREE: |chosen ∩ true top-K| / K */ double route_kl_sum; uint64_t route_kl_n; /* mean KL(true||chosen) on gate mass */ - double t_edisk, t_ewait, t_emm, t_attn, t_kvb, t_head;/* profiling: dove va il tempo */ + double t_ewait, t_emm, t_attn, t_kvb, t_head;/* profiling: dove va il tempo (wall del + * thread di compute; il servizio disco + * overlappato vive in g_edisk_ns) */ double t_aproj,t_acore,t_aout; /* attention breakdown */ int64_t resident_bytes; /* DISK_SPLIT=1: split dei DISK LOAD (miss LRU -> expert_load) per contesto e per tipo @@ -285,6 +287,14 @@ static double rss_gb(void){ struct rusage r; getrusage(RUSAGE_SELF,&r); * every mode stays byte-identical. */ static int g_prof=0; static _Atomic int64_t g_prof_io; /* bytes pread()/faulted from expert files */ +/* Disk service: wall time inside expert_load on whichever thread runs the read + * (PIPE I/O workers, OMP loaders, the speculative pilot). It overlaps compute, + * so it is NOT a wall-time phase — the stall the compute thread actually felt + * is m->t_ewait. Thread-seconds, so it can exceed wall time under parallel + * reads; wait << service means overlap/parallelism is hiding the reads, + * wait ~ service means the loads block the compute thread. */ +static _Atomic int64_t g_edisk_ns; +static double edisk_s(void){ return atomic_load_explicit(&g_edisk_ns,memory_order_relaxed)*1e-9; } #define PROF_LAT_CAP 32768 static double g_prof_lat[PROF_LAT_CAP]; /* per-forward decode wall clock (ring) */ static uint64_t g_prof_nlat; /* forwards recorded (monotonic) */ @@ -295,7 +305,7 @@ typedef struct { int64_t io; uint64_t hits,miss,ereq,n_fw,n_emit,nlat; } ProfBase; static void prof_base(Model *m, ProfBase *b){ - b->edisk=m->t_edisk; b->ewait=m->t_ewait; b->emm=m->t_emm; + b->edisk=edisk_s(); b->ewait=m->t_ewait; b->emm=m->t_emm; b->attn=m->t_attn; b->head=m->t_head; b->io=atomic_load_explicit(&g_prof_io,memory_order_relaxed); b->hits=m->hits; b->miss=m->miss; b->ereq=m->ereq; @@ -1663,7 +1673,7 @@ static int pread_full(int fd, void *buf, int64_t n, int64_t off, const char *tag } return 0; } -static int expert_load(Model *m, int layer, int eid, ESlot *s, int fatal){ +static int expert_load_impl(Model *m, int layer, int eid, ESlot *s, int fatal){ #ifdef COLI_CUDA /* A live REPIN may reuse a GPU-enabled pinned slot for a different expert. * Keep its tier assignment, but invalidate the old device weights. */ @@ -1842,6 +1852,14 @@ static int expert_load(Model *m, int layer, int eid, ESlot *s, int fatal){ } s->eid=eid; return 0; } +/* Every expert read goes through here: time the whole load (pread/fault + + * bookkeeping) on the thread that runs it, into the disk-service counter. */ +static int expert_load(Model *m, int layer, int eid, ESlot *s, int fatal){ + double t0=now_s(); + int rc=expert_load_impl(m,layer,eid,s,fatal); + atomic_fetch_add_explicit(&g_edisk_ns,(int64_t)((now_s()-t0)*1e9),memory_order_relaxed); + return rc; +} #ifdef __linux__ /* io_uring expert batches. One owner prepares all reads for a block, submits @@ -3040,11 +3058,12 @@ static void moe(Model *m, Layer *l, int layer, float *x, int S, float *out, int double t0=now_s(); int eids[64]; for(int q=0;qt_edisk += now_s()-t0; /* dispatch only; real reads hide behind matmul */ + m->t_ewait += now_s()-t0; /* dispatch only; the reads overlap matmul and + * are timed as service inside expert_load */ } else { double t0=now_s(); /* ORIGINALE: blocking parallel load */ #pragma omp parallel for schedule(dynamic,1) for(int q=0;qws[q],1); - m->t_ewait += now_s()-t0; } /* blocking: whole load stalls compute */ + m->t_ewait += now_s()-t0; } /* compute thread blocked for the whole load */ } /* I/O ASINCRONO: readahead (WILLNEED) del blocco SUCCESSIVO mentre calcoliamo * questo — il kernel legge in background, le pread dopo trovano cache calda */ @@ -3073,7 +3092,7 @@ static void moe(Model *m, Layer *l, int layer, float *x, int S, float *out, int * correct (and free) when a subset falls back to the CPU. */ if(g_pipe && nmiss){ double tw=now_s(); for(int q=0;qt_ewait += now_s()-tw; } /* blocking: drain stalled compute */ + m->t_ewait += now_s()-tw; } MB_BUILD(1, 0); /* missed experts, now loaded */ if(nbb>0){ double t0=now_s(); @@ -3097,7 +3116,7 @@ static void moe(Model *m, Layer *l, int layer, float *x, int S, float *out, int * Stays ABOVE the METAL skip: a subset that fell back to the CPU still needs its * slot drained here, and under METAL the block-level drain above already ran (this * spin is then a no-op). */ - if(g_pipe && qof[j]>=0){ double tw=now_s(); pipe_wait(qof[j]); m->t_ewait += now_s()-tw; } /* blocking */ + if(g_pipe && qof[j]>=0){ double tw=now_s(); pipe_wait(qof[j]); m->t_ewait += now_s()-tw; } #ifdef COLI_METAL /* skip the subsets already computed on GPU */ if(g_metal_enabled && ((is_miss[j] && !cpu_miss) || (!is_miss[j] && !cpu_res))) continue; @@ -4378,10 +4397,10 @@ static void generate(Model *m, const int *prompt, int np, int n_new, int *out){ } static void profile_print(Model *m, double elapsed){ - double accounted=m->t_edisk+m->t_ewait+m->t_emm+m->t_attn+m->t_head; + double accounted=m->t_ewait+m->t_emm+m->t_attn+m->t_head; printf("PROFILE: expert-disk %.3fs service / %.3fs wait | expert-matmul %.3fs | attention %.3fs " "(including kvb %.3fs) | lm_head %.3fs | other %.3fs\n", - m->t_edisk,m->t_ewait,m->t_emm,m->t_attn,m->t_kvb,m->t_head,elapsed-accounted); + edisk_s(),m->t_ewait,m->t_emm,m->t_attn,m->t_kvb,m->t_head,elapsed-accounted); printf("ATTENTION: projection/RoPE %.3fs | score-softmax-value %.3fs | output projection %.3fs\n", m->t_aproj,m->t_acore,m->t_aout); #ifdef COLI_METAL @@ -4396,8 +4415,9 @@ static void profile_print(Model *m, double elapsed){ } static void profile_reset(Model *m){ - m->t_edisk=m->t_ewait=m->t_emm=m->t_attn=m->t_kvb=m->t_head=0; + m->t_ewait=m->t_emm=m->t_attn=m->t_kvb=m->t_head=0; m->t_aproj=m->t_acore=m->t_aout=0; + atomic_store_explicit(&g_edisk_ns,0,memory_order_relaxed); } /* PROF=1 report: forward-latency percentiles, expert I/O totals, phase shares @@ -4430,17 +4450,19 @@ static void prof_report(Model *m, const ProfBase *b, double elapsed, int tokens, double eb=(double)expert_bytes_probe(m,m->ebits); int pinned=0,lru=0; for(int i=0;i<=c->n_layers;i++){ if(m->npin)pinned+=m->npin[i]; if(m->ecn)lru+=m->ecn[i]; } + double io_w=m->t_ewait-b->ewait; /* stall the compute thread felt */ + double io_svc=edisk_s()-b->edisk; /* read service on the loading threads (overlaps compute) */ fprintf(f,"[PROF] expert I/O: %.3f GB fetched (%.1f MB/token, %.2f GB/s over the run%s) | " - "hit %.1f%% (%llu hit / %llu load) | %.1f loads/token\n", + "hit %.1f%% (%llu hit / %llu load) | %.1f loads/token | %.1fs read service / %.1fs felt wait\n", io/1e9, tokens>0?io/1e6/tokens:0.0, io/1e9/elapsed, g_mmap?"; COLI_MMAP=1: page cache may serve part":"", - hitp,(unsigned long long)dh,(unsigned long long)dm, tokens>0?(double)dq/tokens:0.0); + hitp,(unsigned long long)dh,(unsigned long long)dm, tokens>0?(double)dq/tokens:0.0, + io_svc,io_w); fprintf(f,"[PROF] resident experts: %d pinned (%.1f GB) + %d in LRU (%.1f GB, cap %d/layer)\n", pinned,pinned*eb/1e9,lru,lru*eb/1e9,m->ecap); - double io_s=(m->t_edisk-b->edisk)+(m->t_ewait-b->ewait); double emm=m->t_emm-b->emm, attn=m->t_attn-b->attn, head=m->t_head-b->head; - double other=elapsed-io_s-emm-attn-head; if(other<0) other=0; - double f_io=io_s/elapsed, f_emm=emm/elapsed, f_attn=attn/elapsed; + double other=elapsed-io_w-emm-attn-head; if(other<0) other=0; + double f_io=io_w/elapsed, f_emm=emm/elapsed, f_attn=attn/elapsed; fprintf(f,"[PROF] time shares: expert-I/O %.0f%% | expert-matmul %.0f%% | attention %.0f%% | lm_head %.0f%% | other %.0f%%\n", 100*f_io,100*f_emm,100*f_attn,100*head/elapsed,100*other/elapsed); if(f_io>=0.30){ @@ -4894,12 +4916,14 @@ static void mux_done(Model *m, ServeCtx *sc, ServeReq *r){ hits_emit(m); /* PROF: per-turn phase timings for the dashboard profiling page — * "PROF ". - * With KV_SLOTS>1 concurrent slots share the batched forwards, so the shares - * describe the whole engine over the window, not the single request (same - * convention as the STAT hit% below). */ + * edisk = disk service (expert_load wall on the reading threads, overlaps + * compute); ewait = the stall the compute thread felt — only ewait belongs + * in a wall-time breakdown. With KV_SLOTS>1 concurrent slots share the + * batched forwards, so the shares describe the whole engine over the + * window, not the single request (same convention as the STAT hit% below). */ printf("PROF %.3f %d %d %.3f %.3f %.3f %.3f %.3f %llu\n",dt, r->prompt_tokens,r->emitted, - m->t_edisk-r->pb.edisk,m->t_ewait-r->pb.ewait,m->t_emm-r->pb.emm, + edisk_s()-r->pb.edisk,m->t_ewait-r->pb.ewait,m->t_emm-r->pb.emm, m->t_attn-r->pb.attn,m->t_head-r->pb.head, (unsigned long long)(m->n_fw-r->pb.n_fw)); printf("DONE %llu STAT %d %.2f %.1f %.2f %d %d\n",r->id,r->emitted,