From 4ddc074dfbad719908578258598f502b02c1762a Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?Ste=CC=81phane=20Duchesneau?=
 <stephane.duchesneau@streamingfast.io>
Date: Fri, 7 Aug 2026 11:15:52 -0400
Subject: [PATCH 1/3] Report failing and in-flight external calls from tier2

An eth_call retrying against an unreachable endpoint is a single wasm
extension call that can last minutes. Tier2 only reported external calls
once they returned, and only ever emitted progress when a block completed,
so tier1 saw an idle job with no external call metrics until the whole
segment gave up.

ExternalCallMetric now carries the failures, the calls still waiting, how
long the oldest has waited and the block it holds up. Tier2 reports every
10s while a block is in flight, and counts the time already spent by a
call that has not returned, so a hung call shows up as time spent rather
than as nothing at all.

The tier2 response function needed a mutex: the snapshots are sent from a
ticker goroutine while the block loop keeps sending, and gRPC forbids
concurrent Send on one stream.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
---
 metrics/stats.go                              |  37 ++-
 metrics/stats_test.go                         |  63 ++++-
 metrics/wasm_ext_gatherer.go                  |  22 +-
 metrics/wasm_ext_gatherer_test.go             |  18 +-
 pb/sf/substreams/intern/v2/service.pb.go      |  62 ++++-
 .../intern/v2/service_vtproto.pb.go           | 236 +++++++++++-------
 pipeline/pipeline.go                          |  34 +++
 pipeline/process_block.go                     |   1 +
 proto/sf/substreams/intern/v2/service.proto   |  15 ++
 service/tier2.go                              |  35 +++
 wasm/wasmtime/instance.go                     |   4 +-
 wasm/wazero/module.go                         |   4 +-
 12 files changed, 402 insertions(+), 129 deletions(-)

diff --git a/metrics/stats.go b/metrics/stats.go
index d1cb1093b..d84ca8a00 100644
--- a/metrics/stats.go
+++ b/metrics/stats.go
@@ -206,11 +206,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 +233,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
 			}
 		}
 
@@ -422,7 +439,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 +450,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 +464,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 +480,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)
 }
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..bee9e24f6 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,22 @@ 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
 		}
 	}
 
