iotlcm/worker-svr/internal/producer/monthlyusagehistory/supply_observation.go

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
	}
}