feat: metrics for the tasks of background workers

The existing worker metrics apply to background workers as they are:
busy_workers counts a thread holding a task, from pickup to the close of
the task's stream, and worker_queue_depth counts the tasks waiting for a
thread, which is the only queue a background worker has. Two new ones
break tasks down: worker_task_count{worker,outcome} with completed,
aborted (the script ended with the task open), abandoned (the sender
closed its stream first) or timeout (no thread picked the task up in
time), settled by whichever side closes first so every task counts once,
and worker_task_time, the seconds spent on tasks from pickup to close.

The threads endpoint follows: a background thread is busy while it holds
a task and waiting otherwise, counted per thread since a script may hold
several.

Author: nicolas-grekas

caddy/caddy_test.go

@@ -866,7 +866,7 @@ func TestWorkerMetrics(t *testing.T) {
 	# TYPE frankenphp_busy_threads gauge
 	frankenphp_busy_threads 2
 
-	# HELP frankenphp_busy_workers Number of busy PHP workers for this worker
+	# HELP frankenphp_busy_workers Number of busy PHP workers for this worker: processing a request, or a task for a background worker
 	# TYPE frankenphp_busy_workers gauge
 	frankenphp_busy_workers{worker="` + workerName + `"} 0
 
@@ -1023,7 +1023,7 @@ func TestNamedWorkerMetrics(t *testing.T) {
 	# TYPE frankenphp_busy_threads gauge
 	frankenphp_busy_threads 2
 
-	# HELP frankenphp_busy_workers Number of busy PHP workers for this worker
+	# HELP frankenphp_busy_workers Number of busy PHP workers for this worker: processing a request, or a task for a background worker
         # TYPE frankenphp_busy_workers gauge
         frankenphp_busy_workers{worker="my_app"} 0
 
@@ -1119,7 +1119,7 @@ func TestAutoWorkerConfig(t *testing.T) {
 	# TYPE frankenphp_busy_threads gauge
 	frankenphp_busy_threads ` + workers + `
 
-	# HELP frankenphp_busy_workers Number of busy PHP workers for this worker
+	# HELP frankenphp_busy_workers Number of busy PHP workers for this worker: processing a request, or a task for a background worker
 	# TYPE frankenphp_busy_workers gauge
 	frankenphp_busy_workers{worker="` + workerName + `"} 0
 
@@ -1386,6 +1386,7 @@ func TestMaxWaitTimeWorker(t *testing.T) {
 	require.NoError(t, err)
 
 	expectedMetrics := `
+	# HELP frankenphp_worker_queue_depth Number of queued requests for this worker, or of tasks waiting for a thread of a background worker
 	# TYPE frankenphp_worker_queue_depth gauge
 	frankenphp_worker_queue_depth{worker="service"} 0
 	`
@@ -1486,7 +1487,7 @@ func TestMultiWorkersMetrics(t *testing.T) {
 	# TYPE frankenphp_busy_threads gauge
 	frankenphp_busy_threads 5
 
-	# HELP frankenphp_busy_workers Number of busy PHP workers for this worker
+	# HELP frankenphp_busy_workers Number of busy PHP workers for this worker: processing a request, or a task for a background worker
 	# TYPE frankenphp_busy_workers gauge
 	frankenphp_busy_workers{worker="service1"} 0
 

docs/metrics.md

@@ -16,13 +16,15 @@ When [Caddy metrics](https://caddyserver.com/docs/metrics) are enabled, FrankenP
 - `frankenphp_busy_threads`: The number of PHP threads currently processing a request (running workers always consume a thread).
 - `frankenphp_queue_depth`: The number of regular queued requests.
 - `frankenphp_total_workers{worker="[worker_name]"}`: The total number of workers.
-- `frankenphp_busy_workers{worker="[worker_name]"}`: The number of workers currently processing a request.
+- `frankenphp_busy_workers{worker="[worker_name]"}`: The number of workers currently processing a request, or a task for a background worker.
 - `frankenphp_worker_request_time{worker="[worker_name]"}`: The time spent processing requests by all workers.
 - `frankenphp_worker_request_count{worker="[worker_name]"}`: The number of requests processed by all workers.
 - `frankenphp_ready_workers{worker="[worker_name]"}`: The number of workers that have reached their ready point at least once: `frankenphp_handle_request()` for HTTP workers, `frankenphp_get_worker_handle()` for background workers.
 - `frankenphp_worker_crashes{worker="[worker_name]"}`: The number of times a worker has unexpectedly terminated.
 - `frankenphp_worker_restarts{worker="[worker_name]"}`: The number of times a worker has been deliberately restarted.
-- `frankenphp_worker_queue_depth{worker="[worker_name]"}`: The number of queued requests.
+- `frankenphp_worker_queue_depth{worker="[worker_name]"}`: The number of queued requests, or of tasks waiting for a thread of a background worker.
+- `frankenphp_worker_task_count{worker="[worker_name]",outcome="[outcome]"}`: The number of tasks sent to a background worker, by outcome: `completed`, `aborted` (the script ended with the task open), `abandoned` (the sender closed its stream first) or `timeout` (no thread picked the task up in time).
+- `frankenphp_worker_task_time{worker="[worker_name]"}`: The time spent on tasks by all threads of a background worker, from pickup to the close of the task's stream.
 
 `[worker_name]` is the worker name from the Caddyfile, or the absolute path of the worker file when it has none. Workers of a `php_server` block are prefixed with the name of that block: `<server name>:<worker name>`. They used to be reported under their bare name unless two blocks declared the same one, so dashboards and alerts built on those series need the prefix.
 
@@ -73,8 +75,8 @@ Each entry in `ThreadDebugStates` contains:
 | `Index` | integer | The index of the thread. |
 | `Name` | string | The name of the thread (e.g., the worker file path). |
 | `State` | string | The internal state of the thread (e.g., `ready`, `shutting down`). |
-| `IsWaiting` | boolean | Whether the thread is waiting for a request. |
-| `IsBusy` | boolean | Whether the thread is currently processing a request. |
+| `IsWaiting` | boolean | Whether the thread is waiting for a request, or for a task in a background worker. |
+| `IsBusy` | boolean | Whether the thread is currently processing a request, or a task in a background worker. |
 | `WaitingSinceMilliseconds` | integer | How long the thread has been idle, in milliseconds. `0` if the thread is busy. |
 | `CurrentURI` | string | The URI currently being processed. Empty if the thread is idle. |
 | `CurrentMethod` | string | The HTTP method of the current request (e.g., `GET`, `POST`). Empty if the thread is idle. |

metrics.go

@@ -16,6 +16,16 @@ const (
 
 type StopReason int
 
+// TaskOutcome is how a task sent to a background worker ended
+type TaskOutcome string
+
+const (
+	TaskOutcomeCompleted TaskOutcome = "completed" // the worker closed the task's stream
+	TaskOutcomeAborted   TaskOutcome = "aborted"   // the worker's script ended with the task open
+	TaskOutcomeAbandoned TaskOutcome = "abandoned" // the sender closed its stream first
+	TaskOutcomeTimeout   TaskOutcome = "timeout"   // no thread picked the task up in time
+)
+
 type Metrics interface {
 	// StartWorker collects started workers
 	StartWorker(name string)
@@ -40,6 +50,12 @@ type Metrics interface {
 	DequeuedWorkerRequest(name string)
 	QueuedRequest()
 	DequeuedRequest()
+	// StartWorkerTask collects tasks picked up by a thread of a background worker
+	StartWorkerTask(name string)
+	// StopWorkerTask collects tasks a thread of a background worker is done with
+	StopWorkerTask(name string, duration time.Duration)
+	// WorkerTaskOutcome collects how tasks sent to a background worker ended
+	WorkerTaskOutcome(name string, outcome TaskOutcome)
 }
 
 type nullMetrics struct{}
@@ -81,6 +97,12 @@ func (n nullMetrics) DequeuedWorkerRequest(string) {}
 func (n nullMetrics) QueuedRequest()   {}
 func (n nullMetrics) DequeuedRequest() {}
 
+func (n nullMetrics) StartWorkerTask(string) {}
+
+func (n nullMetrics) StopWorkerTask(string, time.Duration) {}
+
+func (n nullMetrics) WorkerTaskOutcome(string, TaskOutcome) {}
+
 type PrometheusMetrics struct {
 	registry           prometheus.Registerer
 	totalThreads       prometheus.Gauge
@@ -93,6 +115,8 @@ type PrometheusMetrics struct {
 	workerRequestTime  *prometheus.CounterVec
 	workerRequestCount *prometheus.CounterVec
 	workerQueueDepth   *prometheus.GaugeVec
+	workerTaskCount    *prometheus.CounterVec
+	workerTaskTime     *prometheus.CounterVec
 	queueDepth         prometheus.Gauge
 	mu                 sync.RWMutex
 }
@@ -186,7 +210,7 @@ func (m *PrometheusMetrics) TotalWorkers(string, int) {
 		m.busyWorkers = prometheus.NewGaugeVec(prometheus.GaugeOpts{
 			Namespace: ns,
 			Name:      "busy_workers",
-			Help:      "Number of busy PHP workers for this worker",
+			Help:      "Number of busy PHP workers for this worker: processing a request, or a task for a background worker",
 		}, basicLabels)
 		m.mustRegister(m.busyWorkers)
 	}
@@ -234,9 +258,30 @@ func (m *PrometheusMetrics) TotalWorkers(string, int) {
 			Namespace: "frankenphp",
 			Subsystem: sub,
 			Name:      "queue_depth",
+			Help:      "Number of queued requests for this worker, or of tasks waiting for a thread of a background worker",
 		}, basicLabels)
 		m.mustRegister(m.workerQueueDepth)
 	}
+
+	if m.workerTaskCount == nil {
+		m.workerTaskCount = prometheus.NewCounterVec(prometheus.CounterOpts{
+			Namespace: ns,
+			Subsystem: sub,
+			Name:      "task_count",
+			Help:      "Number of tasks sent to this background worker, by outcome: completed, aborted (the script ended with the task open), abandoned (the sender closed its stream first) or timeout (no thread picked the task up in time)",
+		}, []string{"worker", "outcome"})
+		m.mustRegister(m.workerTaskCount)
+	}
+
+	if m.workerTaskTime == nil {
+		m.workerTaskTime = prometheus.NewCounterVec(prometheus.CounterOpts{
+			Namespace: ns,
+			Subsystem: sub,
+			Name:      "task_time",
+			Help:      "Time spent on tasks by all threads of this background worker, from pickup to the close of the task's stream",
+		}, basicLabels)
+		m.mustRegister(m.workerTaskTime)
+	}
 }
 
 func (m *PrometheusMetrics) TotalThreads(num int) {
@@ -317,6 +362,37 @@ func (m *PrometheusMetrics) DequeuedRequest() {
 	m.queueDepth.Dec()
 }
 
+func (m *PrometheusMetrics) StartWorkerTask(name string) {
+	m.mu.RLock()
+	defer m.mu.RUnlock()
+
+	if m.busyWorkers == nil {
+		return
+	}
+	m.busyWorkers.WithLabelValues(name).Inc()
+}
+
+func (m *PrometheusMetrics) StopWorkerTask(name string, duration time.Duration) {
+	m.mu.RLock()
+	defer m.mu.RUnlock()
+
+	if m.workerTaskTime == nil {
+		return
+	}
+	m.busyWorkers.WithLabelValues(name).Dec()
+	m.workerTaskTime.WithLabelValues(name).Add(duration.Seconds())
+}
+
+func (m *PrometheusMetrics) WorkerTaskOutcome(name string, outcome TaskOutcome) {
+	m.mu.RLock()
+	defer m.mu.RUnlock()
+
+	if m.workerTaskCount == nil {
+		return
+	}
+	m.workerTaskCount.WithLabelValues(name, string(outcome)).Inc()
+}
+
 func (m *PrometheusMetrics) Shutdown() {
 	m.mu.Lock()
 	defer m.mu.Unlock()
@@ -356,6 +432,14 @@ func (m *PrometheusMetrics) Shutdown() {
 	if m.workerQueueDepth != nil {
 		m.registry.Unregister(m.workerQueueDepth)
 	}
+
+	if m.workerTaskCount != nil {
+		m.registry.Unregister(m.workerTaskCount)
+	}
+
+	if m.workerTaskTime != nil {
+		m.registry.Unregister(m.workerTaskTime)
+	}
 }
 
 func NewPrometheusMetrics(registry prometheus.Registerer) *PrometheusMetrics {
@@ -385,6 +469,8 @@ func NewPrometheusMetrics(registry prometheus.Registerer) *PrometheusMetrics {
 		workerCrashes:      nil,
 		readyWorkers:       nil,
 		workerQueueDepth:   nil,
+		workerTaskCount:    nil,
+		workerTaskTime:     nil,
 	}
 
 	m.mustRegister(m.totalThreads)

metrics_test.go

@@ -50,6 +50,8 @@ func TestPrometheusMetrics_TotalWorkers(t *testing.T) {
 	require.Nil(t, m.workerRestarts)
 	require.Nil(t, m.workerRequestTime)
 	require.Nil(t, m.workerRequestCount)
+	require.Nil(t, m.workerTaskCount)
+	require.Nil(t, m.workerTaskTime)
 
 	m.TotalWorkers("test_worker", 2)
 
@@ -60,6 +62,65 @@ func TestPrometheusMetrics_TotalWorkers(t *testing.T) {
 	require.NotNil(t, m.workerRestarts)
 	require.NotNil(t, m.workerRequestTime)
 	require.NotNil(t, m.workerRequestCount)
+	require.NotNil(t, m.workerTaskCount)
+	require.NotNil(t, m.workerTaskTime)
+}
+
+func TestPrometheusMetrics_WorkerTask(t *testing.T) {
+	m := createPrometheusMetrics()
+	m.TotalWorkers("bg_worker", 1)
+	m.StartWorkerTask("bg_worker")
+	m.StopWorkerTask("bg_worker", 3*time.Second)
+	m.WorkerTaskOutcome("bg_worker", TaskOutcomeCompleted)
+	m.WorkerTaskOutcome("bg_worker", TaskOutcomeTimeout)
+
+	inputs := []struct {
+		name     string
+		c        prometheus.Collector
+		metadata string
+		expect   string
+	}{
+		{
+			name: "Testing BusyWorkers",
+			c:    m.busyWorkers,
+			metadata: `
+				# HELP frankenphp_busy_workers Number of busy PHP workers for this worker: processing a request, or a task for a background worker
+				# TYPE frankenphp_busy_workers gauge
+			`,
+			expect: `
+				frankenphp_busy_workers{worker="bg_worker"} 0
+			`,
+		},
+		{
+			name: "Testing WorkerTaskTime",
+			c:    m.workerTaskTime,
+			metadata: `
+				# HELP frankenphp_worker_task_time Time spent on tasks by all threads of this background worker, from pickup to the close of the task's stream
+				# TYPE frankenphp_worker_task_time counter
+			`,
+			expect: `
+				frankenphp_worker_task_time{worker="bg_worker"} 3
+			`,
+		},
+		{
+			name: "Testing WorkerTaskCount",
+			c:    m.workerTaskCount,
+			metadata: `
+				# HELP frankenphp_worker_task_count Number of tasks sent to this background worker, by outcome: completed, aborted (the script ended with the task open), abandoned (the sender closed its stream first) or timeout (no thread picked the task up in time)
+				# TYPE frankenphp_worker_task_count counter
+			`,
+			expect: `
+				frankenphp_worker_task_count{outcome="completed",worker="bg_worker"} 1
+				frankenphp_worker_task_count{outcome="timeout",worker="bg_worker"} 1
+			`,
+		},
+	}
+
+	for _, input := range inputs {
+		t.Run(input.name, func(t *testing.T) {
+			require.NoError(t, testutil.CollectAndCompare(input.c, strings.NewReader(input.metadata+input.expect)))
+		})
+	}
 }
 
 func TestPrometheusMetrics_StopWorkerRequest(t *testing.T) {
@@ -88,7 +149,7 @@ func TestPrometheusMetrics_StopWorkerRequest(t *testing.T) {
 			name: "Testing BusyWorkers",
 			c:    m.busyWorkers,
 			metadata: `
-				# HELP frankenphp_busy_workers Number of busy PHP workers for this worker
+				# HELP frankenphp_busy_workers Number of busy PHP workers for this worker: processing a request, or a task for a background worker
 				# TYPE frankenphp_busy_workers gauge
 			`,
 			expect: `
@@ -131,7 +192,7 @@ func TestPrometheusMetrics_StartWorkerRequest(t *testing.T) {
 			name: "Testing BusyWorkers",
 			c:    m.busyWorkers,
 			metadata: `
-				# HELP frankenphp_busy_workers Number of busy PHP workers for this worker
+				# HELP frankenphp_busy_workers Number of busy PHP workers for this worker: processing a request, or a task for a background worker
 				# TYPE frankenphp_busy_workers gauge
 			`,
 			expect: `

threadbackgroundworker.go

@@ -40,6 +40,11 @@ type backgroundWorkerThread struct {
 	// backgroundBootWarnDelay; only touched on the PHP thread
 	bootTimer *time.Timer
 
+	// openTasks counts the tasks picked up and not closed yet: the thread
+	// is busy rather than waiting on the threads endpoint meanwhile. Only
+	// touched on the PHP thread, pickup and close both happen there.
+	openTasks int
+
 	// stopSock holds the Go side's end of this thread's stop socket pair
 	// (per thread so pool workers drain independently); the other end is
 	// exposed to the script via frankenphp_get_worker_handle(). Wide enough
@@ -191,6 +196,7 @@ func (handler *backgroundWorkerThread) setupScript() error {
 	handler.dummyFrankenPHPContext = fc
 
 	handler.isBootingScript = true
+	handler.openTasks = 0
 	metrics.StartWorker(handler.worker.qualifiedName)
 	handler.bootTimer = time.AfterFunc(backgroundBootWarnDelay, func() {
 		if globalLogger.Enabled(globalCtx, slog.LevelWarn) {