+	// Calls that have not returned are the ones worth reporting the soonest, and they are the
+	// ones this loop would otherwise drop: they sit in inProcessCalls until they complete, which
+	// for a call retrying against a dead endpoint can be minutes.
+	for moduleName, inProcess := range m.inProcessCalls {
+		modStats := stats.moduleStats(moduleName)
+		for uniqueID, call := range inProcess {
+			modStats.inprocessCallMetrics[uniqueID] = *call
+		}
+	}
 }
 
 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/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/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/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 {

From c97ef0f8768748c21f5dd7ca66c3481671bed63b Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?Ste=CC=81phane=20Duchesneau?=
 <stephane.duchesneau@streamingfast.io>
Date: Fri, 7 Aug 2026 11:46:03 -0400
Subject: [PATCH 2/3] Add a tools command to simulate a slow reading consumer

Waiting before handling each block blocks the receive loop, which is what
a genuinely slow consumer does: the gRPC flow-control window fills and the
server blocks on sending. Sleeping in a goroutine would exert none of that
back-pressure.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
---
 docs/release-notes/change-log.md |   2 +
 tools/logging.go                 |   2 +-
 tools/simulate_slow_reader.go    | 126 +++++++++++++++++++++++++++++++
 3 files changed, 129 insertions(+), 1 deletion(-)
 create mode 100644 tools/simulate_slow_reader.go

diff --git a/docs/release-notes/change-log.md b/docs/release-notes/change-log.md
index be06e8c7d..2bd32518a 100644
--- a/docs/release-notes/change-log.md
+++ b/docs/release-notes/change-log.md
@@ -25,6 +25,8 @@ The format is based on [Keep a Changelog](https://keepachangelog.com/en/1.0.0/),
 
 - 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 <manifest> [<module>] --delay <duration>` command, consuming a substreams while waiting that long before handling each block. It exerts real back-pressure — the client stops reading, the gRPC flow-control window fills and the server blocks on sending — which is how the server-side "consumer is the bottleneck" reporting can be exercised on demand.
+
 ### 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/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 <manifest> [<module_name>]",
+	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
+}

From 809074560566b4c97d5eeea9942a3582195439c6 Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?Ste=CC=81phane=20Duchesneau?=
 <stephane.duchesneau@streamingfast.io>
Date: Fri, 7 Aug 2026 11:50:56 -0400
Subject: [PATCH 3/3] Log why a request is slow, every 5 minutes

The final "substreams request stats" line only lands once a request is
over, which is too late to answer "why is my substreams slow?" while it
still runs. Emit a bounded summary per tier1 request: where the blocks the
client receives come from, how far each stage got and what its jobs are
doing, what the external calls cost, the error that killed the last job,
and how long we spent blocked writing to the consumer.

Every rate and delta covers a fixed trailing 5 minutes accumulated in time
buckets, so it means the same thing whatever the emission interval is set
to, and two consecutive lines are always comparable.

A short hints list names the likely bottleneck when one is detected. They
are deliberately hard to trigger: a hint that fires on a healthy request is
worse than no hint at all. In particular a full cache lead and a throttled
scheduler are the steady state of a healthy production request, not
symptoms, so the consumer is only blamed for time actually spent blocked in
SendMsg, and a slow segment is projected from the rate a job is holding
rather than waited out.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
---
 ENVIRONMENT_VARIABLES.md            |   14 +
 docs/release-notes/change-log.md    |    6 +-
 metrics/progress_log.go             | 1080 +++++++++++++++++++++++++++
 metrics/progress_log_test.go        |  817 ++++++++++++++++++++
 metrics/progress_window.go          |  239 ++++++
 metrics/stats.go                    |  172 ++++-
 metrics/wasm_ext_gatherer.go        |   13 +-
 orchestrator/scheduler/scheduler.go |    8 +
 orchestrator/stage/progress_test.go |  138 ++++
 orchestrator/stage/stage.go         |    9 +-
 orchestrator/stage/stages.go        |  137 +++-
 orchestrator/work/worker.go         |    4 +
 service/tier1.go                    |   15 +
 13 files changed, 2623 insertions(+), 29 deletions(-)
 create mode 100644 metrics/progress_log.go
 create mode 100644 metrics/progress_log_test.go
 create mode 100644 metrics/progress_window.go
 create mode 100644 orchestrator/stage/progress_test.go

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 2bd32518a..23fff90b4 100644
--- a/docs/release-notes/change-log.md
+++ b/docs/release-notes/change-log.md
@@ -23,9 +23,13 @@ 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 <manifest> [<module>] --delay <duration>` command, consuming a substreams while waiting that long before handling each block. It exerts real back-pressure — the client stops reading, the gRPC flow-control window fills and the server blocks on sending — which is how the server-side "consumer is the bottleneck" reporting can be exercised on demand.
+- CLI: new `substreams tools simulate-slow-reader <manifest> [<module>] --delay <duration>` command, consuming a substreams slowly enough to exert real back-pressure on the server, to exercise the "consumer is the bottleneck" reporting.
 
 ### Changed
 
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 d84ca8a00..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
@@ -271,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) {
@@ -296,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)
 }
@@ -333,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()
@@ -364,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
@@ -376,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) {
@@ -403,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
 
@@ -527,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 {
@@ -856,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 {
@@ -906,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) {
@@ -918,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/wasm_ext_gatherer.go b/metrics/wasm_ext_gatherer.go
index bee9e24f6..714da930c 100644
--- a/metrics/wasm_ext_gatherer.go
+++ b/metrics/wasm_ext_gatherer.go
@@ -96,15 +96,10 @@ func (m *WasmMetricsGatherer) ApplyToStats(stats *Stats) {
 		}
 	}
 
-	// Calls that have not returned are the ones worth reporting the soonest, and they are the
-	// ones this loop would otherwise drop: they sit in inProcessCalls until they complete, which
-	// for a call retrying against a dead endpoint can be minutes.
-	for moduleName, inProcess := range m.inProcessCalls {
-		modStats := stats.moduleStats(moduleName)
-		for uniqueID, call := range inProcess {
-			modStats.inprocessCallMetrics[uniqueID] = *call
-		}
-	}
+	// 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 {
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/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)
 		}