package monthlyusagehistory import ( "context" "sync" "time" "github.com/gogf/gf/v2/frame/g" ) // Producer-local telemetry: no run/archive schema changes and no assertion of // consumer readiness. Empty queues alone do not prove consumer starvation. type supplyChannel struct { stage string pending int version uint64 ended bool firstQuery, firstEnqueue *int64 changed time.Time stageDuration map[string]time.Duration validSamples, missingSamples int64 } type supplyObservation struct { mu sync.Mutex started time.Time channels map[string]*supplyChannel } func (o *supplyObservation) event(key, stage string, pending int, added, ended bool, now time.Time) { o.mu.Lock() defer o.mu.Unlock() s := o.channels[key] if s == nil { return } s.stageDuration[s.stage] += now.Sub(s.changed) s.changed, s.stage, s.pending, s.ended = now, stage, pending, ended s.version++ if stage == "sql_query" && s.firstQuery == nil { v := now.Sub(o.started).Milliseconds() s.firstQuery = &v } if added && s.firstEnqueue == nil { v := now.Sub(o.started).Milliseconds() s.firstEnqueue = &v } } // Preserve fractional milliseconds across transitions; round only for logs. func (s *supplyChannel) stageMilliseconds(now time.Time) map[string]int64 { if !s.ended { s.stageDuration[s.stage] += now.Sub(s.changed) s.changed = now } ms := make(map[string]int64, len(s.stageDuration)) for stage, duration := range s.stageDuration { ms[stage] = duration.Milliseconds() } return ms } func (p *Producer) observe(key, stage string, pending int, added, ended bool) { if p.observation != nil { p.observation.event(key, stage, pending, added, ended, time.Now()) } } // Queue-only samples mirror e6ec5b8: cardinalities, never task bodies. All keys // share the run hash tag, and round/producer state is checked in the same Lua. // Leases are token HASHes, not ZSets; future scores include leased members. const supplySampleScript = ` local run=redis.call('HMGET',KEYS[1],'runId','status','currentRound','producerDone','syncType') local known=run[1] and run[2] and run[3] and run[4] local eligible=known and (run[2]=='producing' or run[2]=='running') and run[3]=='1' and run[4]=='0' and run[5]~='replay' local blocked=redis.call('HGET',KEYS[1],'blocked:'..ARGV[2]) return {known and 1 or 0,(eligible and blocked~='1') and 1 or 0,redis.call('ZCOUNT',KEYS[2],'-inf',ARGV[1]),redis.call('HLEN',KEYS[3]),redis.call('ZCOUNT',KEYS[2],'('..ARGV[1],'+inf')} ` func (p *Producer) sampleSupply(ctx context.Context, run, key string) ([]int64, error) { meta, err := p.store.RunMetaKey(run) if err != nil { return nil, err } active, err := p.store.RoundActiveKey(run, 1, key) if err != nil { return nil, err } lease, err := p.store.RoundLeaseKey(run, 1, key) if err != nil { return nil, err } result, err := p.store.RedisClient().Eval(ctx, supplySampleScript, 3, []string{meta, active, lease}, []any{time.Now().UnixMilli(), key}) if err != nil { return nil, err } return result.Int64s(), nil } func (p *Producer) startObservation(ctx context.Context, run string, keys []string, started time.Time) func() { o := &supplyObservation{started: started, channels: make(map[string]*supplyChannel, len(keys))} for _, key := range keys { o.channels[key] = &supplyChannel{stage: "initializing", changed: started, stageDuration: make(map[string]time.Duration)} } p.observation = o stop, done := make(chan struct{}), make(chan struct{}) go func() { defer close(done) ticker := time.NewTicker(time.Second) defer ticker.Stop() for { select { case <-ctx.Done(): return case <-stop: return case <-ticker.C: for _, key := range keys { select { case <-stop: return case <-ctx.Done(): return default: } o.mu.Lock() s := o.channels[key] version, ended := s.version, s.ended o.mu.Unlock() if ended { continue } sampleCtx, cancel := context.WithTimeout(ctx, 500*time.Millisecond) values, err := p.sampleSupply(sampleCtx, run, key) cancel() o.mu.Lock() known := err == nil && len(values) == 5 && values[0] == 1 && s.version == version && !s.ended stage, pending := s.stage, s.pending if known { s.validSamples++ } else { s.missingSamples++ } o.mu.Unlock() // Logging must not hold the mutex used by producer progress. if known { g.Log().Infof(ctx, "event=monthly_usage_history_supply status=sample runId=%s chanKey=%s stage=%s pending=%d firstRoundEligible=%t ready=%d leases=%d futureIncludingLeases=%d consumerEligibility=unknown", run, key, stage, pending, values[1] == 1, values[2], values[3], values[4]) } else { g.Log().Infof(ctx, "event=monthly_usage_history_supply status=unknown runId=%s chanKey=%s stage=%s pending=%d consumerEligibility=unknown", run, key, stage, pending) } } } } }() return func() { close(stop) <-done o.mu.Lock() defer o.mu.Unlock() for _, key := range keys { s := o.channels[key] stageMS := s.stageMilliseconds(time.Now()) query, enqueue := int64(-1), int64(-1) if s.firstQuery != nil { query = *s.firstQuery } if s.firstEnqueue != nil { enqueue = *s.firstEnqueue } g.Log().Infof(ctx, "event=monthly_usage_history_supply status=ended runId=%s chanKey=%s firstQueryMs=%d firstEnqueueMs=%d stageMs=%v validSamples=%d missingSamples=%d terminalStage=%s consumerEligibility=unknown", run, key, query, enqueue, stageMS, s.validSamples, s.missingSamples, s.stage) } p.observation = nil } }