diff --git a/ENVIRONMENT_VARIABLES.md b/ENVIRONMENT_VARIABLES.md index 13a7f292e..a3a79a5fb 100644 --- a/ENVIRONMENT_VARIABLES.md +++ b/ENVIRONMENT_VARIABLES.md @@ -111,6 +111,20 @@ This document lists all environment variables used by the Substreams project, or ### Debugging and Logging +#### `SUBSTREAMS_PROGRESS_LOG_FIRST_DELAY` +**Delay before the first request progress log** +- **Purpose**: Override how long tier1 waits before emitting the first `substreams request progress` log of a request +- **Usage**: Set to any Go duration (ex: `30s`, `2m`). Must be greater than 0; an invalid or non-positive value panics at startup +- **Default**: `1m` +- **Location**: `metrics/progress_log.go` + +#### `SUBSTREAMS_PROGRESS_LOG_INTERVAL` +**Interval between request progress logs** +- **Purpose**: Override the interval between subsequent `substreams request progress` logs, after the first one. This only changes how often the line is printed: the `_5m` values on it always cover a fixed trailing 5 minutes +- **Usage**: Set to any Go duration (ex: `1m`, `10m`). Must be greater than 0; an invalid or non-positive value panics at startup +- **Default**: `5m` +- **Location**: `metrics/progress_log.go` + #### `SUBSTREAMS_PRINT_STACK` **Debug stack traces** - **Purpose**: Enable printing of stack traces for debugging execution issues diff --git a/docs/release-notes/change-log.md b/docs/release-notes/change-log.md index be06e8c7d..23fff90b4 100644 --- a/docs/release-notes/change-log.md +++ b/docs/release-notes/change-log.md @@ -23,8 +23,14 @@ The format is based on [Keep a Changelog](https://keepachangelog.com/en/1.0.0/), - CLI: `substreams-sink-sql` is now part of the `substreams` CLI: `substreams sink postgres {setup,generate-csv,inject-csv,tools}` and `substreams sink clickhouse {setup,tools}`, where the engine command itself runs the sink. Both the sink and `setup` auto-detect the mode from the output module's type (`DatabaseChanges` → `schema.sql`, any other proto → relational mappings). See the [migration guide](https://docs.substreams.dev/how-to-guides/sinks/sql/migration) for the full command, flag, and operator (Docker image) mapping. +- Server: tier1 emits a periodic `substreams request progress` log per request (after 1 minute, then every 5 minutes) meant to answer "why is my substreams slow?" while the request is still running: phase, per-stage module and job progress, external call cost, last job error, and time spent blocked writing to the consumer. It ends with a short `hints` list naming the likely bottleneck when one is detected. Rates and deltas are suffixed `_5m` and cover a fixed trailing 5 minutes whatever the emission interval is; cadence is tunable with `SUBSTREAMS_PROGRESS_LOG_FIRST_DELAY` and `SUBSTREAMS_PROGRESS_LOG_INTERVAL`. + +- Server: tier2 reports its progress every 10 seconds while a block is being processed, instead of only once the block completes, and `ExternalCallMetric` gained `failed_count`, `in_flight_count`, `oldest_in_flight_ms` and `oldest_in_flight_block`. An `eth_call` retrying against an unreachable endpoint is a single wasm extension call that can last minutes: it used to be completely invisible to tier1 until the segment timed out. + - Server: new `substreams_undo_signal_distance_blocks` prometheus histogram, observing how many blocks each `BlockUndoSignal` sent to clients reverts, labeled by `source` (`reorg` when a fork is seen while streaming, `cursor_resolution` when the cursor of an incoming request points to a block that was reorged out). Its `_count` gives the total number of undo signals sent; subtracting the `le="5"` bucket from it gives the number of large ones. Undo signals reverting more than 5 blocks are also logged as a warning with `trace_id`, `head`, `revert_up_to`, `distance` and, on the `cursor_resolution` path, the client `cursor`. +- CLI: new `substreams tools simulate-slow-reader [] --delay ` command, consuming a substreams slowly enough to exert real back-pressure on the server, to exercise the "consumer is the bottleneck" reporting. + ### Changed - Sink: **Breaking** the `handleSessionInit` callback passed to `sink.NewSinkerFullHandlers` and `sink.NewSinkerFullHandlersWithPartial` now receives a `*pbsubstreamsrpcv3.Request` instead of a `*pbsubstreamsrpc.Request` (`rpc/v2`), matching both the `SinkerSessionInitHandler` interface and the request the sinker actually sends. The two disagreed, so the sinker's type assertion never matched and the callback was never invoked — no behavior can depend on it today. diff --git a/metrics/progress_log.go b/metrics/progress_log.go new file mode 100644 index 000000000..69ab5d273 --- /dev/null +++ b/metrics/progress_log.go @@ -0,0 +1,1080 @@ +package metrics + +import ( + "cmp" + "context" + "fmt" + "os" + "slices" + "strings" + "time" + + "github.com/dustin/go-humanize" + "go.uber.org/zap" + "go.uber.org/zap/zapcore" +) + +// The periodic progress log answers one question for whoever reads it: "why is my +// substreams slow?". It is emitted once shortly after the request starts (so a request +// that dies young still leaves a trace) and then at a slow interval, on tier1 only. +var ( + // FirstProgressLogDelay is how long we wait before the very first progress log. Short + // enough to be useful on a request that fails early, long enough that the numbers mean + // something. Overridable with SUBSTREAMS_PROGRESS_LOG_FIRST_DELAY. + FirstProgressLogDelay = 1 * time.Minute + // ProgressLogInterval is the steady-state interval between progress logs. Overridable + // with SUBSTREAMS_PROGRESS_LOG_INTERVAL. + ProgressLogInterval = 5 * time.Minute +) + +const ( + EnvProgressLogFirstDelay = "SUBSTREAMS_PROGRESS_LOG_FIRST_DELAY" + EnvProgressLogInterval = "SUBSTREAMS_PROGRESS_LOG_INTERVAL" +) + +func init() { + FirstProgressLogDelay = progressLogDurationFromEnv(EnvProgressLogFirstDelay, FirstProgressLogDelay) + ProgressLogInterval = progressLogDurationFromEnv(EnvProgressLogInterval, ProgressLogInterval) +} + +// progressLogDurationFromEnv reads a duration override. A non-positive value would turn the +// reporting loop into a busy loop, so it is rejected outright rather than silently ignored: +// an operator setting this wants a specific cadence and needs to hear about a typo. +func progressLogDurationFromEnv(name string, fallback time.Duration) time.Duration { + value := os.Getenv(name) + if value == "" { + return fallback + } + parsed, err := time.ParseDuration(value) + if err != nil { + panic(fmt.Errorf("invalid value for env var %s: %w", name, err)) + } + if parsed <= 0 { + panic(fmt.Errorf("invalid value for env var %s: must be greater than 0, got %s", name, value)) + } + return parsed +} + +// Bounds on what a single log line may contain. A request can have hundreds of modules and +// jobs; the line must stay readable and must never grow with the size of the run. +const ( + maxLoggedModules = 20 + maxLoggedStages = 12 + maxLoggedExternalCalls = 5 + maxLoggedHints = 6 +) + +// Thresholds used to decide whether a hint is worth printing. They are deliberately +// generous: a hint that fires on a healthy request is worse than no hint at all. +const ( + // A tier2 job is expected to complete within 1 to 10 minutes. + slowJobThreshold = 15 * time.Minute + // How long a job must have been running before the rate it holds is worth extrapolating + // from: a projection off the first couple of blocks would be noise. + minJobRateSample = 30 * time.Second + // Share of the window that must have been spent blocked inside SendMsg before the consumer + // can be called the bottleneck. Set below half because the gRPC send buffer absorbs a good + // part of a slow consumer's lag: a client taking seconds per block still leaves the server + // unblocked most of the time, so a majority share only shows up on an extremely slow one. + sendBlockedShareToReport = 0.35 + // A share computed over a window this short is noise, whatever it says: a request seconds + // old has not lived long enough for any proportion to mean anything. + minWindowForShare = 30 * time.Second + // A single external call (eth_call & friends) taking this long is worth mentioning. + slowExternalCallAvg = 100 * time.Millisecond + // Calls per block above this means the module itself is call-hungry. + highExternalCallsPerBlock = 20 + // An external call that has been waiting this long is not slow, it is stuck. + stuckExternalCall = 30 * time.Second + // Partial store segments waiting to be squashed. Counted in segments rather than blocks + // so the threshold means the same thing on a chain bundling 1000 blocks per segment and + // on one bundling 10000. A handful of partials waiting is normal — jobs finish faster than + // the squasher merges and it catches up — so what matters is the backlog *holding*, hence + // the second threshold. + squashingBehindSegments = 5 + squashingBehindFor = 2 * time.Minute +) + +// StageProgress is a point-in-time view of one stage of the parallel phase: what it executes, +// the range of work it is planned to cover for this whole request, and how far it got. It is +// pushed by the orchestrator's Stages while the parallel phase runs. +type StageProgress struct { + Stage int + + // Stores and Mappers name the modules this stage executes; index modules are reported as + // mappers, they behave the same from here. + Stores []string + Mappers []string + + // PlannedFirstJobStartBlock and PlannedLastJobStopBlock bound the work this stage is + // expected to do over the session, straight from the request plan — not from what the + // scheduler has gotten around to so far. Both are 0 when the stage has nothing to do. + PlannedFirstJobStartBlock uint64 + PlannedLastJobStopBlock uint64 + + // HighestContiguousBlock is the exclusive end block up to which the whole stage is + // immediately usable: the lowest such block across its modules, since a stage is only as + // advanced as its least advanced module. For stores it stops at the last *squashed* + // segment — partials that exist but were not merged yet are excluded on purpose and + // reported separately in BlocksReadyForSquashing. + HighestContiguousBlock uint64 + + // SegmentsReadyForSquashing counts the partial store segments sitting above the + // contiguous prefix, waiting for the squasher. Always 0 for a stage that has no store. + SegmentsReadyForSquashing uint64 +} + +// stageJobStats is the per-stage job accounting behind the "jobs" section of the progress +// log. Fields prefixed with `window` are reset on every report, so they read as +// "since the last progress log" rather than "since the beginning of time". +type stageJobStats struct { + scheduled uint64 + completed uint64 + failed uint64 + cancelled uint64 + retried uint64 + delayed uint64 + + lastCompletedStopBlock uint64 + + window windowedStage +} + +type durationStats struct { + count uint64 + total time.Duration + minimum time.Duration + maximum time.Duration + + // blocks is the number of blocks carried by the timed messages; a message can hold + // several blocks when the client supports buffering. + blocks uint64 +} + +func (d durationStats) average() time.Duration { + if d.count == 0 { + return 0 + } + return d.total / time.Duration(d.count) +} + +func (d durationStats) averagePerBlock() time.Duration { + if d.blocks == 0 { + return 0 + } + return d.total / time.Duration(d.blocks) +} + +// MarshalLogObject reports what sending cost over the window. +// +// The timings are `SendMsg` durations, and `SendMsg` returns as soon as the message fits in +// the gRPC flow-control window — it blocks only once that window is full, until the consumer +// drains it. So the distribution is bimodal: near-zero while there is room, then one call +// stalling for as long as the consumer takes to read a whole window's worth of blocks. That +// makes a single stall a poor measure of how slow the consumer is (it measures the buffer as +// much as the client), while the total time blocked over the window is a sound one. +func (d durationStats) MarshalLogObject(encoder zapcore.ObjectEncoder) error { + encoder.AddUint64("blocks", d.blocks) + if d.count == 0 { + // Nothing was sent over the window. Printing a wall of "0s" next to the lifetime + // counters reads as a contradiction ("118 blocks sent, 0s to send them"), when it + // really means the stream has not moved for the whole period. + return nil + } + encoder.AddString("blocked", humanDuration(d.total)) + encoder.AddString("avg_per_block", humanDuration(d.averagePerBlock())) + encoder.AddString("longest_stall", humanDuration(d.maximum)) + return nil +} + +// RecordBlockSent should be called once per message actually carrying block data to the +// consumer, with the time the `SendMsg` call took and the number of blocks in that message +// (messages can be batched). Only the send itself must be timed: this is what tells a slow +// client apart from a slow pipeline. +func (s *Stats) RecordBlockSent(elapsed time.Duration, blockCount int) { + s.Lock() + defer s.Unlock() + blocks := uint64(max(blockCount, 0)) + s.blockSendWindow.record(time.Now(), elapsed, blocks) + s.blocksSent += blocks +} + +// RecordStagesProgress is called by the orchestrator's Stages, at most once per second, +// with the per-stage, per-module state of the parallel processing. +func (s *Stats) RecordStagesProgress(progress []StageProgress) { + s.Lock() + defer s.Unlock() + + // Remember when each stage's squash backlog started, so a burst that the squasher works off + // in seconds can be told apart from one it is not keeping up with. + now := time.Now() + if s.squashBacklogSince == nil { + s.squashBacklogSince = make(map[int]time.Time, len(progress)) + } + for _, stage := range progress { + if stage.SegmentsReadyForSquashing < squashingBehindSegments { + delete(s.squashBacklogSince, stage.Stage) + continue + } + if s.squashBacklogSince[stage.Stage].IsZero() { + s.squashBacklogSince[stage.Stage] = now + } + } + + s.stagesProgress = progress +} + +// RecordStreamingFirstSegment flags the window during which the output the client receives +// comes straight from a tier2 job rather than from the exec-out cache. In production mode the +// first mapper segment is usually not cached yet, so tier1 has a worker stream it back live +// while the rest is being backprocessed. +func (s *Stats) RecordStreamingFirstSegment(streaming bool) { + s.Lock() + defer s.Unlock() + s.streamingFirstSegment = streaming +} + +// RecordJobSchedulingBlocked flags whether the scheduler is currently holding back jobs +// because they would run too far ahead of what the client has consumed. This is a normal +// back-pressure mechanism, but it is the difference between "we are slow" and "you are slow". +func (s *Stats) RecordJobSchedulingBlocked(blocked bool) { + s.Lock() + defer s.Unlock() + if blocked == s.schedulingBlockedOnConsumption { + return + } + + now := time.Now() + s.schedulingBlockedOnConsumption = blocked + if blocked { + s.schedulingBlockedSince = now + return + } + // Closing an interval: only the accumulated time says whether the throttle was a blip + // between two scheduling attempts or a state the request actually sat in. + s.windowThrottled.add(now, now.Sub(s.schedulingBlockedSince)) + s.schedulingBlockedSince = time.Time{} +} + +// RecordMaxParallelJobs records how many jobs this request may run at once. +func (s *Stats) RecordMaxParallelJobs(count uint64) { + s.Lock() + defer s.Unlock() + s.maxParallelJobs = count +} + +// throttledOverWindow is how long scheduling was held back over the window, including the +// interval still open. +// +// Being throttled is the normal steady state of a healthy request, not a problem: the first +// stage has no dependencies, so it races ahead until it hits the limit and sits there. The +// limit exists so that a request whose output is not advancing — because a job broke, or +// because the consumer stopped reading — does not burn workers on segments nobody may ever +// read, keeping them available for other sessions. So this number explains why few jobs are +// running; it says nothing about who is responsible for it. +// +// throttledOverWindow should be called while locked +func (s *Stats) throttledOverWindow(now time.Time, measured time.Duration) time.Duration { + throttled := s.windowThrottled.sum(now) + if s.schedulingBlockedOnConsumption { + throttled += now.Sub(s.schedulingBlockedSince) + } + return min(throttled, measured) +} + +// ProgressLogger emits the periodic "substreams request progress" log for a tier1 request. +// Emitting is decoupled from measuring: the window each `_5m` value covers is a property of +// the data, not of how often the line happens to be printed, so two consecutive lines are +// always comparable even if the interval is changed. +type ProgressLogger struct { + stats *Stats + logger *zap.Logger + + firstDelay time.Duration + interval time.Duration +} + +// NewProgressLogger reports on `stats` through `logger`, which is expected to be the request's +// own logger: the logging middleware already binds `trace_id` to it, so the line must not add +// one of its own or every entry carries the field twice. +func NewProgressLogger(stats *Stats, logger *zap.Logger) *ProgressLogger { + return &ProgressLogger{ + stats: stats, + logger: logger, + firstDelay: FirstProgressLogDelay, + interval: ProgressLogInterval, + } +} + +// Run blocks until ctx is done, logging progress at the configured intervals. It also drives +// the sampling of external call totals, which has to happen on the window's own cadence: those +// totals arrive from tier2 as running sums, so a delta needs a reference point taken a window +// ago rather than at the previous log line. +func (p *ProgressLogger) Run(ctx context.Context) { + sampler := time.NewTicker(windowBucketDuration) + defer sampler.Stop() + + report := time.NewTimer(p.firstDelay) + defer report.Stop() + + for { + select { + case <-ctx.Done(): + return + case <-sampler.C: + p.stats.sampleExternalCalls(time.Now()) + case <-report.C: + p.logProgress() + report.Reset(p.interval) + } + } +} + +func (p *ProgressLogger) logProgress() { + p.logger.Info("substreams request progress", p.stats.progressFields()...) +} + +// progressFields builds the whole log line under a single lock, and returns the external +// progressFields builds the whole log line under a single lock. +func (s *Stats) progressFields() []zap.Field { + s.Lock() + defer s.Unlock() + + now := time.Now() + elapsed := now.Sub(s.startTime) + // The linear pipeline only ever runs once parallel processing handed off, so any block + // going through it means the parallel phase is behind us. + linearPhase := s.initDuration != 0 || s.lastProcessedBlockNum != 0 + + // The phase says where the blocks the client is receiving right now come from. + phase := "parallel_processing" + switch { + case linearPhase: + phase = "linear_processing" + case s.streamingFirstSegment: + phase = "streaming_first_segment" + } + + // Values suffixed `_5m` cover the trailing ProgressWindow. Until the request is that old + // they cover its whole lifetime, which `elapsed` makes obvious. + measured := min(elapsed, ProgressWindow) + + sendStats := s.blockSendWindow.snapshot(now) + linearBlocksInWindow := s.windowLocalBlocks.sum(now) + stages := s.stageJobReport(now) + calls := s.externalCallReport(now, measured) + + // How much output is sitting in the cache that the consumer has not taken yet. Measured + // from where the consumer actually is, which before the first block is the start of the + // stream: measuring from 0 would report the whole chain height as "ready and waiting". + // lastBlockInCache is where the cached output stops; the gap with last_sent_block is what + // the consumer has left to take. Only meaningful while the output still comes from the + // cache, the linear pipeline produces blocks as it sends them. + var lastBlockInCache uint64 + var cachedAhead uint64 + if !linearPhase { + lastBlockInCache = highestContiguousFor(stages, s.config.OutputModule) + if consumedUpTo := s.consumedUpTo(); lastBlockInCache > consumedUpTo { + cachedAhead = lastBlockInCache - consumedUpTo + } + } + + fields := []zap.Field{ + zap.String("user_id", s.config.UserID), + zap.String("api_key_id", s.config.ApiKeyID), + zap.String("output_module", s.config.OutputModule), + zap.Bool("production_mode", s.config.ProductionMode), + zap.String("phase", phase), + zap.String("elapsed", humanDuration(elapsed)), + zap.Uint64("last_sent_block", s.lastSentBlockNum), + zap.Uint64("last_block_in_cache", lastBlockInCache), + zap.Float64("linear_blocks_processed_per_sec_5m", perSecond(linearBlocksInWindow, measured)), + zap.Uint64("blocks_sent", s.blocksSent), + zap.Object("blocks_sent_5m", sendStats), + zap.Objects("stages", stages), + zap.Objects("external_calls", calls), + } + + // Reported as context, not as a symptom: see throttledOverWindow. + if throttled := s.throttledOverWindow(now, measured); throttled > 0 { + fields = append(fields, zap.String("jobs_throttled_5m", humanDuration(throttled))) + } + + jobErrorsInWindow := s.windowJobErrors.sum(now) + if s.lastJobError != "" { + fields = append(fields, zap.Object("last_job_error", &jobErrorReport{ + stage: s.lastJobErrorStage, + age: now.Sub(s.lastJobErrorTime), + total: s.jobErrors, + inWindow: jobErrorsInWindow, + message: s.lastJobError, + likelyExternal: looksLikeExternalCallFailure(s.lastJobError), + })) + } + + fields = append(fields, zap.Strings("hints", s.progressHints(stages, calls, sendStats, cachedAhead, linearPhase, measured, jobErrorsInWindow, now))) + + return fields +} + +// stageJobReport summarizes, per stage, which modules it computes, how far they are, and how +// its jobs behaved over the trailing window. +// +// stageJobReport should be called while locked +func (s *Stats) stageJobReport(now time.Time) []*stageJobReport { + running := make(map[int]*runningJobsSummary) + for _, job := range s.runningJobs { + summary, ok := running[int(job.Stage)] + if !ok { + summary = &runningJobsSummary{oldestStartBlock: job.StartBlock} + running[int(job.Stage)] = summary + } + summary.count++ + age := now.Sub(job.start) + if age > summary.oldestAge { + summary.oldestAge = age + summary.oldestStartBlock = job.StartBlock + summary.oldestCurrentBlock = job.StartBlock + job.ProgressBlocks + } + + // A job that has been running a minute and covered 33 of its 1000 blocks already tells + // us the whole segment needs half an hour; waiting for it to actually take that long + // before saying so wastes the half hour. + segment := job.StopBlock - job.StartBlock + if age < minJobRateSample || job.ProgressBlocks == 0 || segment == 0 { + continue + } + projected := time.Duration(float64(age) * float64(segment) / float64(job.ProgressBlocks)) + if projected > summary.worstProjection { + summary.worstProjection = projected + summary.worstProjectionJob = projectedJob{ + startBlock: job.StartBlock, + stopBlock: job.StopBlock, + currentBlock: job.StartBlock + job.ProgressBlocks, + blocks: job.ProgressBlocks, + age: age, + } + } + } + + planned := make(map[int]StageProgress, len(s.stagesProgress)) + for _, stage := range s.stagesProgress { + planned[stage.Stage] = stage + } + + count := max(len(s.stageJobs), len(s.stages), len(s.stagesProgress)) + + out := make([]*stageJobReport, 0, count) + for idx := 0; idx < count && idx < maxLoggedStages; idx++ { + report := &stageJobReport{stage: idx} + if stage, ok := planned[idx]; ok { + report.stores = stage.Stores + report.mappers = stage.Mappers + report.plannedFirstJobStartBlock = stage.PlannedFirstJobStartBlock + report.plannedLastJobStopBlock = stage.PlannedLastJobStopBlock + report.segmentsReadyForSquashing = stage.SegmentsReadyForSquashing + if since := s.squashBacklogSince[stage.Stage]; !since.IsZero() { + report.squashBacklogFor = now.Sub(since) + } + + // Once blocks flow through the linear pipeline, that block is the truth for every + // module, whatever the cached files said. + report.readyUpTo = max(stage.HighestContiguousBlock, s.lastProcessedBlockNum) + } + if idx < len(s.stageJobs) { + stg := s.stageJobs[idx] + report.scheduled = stg.scheduled + report.completed = stg.completed + report.failed = stg.failed + report.cancelled = stg.cancelled + report.retried = stg.retried + report.delayed = stg.delayed + report.lastCompletedStopBlock = stg.lastCompletedStopBlock + + window := stg.window.sum(now) + report.windowCompleted = window.completed + report.windowFailed = window.failed + report.windowCancelled = window.cancelled + report.windowRetried = window.retried + report.windowDelayed = window.delayed + report.windowMaxDuration = window.maxDuration + if window.completed != 0 { + report.windowAvgDuration = window.duration / time.Duration(window.completed) + } + } + if summary, ok := running[idx]; ok { + report.running = summary.count + report.oldestRunningAge = summary.oldestAge + report.oldestRunningStartBlock = summary.oldestStartBlock + report.oldestRunningCurrentBlock = summary.oldestCurrentBlock + report.worstProjection = summary.worstProjection + report.worstProjectionJob = summary.worstProjectionJob + } + out = append(out, report) + } + return out +} + +type runningJobsSummary struct { + count int + oldestAge time.Duration + // oldestStartBlock is where that job's segment begins, oldestCurrentBlock how far into it + // the job actually got — the gap is what it has processed so far. + oldestStartBlock uint64 + oldestCurrentBlock uint64 + + // worstProjection is how long the slowest running job's segment is on track to take at the + // rate it has held so far. + worstProjection time.Duration + worstProjectionJob projectedJob +} + +// projectedJob is the evidence behind a projection: what it has covered, and in how long. +type projectedJob struct { + startBlock uint64 + stopBlock uint64 + currentBlock uint64 + blocks uint64 + age time.Duration +} + +type stageJobReport struct { + stage int + stores []string + mappers []string + + readyUpTo uint64 + segmentsReadyForSquashing uint64 + squashBacklogFor time.Duration + + scheduled uint64 + completed uint64 + failed uint64 + cancelled uint64 + retried uint64 + delayed uint64 + + plannedFirstJobStartBlock uint64 + plannedLastJobStopBlock uint64 + lastCompletedStopBlock uint64 + + running int + oldestRunningAge time.Duration + oldestRunningStartBlock uint64 + oldestRunningCurrentBlock uint64 + worstProjection time.Duration + worstProjectionJob projectedJob + + windowCompleted uint64 + windowFailed uint64 + windowCancelled uint64 + windowRetried uint64 + windowDelayed uint64 + windowAvgDuration time.Duration + windowMaxDuration time.Duration +} + +func (j *stageJobReport) MarshalLogObject(encoder zapcore.ObjectEncoder) error { + if len(j.stores) != 0 { + if err := encoder.AddArray("stores", stringArray(j.stores)); err != nil { + return err + } + } + if len(j.mappers) != 0 { + if err := encoder.AddArray("mappers", stringArray(j.mappers)); err != nil { + return err + } + } + if j.readyUpTo != 0 { + encoder.AddUint64("ready_up_to", j.readyUpTo) + } + if j.segmentsReadyForSquashing != 0 { + encoder.AddUint64("squash_wait_segments", j.segmentsReadyForSquashing) + } + return encoder.AddObject("jobs", (*stageJobsSummary)(j)) +} + +// stageJobsSummary is the compact job block of a stage: the range it has to cover, and where +// it stands within it. +type stageJobsSummary stageJobReport + +func (j *stageJobsSummary) MarshalLogObject(encoder zapcore.ObjectEncoder) error { + // The bounds come from the request plan, so they are the whole range this stage has to + // cover in this session, whether or not the scheduler got to it yet. + if j.plannedLastJobStopBlock != 0 { + encoder.AddUint64("start", j.plannedFirstJobStartBlock) + encoder.AddUint64("end", j.plannedLastJobStopBlock) + } + encoder.AddUint64("completed", j.completed) + encoder.AddUint64("completed_5m", j.windowCompleted) + encoder.AddInt("running", j.running) + if j.running != 0 { + encoder.AddUint64("oldest_running", j.oldestRunningStartBlock) + encoder.AddUint64("oldest_running_at", j.oldestRunningCurrentBlock) + encoder.AddString("oldest_running_age", humanDuration(j.oldestRunningAge)) + } + if j.windowCompleted != 0 { + encoder.AddString("avg_dur", humanDuration(j.windowAvgDuration)) + } + // Anything below is absent on a healthy stage: a run of zeroes on every stage of every + // line would bury the one stage that is actually losing work. + if j.failed != 0 || j.windowFailed != 0 { + encoder.AddUint64("failed_total", j.failed) + encoder.AddUint64("failed_5m", j.windowFailed) + } + if j.cancelled != 0 || j.windowCancelled != 0 { + encoder.AddUint64("cancelled_total", j.cancelled) + encoder.AddUint64("cancelled_5m", j.windowCancelled) + } + if j.retried != 0 || j.windowRetried != 0 { + encoder.AddUint64("retried_total", j.retried) + encoder.AddUint64("retried_5m", j.windowRetried) + } + if j.delayed != 0 || j.windowDelayed != 0 { + encoder.AddUint64("delayed_total", j.delayed) + encoder.AddUint64("delayed_5m", j.windowDelayed) + } + return nil +} + +// stringArray renders a plain list of names. +type stringArray []string + +func (a stringArray) MarshalLogArray(encoder zapcore.ArrayEncoder) error { + for _, value := range a { + encoder.AppendString(value) + } + return nil +} + +// jobErrorReport carries the most recent tier2 job error. Only one is kept per request: when +// jobs fail in a burst they almost always share a root cause, and one readable error beats a +// list of truncated ones. +type jobErrorReport struct { + stage int + age time.Duration + total uint64 + inWindow uint64 + message string + // likelyExternal marks an error whose innermost cause points at a chain RPC endpoint + // rather than at the module or at substreams itself. + likelyExternal bool +} + +func (e *jobErrorReport) MarshalLogObject(encoder zapcore.ObjectEncoder) error { + encoder.AddInt("stage", e.stage) + encoder.AddString("age", humanDuration(e.age)) + encoder.AddUint64("count_total", e.total) + encoder.AddUint64("count_5m", e.inWindow) + encoder.AddString("error", e.message) + return nil +} + +// externalCallFailureMarkers are the substrings a chain RPC failure leaves in a worker error +// once it has bubbled up through the wasm extension. Matching on text is crude, but the tier2 +// protocol reports external calls as counts and durations only — the reason a call failed +// exists nowhere else by the time tier1 sees it. +var externalCallFailureMarkers = []string{ + "connection refused", + "no such host", + "dial tcp", + "rpc provider", + "json_rpc", + "eth_call", +} + +func looksLikeExternalCallFailure(message string) bool { + lowered := strings.ToLower(message) + for _, marker := range externalCallFailureMarkers { + if strings.Contains(lowered, marker) { + return true + } + } + return false +} + +// externalCallReport reports external calls (eth_call & friends) per module, both in +// absolute terms and, more usefully, over the trailing window. Lifetime totals stop telling +// you anything once a request has been running for hours. +// +// externalCallReport should be called while locked +func (s *Stats) externalCallReport(now time.Time, measured time.Duration) []*externalCallReport { + byModule := s.wasmExtensionCallMetricsByModule() + previous := s.windowExternalCalls.baseline(now) + + // A call made inside a tier2 job reports no block of its own, but the job it blocks does + // not advance while the call is pending, so the job's current block is where it is stuck. + stuckBlocks := make(map[string]uint64) + for _, job := range s.runningJobs { + for module := range job.modulesStats { + if current := job.StartBlock + job.ProgressBlocks; current > stuckBlocks[module] { + stuckBlocks[module] = current + } + } + } + + // Blocks a module went through, so a call count can be turned into "calls per block", + // which is the number that tells whether the module itself is call-hungry. Modules only + // ever executed remotely have no local stats entry, hence the fallback. + inFlightBlocks := s.runningJobs.blocksProcessed() + fallbackBlocks := s.remoteProcessedBlockCount + inFlightBlocks + s.localProcessedBlockCount + blocksByModule := make(map[string]uint64, len(s.modulesStats)) + for name, mod := range s.modulesStats { + blocksByModule[name] = mod.processedBlocksInCompleteJobs + inFlightBlocks + s.localProcessedBlockCount + } + + out := make([]*externalCallReport, 0, len(byModule)) + for _, metric := range byModule { + key := metric.module + "|" + metric.extension + + report := &externalCallReport{ + module: metric.module, + extension: metric.extension, + count: metric.count, + totalTime: metric.totalTime, + maxTime: metric.maxTime, + inFlight: metric.inFlight, + oldestInFlight: metric.oldestInFlight, + atBlock: metric.oldestInFlightBlock, + windowCount: metric.count, + windowTime: metric.totalTime, + } + if prev, ok := previous[key]; ok { + report.windowCount = metric.count - prev.count + report.windowTime = metric.totalTime - prev.time + } + // Call-seconds spent per second of wall clock. A module doing many short calls stays + // near 0; a value close to 1 means one call held the whole window, which is how a call + // that never returns shows up when only the remote totals are available. + if measured > 0 { + report.avgConcurrentCalls = report.windowTime.Seconds() / measured.Seconds() + } + report.window = measured + if report.atBlock == 0 { + report.atBlock = stuckBlocks[metric.module] + } + blocks, ok := blocksByModule[metric.module] + if !ok || blocks == 0 { + blocks = fallbackBlocks + } + if blocks != 0 { + report.callsPerBlock = float64(metric.count) / float64(blocks) + report.callsPerBlockKnown = true + } + out = append(out, report) + } + + // Keep only what matters: the calls that consumed the most time during the window. + slices.SortFunc(out, func(a, b *externalCallReport) int { + return cmp.Or( + cmp.Compare(b.windowTime, a.windowTime), + cmp.Compare(b.totalTime, a.totalTime), + ) + }) + if len(out) > maxLoggedExternalCalls { + out = out[:maxLoggedExternalCalls] + } + return out +} + +// sampleExternalCalls stores the current cumulative external call totals so later reports can +// measure a delta against a reference point one window old. +func (s *Stats) sampleExternalCalls(now time.Time) { + s.Lock() + defer s.Unlock() + + byModule := s.wasmExtensionCallMetricsByModule() + current := make(map[string]callCounters, len(byModule)) + for _, metric := range byModule { + current[metric.module+"|"+metric.extension] = callCounters{count: metric.count, time: metric.totalTime} + } + s.windowExternalCalls.observe(now, current) +} + +type externalCallReport struct { + module string + extension string + count uint64 + totalTime time.Duration + maxTime time.Duration + inFlight uint64 + oldestInFlight time.Duration + atBlock uint64 + windowCount uint64 + windowTime time.Duration + // callsPerBlock is only known once some block count is available for the module; a module + // executed remotely whose jobs have not reported progress yet has none, and printing 0 + // there reads as "makes no call per block" when the truth is "we cannot tell yet". + callsPerBlock float64 + callsPerBlockKnown bool + + window time.Duration + avgConcurrentCalls float64 +} + +// callsStillRunning reports whether a call is waiting for an answer right now. +// +// Both tier1 and tier2 report their open calls, so the count is normally exact. The fallback +// covers a tier2 old enough to predate that reporting: it sends counts and totals only, and a +// count that does not move while the time does can only come from calls that are still waiting. +func (e *externalCallReport) callsStillRunning() bool { + if e.inFlight != 0 { + return true + } + // Close to a full window of call time with nothing having started means at least one call + // was waiting for the entire window. + return e.window > 0 && e.windowCount == 0 && e.avgConcurrentCalls >= 0.9 +} + +func (e *externalCallReport) windowAverage() time.Duration { + if e.windowCount == 0 { + return 0 + } + return e.windowTime / time.Duration(e.windowCount) +} + +func (e *externalCallReport) MarshalLogObject(encoder zapcore.ObjectEncoder) error { + encoder.AddString("module", e.module) + encoder.AddString("extension", e.extension) + encoder.AddUint64("count_total", e.count) + encoder.AddString("total_time", humanDuration(e.totalTime)) + encoder.AddUint64("count_5m", e.windowCount) + encoder.AddString("time_5m", humanDuration(e.windowTime)) + encoder.AddString("avg_5m", humanDuration(e.windowAverage())) + if e.maxTime != 0 { + // Only calls made by this process report a per-call max; tier2 jobs send back + // counts and totals only, and log their own max on their side. + encoder.AddString("slowest_local_call", humanDuration(e.maxTime)) + } + if e.inFlight != 0 { + // Exact, but only for modules this process executed itself. + encoder.AddUint64("in_flight", e.inFlight) + encoder.AddString("oldest_in_flight", humanDuration(e.oldestInFlight)) + } + if e.callsStillRunning() { + encoder.AddBool("calls_still_running", true) + if e.atBlock != 0 { + encoder.AddUint64("at_block", e.atBlock) + } + } + if e.callsPerBlockKnown { + encoder.AddFloat64("calls_per_block", roundTo(e.callsPerBlock, 2)) + } + return nil +} + +// progressHints turns the numbers above into the handful of sentences a human actually +// wants: which of the usual suspects is responsible for this request being slow. +// +// progressHints should be called while locked +func (s *Stats) progressHints( + stages []*stageJobReport, + calls []*externalCallReport, + sendStats durationStats, + cachedAhead uint64, + linearPhase bool, + measured time.Duration, + jobErrorsInWindow uint64, + now time.Time, +) []string { + var hints []string + + // 0. The stream was flowing and stopped. Everything below reads as "slow"; this one + // says "stopped", which is a different problem and worth stating first. + if sendStats.count == 0 && s.blocksSent != 0 { + hints = append(hints, fmt.Sprintf( + "no block was sent to the consumer during the last %s (the stream is stopped at block %d, %s blocks sent in total): look at the stages below to tell whether the pipeline stopped producing or the consumer stopped reading", + humanDuration(measured), s.lastSentBlockNum, humanize.Comma(int64(s.blocksSent)))) + } + + // 1a. An external call that has not returned yet. This is the one that used to be + // invisible: a call retrying against a dead endpoint reports no time and no failure until + // it finally gives up, minutes later, taking the whole segment down with it. + for _, call := range calls { + if !call.callsStillRunning() { + continue + } + // The open-call count is exact whenever the worker reports it; against a tier2 that + // predates that reporting only the accrued time is available, so the second wording + // says what was actually measured rather than claiming a count it does not have. + var atBlock string + if call.atBlock != 0 { + atBlock = fmt.Sprintf(" on block %d", call.atBlock) + } + if call.inFlight != 0 && call.oldestInFlight >= stuckExternalCall { + hints = append(hints, fmt.Sprintf( + "module %q has %d %s call(s) still waiting for an answer%s, the oldest for %s: the endpoint behind that call is unreachable or far too slow, and the segment will eventually time out on it", + call.module, call.inFlight, call.extension, atBlock, humanDuration(call.oldestInFlight))) + break + } + if call.inFlight == 0 && call.window >= stuckExternalCall { + hints = append(hints, fmt.Sprintf( + "module %q spent %s of the last %s inside %s calls without a single one completing%s: at least one call has been waiting for the whole window, so the endpoint behind it is unreachable or far too slow and the segment will eventually time out on it", + call.module, humanDuration(call.windowTime), humanDuration(call.window), call.extension, atBlock)) + break + } + } + + // 1b. External calls (eth_call and friends) are slow or too numerous. + for _, call := range calls { + if call.windowCount == 0 { + continue + } + avg := call.windowAverage() + slow := avg >= slowExternalCallAvg + chatty := call.callsPerBlockKnown && call.callsPerBlock >= highExternalCallsPerBlock + if !slow && !chatty { + continue + } + + // Name the one that actually fired: a module making two 50s calls and one making + // thousands of 1ms calls are opposite problems with opposite fixes. + var cause string + switch { + case slow && chatty: + cause = fmt.Sprintf("each call takes %s and the module makes %.1f of them per block, so both the endpoint and the module's call volume are limiting throughput", humanDuration(avg), call.callsPerBlock) + case slow: + cause = fmt.Sprintf("each call takes %s on average, so the endpoint answering them is what limits throughput", humanDuration(avg)) + default: + cause = fmt.Sprintf("the module makes %.1f of them per block, so its call volume is what limits throughput", call.callsPerBlock) + } + hints = append(hints, fmt.Sprintf("module %q spent %s in %d %s call(s) over the last %s: %s", + call.module, humanDuration(call.windowTime), call.windowCount, call.extension, humanDuration(measured), cause)) + break + } + + // 2. The consumer is what we are waiting on. The only direct evidence of that is the time + // spent blocked inside SendMsg: how far the cache runs ahead of the consumer says nothing, + // since the scheduler deliberately keeps it a fixed distance ahead and a healthy request + // sits at that ceiling permanently. + if measured >= minWindowForShare && sendStats.total >= time.Duration(float64(measured)*sendBlockedShareToReport) { + ahead := "" + if cachedAhead != 0 { + ahead = fmt.Sprintf(", with %s blocks already processed and waiting in the cache", humanize.Comma(int64(cachedAhead))) + } + hints = append(hints, fmt.Sprintf( + "%s of the last %s were spent blocked writing to the consumer (%s per block on average, longest single stall %s)%s: the client or the network is the bottleneck, not the processing", + humanDuration(sendStats.total), humanDuration(measured), + humanDuration(sendStats.averagePerBlock()), humanDuration(sendStats.maximum), ahead)) + } + + // 3. Tier2 jobs are slow, or keep getting cancelled/retried. Reported from the rate a job + // is holding rather than from its age, so a segment on track to take half an hour is called + // out in the first minute instead of fifteen minutes later. + var slowest *stageJobReport + for _, stage := range stages { + if stage.running != 0 && (slowest == nil || stage.worstProjection > slowest.worstProjection) { + slowest = stage + } + } + switch { + case slowest == nil: + case slowest.worstProjection >= slowJobThreshold: + job := slowest.worstProjectionJob + hints = append(hints, fmt.Sprintf( + "stage %d covered %d of the %d blocks of segment [%d, %d) in %s (%s per block): at that rate the segment needs about %s, where 1 to 10 minutes is expected", + slowest.stage, job.blocks, job.stopBlock-job.startBlock, job.startBlock, job.stopBlock, + humanDuration(job.age), humanDuration(job.age/time.Duration(job.blocks)), + // Rounded: a projection off a partial segment does not deserve second precision. + humanDuration(slowest.worstProjection.Round(time.Minute)))) + default: + // No rate to extrapolate from on any stage: all we can say is that it has been a while. + for _, stage := range stages { + if stage.running != 0 && stage.oldestRunningAge >= slowJobThreshold { + hints = append(hints, fmt.Sprintf( + "stage %d has a job running for %s (started at block %d, reached block %d); jobs are expected to complete within 1 to 10 minutes, so this one is stuck or the module is very slow on that range", + stage.stage, humanDuration(stage.oldestRunningAge), stage.oldestRunningStartBlock, stage.oldestRunningCurrentBlock)) + break + } + } + } + for _, stage := range stages { + if unstable := stage.windowFailed + stage.windowCancelled + stage.windowRetried; unstable > 0 { + hints = append(hints, fmt.Sprintf( + "stage %d lost %d job(s) over the last %s (%d failed, %d cancelled, %d retried): work is being redone, which slows the whole request down", + stage.stage, unstable, humanDuration(measured), stage.windowFailed, stage.windowCancelled, stage.windowRetried)) + break + } + } + // 3b. Why the jobs died. The counts above say work is being redone; only the error says + // whether the fix is on the chain endpoint, in the module, or on the tier2 fleet. + if jobErrorsInWindow > 0 && s.lastJobError != "" { + if looksLikeExternalCallFailure(s.lastJobError) { + hints = append(hints, fmt.Sprintf( + "%d job error(s) over the last %s and the last one points at a chain RPC endpoint, not at the substreams itself — check that the endpoint is reachable and keeping up: %s", + jobErrorsInWindow, humanDuration(measured), s.lastJobError)) + } else { + hints = append(hints, fmt.Sprintf( + "%d job error(s) over the last %s, last one on stage %d: %s", + jobErrorsInWindow, humanDuration(measured), s.lastJobErrorStage, s.lastJobError)) + } + } + + // 4. Jobs produced the partials but squashing them into the full stores lags behind. + for _, stage := range stages { + if stage.segmentsReadyForSquashing >= squashingBehindSegments && stage.squashBacklogFor >= squashingBehindFor { + hints = append(hints, fmt.Sprintf( + "stage %d (%s) has had at least %d processed segments waiting to be merged for %s, %s right now (highest fully merged block is %d): squashing, not processing, is the bottleneck", + stage.stage, strings.Join(stage.stores, ", "), squashingBehindSegments, humanDuration(stage.squashBacklogFor), + humanize.Comma(int64(stage.segmentsReadyForSquashing)), stage.readyUpTo)) + break + } + } + if !linearPhase { + for _, stat := range s.modulesStats { + if stat.merging && time.Since(stat.mergeBegin) > slowJobThreshold { + hints = append(hints, fmt.Sprintf( + "store %q has been merging a single segment for %s: the store is likely very large or the storage backend is slow", + stat.Name, humanDuration(time.Since(stat.mergeBegin)))) + break + } + } + } + + if len(hints) > maxLoggedHints { + hints = hints[:maxLoggedHints] + } + return hints +} + +// highestContiguousFor returns how far the stage owning the given module has been processed. +func highestContiguousFor(stages []*stageJobReport, name string) uint64 { + for _, stage := range stages { + if slices.Contains(stage.stores, name) || slices.Contains(stage.mappers, name) { + return stage.readyUpTo + } + } + return 0 +} + +// humanDuration keeps durations short and readable ("1m3s", "450ms") instead of zap's +// float-seconds rendering, because these lines are meant to be read by people. +func humanDuration(d time.Duration) string { + switch { + case d == 0: + return "0s" + case d < time.Millisecond: + return d.Round(time.Microsecond).String() + case d < time.Second: + return d.Round(time.Millisecond).String() + case d < time.Minute: + return d.Round(10 * time.Millisecond).String() + default: + return d.Round(time.Second).String() + } +} + +func perSecond(count uint64, window time.Duration) float64 { + if window <= 0 { + return 0 + } + return roundTo(float64(count)/window.Seconds(), 2) +} + +func roundTo(v float64, decimals int) float64 { + pow := 1.0 + for i := 0; i < decimals; i++ { + pow *= 10 + } + return float64(int64(v*pow+0.5)) / pow +} diff --git a/metrics/progress_log_test.go b/metrics/progress_log_test.go new file mode 100644 index 000000000..9545af1e0 --- /dev/null +++ b/metrics/progress_log_test.go @@ -0,0 +1,817 @@ +package metrics + +import ( + "context" + "errors" + "fmt" + "testing" + "time" + + "github.com/streamingfast/bstream" + pbssinternal "github.com/streamingfast/substreams/pb/sf/substreams/intern/v2" + pbsubstreamsrpc "github.com/streamingfast/substreams/pb/sf/substreams/rpc/v2" + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + "go.uber.org/zap" + "go.uber.org/zap/zapcore" + "go.uber.org/zap/zaptest/observer" +) + +func testStats(t *testing.T) *Stats { + t.Helper() + return NewReqStats(&Config{ + UserID: "user-1", + OutputModule: "map_out", + }, nil, nil, zap.NewNop()) +} + +func fieldMap(t *testing.T, entry observer.LoggedEntry) map[string]interface{} { + t.Helper() + return entry.ContextMap() +} + +func TestProgressLoggerEmitsOneLine(t *testing.T) { + stats := testStats(t) + core, logs := observer.New(zapcore.InfoLevel) + + stats.RecordStagesProgress([]StageProgress{ + {Stage: 0, Stores: []string{"store_a"}, Mappers: []string{"map_events"}, + PlannedFirstJobStartBlock: 1_000_000, PlannedLastJobStopBlock: 2_000_000, + HighestContiguousBlock: 1_200_000, SegmentsReadyForSquashing: 300}, + {Stage: 1, Mappers: []string{"map_out"}, + PlannedFirstJobStartBlock: 1_000_000, PlannedLastJobStopBlock: 2_000_000, + HighestContiguousBlock: 1_500_000}, + }) + stats.RecordLastBlockSent(nil) + stats.lastSentBlockNum = 1_000_000 + + jobIdx := stats.RecordNewSubrequest(0, 1_200_000, 1_300_000) + stats.RecordStages([]*pbsubstreamsrpc.Stage{{Modules: []string{"store_a"}}, {Modules: []string{"map_out"}}}) + stats.RecordEndSubrequest(jobIdx, JobComplete) + + stats.RecordBlockSent(20*time.Millisecond, 10) + stats.RecordBlockSent(80*time.Millisecond, 10) + + logger := NewProgressLogger(stats, zap.New(core)) + logger.logProgress() + + require.Equal(t, 1, logs.Len()) + entry := logs.All()[0] + assert.Equal(t, "substreams request progress", entry.Message) + + fields := fieldMap(t, entry) + assert.Equal(t, "parallel_processing", fields["phase"]) + assert.Equal(t, uint64(1_000_000), fields["last_sent_block"]) + // map_out is contiguously ready up to 1.5M while the consumer only got to 1M. + assert.Equal(t, uint64(1_500_000), fields["last_block_in_cache"]) + + // Modules are nested under the stage that computes them. + stages, ok := fields["stages"].([]interface{}) + require.True(t, ok) + require.Len(t, stages, 2) + + storeStage := stages[0].(map[string]interface{}) + assert.Equal(t, []interface{}{"store_a"}, storeStage["stores"]) + assert.Equal(t, []interface{}{"map_events"}, storeStage["mappers"]) + assert.Equal(t, uint64(1_200_000), storeStage["ready_up_to"]) + assert.Equal(t, uint64(300), storeStage["squash_wait_segments"]) + + storeJobs := storeStage["jobs"].(map[string]interface{}) + assert.Equal(t, uint64(1_000_000), storeJobs["start"]) + assert.Equal(t, uint64(2_000_000), storeJobs["end"]) + assert.Equal(t, uint64(1), storeJobs["completed"]) + mapStage := stages[1].(map[string]interface{}) + assert.Equal(t, []interface{}{"map_out"}, mapStage["mappers"]) + assert.NotContains(t, mapStage, "stores") + // The planned range is known upfront even though no job ran on that stage yet. + assert.Equal(t, uint64(1_000_000), mapStage["jobs"].(map[string]interface{})["start"]) + + send := fields["blocks_sent_5m"].(map[string]interface{}) + assert.Equal(t, uint64(20), send["blocks"]) + assert.Equal(t, "5ms", send["avg_per_block"]) + // A stall is one SendMsg call blocking on gRPC flow control, not the cost of one block. + assert.Equal(t, "100ms", send["blocked"]) + assert.Equal(t, "80ms", send["longest_stall"]) + assert.NotContains(t, send, "messages") + assert.NotContains(t, send, "avg_per_message") + assert.NotContains(t, send, "min") + assert.NotContains(t, send, "p50") + assert.NotContains(t, send, "p90") +} + +func TestProgressLoggerPhases(t *testing.T) { + phaseOf := func(t *testing.T, setup func(*Stats)) string { + t.Helper() + stats := testStats(t) + core, logs := observer.New(zapcore.InfoLevel) + setup(stats) + NewProgressLogger(stats, zap.New(core)).logProgress() + return fieldMap(t, logs.All()[0])["phase"].(string) + } + + assert.Equal(t, "parallel_processing", phaseOf(t, func(stats *Stats) {})) + + // In production mode the first mapper segment is usually not cached, so a worker streams + // it back live: the client is receiving blocks, but not from the cache and not from the + // linear pipeline. + assert.Equal(t, "streaming_first_segment", phaseOf(t, func(stats *Stats) { + stats.RecordStreamingFirstSegment(true) + })) + + assert.Equal(t, "parallel_processing", phaseOf(t, func(stats *Stats) { + stats.RecordStreamingFirstSegment(true) + stats.RecordStreamingFirstSegment(false) + }), "once that segment landed, the rest is read from the cache") + + assert.Equal(t, "linear_processing", phaseOf(t, func(stats *Stats) { + stats.RecordStreamingFirstSegment(true) + stats.RecordBlock(bstream.NewBlockRef("aa", 12_369_800)) + }), "a block through the linear pipeline outranks everything") +} + +func TestProgressLoggerWindowSurvivesReports(t *testing.T) { + stats := testStats(t) + core, logs := observer.New(zapcore.InfoLevel) + stats.RecordStages([]*pbsubstreamsrpc.Stage{{Modules: []string{"store_a"}}}) + + logger := NewProgressLogger(stats, zap.New(core)) + + jobIdx := stats.RecordNewSubrequest(0, 0, 1000) + stats.RecordEndSubrequest(jobIdx, JobComplete) + logger.logProgress() + + logger.logProgress() + + require.Equal(t, 2, logs.Len()) + first := fieldMap(t, logs.All()[0])["stages"].([]interface{})[0].(map[string]interface{})["jobs"].(map[string]interface{}) + second := fieldMap(t, logs.All()[1])["stages"].([]interface{})[0].(map[string]interface{})["jobs"].(map[string]interface{}) + + assert.Equal(t, uint64(1), first["completed_5m"]) + assert.Equal(t, uint64(1), first["completed"]) + // A stage the plan says nothing about reports no planned range rather than 0-0. + assert.NotContains(t, first, "start") + + // The window is a trailing period, not "since the previous line": emitting a report does + // not consume it, otherwise two lines close together would each cover a different span. + assert.Equal(t, uint64(1), second["completed_5m"], "the window must not be reset by a report") + assert.Equal(t, uint64(1), second["completed"]) +} + +func TestProgressLoggerWindowAgesOut(t *testing.T) { + stats := testStats(t) + core, logs := observer.New(zapcore.InfoLevel) + stats.RecordStages([]*pbsubstreamsrpc.Stage{{Modules: []string{"store_a"}}}) + + // One job completed inside the window, one long before it. + stats.stageJobStats(0).window.bucket(time.Now()).completed++ + stats.stageJobStats(0).window.bucket(time.Now().Add(-ProgressWindow-time.Minute)).completed++ + + NewProgressLogger(stats, zap.New(core)).logProgress() + + jobs := fieldMap(t, logs.All()[0])["stages"].([]interface{})[0].(map[string]interface{})["jobs"].(map[string]interface{}) + assert.Equal(t, uint64(1), jobs["completed_5m"], "only what happened inside the window counts") +} + +func TestProgressLoggerExternalCallsReportWindowDelta(t *testing.T) { + stats := testStats(t) + core, logs := observer.New(zapcore.InfoLevel) + logger := NewProgressLogger(stats, zap.New(core)) + + remote := &pbssinternal.ModuleStats{ + Name: "map_out", + ExternalCallMetrics: []*pbssinternal.ExternalCallMetric{{Name: "eth_call", Count: 100, TimeMs: 10_000}}, + } + stats.completedJobsStats["map_out"] = remote + + // Calls made by tier2 jobs arrive as running totals, so the delta is measured against a + // snapshot taken a window earlier rather than against the previous report. + stats.sampleExternalCalls(time.Now().Add(-4 * time.Minute)) + + remote.ExternalCallMetrics[0].Count = 150 + remote.ExternalCallMetrics[0].TimeMs = 25_000 + logger.logProgress() + + call := fieldMap(t, logs.All()[0])["external_calls"].([]interface{})[0].(map[string]interface{}) + assert.Equal(t, uint64(150), call["count_total"]) + assert.Equal(t, uint64(50), call["count_5m"]) + assert.Equal(t, "15s", call["time_5m"]) + assert.Equal(t, "300ms", call["avg_5m"]) +} + +func TestProgressLoggerExternalCallBaselineAgesOut(t *testing.T) { + stats := testStats(t) + core, logs := observer.New(zapcore.InfoLevel) + logger := NewProgressLogger(stats, zap.New(core)) + + remote := &pbssinternal.ModuleStats{ + Name: "map_out", + ExternalCallMetrics: []*pbssinternal.ExternalCallMetric{{Name: "eth_call", Count: 100, TimeMs: 10_000}}, + } + stats.completedJobsStats["map_out"] = remote + + // A baseline older than the window must be ignored, otherwise the "last 5 minutes" would + // silently grow into "since the request started". + stats.sampleExternalCalls(time.Now().Add(-ProgressWindow - time.Minute)) + remote.ExternalCallMetrics[0].Count = 150 + logger.logProgress() + + call := fieldMap(t, logs.All()[0])["external_calls"].([]interface{})[0].(map[string]interface{}) + assert.Equal(t, uint64(150), call["count_5m"], "with no usable baseline the lifetime total is reported") +} + +func TestProgressHints(t *testing.T) { + t.Run("slow external calls", func(t *testing.T) { + stats := testStats(t) + core, logs := observer.New(zapcore.InfoLevel) + logger := NewProgressLogger(stats, zap.New(core)) + + stats.completedJobsStats["map_out"] = &pbssinternal.ModuleStats{ + Name: "map_out", + ExternalCallMetrics: []*pbssinternal.ExternalCallMetric{{Name: "eth_call", Count: 1000, TimeMs: 500_000}}, + } + logger.logProgress() + + fields := fieldMap(t, logs.All()[0]) + hints := fields["hints"].([]interface{}) + require.Len(t, hints, 1) + // 1000 calls of 500ms: slow endpoint, and nothing is known about the call volume per + // block, so the hint must not blame it. + assert.Contains(t, hints[0].(string), "the endpoint answering them is what limits throughput") + assert.NotContains(t, hints[0].(string), "per block") + + call := fields["external_calls"].([]interface{})[0].(map[string]interface{}) + assert.NotContains(t, call, "calls_per_block", "0 would read as \"makes no call per block\"") + }) + + t.Run("a module making too many calls per block", func(t *testing.T) { + stats := testStats(t) + core, logs := observer.New(zapcore.InfoLevel) + logger := NewProgressLogger(stats, zap.New(core)) + + // 5000 fast calls over 100 blocks: the endpoint is fine, the module is not. + stats.remoteProcessedBlockCount = 100 + stats.completedJobsStats["map_out"] = &pbssinternal.ModuleStats{ + Name: "map_out", + ExternalCallMetrics: []*pbssinternal.ExternalCallMetric{{Name: "eth_call", Count: 5000, TimeMs: 500}}, + } + logger.logProgress() + + fields := fieldMap(t, logs.All()[0]) + hints := fields["hints"].([]interface{}) + require.Len(t, hints, 1) + assert.Contains(t, hints[0].(string), "its call volume is what limits throughput") + + call := fields["external_calls"].([]interface{})[0].(map[string]interface{}) + assert.Equal(t, float64(50), call["calls_per_block"]) + }) + + t.Run("an external call that never returns", func(t *testing.T) { + stats := testStats(t) + core, logs := observer.New(zapcore.InfoLevel) + logger := NewProgressLogger(stats, zap.New(core)) + + // Begin without End: exactly what a retrying eth_call against an unreachable endpoint + // looks like from here — the extension retries internally, so this stays one call. + callID := stats.RecordModuleWasmExternalCallBegin("map_out", "rpc:eth_call", 12_450_739) + stats.modulesStats["map_out"].inprocessCallMetrics[callID] = inprocessCall{ + startTime: time.Now().Add(-3 * time.Minute), + extension: "rpc:eth_call", + blockNum: 12_450_739, + } + logger.logProgress() + + call := fieldMap(t, logs.All()[0])["external_calls"].([]interface{})[0].(map[string]interface{}) + assert.Equal(t, uint64(1), call["in_flight"]) + assert.Equal(t, "3m0s", call["oldest_in_flight"]) + // Where processing is stuck for as long as the call does not return. + assert.Equal(t, uint64(12_450_739), call["at_block"]) + // The elapsed time of a call still running must be accounted for, otherwise a call + // hung for minutes reports as instantaneous. + assert.Equal(t, "3m0s", call["time_5m"]) + + hints := fieldMap(t, logs.All()[0])["hints"].([]interface{}) + require.NotEmpty(t, hints) + assert.Contains(t, hints[0].(string), "still waiting for an answer") + assert.Contains(t, hints[0].(string), "rpc:eth_call") + }) + + t.Run("a tier2 call that never returns", func(t *testing.T) { + stats := testStats(t) + core, logs := observer.New(zapcore.InfoLevel) + logger := NewProgressLogger(stats, zap.New(core)) + + // A module executed by a tier2 job: the worker protocol carries counts and totals + // only, so the open call is invisible. It shows up as accrued time on a count that + // does not move. + stats.startTime = time.Now().Add(-30 * time.Minute) + remote := &pbssinternal.ModuleStats{ + Name: "map_pools_created", + ExternalCallMetrics: []*pbssinternal.ExternalCallMetric{{Name: "rpc:eth_call", Count: 4, TimeMs: 500_000}}, + } + stats.completedJobsStats["map_pools_created"] = remote + stats.sampleExternalCalls(time.Now().Add(-4 * time.Minute)) + + // No new call started, yet a whole window of call time accrued. + remote.ExternalCallMetrics[0].TimeMs += uint64(ProgressWindow.Milliseconds()) + logger.logProgress() + + call := fieldMap(t, logs.All()[0])["external_calls"].([]interface{})[0].(map[string]interface{}) + assert.Equal(t, uint64(0), call["count_5m"]) + assert.Equal(t, true, call["calls_still_running"]) + + hints := fieldMap(t, logs.All()[0])["hints"].([]interface{}) + require.NotEmpty(t, hints) + assert.Contains(t, hints[0].(string), "without a single one completing") + assert.Contains(t, hints[0].(string), "rpc:eth_call") + }) + + t.Run("many short calls are not reported as still running", func(t *testing.T) { + stats := testStats(t) + core, logs := observer.New(zapcore.InfoLevel) + logger := NewProgressLogger(stats, zap.New(core)) + + stats.startTime = time.Now().Add(-30 * time.Minute) + remote := &pbssinternal.ModuleStats{ + Name: "map_pools_created", + ExternalCallMetrics: []*pbssinternal.ExternalCallMetric{{Name: "rpc:eth_call", Count: 100, TimeMs: 1_000}}, + } + stats.completedJobsStats["map_pools_created"] = remote + stats.sampleExternalCalls(time.Now().Add(-4 * time.Minute)) + + // A busy but healthy module: 900 calls totalling 9s over the window. + remote.ExternalCallMetrics[0].Count += 900 + remote.ExternalCallMetrics[0].TimeMs += 9_000 + logger.logProgress() + + call := fieldMap(t, logs.All()[0])["external_calls"].([]interface{})[0].(map[string]interface{}) + assert.NotContains(t, call, "calls_still_running") + }) + + t.Run("a short in-flight call is not reported as stuck", func(t *testing.T) { + stats := testStats(t) + core, logs := observer.New(zapcore.InfoLevel) + logger := NewProgressLogger(stats, zap.New(core)) + + stats.RecordModuleWasmExternalCallBegin("map_out", "rpc:eth_call", 12_450_739) + logger.logProgress() + + hints := fieldMap(t, logs.All()[0])["hints"].([]interface{}) + for _, hint := range hints { + assert.NotContains(t, hint.(string), "still waiting for an answer") + } + }) + + t.Run("the consumer is the bottleneck", func(t *testing.T) { + stats := testStats(t) + core, logs := observer.New(zapcore.InfoLevel) + logger := NewProgressLogger(stats, zap.New(core)) + + // Most of the window spent blocked inside SendMsg: the only direct evidence that the + // client, and not the pipeline, is what we are waiting on. + stats.startTime = time.Now().Add(-30 * time.Minute) + stats.RecordStagesProgress([]StageProgress{ + {Stage: 0, Mappers: []string{"map_out"}, HighestContiguousBlock: 2_000_000}, + }) + stats.lastSentBlockNum = 1_000_000 + stats.blockSendWindow.record(time.Now(), 4*time.Minute, 1_000) + logger.logProgress() + + hints := fieldMap(t, logs.All()[0])["hints"].([]interface{}) + require.Len(t, hints, 1) + assert.Contains(t, hints[0].(string), "blocked writing to the consumer") + assert.Contains(t, hints[0].(string), "1,000,000 blocks already processed and waiting in the cache") + }) + + t.Run("blocked just under and just over the threshold", func(t *testing.T) { + blockedFor := func(t *testing.T, share float64) []interface{} { + t.Helper() + stats := testStats(t) + core, logs := observer.New(zapcore.InfoLevel) + stats.startTime = time.Now().Add(-30 * time.Minute) + stats.blockSendWindow.record(time.Now(), time.Duration(float64(ProgressWindow)*share), 1_000) + NewProgressLogger(stats, zap.New(core)).logProgress() + return fieldMap(t, logs.All()[0])["hints"].([]interface{}) + } + + assert.Empty(t, blockedFor(t, sendBlockedShareToReport-0.05)) + assert.Len(t, blockedFor(t, sendBlockedShareToReport+0.05), 1) + }) + + t.Run("a full cache lead is not a slow consumer", func(t *testing.T) { + stats := testStats(t) + core, logs := observer.New(zapcore.InfoLevel) + logger := NewProgressLogger(stats, zap.New(core)) + + // The scheduler deliberately keeps the cache a fixed distance ahead of the consumer, + // so a healthy request sits at that ceiling permanently. Sends are fast here. + stats.startTime = time.Now().Add(-30 * time.Minute) + stats.RecordStagesProgress([]StageProgress{ + {Stage: 0, Mappers: []string{"map_out"}, HighestContiguousBlock: 2_000_000}, + }) + stats.lastSentBlockNum = 1_000_000 + stats.blockSendWindow.record(time.Now(), 20*time.Millisecond, 1_000) + logger.logProgress() + + assert.Empty(t, fieldMap(t, logs.All()[0])["hints"]) + }) + + t.Run("a throttle is never a hint on its own", func(t *testing.T) { + stats := testStats(t) + core, logs := observer.New(zapcore.InfoLevel) + logger := NewProgressLogger(stats, zap.New(core)) + + // The first stage has no dependencies, so it runs ahead until it hits the scheduler's + // limit and stays there: being throttled for the whole window is the healthy state of + // a production request, whatever the consumer is doing. + stats.startTime = time.Now().Add(-30 * time.Minute) + stats.RecordMaxParallelJobs(10) + stats.windowThrottled.add(time.Now(), ProgressWindow) + logger.logProgress() + + fields := fieldMap(t, logs.All()[0]) + assert.Equal(t, "5m0s", fields["jobs_throttled_5m"], "still reported as context") + assert.Empty(t, fields["hints"]) + }) + + t.Run("nothing processed yet is not the consumer being behind", func(t *testing.T) { + stats := testStats(t) + core, logs := observer.New(zapcore.InfoLevel) + logger := NewProgressLogger(stats, zap.New(core)) + + // A module that has done nothing reports its own initial block as its highest + // contiguous block. Measured against a last-sent block of 0, that used to read as + // "12 million blocks are cached and the consumer will not take them". + stats.RecordResolvedStartBlock(12_369_621) + stats.RecordStagesProgress([]StageProgress{ + {Stage: 0, Mappers: []string{"map_out"}, HighestContiguousBlock: 12_369_621}, + }) + logger.logProgress() + + fields := fieldMap(t, logs.All()[0]) + assert.Equal(t, uint64(12_369_621), fields["last_block_in_cache"], "the cache stops where nothing was processed") + assert.Empty(t, fields["hints"]) + }) + + t.Run("output cached ahead before the consumer read anything", func(t *testing.T) { + stats := testStats(t) + core, logs := observer.New(zapcore.InfoLevel) + logger := NewProgressLogger(stats, zap.New(core)) + + // Genuinely ahead this time: processed to 12.4M from a stream starting at 12,369,621, + // and the consumer has not taken a single block. + stats.startTime = time.Now().Add(-30 * time.Minute) + stats.RecordResolvedStartBlock(12_369_621) + stats.RecordStagesProgress([]StageProgress{ + {Stage: 0, Mappers: []string{"map_out"}, HighestContiguousBlock: 12_400_000}, + }) + stats.blockSendWindow.record(time.Now(), 4*time.Minute, 10) + logger.logProgress() + + fields := fieldMap(t, logs.All()[0]) + assert.Equal(t, uint64(12_400_000), fields["last_block_in_cache"]) + + hints := fields["hints"].([]interface{}) + require.Len(t, hints, 1) + assert.Contains(t, hints[0].(string), "blocked writing to the consumer") + assert.Contains(t, hints[0].(string), "30,379 blocks already processed and waiting in the cache") + }) + + t.Run("a segment on track to take far too long", func(t *testing.T) { + stats := testStats(t) + core, logs := observer.New(zapcore.InfoLevel) + logger := NewProgressLogger(stats, zap.New(core)) + + // 33 blocks of a 1000-block segment in 53s: the segment needs ~27 minutes, and there + // is no reason to wait 15 of them before saying so. + id := stats.RecordNewSubrequest(1, 5_000, 6_000) + stats.runningJobs[id].start = time.Now().Add(-53 * time.Second) + stats.runningJobs[id].ProgressBlocks = 33 + logger.logProgress() + + hints := fieldMap(t, logs.All()[0])["hints"].([]interface{}) + require.Len(t, hints, 1) + assert.Contains(t, hints[0].(string), "covered 33 of the 1000 blocks of segment [5000, 6000)") + assert.Contains(t, hints[0].(string), "the segment needs about 27m") + }) + + t.Run("a segment on track to finish in time", func(t *testing.T) { + stats := testStats(t) + core, logs := observer.New(zapcore.InfoLevel) + logger := NewProgressLogger(stats, zap.New(core)) + + // 600 blocks in 60s: done in under two minutes. + id := stats.RecordNewSubrequest(1, 5_000, 6_000) + stats.runningJobs[id].start = time.Now().Add(-time.Minute) + stats.runningJobs[id].ProgressBlocks = 600 + logger.logProgress() + + assert.Empty(t, fieldMap(t, logs.All()[0])["hints"]) + }) + + t.Run("a rate is not extrapolated from the first seconds", func(t *testing.T) { + stats := testStats(t) + core, logs := observer.New(zapcore.InfoLevel) + logger := NewProgressLogger(stats, zap.New(core)) + + // One block in the first second projects to 16 minutes, which is noise, not a signal. + id := stats.RecordNewSubrequest(1, 5_000, 6_000) + stats.runningJobs[id].start = time.Now().Add(-time.Second) + stats.runningJobs[id].ProgressBlocks = 1 + logger.logProgress() + + assert.Empty(t, fieldMap(t, logs.All()[0])["hints"]) + }) + + t.Run("a job with no progress at all", func(t *testing.T) { + stats := testStats(t) + core, logs := observer.New(zapcore.InfoLevel) + logger := NewProgressLogger(stats, zap.New(core)) + + // Nothing to extrapolate from, so it falls back to reporting the age. + id := stats.RecordNewSubrequest(1, 5_000, 6_000) + stats.runningJobs[id].start = time.Now().Add(-20 * time.Minute) + logger.logProgress() + + hints := fieldMap(t, logs.All()[0])["hints"].([]interface{}) + require.Len(t, hints, 1) + assert.Contains(t, hints[0].(string), "has a job running for 20m0s") + }) + + t.Run("squashing is behind", func(t *testing.T) { + stats := testStats(t) + core, logs := observer.New(zapcore.InfoLevel) + logger := NewProgressLogger(stats, zap.New(core)) + + stats.RecordStagesProgress([]StageProgress{ + {Stage: 0, Stores: []string{"store_a"}, HighestContiguousBlock: 100_000, SegmentsReadyForSquashing: 8}, + }) + // The backlog has been there a while, so the squasher is not keeping up with it. + stats.squashBacklogSince[0] = time.Now().Add(-3 * time.Minute) + logger.logProgress() + + hints := fieldMap(t, logs.All()[0])["hints"].([]interface{}) + require.Len(t, hints, 1) + assert.Contains(t, hints[0].(string), "waiting to be merged for 3m0s, 8 right now") + }) + + t.Run("a squash backlog the squasher is working off", func(t *testing.T) { + stats := testStats(t) + core, logs := observer.New(zapcore.InfoLevel) + logger := NewProgressLogger(stats, zap.New(core)) + + // Partials pile up faster than they are merged all the time; what matters is whether + // the backlog holds, and this one has only just appeared. + stats.RecordStagesProgress([]StageProgress{ + {Stage: 0, Stores: []string{"store_a"}, HighestContiguousBlock: 100_000, SegmentsReadyForSquashing: 40}, + }) + logger.logProgress() + + assert.Empty(t, fieldMap(t, logs.All()[0])["hints"]) + }) + + t.Run("a squash backlog that drops below the threshold restarts the clock", func(t *testing.T) { + stats := testStats(t) + core, logs := observer.New(zapcore.InfoLevel) + logger := NewProgressLogger(stats, zap.New(core)) + + stats.RecordStagesProgress([]StageProgress{ + {Stage: 0, Stores: []string{"store_a"}, HighestContiguousBlock: 100_000, SegmentsReadyForSquashing: 8}, + }) + stats.squashBacklogSince[0] = time.Now().Add(-3 * time.Minute) + + // The squasher caught up, then partials piled up again: that is a new backlog, not a + // three-minute-old one. + stats.RecordStagesProgress([]StageProgress{ + {Stage: 0, Stores: []string{"store_a"}, HighestContiguousBlock: 100_000, SegmentsReadyForSquashing: 1}, + }) + stats.RecordStagesProgress([]StageProgress{ + {Stage: 0, Stores: []string{"store_a"}, HighestContiguousBlock: 100_000, SegmentsReadyForSquashing: 8}, + }) + logger.logProgress() + + assert.Empty(t, fieldMap(t, logs.All()[0])["hints"]) + }) + + t.Run("stream stopped moving", func(t *testing.T) { + stats := testStats(t) + core, logs := observer.New(zapcore.InfoLevel) + logger := NewProgressLogger(stats, zap.New(core)) + + // Everything was sent longer ago than the window covers: nothing moved since. + stats.blockSendWindow.record(time.Now().Add(-ProgressWindow-time.Minute), 2*time.Millisecond, 118) + stats.blocksSent = 118 + stats.lastSentBlockNum = 12_369_738 + logger.logProgress() + + send := fieldMap(t, logs.All()[0])["blocks_sent_5m"].(map[string]interface{}) + assert.Equal(t, uint64(0), send["blocks"]) + // A window with nothing sent reports no timings at all rather than a wall of "0s" + // sitting next to the lifetime counters. + assert.NotContains(t, send, "avg_per_block") + assert.NotContains(t, send, "longest_stall") + + hints := fieldMap(t, logs.All()[0])["hints"].([]interface{}) + require.NotEmpty(t, hints) + assert.Contains(t, hints[0].(string), "no block was sent to the consumer") + assert.Contains(t, hints[0].(string), "12369738") + }) + + t.Run("nothing sent yet does not count as stopped", func(t *testing.T) { + stats := testStats(t) + core, logs := observer.New(zapcore.InfoLevel) + logger := NewProgressLogger(stats, zap.New(core)) + + // Still backprocessing, the stream never started: not a stall. + logger.logProgress() + + assert.Empty(t, fieldMap(t, logs.All()[0])["hints"]) + }) + + t.Run("job errors caused by an unreachable rpc endpoint", func(t *testing.T) { + stats := testStats(t) + core, logs := observer.New(zapcore.InfoLevel) + logger := NewProgressLogger(stats, zap.New(core)) + + jobIdx := stats.RecordNewSubrequest(2, 12_369_000, 12_370_000) + stats.RecordJobError(jobIdx, errors.New(`rpc error: code = DeadlineExceeded desc = execute modules: `+ + `deadline_exceeded: execution timed out at block #12369739: unknown error: running wasm extension `+ + `"rpc::eth_call": timeout while doing eth_call, waiting for rpc provider for 169.542µs (29 attempt(s), `+ + `last error: sending request to json_rpc endpoint: Post "http://localhost:8080/": dial tcp [::1]:8080: `+ + `connect: connection refused)`)) + stats.RecordJobRetried(jobIdx) + logger.logProgress() + + fields := fieldMap(t, logs.All()[0]) + jobError := fields["last_job_error"].(map[string]interface{}) + assert.Equal(t, 2, jobError["stage"]) + assert.Equal(t, uint64(1), jobError["count_total"]) + assert.Equal(t, uint64(1), jobError["count_5m"]) + assert.Contains(t, jobError["error"], "connection refused") + + hints := fields["hints"].([]interface{}) + require.NotEmpty(t, hints) + joined := fmt.Sprint(hints...) + assert.Contains(t, joined, "points at a chain RPC endpoint") + assert.Contains(t, joined, "connection refused") + + // A second report covers the same window, so the error still counts in it. + logger.logProgress() + second := fieldMap(t, logs.All()[1])["last_job_error"].(map[string]interface{}) + assert.Equal(t, uint64(1), second["count_5m"]) + assert.Equal(t, uint64(1), second["count_total"]) + }) + + t.Run("a module error is not blamed on the rpc endpoint", func(t *testing.T) { + stats := testStats(t) + core, logs := observer.New(zapcore.InfoLevel) + logger := NewProgressLogger(stats, zap.New(core)) + + jobIdx := stats.RecordNewSubrequest(1, 0, 1000) + stats.RecordJobError(jobIdx, errors.New("execute modules: panic in module map_out: index out of range")) + logger.logProgress() + + fields := fieldMap(t, logs.All()[0]) + hints := fields["hints"].([]interface{}) + require.NotEmpty(t, hints) + joined := fmt.Sprint(hints...) + assert.Contains(t, joined, "index out of range") + assert.NotContains(t, joined, "chain RPC endpoint") + }) + + t.Run("a cancelled request is not a job error", func(t *testing.T) { + stats := testStats(t) + core, logs := observer.New(zapcore.InfoLevel) + logger := NewProgressLogger(stats, zap.New(core)) + + jobIdx := stats.RecordNewSubrequest(0, 0, 1000) + stats.RecordJobError(jobIdx, fmt.Errorf("worker gave up: %w", context.Canceled)) + logger.logProgress() + + fields := fieldMap(t, logs.All()[0]) + assert.NotContains(t, fields, "last_job_error") + assert.Empty(t, fields["hints"]) + }) + + t.Run("healthy request has no hint", func(t *testing.T) { + stats := testStats(t) + core, logs := observer.New(zapcore.InfoLevel) + logger := NewProgressLogger(stats, zap.New(core)) + + stats.startTime = time.Now().Add(-30 * time.Minute) + stats.RecordStagesProgress([]StageProgress{ + {Stage: 0, Mappers: []string{"map_out"}, HighestContiguousBlock: 1_000_100}, + }) + stats.lastSentBlockNum = 1_000_000 + stats.RecordBlockSent(2*time.Millisecond, 1) + logger.logProgress() + + assert.Empty(t, fieldMap(t, logs.All()[0])["hints"]) + }) +} + +func TestProgressLogDurationFromEnv(t *testing.T) { + fallback := 5 * time.Minute + + t.Run("unset keeps the default", func(t *testing.T) { + assert.Equal(t, fallback, progressLogDurationFromEnv("SUBSTREAMS_TEST_UNSET_VAR", fallback)) + }) + + t.Run("valid duration overrides", func(t *testing.T) { + t.Setenv(EnvProgressLogInterval, "90s") + assert.Equal(t, 90*time.Second, progressLogDurationFromEnv(EnvProgressLogInterval, fallback)) + }) + + t.Run("unparseable value panics", func(t *testing.T) { + t.Setenv(EnvProgressLogInterval, "5 minutes") + assert.PanicsWithError(t, + `invalid value for env var SUBSTREAMS_PROGRESS_LOG_INTERVAL: time: unknown unit " minutes" in duration "5 minutes"`, + func() { progressLogDurationFromEnv(EnvProgressLogInterval, fallback) }) + }) + + t.Run("non-positive value panics, it would busy-loop", func(t *testing.T) { + t.Setenv(EnvProgressLogInterval, "0s") + assert.Panics(t, func() { progressLogDurationFromEnv(EnvProgressLogInterval, fallback) }) + + t.Setenv(EnvProgressLogInterval, "-1m") + assert.Panics(t, func() { progressLogDurationFromEnv(EnvProgressLogInterval, fallback) }) + }) +} + +func TestProgressLoggerUsesConfiguredIntervals(t *testing.T) { + previousFirst, previousInterval := FirstProgressLogDelay, ProgressLogInterval + FirstProgressLogDelay, ProgressLogInterval = 10*time.Millisecond, 20*time.Millisecond + t.Cleanup(func() { FirstProgressLogDelay, ProgressLogInterval = previousFirst, previousInterval }) + + core, logs := observer.New(zapcore.InfoLevel) + logger := NewProgressLogger(testStats(t), zap.New(core)) + assert.Equal(t, 10*time.Millisecond, logger.firstDelay) + assert.Equal(t, 20*time.Millisecond, logger.interval) + + ctx, cancel := context.WithCancel(context.Background()) + go logger.Run(ctx) + require.Eventually(t, func() bool { return logs.Len() >= 3 }, 2*time.Second, 5*time.Millisecond) + cancel() +} + +func TestWindowedDurations(t *testing.T) { + now := time.Now() + w := &windowedDurations{} + for i := 1; i <= 100; i++ { + w.record(now, time.Duration(i)*time.Millisecond, 1) + } + snap := w.snapshot(now) + + assert.Equal(t, uint64(100), snap.count) + assert.Equal(t, uint64(100), snap.blocks) + assert.Equal(t, 5050*time.Millisecond, snap.total) + assert.Equal(t, 1*time.Millisecond, snap.minimum) + assert.Equal(t, 100*time.Millisecond, snap.maximum) +} + +func TestWindowedDurationsSpanBuckets(t *testing.T) { + now := time.Now() + w := &windowedDurations{} + + // Spread over the window: everything still counts, and reading twice does not consume it. + for i := 0; i < 10; i++ { + w.record(now.Add(-time.Duration(i)*30*time.Second), 10*time.Millisecond, 2) + } + assert.Equal(t, uint64(10), w.snapshot(now).count) + assert.Equal(t, uint64(20), w.snapshot(now).blocks, "a report must not consume the window") + +} + +func TestWindowedDurationsAgeOut(t *testing.T) { + now := time.Now() + w := &windowedDurations{} + + w.record(now.Add(-ProgressWindow-time.Minute), time.Second, 100) + + snap := w.snapshot(now) + assert.Equal(t, uint64(0), snap.count, "a sample older than the window must not be reported") + assert.Equal(t, time.Duration(0), snap.maximum) +} + +func TestWindowedCounterAgesOut(t *testing.T) { + now := time.Now() + var c windowedCounter + + c.add(now, 3) + c.add(now.Add(-2*time.Minute), 4) + c.add(now.Add(-ProgressWindow-time.Minute), 100) + + assert.Equal(t, uint64(7), c.sum(now)) +} + +// A slot is addressed by absolute time, so a stale bucket must be overwritten rather than +// summed when its slot comes back around a full cycle later. +func TestWindowedCounterReusesStaleSlot(t *testing.T) { + now := time.Now() + var c windowedCounter + + old := now.Add(-time.Duration(windowBuckets) * windowBucketDuration) + c.add(old, 100) + c.add(now, 1) + + assert.Equal(t, uint64(1), c.sum(now)) +} diff --git a/metrics/progress_window.go b/metrics/progress_window.go new file mode 100644 index 000000000..b9de46737 --- /dev/null +++ b/metrics/progress_window.go @@ -0,0 +1,239 @@ +package metrics + +import ( + "time" +) + +// Every rate and delta in the progress log covers a fixed trailing period, independent of how +// often the log is actually emitted. Tying the two together made the numbers change meaning +// whenever the emission interval was tuned, and made two consecutive lines incomparable when +// the first one covered a minute and the second one five. +// +// The window is accumulated in fixed time buckets: each recorded event lands in the bucket +// covering its timestamp, and reading sums the buckets still inside the window. Buckets are +// addressed by absolute time, so one that fell out of the window is simply overwritten when +// its slot comes back around — there is no rolling to do and no cleanup goroutine. +const ( + // ProgressWindow is the period every `_5m`-suffixed value in the progress log covers. + ProgressWindow = 5 * time.Minute + + windowBucketDuration = 30 * time.Second + // One extra bucket so the covered span is always at least ProgressWindow, even though the + // most recent bucket is only partially elapsed. + windowBuckets = int(ProgressWindow/windowBucketDuration) + 1 +) + +// bucketFor returns the slot a timestamp belongs to, and that slot's start time. Slots are +// derived from absolute time rather than from a moving cursor, so concurrent writers and +// readers always agree on which slot holds which period. +func bucketFor(now time.Time) (slot int, start time.Time) { + bucket := now.UnixNano() / int64(windowBucketDuration) + return int(bucket % int64(windowBuckets)), time.Unix(0, bucket*int64(windowBucketDuration)) +} + +// inWindow reports whether a bucket stamped at `start` still counts at `now`. +func inWindow(start, now time.Time) bool { + return !start.IsZero() && !start.Before(now.Add(-ProgressWindow)) +} + +// windowedCounter sums increments over the trailing window. +type windowedCounter struct { + stamps [windowBuckets]time.Time + values [windowBuckets]uint64 +} + +func (w *windowedCounter) add(now time.Time, n uint64) { + slot, start := bucketFor(now) + if !w.stamps[slot].Equal(start) { + w.stamps[slot] = start + w.values[slot] = 0 + } + w.values[slot] += n +} + +func (w *windowedCounter) sum(now time.Time) (out uint64) { + for slot, start := range w.stamps { + if inWindow(start, now) { + out += w.values[slot] + } + } + return out +} + +// windowedDuration sums elapsed time over the trailing window. +type windowedDuration struct { + stamps [windowBuckets]time.Time + values [windowBuckets]time.Duration +} + +func (w *windowedDuration) add(now time.Time, d time.Duration) { + slot, start := bucketFor(now) + if !w.stamps[slot].Equal(start) { + w.stamps[slot] = start + w.values[slot] = 0 + } + w.values[slot] += d +} + +func (w *windowedDuration) sum(now time.Time) (out time.Duration) { + for slot, start := range w.stamps { + if inWindow(start, now) { + out += w.values[slot] + } + } + return out +} + +// windowedStage holds one stage's job accounting over the trailing window. The fields are +// grouped in a single bucket so a stage costs one small array instead of one per counter. +type windowedStage struct { + stamps [windowBuckets]time.Time + buckets [windowBuckets]stageBucket +} + +type stageBucket struct { + completed uint64 + failed uint64 + cancelled uint64 + retried uint64 + delayed uint64 + duration time.Duration + maxDuration time.Duration +} + +func (w *windowedStage) bucket(now time.Time) *stageBucket { + slot, start := bucketFor(now) + if !w.stamps[slot].Equal(start) { + w.stamps[slot] = start + w.buckets[slot] = stageBucket{} + } + return &w.buckets[slot] +} + +func (w *windowedStage) sum(now time.Time) (out stageBucket) { + for slot, start := range w.stamps { + if !inWindow(start, now) { + continue + } + bucket := w.buckets[slot] + out.completed += bucket.completed + out.failed += bucket.failed + out.cancelled += bucket.cancelled + out.retried += bucket.retried + out.delayed += bucket.delayed + out.duration += bucket.duration + if bucket.maxDuration > out.maxDuration { + out.maxDuration = bucket.maxDuration + } + } + return out +} + +// windowedDurations accumulates timed events over the trailing window: count, total, min and +// max. No sample is retained: quantiles over SendMsg durations described the gRPC flow-control +// window as much as the consumer, and the total is what the reporting relies on. +type windowedDurations struct { + stamps [windowBuckets]time.Time + buckets [windowBuckets]durationBucket +} + +type durationBucket struct { + count uint64 + blocks uint64 + total time.Duration + minimum time.Duration + maximum time.Duration +} + +func (w *windowedDurations) record(now time.Time, elapsed time.Duration, blocks uint64) { + slot, start := bucketFor(now) + if !w.stamps[slot].Equal(start) { + w.stamps[slot] = start + w.buckets[slot] = durationBucket{} + } + + bucket := &w.buckets[slot] + if bucket.count == 0 || elapsed < bucket.minimum { + bucket.minimum = elapsed + } + if elapsed > bucket.maximum { + bucket.maximum = elapsed + } + bucket.count++ + bucket.blocks += blocks + bucket.total += elapsed +} + +func (w *windowedDurations) snapshot(now time.Time) durationStats { + var out durationStats + + for slot, start := range w.stamps { + if !inWindow(start, now) { + continue + } + bucket := w.buckets[slot] + if bucket.count == 0 { + continue + } + if out.count == 0 || bucket.minimum < out.minimum { + out.minimum = bucket.minimum + } + if bucket.maximum > out.maximum { + out.maximum = bucket.maximum + } + out.count += bucket.count + out.blocks += bucket.blocks + out.total += bucket.total + } + return out +} + +// callCounters is the cumulative state of one (module, extension) pair. +type callCounters struct { + count uint64 + time time.Duration +} + +// windowedCallCounters turns cumulative external-call totals into a windowed delta. Unlike +// everything else here it cannot accumulate increments: calls made inside tier2 jobs are +// reported to tier1 as running totals, never as events. So one snapshot of those totals is +// kept per bucket, and the delta is measured against the oldest one still in the window. +type windowedCallCounters struct { + stamps [windowBuckets]time.Time + values [windowBuckets]map[string]callCounters +} + +// observe records the current cumulative totals, once per bucket: the first observation of a +// bucket is what later reads measure against. +func (w *windowedCallCounters) observe(now time.Time, current map[string]callCounters) { + slot, start := bucketFor(now) + if w.stamps[slot].Equal(start) { + return + } + + snapshot := make(map[string]callCounters, len(current)) + for key, counters := range current { + snapshot[key] = counters + } + w.stamps[slot] = start + w.values[slot] = snapshot +} + +// baseline returns the oldest snapshot still inside the window, or nil when none was taken +// yet — in which case the caller reports the lifetime totals, which is correct for a request +// younger than the window. +func (w *windowedCallCounters) baseline(now time.Time) map[string]callCounters { + var oldest time.Time + var out map[string]callCounters + + for slot, start := range w.stamps { + if !inWindow(start, now) { + continue + } + if oldest.IsZero() || start.Before(oldest) { + oldest = start + out = w.values[slot] + } + } + return out +} diff --git a/metrics/stats.go b/metrics/stats.go index d1cb1093b..94eb44899 100644 --- a/metrics/stats.go +++ b/metrics/stats.go @@ -3,6 +3,7 @@ package metrics import ( "cmp" "context" + "errors" "slices" "strings" "sync" @@ -71,6 +72,53 @@ type Stats struct { lastSentBlockNum uint64 lastSentBlockID string lastSentBlockTime time.Time + // resolvedStartBlockNum is where the stream starts, so a request that has not sent + // anything yet still has a baseline to measure the consumer against. Without it, "0" + // stands in for "nothing sent" and every distance computed from it is nonsense. + resolvedStartBlockNum uint64 + + // ---- fields feeding the periodic "substreams request progress" log (tier1) ---- + + // stagesProgress is refreshed by the orchestrator's Stages while parallel processing runs. + stagesProgress []StageProgress + // squashBacklogSince records, per stage, when its squash backlog first crossed the + // reporting threshold, so only a backlog that holds is reported. + squashBacklogSince map[int]time.Time + // lastProcessedBlockNum is the last block that went through the linear pipeline, which + // supersedes modulesProgress once we left the parallel phase. + lastProcessedBlockNum uint64 + // streamingFirstSegment is set while a tier2 job streams the first mapper segment straight + // to the client, instead of tier1 reading it from the exec-out cache. + streamingFirstSegment bool + // schedulingBlockedOnConsumption is set when the scheduler refuses to schedule further + // jobs because they would run too far ahead of what the client consumed. + schedulingBlockedOnConsumption bool + schedulingBlockedSince time.Time + // windowThrottled is how long scheduling was actually held back over the window. The flag + // above is a momentary state that flips on every scheduling attempt, so it says nothing on + // its own about whether the throttle cost anything. + windowThrottled windowedDuration + // maxParallelJobs is what the request is allowed to run at once, so an idle worker count + // can be derived: a throttle only costs something when it leaves workers with nothing to do. + maxParallelJobs uint64 + // stageJobs holds job accounting per stage, indexed by stage number. + stageJobs []*stageJobStats + // lastJobError keeps the most recent tier2 job error of the request. Failure counts tell + // you that jobs are being redone; only the error text tells you why (an unreachable RPC + // endpoint behind an eth_call, a deterministic module panic, an overloaded tier2...). + lastJobError string + lastJobErrorStage int + lastJobErrorTime time.Time + jobErrors uint64 + windowJobErrors windowedCounter + // blockSendWindow times the individual `SendMsg` calls carrying block data, so we can tell + // a slow consumer apart from slow processing. + blockSendWindow windowedDurations + blocksSent uint64 + // windowLocalBlocks counts blocks that went through the linear pipeline, over the window. + windowLocalBlocks windowedCounter + // windowExternalCalls turns the cumulative external-call totals into a windowed delta. + windowExternalCalls windowedCallCounters } type runningJobs map[uint64]*extendedJob @@ -206,11 +254,17 @@ type extendedStats struct { type inprocessCall struct { startTime time.Time extension string + // blockNum is the block the module was executing when it made the call, which is where + // processing is stuck for as long as the call does not return. + blockNum uint64 } type extendedCallMetric struct { count uint64 - time time.Duration + // failed counts the calls that came back with an error. A chain endpoint that is refusing + // connections shows up here long before the segment gives up on it. + failed uint64 + time time.Duration // maxTime is the duration of the slowest single call, which a total or an average hides: one // 30s eth_call among thousands of fast ones barely moves the average. maxTime time.Duration @@ -227,13 +281,24 @@ func (s *extendedStats) updateDurations() { i := 0 for k, v := range s.externalCallMetrics { callMetric := &pbssinternal.ExternalCallMetric{ - Name: k, - Count: v.count, - TimeMs: uint64(v.time.Milliseconds()), + Name: k, + Count: v.count, + TimeMs: uint64(v.time.Milliseconds()), + FailedCount: v.failed, } + // A call that has not returned has already been counted (the count is incremented when + // it starts) but contributed no time yet. Reported as-is, a call hung for minutes looks + // instantaneous and a whole class of problems stays invisible until the segment dies. for _, inproc := range s.inprocessCallMetrics { - if inproc.extension == k { - callMetric.TimeMs += uint64(time.Since(inproc.startTime).Milliseconds()) + if inproc.extension != k { + continue + } + waiting := time.Since(inproc.startTime) + callMetric.TimeMs += uint64(waiting.Milliseconds()) + callMetric.InFlightCount++ + if waiting.Milliseconds() > int64(callMetric.OldestInFlightMs) { + callMetric.OldestInFlightMs = uint64(waiting.Milliseconds()) + callMetric.OldestInFlightBlock = inproc.blockNum } } @@ -254,6 +319,9 @@ func (s *Stats) RecordInitializationComplete() { s.Lock() defer s.Unlock() s.initDuration = time.Since(s.startTime) + // No more jobs to hold back once parallel processing is over. + s.schedulingBlockedOnConsumption = false + s.schedulingBlockedSince = time.Time{} } func (s *Stats) RecordEgress(egressBytes int) { @@ -279,6 +347,24 @@ func (s *Stats) RecordLastBlockSent(clock *pbsubstreams.Clock) { s.lastSentBlockTime = clock.Timestamp.AsTime() } +// RecordResolvedStartBlock sets the block the stream starts at, once it is known. +func (s *Stats) RecordResolvedStartBlock(blockNum uint64) { + s.Lock() + defer s.Unlock() + s.resolvedStartBlockNum = blockNum +} + +// consumedUpTo is the highest block the consumer can be said to have gone through. Before +// the first block is sent that is the start of the stream, not block 0. +// +// consumedUpTo should be called while locked +func (s *Stats) consumedUpTo() uint64 { + if s.lastSentBlockNum != 0 { + return s.lastSentBlockNum + } + return s.resolvedStartBlockNum +} + func (s *Stats) RecordBlocksProcessed(count uint64) { s.processedBlocks.Add(count) } @@ -316,10 +402,21 @@ func (s *Stats) RecordNewSubrequest(stage uint32, startBlock, stopBlock uint64) }, modulesStats: make(map[string]*pbssinternal.ModuleStats), } + + s.stageJobStats(int(stage)).scheduled++ + s.Unlock() return id } +// stageJobStats should be called while locked +func (s *Stats) stageJobStats(stage int) *stageJobStats { + for len(s.stageJobs) <= stage { + s.stageJobs = append(s.stageJobs, &stageJobStats{}) + } + return s.stageJobs[stage] +} + func (s *Stats) RecordModuleMerging(module string) { s.Lock() defer s.Unlock() @@ -347,11 +444,49 @@ const ( JobFailed ) +// maxLoggedJobError bounds how much of a job error reaches the progress log. Worker errors +// are deeply wrapped and can carry a payload dump; the interesting part (the innermost +// cause, e.g. "connection refused" under an eth_call) sits well past the first few hundred +// characters, so the cap has to be generous, but only one error is ever kept. +const maxLoggedJobError = 900 + +// RecordJobError should be called whenever a tier2 job comes back with an error, whether it +// will be retried or not. +func (s *Stats) RecordJobError(jobIdx uint64, err error) { + // A cancellation is the request going away, not a job going wrong: reporting it would + // bury the real error under noise every time a client disconnects. + if err == nil || errors.Is(err, context.Canceled) { + return + } + s.Lock() + defer s.Unlock() + + s.jobErrors++ + s.windowJobErrors.add(time.Now(), 1) + s.lastJobError = truncateError(err.Error()) + s.lastJobErrorTime = time.Now() + if job, ok := s.runningJobs[jobIdx]; ok { + s.lastJobErrorStage = int(job.Stage) + } +} + +func truncateError(in string) string { + if len(in) <= maxLoggedJobError { + return in + } + return in[:maxLoggedJobError] + "…(truncated)" +} + // RecordJobDelayed should be called when a job is retried without any work done (ex: rejected upon connection to tier2) func (s *Stats) RecordJobDelayed(jobIdx uint64) { s.Lock() defer s.Unlock() s.delayedJobs++ + if job, ok := s.runningJobs[jobIdx]; ok { + stg := s.stageJobStats(int(job.Stage)) + stg.delayed++ + stg.window.bucket(time.Now()).delayed++ + } } // RecordJobRetried should be called when a job is retried after having possibly done some work @@ -359,6 +494,11 @@ func (s *Stats) RecordJobRetried(jobIdx uint64) { s.Lock() defer s.Unlock() s.retriedJobs++ + if job, ok := s.runningJobs[jobIdx]; ok { + stg := s.stageJobStats(int(job.Stage)) + stg.retried++ + stg.window.bucket(time.Now()).retried++ + } } func (s *Stats) RecordEndSubrequest(jobIdx uint64, status JobStatus) { @@ -386,13 +526,28 @@ func (s *Stats) RecordEndSubrequest(jobIdx uint64, status JobStatus) { s.completedJobsBytesRead += job.bytesRead s.completedJobsBytesWritten += job.bytesWritten + stg := s.stageJobStats(int(job.Stage)) + bucket := stg.window.bucket(time.Now()) + elapsed := time.Since(job.start) switch status { case JobComplete: s.completedJobs++ + stg.completed++ + bucket.completed++ + bucket.duration += elapsed + if elapsed > bucket.maxDuration { + bucket.maxDuration = elapsed + } + if job.StopBlock > stg.lastCompletedStopBlock { + stg.lastCompletedStopBlock = job.StopBlock + } case JobCancelled: - // no-op + stg.cancelled++ + bucket.cancelled++ case JobFailed: s.failedJobs++ + stg.failed++ + bucket.failed++ } s.remoteProcessedBlockCount += job.ProgressBlocks @@ -422,7 +577,7 @@ func (s *Stats) RecordModuleWasmBlockEnd(moduleName string, uniqueID uint64) { var uniqueIDCounter = atomic.NewUint64(0) // RecordModuleWasmExternalCallBegin can be called multiple times per module per block, for each external module call (ex: eth_call). -func (s *Stats) RecordModuleWasmExternalCallBegin(moduleName string, extension string) uint64 { +func (s *Stats) RecordModuleWasmExternalCallBegin(moduleName string, extension string, blockNum uint64) uint64 { s.Lock() defer s.Unlock() @@ -433,6 +588,7 @@ func (s *Stats) RecordModuleWasmExternalCallBegin(moduleName string, extension s mod.inprocessCallMetrics[uniqueID] = inprocessCall{ startTime: time.Now(), extension: extension, + blockNum: blockNum, } met, ok := mod.externalCallMetrics[extension] @@ -446,7 +602,7 @@ func (s *Stats) RecordModuleWasmExternalCallBegin(moduleName string, extension s } // RecordModuleWasmExternalCallEnd can be called multiple times per module per block, for each external module call (ex: eth_call). `elapsed` is the time spent in executing that call. -func (s *Stats) RecordModuleWasmExternalCallEnd(moduleName string, extension string, uniqueID uint64) { +func (s *Stats) RecordModuleWasmExternalCallEnd(moduleName string, extension string, uniqueID uint64, callErr error) { s.Lock() defer s.Unlock() @@ -462,6 +618,9 @@ func (s *Stats) RecordModuleWasmExternalCallEnd(moduleName string, extension str if elapsed > met.maxTime { met.maxTime = elapsed } + if callErr != nil { + met.failed++ + } delete(mod.inprocessCallMetrics, uniqueID) } @@ -506,6 +665,10 @@ func (s *Stats) RecordBlock(ref bstream.BlockRef) { defer s.Unlock() s.blockRate.Add(1) s.localProcessedBlockCount += 1 + s.windowLocalBlocks.add(time.Now(), 1) + if ref != nil { + s.lastProcessedBlockNum = ref.Num() + } } func newExtendedStats(moduleName string) *extendedStats { @@ -835,6 +998,14 @@ type wasmExtensionCallMetric struct { // maxTime is only known for calls made locally by this process. Calls made by tier2 jobs are // reported back as a count and a total only, and each tier2 logs its own max. maxTime time.Duration + // inFlight, oldestInFlight and oldestInFlightBlock cover calls that started and have not + // returned. Same caveat as maxTime: only locally executed modules are visible here, a + // tier2 job folds the elapsed time of its own in-flight calls into the total it reports. + inFlight uint64 + oldestInFlight time.Duration + oldestInFlightBlock uint64 + // failed counts the calls that came back with an error, wherever they ran. + failed uint64 } func (m *wasmExtensionCallMetric) MarshalLogObject(encoder zapcore.ObjectEncoder) error { @@ -885,10 +1056,24 @@ func (s *Stats) wasmExtensionCallMetricsByModule() []*wasmExtensionCallMetric { metric := metricFor(module, extension) metric.count += callMetric.count metric.totalTime += callMetric.time + metric.failed += callMetric.failed if callMetric.maxTime > metric.maxTime { metric.maxTime = callMetric.maxTime } } + // A call that is still running has already been counted (the count is incremented when + // it starts) but has contributed no time yet. Left out, a call hung for minutes against + // a dead endpoint looks instantaneous, which is the opposite of what is happening. + for _, inProcess := range mod.inprocessCallMetrics { + metric := metricFor(module, inProcess.extension) + elapsed := time.Since(inProcess.startTime) + metric.totalTime += elapsed + metric.inFlight++ + if elapsed > metric.oldestInFlight { + metric.oldestInFlight = elapsed + metric.oldestInFlightBlock = inProcess.blockNum + } + } } addRemote := func(modulesStats map[string]*pbssinternal.ModuleStats) { @@ -897,6 +1082,12 @@ func (s *Stats) wasmExtensionCallMetricsByModule() []*wasmExtensionCallMetric { metric := metricFor(module, callMetric.Name) metric.count += callMetric.Count metric.totalTime += time.Duration(callMetric.TimeMs) * time.Millisecond + metric.failed += callMetric.FailedCount + metric.inFlight += callMetric.InFlightCount + if oldest := time.Duration(callMetric.OldestInFlightMs) * time.Millisecond; oldest > metric.oldestInFlight { + metric.oldestInFlight = oldest + metric.oldestInFlightBlock = callMetric.OldestInFlightBlock + } } } } diff --git a/metrics/stats_test.go b/metrics/stats_test.go index bb5148944..35f3c4098 100644 --- a/metrics/stats_test.go +++ b/metrics/stats_test.go @@ -1,6 +1,7 @@ package metrics import ( + "errors" "testing" "time" @@ -8,6 +9,7 @@ import ( pbsubstreamsrpc "github.com/streamingfast/substreams/pb/sf/substreams/rpc/v2" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" + "go.uber.org/zap" "go.uber.org/zap/zapcore" ) @@ -97,16 +99,16 @@ func TestStats_WasmExtensionCallMetrics_Empty(t *testing.T) { func TestStats_RecordModuleWasmExternalCallEnd_TracksMax(t *testing.T) { stats := NewReqStats(&Config{}, nil, nil, zlogTest) - slowID := stats.RecordModuleWasmExternalCallBegin("mod_a", "eth:call") + slowID := stats.RecordModuleWasmExternalCallBegin("mod_a", "eth:call", 12_450_739) time.Sleep(30 * time.Millisecond) - stats.RecordModuleWasmExternalCallEnd("mod_a", "eth:call", slowID) + stats.RecordModuleWasmExternalCallEnd("mod_a", "eth:call", slowID, nil) slowest := stats.modulesStats["mod_a"].externalCallMetrics["eth:call"].maxTime require.GreaterOrEqual(t, slowest, 30*time.Millisecond) // A faster call afterwards must not lower the recorded max. - fastID := stats.RecordModuleWasmExternalCallBegin("mod_a", "eth:call") - stats.RecordModuleWasmExternalCallEnd("mod_a", "eth:call", fastID) + fastID := stats.RecordModuleWasmExternalCallBegin("mod_a", "eth:call", 12_450_739) + stats.RecordModuleWasmExternalCallEnd("mod_a", "eth:call", fastID, nil) callMetric := stats.modulesStats["mod_a"].externalCallMetrics["eth:call"] assert.Equal(t, slowest, callMetric.maxTime) @@ -149,3 +151,56 @@ func setExternalCallMetric(stats *Stats, moduleName, extension string, count uin mod := stats.moduleStats(moduleName) mod.externalCallMetrics[extension] = &extendedCallMetric{count: count, time: total, maxTime: max} } + +// A tier2 reports its external calls to tier1 as running totals. These two tests pin what those +// totals must carry for a failing or hung endpoint to be visible before the segment gives up. +func TestStats_ExternalCallMetrics_ReportFailures(t *testing.T) { + stats := NewReqStats(&Config{}, nil, nil, zap.NewNop()) + + ok := stats.RecordModuleWasmExternalCallBegin("mod_a", "rpc:eth_call", 500) + stats.RecordModuleWasmExternalCallEnd("mod_a", "rpc:eth_call", ok, nil) + + failed := stats.RecordModuleWasmExternalCallBegin("mod_a", "rpc:eth_call", 501) + stats.RecordModuleWasmExternalCallEnd("mod_a", "rpc:eth_call", failed, errors.New("connection refused")) + + metric := externalCallMetric(t, stats, "mod_a", "rpc:eth_call") + assert.Equal(t, uint64(2), metric.Count) + assert.Equal(t, uint64(1), metric.FailedCount) + assert.Equal(t, uint64(0), metric.InFlightCount) +} + +func TestStats_ExternalCallMetrics_ReportInFlight(t *testing.T) { + stats := NewReqStats(&Config{}, nil, nil, zap.NewNop()) + + // Begin without End is what a call retrying against an unreachable endpoint looks like from + // here: the extension retries internally, so it stays a single call for minutes. + id := stats.RecordModuleWasmExternalCallBegin("mod_a", "rpc:eth_call", 12_450_739) + stats.modulesStats["mod_a"].inprocessCallMetrics[id] = inprocessCall{ + startTime: time.Now().Add(-3 * time.Minute), + extension: "rpc:eth_call", + blockNum: 12_450_739, + } + + metric := externalCallMetric(t, stats, "mod_a", "rpc:eth_call") + assert.Equal(t, uint64(1), metric.InFlightCount) + assert.Equal(t, uint64(12_450_739), metric.OldestInFlightBlock) + assert.InDelta(t, (3 * time.Minute).Milliseconds(), metric.OldestInFlightMs, 1000) + // The time already spent waiting counts, otherwise a hung call reports as instantaneous. + assert.InDelta(t, (3 * time.Minute).Milliseconds(), metric.TimeMs, 1000) +} + +func externalCallMetric(t *testing.T, stats *Stats, module, extension string) *pbssinternal.ExternalCallMetric { + t.Helper() + for _, mod := range stats.LocalModulesStats() { + if mod.Name != module { + continue + } + for _, metric := range mod.ExternalCallMetrics { + if metric.Name == extension { + return metric + } + } + } + t.Fatalf("no %q metric reported for module %q", extension, module) + return nil +} diff --git a/metrics/wasm_ext_gatherer.go b/metrics/wasm_ext_gatherer.go index 4eb4cff01..714da930c 100644 --- a/metrics/wasm_ext_gatherer.go +++ b/metrics/wasm_ext_gatherer.go @@ -18,7 +18,7 @@ type WasmMetricsGatherer struct { logger *zap.Logger } -func (m *WasmMetricsGatherer) RecordModuleWasmExternalCallBegin(moduleName string, extension string) uint64 { +func (m *WasmMetricsGatherer) RecordModuleWasmExternalCallBegin(moduleName string, extension string, blockNum uint64) uint64 { m.Lock() defer m.Unlock() if m.inProcessCalls == nil { @@ -33,12 +33,13 @@ func (m *WasmMetricsGatherer) RecordModuleWasmExternalCallBegin(moduleName strin m.inProcessCalls[moduleName][uniqueID] = &inprocessCall{ startTime: time.Now(), extension: extension, + blockNum: blockNum, } return uniqueID } -func (m *WasmMetricsGatherer) RecordModuleWasmExternalCallEnd(moduleName string, extension string, uniqueID uint64) { +func (m *WasmMetricsGatherer) RecordModuleWasmExternalCallEnd(moduleName string, extension string, uniqueID uint64, callErr error) { m.Lock() defer m.Unlock() @@ -71,6 +72,9 @@ func (m *WasmMetricsGatherer) RecordModuleWasmExternalCallEnd(moduleName string, metric.Count++ metric.TimeMs += uint64(duration.Milliseconds()) + if callErr != nil { + metric.FailedCount++ + } } func (m *WasmMetricsGatherer) ApplyToStats(stats *Stats) { @@ -88,12 +92,17 @@ func (m *WasmMetricsGatherer) ApplyToStats(stats *Stats) { } metrics[extension].count += metric.Count metrics[extension].time += time.Duration(metric.TimeMs) * time.Millisecond + metrics[extension].failed += metric.FailedCount } } + // Deliberately not copying m.inProcessCalls: Stats has no way to ever remove those entries + // (the gatherer deletes from its own map when a call ends), so they would inflate the + // reported in-flight count and duration forever. This gatherer is applied once its wasm + // call has returned anyway, so there is normally nothing in flight left to report. } type WasmExtensionStats interface { - RecordModuleWasmExternalCallBegin(moduleName string, extension string) uint64 - RecordModuleWasmExternalCallEnd(moduleName string, extension string, uniqueID uint64) + RecordModuleWasmExternalCallBegin(moduleName string, extension string, blockNum uint64) uint64 + RecordModuleWasmExternalCallEnd(moduleName string, extension string, uniqueID uint64, callErr error) } diff --git a/metrics/wasm_ext_gatherer_test.go b/metrics/wasm_ext_gatherer_test.go index f3e64cc23..e5b1e6352 100644 --- a/metrics/wasm_ext_gatherer_test.go +++ b/metrics/wasm_ext_gatherer_test.go @@ -10,8 +10,8 @@ import ( func TestWasmMetricsGatherer_RecordsDoneCalls(t *testing.T) { gatherer := &WasmMetricsGatherer{logger: zlogTest} - id := gatherer.RecordModuleWasmExternalCallBegin("mod", "eth:call") - gatherer.RecordModuleWasmExternalCallEnd("mod", "eth:call", id) + id := gatherer.RecordModuleWasmExternalCallBegin("mod", "eth:call", 12_450_739) + gatherer.RecordModuleWasmExternalCallEnd("mod", "eth:call", id, nil) require.Contains(t, gatherer.doneCalls, "mod") require.Contains(t, gatherer.doneCalls["mod"], "eth:call") @@ -19,8 +19,8 @@ func TestWasmMetricsGatherer_RecordsDoneCalls(t *testing.T) { assert.Equal(t, "eth:call", gatherer.doneCalls["mod"]["eth:call"].Name) // A second call on the same (module, extension) must accumulate onto the same metric. - id = gatherer.RecordModuleWasmExternalCallBegin("mod", "eth:call") - gatherer.RecordModuleWasmExternalCallEnd("mod", "eth:call", id) + id = gatherer.RecordModuleWasmExternalCallBegin("mod", "eth:call", 12_450_739) + gatherer.RecordModuleWasmExternalCallEnd("mod", "eth:call", id, nil) assert.Equal(t, uint64(2), gatherer.doneCalls["mod"]["eth:call"].Count) assert.Len(t, gatherer.doneCalls["mod"], 1) @@ -30,11 +30,11 @@ func TestWasmMetricsGatherer_ApplyToStats(t *testing.T) { gatherer := &WasmMetricsGatherer{logger: zlogTest} for range 3 { - id := gatherer.RecordModuleWasmExternalCallBegin("mod", "eth:call") - gatherer.RecordModuleWasmExternalCallEnd("mod", "eth:call", id) + id := gatherer.RecordModuleWasmExternalCallBegin("mod", "eth:call", 12_450_739) + gatherer.RecordModuleWasmExternalCallEnd("mod", "eth:call", id, nil) } - id := gatherer.RecordModuleWasmExternalCallBegin("mod", "eth:balance") - gatherer.RecordModuleWasmExternalCallEnd("mod", "eth:balance", id) + id := gatherer.RecordModuleWasmExternalCallBegin("mod", "eth:balance", 12_450_739) + gatherer.RecordModuleWasmExternalCallEnd("mod", "eth:balance", id, nil) stats := NewReqStats(&Config{}, nil, nil, zlogTest) gatherer.ApplyToStats(stats) @@ -52,7 +52,7 @@ func TestWasmMetricsGatherer_EndWithoutBeginNilLogger(t *testing.T) { gatherer := &WasmMetricsGatherer{} assert.NotPanics(t, func() { - gatherer.RecordModuleWasmExternalCallEnd("mod", "eth:call", 42) + gatherer.RecordModuleWasmExternalCallEnd("mod", "eth:call", 42, nil) }) assert.Empty(t, gatherer.doneCalls) } diff --git a/orchestrator/scheduler/scheduler.go b/orchestrator/scheduler/scheduler.go index ede23993b..2cc223642 100644 --- a/orchestrator/scheduler/scheduler.go +++ b/orchestrator/scheduler/scheduler.go @@ -65,6 +65,10 @@ func New(ctx context.Context, stream *response.Stream) *Scheduler { func (s *Scheduler) Init() loop.Cmd { var cmds []loop.Cmd + // Surfaced as the request's phase: until that segment lands, the blocks the client gets + // come from a worker rather than from the cache. + reqctx.ReqStats(s.ctx).RecordStreamingFirstSegment(s.StreamFirstTier2MapSegment) + if s.StreamFirstTier2MapSegment { cmds = append(cmds, execout.CmdWaitFirstTier2MapSegmentStreamed(250*time.Millisecond)) } else if s.ExecOutWalker != nil { @@ -121,6 +125,7 @@ func (s *Scheduler) Update(msg loop.Msg) loop.Cmd { s.delayedScheduleNextJob = false if msg.Streamed { s.firstTier2MapSegmentStreamed = true + reqctx.ReqStats(s.ctx).RecordStreamingFirstSegment(false) } tryMerge := s.Stages.CmdTryMerge(msg.Unit.Stage) @@ -168,6 +173,9 @@ func (s *Scheduler) Update(msg loop.Msg) loop.Cmd { } workUnit, workRange, skippedAboveSegment := s.Stages.NextJob(notAboveSegment) + // Surfaced in the periodic request progress log: jobs held back here mean the + // consumer, not the processing, is setting the pace. + reqctx.ReqStats(s.ctx).RecordJobSchedulingBlocked(skippedAboveSegment) if workRange == nil { // no job ready if !skippedAboveSegment { s.logger.Debug("no next job available and not skipped above segment, returning nil (potential deadlock point)", diff --git a/orchestrator/stage/progress_test.go b/orchestrator/stage/progress_test.go new file mode 100644 index 000000000..6523e6212 --- /dev/null +++ b/orchestrator/stage/progress_test.go @@ -0,0 +1,138 @@ +package stage + +import ( + "context" + "testing" + + "github.com/streamingfast/bstream" + "github.com/streamingfast/substreams/metrics" + "github.com/streamingfast/substreams/orchestrator/plan" + "github.com/streamingfast/substreams/pipeline/exec" + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" +) + +// stagesForProgress builds 3 stages (store, store, map) over blocks [5, 50) with a segment +// interval of 10. Note that the test graph leaves every module's initial block at 0. +func stagesForProgress(t *testing.T, firstStreamableBlock uint64) *Stages { + t.Helper() + + previous := bstream.GetProtocolFirstStreamableBlock + bstream.GetProtocolFirstStreamableBlock = firstStreamableBlock + t.Cleanup(func() { bstream.GetProtocolFirstStreamableBlock = previous }) + + reqPlan, err := plan.BuildTier1RequestPlan(true, 10, 5, 5, 5, 50, 50, true) + require.NoError(t, err) + + return NewStages(context.Background(), exec.TestGraphStagedModules(5, 5, 5, 5, 5), reqPlan, nil, nil) +} + +func setStates(t *testing.T, stages *Stages, states map[Unit]UnitState) { + t.Helper() + for u := range states { + stages.allocSegments(u.Segment) + } + for u, state := range states { + stages.forceTransition(u.Segment, u.Stage, state) + } +} + +func progressByStage(progress []metrics.StageProgress) map[int]metrics.StageProgress { + out := make(map[int]metrics.StageProgress) + for _, p := range progress { + out[p.Stage] = p + } + return out +} + +func TestModulesProgressNothingDone(t *testing.T) { + // The chain does not start before block 3, so no module can claim anything below it. + stages := stagesForProgress(t, 3) + + progress := progressByStage(stages.stagesProgress(stages.computeStageStats())) + require.Len(t, progress, 3) + + // Nothing processed yet: every stage reports the block its modules start from. + for stage, p := range progress { + assert.Equal(t, uint64(3), p.HighestContiguousBlock, "stage %d", stage) + assert.Equal(t, uint64(0), p.SegmentsReadyForSquashing, "stage %d", stage) + } +} + +func TestStagesProgressPlannedRangeComesFromThePlan(t *testing.T) { + stages := stagesForProgress(t, 0) + + // Nothing was scheduled at all, yet each stage already knows the whole span of jobs it + // has to run for this request — it comes from the plan's segmenter, not from what the + // scheduler picked up. The test graph leaves init blocks at 0, hence [0, 50). + progress := progressByStage(stages.stagesProgress(stages.computeStageStats())) + for stage, p := range progress { + segmenter := stages.stages[stage].segmenter + assert.Equal(t, segmenter.InitialBlock(), p.PlannedFirstJobStartBlock, "stage %d", stage) + assert.Equal(t, segmenter.ExclusiveEndBlock(), p.PlannedLastJobStopBlock, "stage %d", stage) + assert.Equal(t, uint64(0), p.PlannedFirstJobStartBlock, "stage %d", stage) + assert.Equal(t, uint64(50), p.PlannedLastJobStopBlock, "stage %d", stage) + } +} + +func TestModulesProgressStoreExcludesUnsquashedPartials(t *testing.T) { + stages := stagesForProgress(t, 0) + + // Stage 0: segments 0 and 1 are squashed, 2 and 3 only have their partial on disk. + setStates(t, stages, map[Unit]UnitState{ + unit(0, 0): UnitCompleted, + unit(1, 0): UnitCompleted, + unit(2, 0): UnitPartialPresent, + unit(3, 0): UnitMerging, + }) + + progress := progressByStage(stages.stagesProgress(stages.computeStageStats())) + + // Contiguous stops at the end of segment 1, the two partials above are reported apart. + assert.Equal(t, uint64(20), progress[0].HighestContiguousBlock) + assert.Equal(t, uint64(2), progress[0].SegmentsReadyForSquashing) +} + +func TestModulesProgressStoreIgnoresPartialsBehindAHole(t *testing.T) { + stages := stagesForProgress(t, 0) + + // A hole at segment 1 must not let segment 2 count as contiguous. + setStates(t, stages, map[Unit]UnitState{ + unit(0, 0): UnitCompleted, + unit(2, 0): UnitCompleted, + }) + + progress := progressByStage(stages.stagesProgress(stages.computeStageStats())) + assert.Equal(t, uint64(10), progress[0].HighestContiguousBlock) +} + +func TestModulesProgressMapCountsPartials(t *testing.T) { + stages := stagesForProgress(t, 0) + + // Mapper output is read straight from its partial exec-out files, so a partial counts + // as ready, unlike for a store. + setStates(t, stages, map[Unit]UnitState{ + unit(0, 2): UnitCompleted, + unit(1, 2): UnitPartialPresent, + unit(2, 2): UnitPartialPresent, + }) + + progress := progressByStage(stages.stagesProgress(stages.computeStageStats())) + assert.Equal(t, uint64(30), progress[2].HighestContiguousBlock) + assert.Equal(t, uint64(0), progress[2].SegmentsReadyForSquashing, "maps are never squashed") +} + +func TestComputeStageStatsKeepsCompletedRanges(t *testing.T) { + stages := stagesForProgress(t, 0) + setStates(t, stages, map[Unit]UnitState{ + unit(0, 0): UnitCompleted, + unit(1, 0): UnitCompleted, + unit(2, 0): UnitPartialPresent, + }) + + stats := stages.computeStageStats() + merged := stats.ranges[0].Merged() + require.Len(t, merged, 1) + assert.Equal(t, uint64(0), merged[0].StartBlock) + assert.Equal(t, uint64(30), merged[0].ExclusiveEndBlock) +} diff --git a/orchestrator/stage/stage.go b/orchestrator/stage/stage.go index 01e888afb..2001bd7f7 100644 --- a/orchestrator/stage/stage.go +++ b/orchestrator/stage/stage.go @@ -20,6 +20,11 @@ type Stage struct { // allExecutedModules is all the store+mapper executed specifically for this stage allExecutedModules []string + // executedStores and executedMappers split allExecutedModules by kind, for reporting. + // Index modules are grouped with the mappers, they behave the same from a progress + // standpoint. + executedStores []string + executedMappers []string SquashLock sync.Mutex @@ -33,11 +38,13 @@ type Stage struct { asyncWork *llerrgroup.Group } -func NewStage(idx int, kind Kind, segmenter *block.Segmenter, moduleStates []*StoreModuleState, allExecutedModules []string) *Stage { +func NewStage(idx int, kind Kind, segmenter *block.Segmenter, moduleStates []*StoreModuleState, allExecutedModules, executedStores, executedMappers []string) *Stage { return &Stage{ idx: idx, kind: kind, allExecutedModules: allExecutedModules, + executedStores: executedStores, + executedMappers: executedMappers, segmenter: segmenter, segmentCompleted: segmenter.FirstIndex() - 1, storeModuleStates: moduleStates, diff --git a/orchestrator/stage/stages.go b/orchestrator/stage/stages.go index 6af638337..da65bc584 100644 --- a/orchestrator/stage/stages.go +++ b/orchestrator/stage/stages.go @@ -9,7 +9,9 @@ import ( "go.uber.org/zap" "github.com/dustin/go-humanize" + "github.com/streamingfast/bstream" "github.com/streamingfast/substreams/block" + "github.com/streamingfast/substreams/metrics" "github.com/streamingfast/substreams/orchestrator/loop" "github.com/streamingfast/substreams/orchestrator/plan" pbsubstreamsrpc "github.com/streamingfast/substreams/pb/sf/substreams/rpc/v2" @@ -103,10 +105,15 @@ func NewStages( modulesInitBlocks := execGraph.ModulesInitBlocks() for idx, stageLayers := range execGraph.StagedUsedModules() { - var allModules []string + var allModules, storeModules, mapperModules []string for _, layer := range stageLayers { for _, mod := range layer { allModules = append(allModules, mod.Name) + if mod.GetKindStore() != nil { + storeModules = append(storeModules, mod.Name) + } else { + mapperModules = append(mapperModules, mod.Name) + } } } layer := stageLayers.LastLayer() @@ -138,7 +145,7 @@ func NewStages( } stageSegmenter := segmenter.WithInitialBlock(stageLowestInitBlock) - stage := NewStage(idx, kind, stageSegmenter, moduleStates, allModules) + stage := NewStage(idx, kind, stageSegmenter, moduleStates, allModules, storeModules, mapperModules) out.stages = append(out.stages, stage) } @@ -245,39 +252,135 @@ func (s *Stages) UpdateStats() { s.lastStatUpdate = time.Now() out := make([]*pbsubstreamsrpc.Stage, len(s.stages)) - rangesByStage := s.statsRangesByStage() + stats := s.computeStageStats() for stgIdx := range s.stages { mods := make([]string, len(s.stages[stgIdx].allExecutedModules)) _ = copy(mods, s.stages[stgIdx].allExecutedModules) out[stgIdx] = &pbsubstreamsrpc.Stage{ Modules: mods, - CompletedRanges: toProtoRanges(rangesByStage[stgIdx].Merged()), + CompletedRanges: toProtoRanges(stats.ranges[stgIdx].Merged()), } } - reqctx.ReqStats(s.ctx).RecordStages(out) + reqStats := reqctx.ReqStats(s.ctx) + reqStats.RecordStages(out) + reqStats.RecordStagesProgress(s.stagesProgress(stats)) +} + +// stageStats is what a single pass over the segment matrix yields, per stage. +type stageStats struct { + // ranges are the segments that are in progress or done (Completed/PartialPresent/Merging). + ranges []block.Ranges + // contiguousSegment is the highest segment of the uninterrupted prefix of usable + // segments. "Usable" excludes store partials: a partial that was not squashed yet is + // not readable as part of the store. + contiguousSegment []int + // partialSegments counts the store partials sitting above the contiguous prefix, i.e. + // work that is done but still waiting for the squasher. + partialSegments []uint64 } -// statsRangesByStage collects, per stage, the ranges of segments that are in -// progress or done (Completed/PartialPresent/Merging), in a single pass over the -// segment matrix. Because segments are visited in ascending order the ranges come -// out already sorted and de-duplicated (one range per segment), so callers can -// Merged() them directly — no per-stage map allocation and no sort. -func (s *Stages) statsRangesByStage() []block.Ranges { - rangesByStage := make([]block.Ranges, len(s.stages)) +// computeStageStats walks the segment matrix once. Because segments are visited in +// ascending order the ranges come out already sorted and de-duplicated (one range per +// segment), so callers can Merged() them directly — no per-stage map allocation and no sort. +// The contiguous prefix and the pending-partials count are folded into the same pass to keep +// this O(segments × stages) overall, called at most once per second. +func (s *Stages) computeStageStats() stageStats { + out := stageStats{ + ranges: make([]block.Ranges, len(s.stages)), + contiguousSegment: make([]int, len(s.stages)), + partialSegments: make([]uint64, len(s.stages)), + } + // Everything below segmentOffset is assumed to have completed, so the contiguous + // prefix starts there. + for stgIdx := range s.stages { + out.contiguousSegment[stgIdx] = s.segmentOffset - 1 + } + prefixBroken := make([]bool, len(s.stages)) + for segmentIdx, segment := range s.segmentStates { + absoluteSegment := segmentIdx + s.segmentOffset for stgIdx := range s.stages { - switch segment[stgIdx] { + state := segment[stgIdx] + isStore := s.stages[stgIdx].kind == KindStore + segmenter := s.stages[stgIdx].storeModuleStates[0].segmenter + + switch state { case UnitCompleted, UnitPartialPresent, UnitMerging: - segmenter := s.stages[stgIdx].storeModuleStates[0].segmenter - if rng := segmenter.Range(segmentIdx + s.segmentOffset); rng != nil { - rangesByStage[stgIdx] = append(rangesByStage[stgIdx], rng) + if rng := segmenter.Range(absoluteSegment); rng != nil { + out.ranges[stgIdx] = append(out.ranges[stgIdx], rng) + } + } + + // A map segment is usable as soon as its partial exec-out file exists (maps are + // never squashed); a store segment is only usable once it has been merged. + usable := state == UnitCompleted || state == UnitNoOp || (!isStore && state == UnitPartialPresent) + if usable && !prefixBroken[stgIdx] { + out.contiguousSegment[stgIdx] = absoluteSegment + continue + } + prefixBroken[stgIdx] = true + + if isStore && (state == UnitPartialPresent || state == UnitMerging) { + // Bounds-checked rather than asking for the Range: only the segment's existence + // matters here, and Range allocates one per call in a loop that already runs + // once per second over every segment of the run. + if absoluteSegment >= segmenter.FirstIndex() && absoluteSegment <= segmenter.LastIndex() { + out.partialSegments[stgIdx]++ + } + } + } + } + return out +} + +// stagesProgress reports, per stage, the whole range of work it is planned to cover for +// this request, and per module, up to which block it is contiguously ready. Stores stop at +// the last squashed segment and report their unsquashed partials separately; mappers and +// indexes count their partial exec-out files as ready, since that is exactly what the +// output stream reads from. +func (s *Stages) stagesProgress(stats stageStats) []metrics.StageProgress { + firstStreamableBlock := bstream.GetProtocolFirstStreamableBlock + + out := make([]metrics.StageProgress, 0, len(s.stages)) + for stgIdx, stage := range s.stages { + progress := metrics.StageProgress{ + Stage: stgIdx, + Stores: stage.executedStores, + Mappers: stage.executedMappers, + } + // The stage segmenter comes straight from the request plan, so this is the span of + // jobs the stage is expected to run over the session, regardless of what the + // scheduler has picked up so far. Both ranges are nil on an empty stage. + if first := stage.segmenter.Range(stage.segmenter.FirstIndex()); first != nil { + if last := stage.segmenter.Range(stage.segmenter.LastIndex()); last != nil { + progress.PlannedFirstJobStartBlock = first.StartBlock + progress.PlannedLastJobStopBlock = last.ExclusiveEndBlock + } + } + + // A stage is only as advanced as its least advanced module, so report the lowest + // contiguous block across them rather than a per-module breakdown. + for _, modState := range stage.storeModuleStates { + // Base value when nothing was processed yet: where this module starts from. + highest := max(modState.segmenter.InitialBlock(), firstStreamableBlock) + if seg := stats.contiguousSegment[stgIdx]; seg >= modState.segmenter.FirstIndex() { + if rng := modState.segmenter.Range(seg); rng != nil && rng.ExclusiveEndBlock > highest { + highest = rng.ExclusiveEndBlock } } + if progress.HighestContiguousBlock == 0 || highest < progress.HighestContiguousBlock { + progress.HighestContiguousBlock = highest + } } + if stage.kind == KindStore { + progress.SegmentsReadyForSquashing = stats.partialSegments[stgIdx] + } + + out = append(out, progress) } - return rangesByStage + return out } func toProtoRanges(in block.Ranges) []*pbsubstreamsrpc.BlockRange { diff --git a/orchestrator/work/worker.go b/orchestrator/work/worker.go index 8600e7356..1f1f5fe37 100644 --- a/orchestrator/work/worker.go +++ b/orchestrator/work/worker.go @@ -141,6 +141,10 @@ func (w *RemoteWorker) Work(ctx context.Context, unit stage.Unit, startBlock uin res = w.work(ctx, request, moduleNames, upstream, jobIdx) err := res.Error + // Keep the reason around: the request progress log reports failure counts, but + // only the error text says whether jobs die on an unreachable RPC endpoint, a + // module panic or an overloaded tier2. + stats.RecordJobError(jobIdx, err) switch err.(type) { case *RetryableErr: previousError = err diff --git a/pb/sf/substreams/intern/v2/service.pb.go b/pb/sf/substreams/intern/v2/service.pb.go index 2bd014a62..70dddcf56 100644 --- a/pb/sf/substreams/intern/v2/service.pb.go +++ b/pb/sf/substreams/intern/v2/service.pb.go @@ -615,12 +615,26 @@ func (x *ModuleStats) GetStoreSizeBytes() uint64 { } type ExternalCallMetric struct { - state protoimpl.MessageState `protogen:"open.v1"` - Name string `protobuf:"bytes,1,opt,name=name,proto3" json:"name,omitempty"` - Count uint64 `protobuf:"varint,2,opt,name=count,proto3" json:"count,omitempty"` - TimeMs uint64 `protobuf:"varint,3,opt,name=time_ms,json=timeMs,proto3" json:"time_ms,omitempty"` - unknownFields protoimpl.UnknownFields - sizeCache protoimpl.SizeCache + state protoimpl.MessageState `protogen:"open.v1"` + Name string `protobuf:"bytes,1,opt,name=name,proto3" json:"name,omitempty"` + // count is every call that was started, including those still waiting for an answer. + Count uint64 `protobuf:"varint,2,opt,name=count,proto3" json:"count,omitempty"` + // time_ms includes the time already spent by calls that have not returned yet, so a call + // hung against an unreachable endpoint shows up as time spent rather than as nothing at all. + TimeMs uint64 `protobuf:"varint,3,opt,name=time_ms,json=timeMs,proto3" json:"time_ms,omitempty"` + // failed_count is how many of those calls came back with an error. A tier2 keeps retrying + // them internally, so without this tier1 only learns of a failing endpoint once the whole + // segment gives up, minutes later. + FailedCount uint64 `protobuf:"varint,4,opt,name=failed_count,json=failedCount,proto3" json:"failed_count,omitempty"` + // in_flight_count is how many calls are still waiting for an answer right now. + InFlightCount uint64 `protobuf:"varint,5,opt,name=in_flight_count,json=inFlightCount,proto3" json:"in_flight_count,omitempty"` + // oldest_in_flight_ms is how long the oldest of them has been waiting. + OldestInFlightMs uint64 `protobuf:"varint,6,opt,name=oldest_in_flight_ms,json=oldestInFlightMs,proto3" json:"oldest_in_flight_ms,omitempty"` + // oldest_in_flight_block is the block that call was made on, which is where processing is + // stuck for as long as it does not return. + OldestInFlightBlock uint64 `protobuf:"varint,7,opt,name=oldest_in_flight_block,json=oldestInFlightBlock,proto3" json:"oldest_in_flight_block,omitempty"` + unknownFields protoimpl.UnknownFields + sizeCache protoimpl.SizeCache } func (x *ExternalCallMetric) Reset() { @@ -674,6 +688,34 @@ func (x *ExternalCallMetric) GetTimeMs() uint64 { return 0 } +func (x *ExternalCallMetric) GetFailedCount() uint64 { + if x != nil { + return x.FailedCount + } + return 0 +} + +func (x *ExternalCallMetric) GetInFlightCount() uint64 { + if x != nil { + return x.InFlightCount + } + return 0 +} + +func (x *ExternalCallMetric) GetOldestInFlightMs() uint64 { + if x != nil { + return x.OldestInFlightMs + } + return 0 +} + +func (x *ExternalCallMetric) GetOldestInFlightBlock() uint64 { + if x != nil { + return x.OldestInFlightBlock + } + return 0 +} + type Completed struct { state protoimpl.MessageState `protogen:"open.v1"` AllProcessedRanges []*BlockRange `protobuf:"bytes,1,rep,name=all_processed_ranges,json=allProcessedRanges,proto3" json:"all_processed_ranges,omitempty"` @@ -910,11 +952,15 @@ const file_sf_substreams_intern_v2_service_proto_rawDesc = "" + "\x11store_write_count\x18\n" + " \x01(\x04R\x0fstoreWriteCount\x128\n" + "\x18store_deleteprefix_count\x18\v \x01(\x04R\x16storeDeleteprefixCount\x12(\n" + - "\x10store_size_bytes\x18\f \x01(\x04R\x0estoreSizeBytes\"W\n" + + "\x10store_size_bytes\x18\f \x01(\x04R\x0estoreSizeBytes\"\x86\x02\n" + "\x12ExternalCallMetric\x12\x12\n" + "\x04name\x18\x01 \x01(\tR\x04name\x12\x14\n" + "\x05count\x18\x02 \x01(\x04R\x05count\x12\x17\n" + - "\atime_ms\x18\x03 \x01(\x04R\x06timeMs\"\xbc\x01\n" + + "\atime_ms\x18\x03 \x01(\x04R\x06timeMs\x12!\n" + + "\ffailed_count\x18\x04 \x01(\x04R\vfailedCount\x12&\n" + + "\x0fin_flight_count\x18\x05 \x01(\x04R\rinFlightCount\x12-\n" + + "\x13oldest_in_flight_ms\x18\x06 \x01(\x04R\x10oldestInFlightMs\x123\n" + + "\x16oldest_in_flight_block\x18\a \x01(\x04R\x13oldestInFlightBlock\"\xbc\x01\n" + "\tCompleted\x12W\n" + "\x14all_processed_ranges\x18\x01 \x03(\v2%.sf.substreams.internal.v2.BlockRangeR\x12allProcessedRanges\x12)\n" + "\x10processed_blocks\x18\x03 \x01(\x04R\x0fprocessedBlocks\x12%\n" + diff --git a/pb/sf/substreams/intern/v2/service_vtproto.pb.go b/pb/sf/substreams/intern/v2/service_vtproto.pb.go index 37307e2b7..71fc1208a 100644 --- a/pb/sf/substreams/intern/v2/service_vtproto.pb.go +++ b/pb/sf/substreams/intern/v2/service_vtproto.pb.go @@ -29,6 +29,7 @@ func (m *ProcessRangeRequest) CloneVT() *ProcessRangeRequest { r := new(ProcessRangeRequest) r.StopBlockNum = m.StopBlockNum r.OutputModule = m.OutputModule + r.Modules = m.Modules.CloneVT() r.Stage = m.Stage r.MeteringConfig = m.MeteringConfig r.FirstStreamableBlock = m.FirstStreamableBlock @@ -44,13 +45,6 @@ func (m *ProcessRangeRequest) CloneVT() *ProcessRangeRequest { r.EthCallFallbackToNumberDuration = m.EthCallFallbackToNumberDuration r.StoreSizeLimit = m.StoreSizeLimit r.MergedBlocksBundleSize = m.MergedBlocksBundleSize - if rhs := m.Modules; rhs != nil { - if vtpb, ok := interface{}(rhs).(interface{ CloneVT() *v1.Modules }); ok { - r.Modules = vtpb.CloneVT() - } else { - r.Modules = proto.Clone(rhs).(*v1.Modules) - } - } if rhs := m.WasmExtensionConfigs; rhs != nil { tmpContainer := make(map[string]string, len(rhs)) for k, v := range rhs { @@ -139,13 +133,7 @@ func (m *BlockScopedData) CloneVT() *BlockScopedData { } r := new(BlockScopedData) r.Output = (*anypb.Any)((*anypb1.Any)(m.Output).CloneVT()) - if rhs := m.Clock; rhs != nil { - if vtpb, ok := interface{}(rhs).(interface{ CloneVT() *v1.Clock }); ok { - r.Clock = vtpb.CloneVT() - } else { - r.Clock = proto.Clone(rhs).(*v1.Clock) - } - } + r.Clock = m.Clock.CloneVT() if len(m.unknownFields) > 0 { r.unknownFields = make([]byte, len(m.unknownFields)) copy(r.unknownFields, m.unknownFields) @@ -222,6 +210,10 @@ func (m *ExternalCallMetric) CloneVT() *ExternalCallMetric { r.Name = m.Name r.Count = m.Count r.TimeMs = m.TimeMs + r.FailedCount = m.FailedCount + r.InFlightCount = m.InFlightCount + r.OldestInFlightMs = m.OldestInFlightMs + r.OldestInFlightBlock = m.OldestInFlightBlock if len(m.unknownFields) > 0 { r.unknownFields = make([]byte, len(m.unknownFields)) copy(r.unknownFields, m.unknownFields) @@ -311,11 +303,7 @@ func (this *ProcessRangeRequest) EqualVT(that *ProcessRangeRequest) bool { if this.OutputModule != that.OutputModule { return false } - if equal, ok := interface{}(this.Modules).(interface{ EqualVT(*v1.Modules) bool }); ok { - if !equal.EqualVT(that.Modules) { - return false - } - } else if !proto.Equal(this.Modules, that.Modules) { + if !this.Modules.EqualVT(that.Modules) { return false } if this.Stage != that.Stage { @@ -534,11 +522,7 @@ func (this *BlockScopedData) EqualVT(that *BlockScopedData) bool { if !(*anypb1.Any)(this.Output).EqualVT((*anypb1.Any)(that.Output)) { return false } - if equal, ok := interface{}(this.Clock).(interface{ EqualVT(*v1.Clock) bool }); ok { - if !equal.EqualVT(that.Clock) { - return false - } - } else if !proto.Equal(this.Clock, that.Clock) { + if !this.Clock.EqualVT(that.Clock) { return false } return string(this.unknownFields) == string(that.unknownFields) @@ -665,6 +649,18 @@ func (this *ExternalCallMetric) EqualVT(that *ExternalCallMetric) bool { if this.TimeMs != that.TimeMs { return false } + if this.FailedCount != that.FailedCount { + return false + } + if this.InFlightCount != that.InFlightCount { + return false + } + if this.OldestInFlightMs != that.OldestInFlightMs { + return false + } + if this.OldestInFlightBlock != that.OldestInFlightBlock { + return false + } return string(this.unknownFields) == string(that.unknownFields) } @@ -945,24 +941,12 @@ func (m *ProcessRangeRequest) MarshalToSizedBufferVT(dAtA []byte) (int, error) { dAtA[i] = 0x28 } if m.Modules != nil { - if vtmsg, ok := interface{}(m.Modules).(interface { - MarshalToSizedBufferVT([]byte) (int, error) - }); ok { - size, err := vtmsg.MarshalToSizedBufferVT(dAtA[:i]) - if err != nil { - return 0, err - } - i -= size - i = protohelpers.EncodeVarint(dAtA, i, uint64(size)) - } else { - encoded, err := proto.Marshal(m.Modules) - if err != nil { - return 0, err - } - i -= len(encoded) - copy(dAtA[i:], encoded) - i = protohelpers.EncodeVarint(dAtA, i, uint64(len(encoded))) + size, err := m.Modules.MarshalToSizedBufferVT(dAtA[:i]) + if err != nil { + return 0, err } + i -= size + i = protohelpers.EncodeVarint(dAtA, i, uint64(size)) i-- dAtA[i] = 0x22 } @@ -1130,24 +1114,12 @@ func (m *BlockScopedData) MarshalToSizedBufferVT(dAtA []byte) (int, error) { copy(dAtA[i:], m.unknownFields) } if m.Clock != nil { - if vtmsg, ok := interface{}(m.Clock).(interface { - MarshalToSizedBufferVT([]byte) (int, error) - }); ok { - size, err := vtmsg.MarshalToSizedBufferVT(dAtA[:i]) - if err != nil { - return 0, err - } - i -= size - i = protohelpers.EncodeVarint(dAtA, i, uint64(size)) - } else { - encoded, err := proto.Marshal(m.Clock) - if err != nil { - return 0, err - } - i -= len(encoded) - copy(dAtA[i:], encoded) - i = protohelpers.EncodeVarint(dAtA, i, uint64(len(encoded))) + size, err := m.Clock.MarshalToSizedBufferVT(dAtA[:i]) + if err != nil { + return 0, err } + i -= size + i = protohelpers.EncodeVarint(dAtA, i, uint64(size)) i-- dAtA[i] = 0x12 } @@ -1341,6 +1313,26 @@ func (m *ExternalCallMetric) MarshalToSizedBufferVT(dAtA []byte) (int, error) { i -= len(m.unknownFields) copy(dAtA[i:], m.unknownFields) } + if m.OldestInFlightBlock != 0 { + i = protohelpers.EncodeVarint(dAtA, i, uint64(m.OldestInFlightBlock)) + i-- + dAtA[i] = 0x38 + } + if m.OldestInFlightMs != 0 { + i = protohelpers.EncodeVarint(dAtA, i, uint64(m.OldestInFlightMs)) + i-- + dAtA[i] = 0x30 + } + if m.InFlightCount != 0 { + i = protohelpers.EncodeVarint(dAtA, i, uint64(m.InFlightCount)) + i-- + dAtA[i] = 0x28 + } + if m.FailedCount != 0 { + i = protohelpers.EncodeVarint(dAtA, i, uint64(m.FailedCount)) + i-- + dAtA[i] = 0x20 + } if m.TimeMs != 0 { i = protohelpers.EncodeVarint(dAtA, i, uint64(m.TimeMs)) i-- @@ -1537,13 +1529,7 @@ func (m *ProcessRangeRequest) SizeVT() (n int) { n += 1 + l + protohelpers.SizeOfVarint(uint64(l)) } if m.Modules != nil { - if size, ok := interface{}(m.Modules).(interface { - SizeVT() int - }); ok { - l = size.SizeVT() - } else { - l = proto.Size(m.Modules) - } + l = m.Modules.SizeVT() n += 1 + l + protohelpers.SizeOfVarint(uint64(l)) } if m.Stage != 0 { @@ -1688,13 +1674,7 @@ func (m *BlockScopedData) SizeVT() (n int) { n += 1 + l + protohelpers.SizeOfVarint(uint64(l)) } if m.Clock != nil { - if size, ok := interface{}(m.Clock).(interface { - SizeVT() int - }); ok { - l = size.SizeVT() - } else { - l = proto.Size(m.Clock) - } + l = m.Clock.SizeVT() n += 1 + l + protohelpers.SizeOfVarint(uint64(l)) } n += len(m.unknownFields) @@ -1783,6 +1763,18 @@ func (m *ExternalCallMetric) SizeVT() (n int) { if m.TimeMs != 0 { n += 1 + protohelpers.SizeOfVarint(uint64(m.TimeMs)) } + if m.FailedCount != 0 { + n += 1 + protohelpers.SizeOfVarint(uint64(m.FailedCount)) + } + if m.InFlightCount != 0 { + n += 1 + protohelpers.SizeOfVarint(uint64(m.InFlightCount)) + } + if m.OldestInFlightMs != 0 { + n += 1 + protohelpers.SizeOfVarint(uint64(m.OldestInFlightMs)) + } + if m.OldestInFlightBlock != 0 { + n += 1 + protohelpers.SizeOfVarint(uint64(m.OldestInFlightBlock)) + } n += len(m.unknownFields) return n } @@ -1960,16 +1952,8 @@ func (m *ProcessRangeRequest) UnmarshalVT(dAtA []byte) error { if m.Modules == nil { m.Modules = &v1.Modules{} } - if unmarshal, ok := interface{}(m.Modules).(interface { - UnmarshalVT([]byte) error - }); ok { - if err := unmarshal.UnmarshalVT(dAtA[iNdEx:postIndex]); err != nil { - return err - } - } else { - if err := proto.Unmarshal(dAtA[iNdEx:postIndex], m.Modules); err != nil { - return err - } + if err := m.Modules.UnmarshalVT(dAtA[iNdEx:postIndex]); err != nil { + return err } iNdEx = postIndex case 5: @@ -2912,16 +2896,8 @@ func (m *BlockScopedData) UnmarshalVT(dAtA []byte) error { if m.Clock == nil { m.Clock = &v1.Clock{} } - if unmarshal, ok := interface{}(m.Clock).(interface { - UnmarshalVT([]byte) error - }); ok { - if err := unmarshal.UnmarshalVT(dAtA[iNdEx:postIndex]); err != nil { - return err - } - } else { - if err := proto.Unmarshal(dAtA[iNdEx:postIndex], m.Clock); err != nil { - return err - } + if err := m.Clock.UnmarshalVT(dAtA[iNdEx:postIndex]); err != nil { + return err } iNdEx = postIndex default: @@ -3437,6 +3413,82 @@ func (m *ExternalCallMetric) UnmarshalVT(dAtA []byte) error { break } } + case 4: + if wireType != 0 { + return fmt.Errorf("proto: wrong wireType = %d for field FailedCount", wireType) + } + m.FailedCount = 0 + for shift := uint(0); ; shift += 7 { + if shift >= 64 { + return protohelpers.ErrIntOverflow + } + if iNdEx >= l { + return io.ErrUnexpectedEOF + } + b := dAtA[iNdEx] + iNdEx++ + m.FailedCount |= uint64(b&0x7F) << shift + if b < 0x80 { + break + } + } + case 5: + if wireType != 0 { + return fmt.Errorf("proto: wrong wireType = %d for field InFlightCount", wireType) + } + m.InFlightCount = 0 + for shift := uint(0); ; shift += 7 { + if shift >= 64 { + return protohelpers.ErrIntOverflow + } + if iNdEx >= l { + return io.ErrUnexpectedEOF + } + b := dAtA[iNdEx] + iNdEx++ + m.InFlightCount |= uint64(b&0x7F) << shift + if b < 0x80 { + break + } + } + case 6: + if wireType != 0 { + return fmt.Errorf("proto: wrong wireType = %d for field OldestInFlightMs", wireType) + } + m.OldestInFlightMs = 0 + for shift := uint(0); ; shift += 7 { + if shift >= 64 { + return protohelpers.ErrIntOverflow + } + if iNdEx >= l { + return io.ErrUnexpectedEOF + } + b := dAtA[iNdEx] + iNdEx++ + m.OldestInFlightMs |= uint64(b&0x7F) << shift + if b < 0x80 { + break + } + } + case 7: + if wireType != 0 { + return fmt.Errorf("proto: wrong wireType = %d for field OldestInFlightBlock", wireType) + } + m.OldestInFlightBlock = 0 + for shift := uint(0); ; shift += 7 { + if shift >= 64 { + return protohelpers.ErrIntOverflow + } + if iNdEx >= l { + return io.ErrUnexpectedEOF + } + b := dAtA[iNdEx] + iNdEx++ + m.OldestInFlightBlock |= uint64(b&0x7F) << shift + if b < 0x80 { + break + } + } default: iNdEx = preIndex skippy, err := protohelpers.Skip(dAtA[iNdEx:]) diff --git a/pipeline/pipeline.go b/pipeline/pipeline.go index 711744190..13dac10e7 100644 --- a/pipeline/pipeline.go +++ b/pipeline/pipeline.go @@ -39,6 +39,7 @@ import ( "github.com/streamingfast/substreams/storage/store" "github.com/streamingfast/substreams/wasm" "go.opentelemetry.io/otel" + "go.uber.org/atomic" "go.uber.org/zap" "google.golang.org/grpc" "google.golang.org/grpc/credentials/insecure" @@ -141,6 +142,11 @@ type Pipeline struct { moduleCache *cache.ModuleCache blockType string + // currentBlockNum is the block being processed right now. Written by the block loop and + // read by the progress snapshot goroutine, hence the atomic: it is what tells tier1 where + // a job is stuck when a block takes minutes to go through. + currentBlockNum atomic.Uint64 + // lastFinalClock should always be either THE `stopBlock` or a block beyond that point // (for chains with potential block skips) lastFinalClock *pbsubstreams.Clock @@ -853,6 +859,34 @@ func (p *Pipeline) returnInternalModuleComplete() error { return nil } +// SendProgressSnapshot emits an internal progress update from outside the block loop. +// +// returnInternalModuleProgressOutputs only runs once a block finished processing, so a module +// stuck inside a single block — typically blocked on an external call that is retrying against +// an unreachable endpoint — reports nothing at all for as long as it is stuck, and tier1 sees +// an idle job with no external call metrics. The stats already account for calls still in +// flight; they just need to be sent. Safe to call concurrently with the block loop: the tier2 +// response function serializes sends. +func (p *Pipeline) SendProgressSnapshot() error { + if p.respFunc == nil { + return nil + } + + update := p.toInternalUpdate(nil) + // toInternalUpdate only knows how to derive the progress from a completed block, and a + // snapshot is taken precisely when none completed. Reporting 0 here would overwrite the + // job's progress on tier1 with every snapshot. + if current := p.currentBlockNum.Load(); current != 0 && p.processingModule != nil && current > p.processingModule.initialBlockNum { + update.ProgressBlocks = current - p.processingModule.initialBlockNum + } + + return p.respFunc(&pbssinternal.ProcessRangeResponse{ + Type: &pbssinternal.ProcessRangeResponse_Update{ + Update: update, + }, + }) +} + func (p *Pipeline) returnInternalModuleProgressOutputs(clock *pbsubstreams.Clock, forceOutput bool) error { if time.Since(p.lastProgressSent) < progressMessageInterval && !forceOutput { return nil diff --git a/pipeline/process_block.go b/pipeline/process_block.go index 6544595fd..b74df1083 100644 --- a/pipeline/process_block.go +++ b/pipeline/process_block.go @@ -543,6 +543,7 @@ func (p *Pipeline) handleStepNew(ctx context.Context, clock *pbsubstreams.Clock, } p.insideReorgUpTo = nil + p.currentBlockNum.Store(clock.Number) reqDetails := reqctx.Details(ctx) if p.respFunc != nil { diff --git a/proto/sf/substreams/intern/v2/service.proto b/proto/sf/substreams/intern/v2/service.proto index 95e1e5716..250d00c25 100644 --- a/proto/sf/substreams/intern/v2/service.proto +++ b/proto/sf/substreams/intern/v2/service.proto @@ -101,8 +101,23 @@ message ModuleStats { message ExternalCallMetric { string name = 1; + // count is every call that was started, including those still waiting for an answer. uint64 count = 2; + // time_ms includes the time already spent by calls that have not returned yet, so a call + // hung against an unreachable endpoint shows up as time spent rather than as nothing at all. uint64 time_ms = 3; + + // failed_count is how many of those calls came back with an error. A tier2 keeps retrying + // them internally, so without this tier1 only learns of a failing endpoint once the whole + // segment gives up, minutes later. + uint64 failed_count = 4; + // in_flight_count is how many calls are still waiting for an answer right now. + uint64 in_flight_count = 5; + // oldest_in_flight_ms is how long the oldest of them has been waiting. + uint64 oldest_in_flight_ms = 6; + // oldest_in_flight_block is the block that call was made on, which is where processing is + // stuck for as long as it does not return. + uint64 oldest_in_flight_block = 7; } message Completed { diff --git a/service/tier1.go b/service/tier1.go index f55923c5b..75e78302a 100644 --- a/service/tier1.go +++ b/service/tier1.go @@ -910,6 +910,14 @@ func (s *Tier1Service) blocks( logger.Info("incoming Substreams Blocks request", logFields...) + // Periodic snapshot of what this request is doing, so a slow substreams can be + // diagnosed from the logs alone, without waiting for the final stats line. + reqStats.RecordResolvedStartBlock(requestDetails.ResolvedStartBlockNum) + reqStats.RecordMaxParallelJobs(requestDetails.MaxParallelJobs) + progressCtx, cancelProgressLog := context.WithCancel(ctx) + defer cancelProgressLog() + go metrics.NewProgressLogger(reqStats, logger).Run(progressCtx) + defer func() { switch { case errors.Is(err, context.Canceled): @@ -1123,6 +1131,7 @@ func tier1ResponseHandler( } isData := false + blockCount := 0 var lastSentClock *pbsubstreams.Clock switch r := respAny.(type) { @@ -1130,6 +1139,7 @@ func tier1ResponseHandler( d := r.GetBlockScopedData() if d != nil { isData = true + blockCount = 1 lastSentClock = d.Clock filterData(d, noop, debugOutputs) if supportBuffering { @@ -1143,6 +1153,7 @@ func tier1ResponseHandler( for _, d := range r.GetBlockScopedDatas().Items { if d != nil { isData = true + blockCount++ lastSentClock = d.Clock filterData(d, noop, debugOutputs) } @@ -1158,6 +1169,10 @@ func tier1ResponseHandler( stats.RecordReadTime(begin) if isData { + // Only data messages are timed for the progress log: this isolates how long the + // consumer takes to accept one payload, which is what tells a slow client apart + // from a slow pipeline. + stats.RecordBlockSent(time.Since(begin), blockCount) stats.RecordDataSent() stats.RecordLastBlockSent(lastSentClock) } diff --git a/service/tier2.go b/service/tier2.go index 95ebaca04..af01fad07 100644 --- a/service/tier2.go +++ b/service/tier2.go @@ -51,6 +51,11 @@ import ( "google.golang.org/protobuf/types/known/anypb" ) +// inFlightProgressInterval is how often tier2 reports what it is doing while a block is still +// being processed. Frequent enough that a stuck external call shows up in tier1's progress log +// well before the segment times out, cheap enough to be irrelevant next to the block loop. +var inFlightProgressInterval = 10 * time.Second + var slowQueryNotificationFrequency = 30 * time.Second var slowQueryNotificationThreshold = 300 * time.Second var ErrRequestActiveForTooLong = errors.New("request active for too long") @@ -557,6 +562,25 @@ func (s *Tier2Service) processRange(ctx context.Context, request *pbssinternal.P opts..., ) + // Keep reporting while a block is being processed, not only once it completes: a module + // blocked on a retrying external call would otherwise stay silent for the whole stall, + // and tier1 would show a job running for minutes with no external call metrics at all. + go func() { + ticker := time.NewTicker(inFlightProgressInterval) + defer ticker.Stop() + for { + select { + case <-ctx.Done(): + return + case <-ticker.C: + if err := pipe.SendProgressSnapshot(); err != nil { + logger.Debug("cannot send in-flight progress snapshot", zap.Error(err)) + return + } + } + } + }() + logger.Debug("initializing tier2 pipeline", zap.Uint64("request_start_block", requestDetails.ResolvedStartBlockNum), zap.String("output_module", request.OutputModule), @@ -741,7 +765,18 @@ func tier2ResponseHandler(ctx context.Context, logger *zap.Logger, streamSrv pbs logger.Warn("no auth information available in tier2 response handler") } + // Progress snapshots are emitted from a ticker goroutine while the block loop keeps + // sending, and a gRPC stream does not tolerate concurrent Send calls. + var mut sync.Mutex + return func(respAny substreams.ResponseFromAnyTier) error { + mut.Lock() + defer mut.Unlock() + + if ctx.Err() != nil { + return ctx.Err() + } + resp := respAny.(*pbssinternal.ProcessRangeResponse) if err := streamSrv.Send(resp); err != nil { logger.Info("unable to send block probably due to client disconnecting", zap.Error(err), zap.String("user_id", userID), zap.String("key_id", apiKeyID), zap.Error(err)) diff --git a/tools/logging.go b/tools/logging.go index 274b0e7c3..13ddea9cd 100644 --- a/tools/logging.go +++ b/tools/logging.go @@ -5,4 +5,4 @@ import ( "go.uber.org/zap" ) -var zlog, _ = logging.PackageLogger("tools", "github.com/streamingfast/substreams/tools", logging.LoggerDefaultLevel(zap.InfoLevel)) +var zlog, tracer = logging.PackageLogger("tools", "github.com/streamingfast/substreams/tools", logging.LoggerDefaultLevel(zap.InfoLevel)) diff --git a/tools/simulate_slow_reader.go b/tools/simulate_slow_reader.go new file mode 100644 index 000000000..2df215bba --- /dev/null +++ b/tools/simulate_slow_reader.go @@ -0,0 +1,126 @@ +package tools + +import ( + "context" + "fmt" + "time" + + "github.com/spf13/cobra" + "github.com/streamingfast/cli/sflags" + "github.com/streamingfast/derr" + pbsubstreamsrpc "github.com/streamingfast/substreams/pb/sf/substreams/rpc/v2" + "github.com/streamingfast/substreams/sink" + "go.uber.org/zap" +) + +var simulateSlowReaderCmd = &cobra.Command{ + Use: "simulate-slow-reader []", + Short: "Consume a substreams deliberately slowly, to exercise server-side back-pressure", + Long: ExamplePrefixed("substreams tools simulate-slow-reader", ` + Streams a substreams and waits before handling each block, so the server ends up blocked + writing to this client. + + The wait blocks the receive loop rather than happening in the background, which is what a + genuinely slow consumer does: the gRPC flow-control window fills and the server's SendMsg + blocks. That is what the server reports in its periodic "substreams request progress" log, + as the time it spent blocked writing to the consumer. + + Nothing is decoded or printed per block: this is a load-shaping tool, not a way to look at + data. Use 'substreams run' for that. + `), + RunE: simulateSlowReaderE, + Args: cobra.RangeArgs(1, 2), + SilenceUsage: true, +} + +func init() { + sink.AddFlagsToSet(simulateSlowReaderCmd.Flags(), + sink.FlagIncludeOptional(sink.FlagCursor), + sink.FlagExcludeDefault(sink.FlagDevelopmentMode, sink.FlagLiveBlockTimeDelta), + ) + + simulateSlowReaderCmd.Flags().Duration("delay", time.Second, "How long to wait before handling each received block") + simulateSlowReaderCmd.Flags().Bool("production-mode", true, "Enable Production Mode, with high-speed parallel processing") + simulateSlowReaderCmd.Flags().Uint64("limit-processed-blocks", 0, "Limit the number of blocks the server may process, 0 disables the limit") + + Cmd.AddCommand(simulateSlowReaderCmd) +} + +func simulateSlowReaderE(cmd *cobra.Command, args []string) error { + ctx := cmd.Context() + + manifestPath := args[0] + var outputModule string + if len(args) == 2 { + outputModule = args[1] + } + + sink.LoadSubstreamsAuthEnvFile(manifestPath) + + sinkerConfig, err := sink.ConfigFromViper(cmd, sink.IgnoreOutputModuleType, manifestPath, outputModule, "substreams_simulate_slow_reader", zlog, tracer) + if err != nil { + return fmt.Errorf("creating sink config: %w", err) + } + + sinkerConfig.Mode = sink.SubstreamsModeDevelopment + if sflags.MustGetBool(cmd, "production-mode") { + sinkerConfig.Mode = sink.SubstreamsModeProduction + } + sinkerConfig.LimitProcessedBlocks = sflags.MustGetUint64(cmd, "limit-processed-blocks") + + sinker, err := sink.NewFromConfig(sinkerConfig) + if err != nil { + return fmt.Errorf("creating sink: %w", err) + } + + cursor, err := sink.NewCursor(sflags.MustGetString(cmd, "cursor")) + if err != nil { + return fmt.Errorf("creating cursor: %w", err) + } + + delay := sflags.MustGetDuration(cmd, "delay") + zlog.Info("reading deliberately slowly", zap.Duration("delay_per_block", delay), zap.String("output_module", sinkerConfig.OutputModule.GetName())) + + var blocks uint64 + started := time.Now() + handleBlockScopedData := func(ctx context.Context, data *pbsubstreamsrpc.BlockScopedData, isLive *bool, cursor *sink.Cursor) error { + // Blocking here is the point: it stops reading from the stream, which is what exerts + // back-pressure on the server. Sleeping in a goroutine would exert none. + select { + case <-ctx.Done(): + return ctx.Err() + case <-time.After(delay): + } + + blocks++ + if blocks%10 == 0 { + zlog.Info("still reading slowly", + zap.Uint64("blocks_read", blocks), + zap.Uint64("at_block", data.Clock.GetNumber()), + zap.Duration("elapsed", time.Since(started).Round(time.Second)), + ) + } + return nil + } + + handler := sink.NewSinkerHandlers(handleBlockScopedData, func(context.Context, *pbsubstreamsrpc.BlockUndoSignal, *sink.Cursor) error { + return nil + }) + + ctx, cancelCause := context.WithCancelCause(ctx) + go func() { + s := <-derr.SetupSignalHandler(0) + cancelCause(fmt.Errorf("received signal %q", s.String())) + }() + + sinker.Run(ctx, cursor, handler) + + zlog.Info("done", zap.Uint64("blocks_read", blocks), zap.Duration("elapsed", time.Since(started).Round(time.Second))) + if err := sinker.Err(); err != nil { + return err + } + if cause := context.Cause(ctx); cause != nil { + return cause + } + return nil +} diff --git a/wasm/wasmtime/instance.go b/wasm/wasmtime/instance.go index f1a25b0ed..47e0a2c70 100644 --- a/wasm/wasmtime/instance.go +++ b/wasm/wasmtime/instance.go @@ -48,13 +48,13 @@ func (i *instance) newExtensionFunction(ctx context.Context, namespace, name str extension := fmt.Sprintf("%s:%s", namespace, name) extStats := reqctx.WasmExtensionReqStats(ctx) - metricID := extStats.RecordModuleWasmExternalCallBegin(i.CurrentCall.ModuleName, extension) + metricID := extStats.RecordModuleWasmExternalCallBegin(i.CurrentCall.ModuleName, extension, i.CurrentCall.Clock.GetNumber()) startTime := time.Now() out, err := f(ctx, reqctx.Details(ctx).UniqueIDString(), i.CurrentCall.Clock, data) elapsed := time.Since(startTime) // The call must be closed on every path, including errors, otherwise the in-process // entry leaks and keeps inflating the reported external call duration forever. - extStats.RecordModuleWasmExternalCallEnd(i.CurrentCall.ModuleName, extension, metricID) + extStats.RecordModuleWasmExternalCallEnd(i.CurrentCall.ModuleName, extension, metricID, err) outcome := metrics.WasmExtensionCallOutcomeSuccess if err != nil { diff --git a/wasm/wazero/module.go b/wasm/wazero/module.go index 9d574b7af..07bcc33c9 100644 --- a/wasm/wazero/module.go +++ b/wasm/wazero/module.go @@ -274,14 +274,14 @@ func addExtensionFunctions(ctx context.Context, runtime wazero.Runtime, registry extension := fmt.Sprintf("%s:%s", namespace, importName) extStats := reqctx.WasmExtensionReqStats(ctx) - metricID := extStats.RecordModuleWasmExternalCallBegin(call.ModuleName, extension) + metricID := extStats.RecordModuleWasmExternalCallBegin(call.ModuleName, extension, call.Clock.GetNumber()) startTime := time.Now() out, err := f(ctx, reqctx.Details(ctx).UniqueIDString(), call.Clock, data) elapsed := time.Since(startTime) // The call must be closed on every path, including errors, otherwise the in-process // entry leaks and keeps inflating the reported external call duration forever. - extStats.RecordModuleWasmExternalCallEnd(call.ModuleName, extension, metricID) + extStats.RecordModuleWasmExternalCallEnd(call.ModuleName, extension, metricID, err) outcome := metrics.WasmExtensionCallOutcomeSuccess if err != nil {