"context deadline exceeded" on VisibilityDeleteExecution

Community Support
, ,
1

Hi all,

I’m having issues with a lot of logs in the history service that indicate that context deadline exceeded error on VisibilityDeleteExecution. My temporal.visibility_tasks has around 57M rows and metrics show a very low rate of resolution for those tasks. Below some context:

Temporal version: 1.25.2
History service logs:

{"level":"error","ts":"2025-07-25T12:12:01.388Z","msg":"Operation failed with an error.","error":"context deadline exceeded","logging-call-at":"/home/runner/work/docker-builds/docker-builds/temporal/common/persistence/visibility/visiblity_manager_metrics.go:195","stacktrace":"go.temporal.io/server/common/log.(*zapLogger).Error\n\t/home/runner/work/docker-builds/docker-builds/temporal/common/log/zap_logger.go:155\ngo.temporal.io/server/common/persistence/visibility.(*visibilityManagerMetrics).updateErrorMetric\n\t/home/runner/work/docker-builds/docker-builds/temporal/common/persistence/visibility/visiblity_manager_metrics.go:195\ngo.temporal.io/server/common/persistence/visibility.(*visibilityManagerMetrics).DeleteWorkflowExecution\n\t/home/runner/work/docker-builds/docker-builds/temporal/common/persistence/visibility/visiblity_manager_metrics.go:129\ngo.temporal.io/server/service/history.(*visibilityQueueTaskExecutor).processDeleteExecution\n\t/home/runner/work/docker-builds/docker-builds/temporal/service/history/visibility_queue_task_executor.go:344\ngo.temporal.io/server/service/history.(*visibilityQueueTaskExecutor).Execute\n\t/home/runner/work/docker-builds/docker-builds/temporal/service/history/visibility_queue_task_executor.go:127\ngo.temporal.io/server/service/history/queues.(*executableImpl).Execute\n\t/home/runner/work/docker-builds/docker-builds/temporal/service/history/queues/executable.go:330\ngo.temporal.io/server/common/tasks.(*FIFOScheduler[...]).executeTask.func1\n\t/home/runner/work/docker-builds/docker-builds/temporal/common/tasks/fifo_scheduler.go:223\ngo.temporal.io/server/common/backoff.ThrottleRetry.func1\n\t/home/runner/work/docker-builds/docker-builds/temporal/common/backoff/retry.go:63\ngo.temporal.io/server/common/backoff.ThrottleRetryContext\n\t/home/runner/work/docker-builds/docker-builds/temporal/common/backoff/retry.go:90\ngo.temporal.io/server/common/backoff.ThrottleRetry\n\t/home/runner/work/docker-builds/docker-builds/temporal/common/backoff/retry.go:64\ngo.temporal.io/server/common/tasks.(*FIFOScheduler[...]).executeTask\n\t/home/runner/work/docker-builds/docker-builds/temporal/common/tasks/fifo_scheduler.go:233\ngo.temporal.io/server/common/tasks.(*FIFOScheduler[...]).processTask\n\t/home/runner/work/docker-builds/docker-builds/temporal/common/tasks/fifo_scheduler.go:211"}
{"level":"warn","ts":"2025-07-25T12:12:01.388Z","msg":"Fail to process task","shard-id":169,"address":"10.244.33.208:7234","component":"visibility-queue-processor","wf-namespace-id":"79499301-84c7-45ab-a20f-fc1bc509066b","wf-id":"webhook-dispatch-251961-66-63538efb-25f4-466b-aaf2-1833dcfd5b34","wf-run-id":"7757a575-3a85-4b04-82c1-ced46a7dd5a9","queue-task-key":{"FireTime":"1970-01-01T00:00:00Z","TaskID":2396007582},"queue-task-type":"VisibilityDeleteExecution","queue-task":"79499301-84c7-45ab-a20f-fc1bc509066b/webhook-dispatch-251961-66-63538efb-25f4-466b-aaf2-1833dcfd5b34/7757a575-3a85-4b04-82c1-ced46a7dd5a9","wf-history-event-id":0,"error":"context deadline exceeded","error-type":"serviceerror.Unavailable","unexpected-error-attempts":10,"lifecycle":"ProcessingFailed","logging-call-at":"/home/runner/work/docker-builds/docker-builds/temporal/common/log/lazy_logger.go:63"}
{"level":"error","ts":"2025-07-25T12:12:01.388Z","msg":"Operation failed with an error.","error":"context deadline exceeded","logging-call-at":"/home/runner/work/docker-builds/docker-builds/temporal/common/persistence/visibility/visiblity_manager_metrics.go:195","stacktrace":"go.temporal.io/server/common/log.(*zapLogger).Error\n\t/home/runner/work/docker-builds/docker-builds/temporal/common/log/zap_logger.go:155\ngo.temporal.io/server/common/persistence/visibility.(*visibilityManagerMetrics).updateErrorMetric\n\t/home/runner/work/docker-builds/docker-builds/temporal/common/persistence/visibility/visiblity_manager_metrics.go:195\ngo.temporal.io/server/common/persistence/visibility.(*visibilityManagerMetrics).DeleteWorkflowExecution\n\t/home/runner/work/docker-builds/docker-builds/temporal/common/persistence/visibility/visiblity_manager_metrics.go:129\ngo.temporal.io/server/service/history.(*visibilityQueueTaskExecutor).processDeleteExecution\n\t/home/runner/work/docker-builds/docker-builds/temporal/service/history/visibility_queue_task_executor.go:344\ngo.temporal.io/server/service/history.(*visibilityQueueTaskExecutor).Execute\n\t/home/runner/work/docker-builds/docker-builds/temporal/service/history/visibility_queue_task_executor.go:127\ngo.temporal.io/server/service/history/queues.(*executableImpl).Execute\n\t/home/runner/work/docker-builds/docker-builds/temporal/service/history/queues/executable.go:330\ngo.temporal.io/server/common/tasks.(*FIFOScheduler[...]).executeTask.func1\n\t/home/runner/work/docker-builds/docker-builds/temporal/common/tasks/fifo_scheduler.go:223\ngo.temporal.io/server/common/backoff.ThrottleRetry.func1\n\t/home/runner/work/docker-builds/docker-builds/temporal/common/backoff/retry.go:63\ngo.temporal.io/server/common/backoff.ThrottleRetryContext\n\t/home/runner/work/docker-builds/docker-builds/temporal/common/backoff/retry.go:90\ngo.temporal.io/server/common/backoff.ThrottleRetry\n\t/home/runner/work/docker-builds/docker-builds/temporal/common/backoff/retry.go:64\ngo.temporal.io/server/common/tasks.(*FIFOScheduler[...]).executeTask\n\t/home/runner/work/docker-builds/docker-builds/temporal/common/tasks/fifo_scheduler.go:233\ngo.temporal.io/server/common/tasks.(*FIFOScheduler[...]).processTask\n\t/home/runner/work/docker-builds/docker-builds/temporal/common/tasks/fifo_scheduler.go:211"}
{"level":"warn","ts":"2025-07-25T12:12:01.388Z","msg":"Fail to process task","shard-id":505,"address":"10.244.33.208:7234","component":"visibility-queue-processor","wf-namespace-id":"79499301-84c7-45ab-a20f-fc1bc509066b","wf-id":"webhook-dispatch-264916-45-f079ac2f-3cdb-4c6e-93fc-fbabd9a4dade","wf-run-id":"067e2ba5-c9b3-4272-8a60-5aa7a72c32e9","queue-task-key":{"FireTime":"1970-01-01T00:00:00Z","TaskID":1417676950},"queue-task-type":"VisibilityDeleteExecution","queue-task":"79499301-84c7-45ab-a20f-fc1bc509066b/webhook-dispatch-264916-45-f079ac2f-3cdb-4c6e-93fc-fbabd9a4dade/067e2ba5-c9b3-4272-8a60-5aa7a72c32e9","wf-history-event-id":0,"error":"context deadline exceeded","error-type":"serviceerror.Unavailable","unexpected-error-attempts":6,"lifecycle":"ProcessingFailed","logging-call-at":"/home/runner/work/docker-builds/docker-builds/temporal/common/log/lazy_logger.go:63"}
{"level":"error","ts":"2025-07-25T12:12:01.388Z","msg":"Operation failed with an error.","error":"context deadline exceeded","logging-call-at":"/home/runner/work/docker-builds/docker-builds/temporal/common/persistence/visibility/visiblity_manager_metrics.go:195","stacktrace":"go.temporal.io/server/common/log.(*zapLogger).Error\n\t/home/runner/work/docker-builds/docker-builds/temporal/common/log/zap_logger.go:155\ngo.temporal.io/server/common/persistence/visibility.(*visibilityManagerMetrics).updateErrorMetric\n\t/home/runner/work/docker-builds/docker-builds/temporal/common/persistence/visibility/visiblity_manager_metrics.go:195\ngo.temporal.io/server/common/persistence/visibility.(*visibilityManagerMetrics).DeleteWorkflowExecution\n\t/home/runner/work/docker-builds/docker-builds/temporal/common/persistence/visibility/visiblity_manager_metrics.go:129\ngo.temporal.io/server/service/history.(*visibilityQueueTaskExecutor).processDeleteExecution\n\t/home/runner/work/docker-builds/docker-builds/temporal/service/history/visibility_queue_task_executor.go:344\ngo.temporal.io/server/service/history.(*visibilityQueueTaskExecutor).Execute\n\t/home/runner/work/docker-builds/docker-builds/temporal/service/history/visibility_queue_task_executor.go:127\ngo.temporal.io/server/service/history/queues.(*executableImpl).Execute\n\t/home/runner/work/docker-builds/docker-builds/temporal/service/history/queues/executable.go:330\ngo.temporal.io/server/common/tasks.(*FIFOScheduler[...]).executeTask.func1\n\t/home/runner/work/docker-builds/docker-builds/temporal/common/tasks/fifo_scheduler.go:223\ngo.temporal.io/server/common/backoff.ThrottleRetry.func1\n\t/home/runner/work/docker-builds/docker-builds/temporal/common/backoff/retry.go:63\ngo.temporal.io/server/common/backoff.ThrottleRetryContext\n\t/home/runner/work/docker-builds/docker-builds/temporal/common/backoff/retry.go:90\ngo.temporal.io/server/common/backoff.ThrottleRetry\n\t/home/runner/work/docker-builds/docker-builds/temporal/common/backoff/retry.go:64\ngo.temporal.io/server/common/tasks.(*FIFOScheduler[...]).executeTask\n\t/home/runner/work/docker-builds/docker-builds/temporal/common/tasks/fifo_scheduler.go:233\ngo.temporal.io/server/common/tasks.(*FIFOScheduler[...]).processTask\n\t/home/runner/work/docker-builds/docker-builds/temporal/common/tasks/fifo_scheduler.go:211"}
{"level":"warn","ts":"2025-07-25T12:12:01.388Z","msg":"Fail to process task","shard-id":244,"address":"10.244.33.208:7234","component":"visibility-queue-processor","wf-namespace-id":"9c49769f-bc0c-44a6-869e-a0ecdda9c7de","wf-id":"dsl-workflow-v2-8-1638173-25609f86-5c14-46ef-92c1-41a346898012","wf-run-id":"7f3760e4-c1a1-46df-b261-bd543045c4bb","queue-task-key":{"FireTime":"1970-01-01T00:00:00Z","TaskID":1821377284},"queue-task-type":"VisibilityDeleteExecution","queue-task":"9c49769f-bc0c-44a6-869e-a0ecdda9c7de/dsl-workflow-v2-8-1638173-25609f86-5c14-46ef-92c1-41a346898012/7f3760e4-c1a1-46df-b261-bd543045c4bb","wf-history-event-id":0,"error":"context deadline exceeded","error-type":"serviceerror.Unavailable","unexpected-error-attempts":2,"lifecycle":"ProcessingFailed","logging-call-at":"/home/runner/work/docker-builds/docker-builds/temporal/common/log/lazy_logger.go:63"}
{"level":"error","ts":"2025-07-25T12:12:01.388Z","msg":"Operation failed with an error.","error":"context deadline exceeded","logging-call-at":"/home/runner/work/docker-builds/docker-builds/temporal/common/persistence/visibility/visiblity_manager_metrics.go:195","stacktrace":"go.temporal.io/server/common/log.(*zapLogger).Error\n\t/home/runner/work/docker-builds/docker-builds/temporal/common/log/zap_logger.go:155\ngo.temporal.io/server/common/persistence/visibility.(*visibilityManagerMetrics).updateErrorMetric\n\t/home/runner/work/docker-builds/docker-builds/temporal/common/persistence/visibility/visiblity_manager_metrics.go:195\ngo.temporal.io/server/common/persistence/visibility.(*visibilityManagerMetrics).DeleteWorkflowExecution\n\t/home/runner/work/docker-builds/docker-builds/temporal/common/persistence/visibility/visiblity_manager_metrics.go:129\ngo.temporal.io/server/service/history.(*visibilityQueueTaskExecutor).processDeleteExecution\n\t/home/runner/work/docker-builds/docker-builds/temporal/service/history/visibility_queue_task_executor.go:344\ngo.temporal.io/server/service/history.(*visibilityQueueTaskExecutor).Execute\n\t/home/runner/work/docker-builds/docker-builds/temporal/service/history/visibility_queue_task_executor.go:127\ngo.temporal.io/server/service/history/queues.(*executableImpl).Execute\n\t/home/runner/work/docker-builds/docker-builds/temporal/service/history/queues/executable.go:330\ngo.temporal.io/server/common/tasks.(*FIFOScheduler[...]).executeTask.func1\n\t/home/runner/work/docker-builds/docker-builds/temporal/common/tasks/fifo_scheduler.go:223\ngo.temporal.io/server/common/backoff.ThrottleRetry.func1\n\t/home/runner/work/docker-builds/docker-builds/temporal/common/backoff/retry.go:63\ngo.temporal.io/server/common/backoff.ThrottleRetryContext\n\t/home/runner/work/docker-builds/docker-builds/temporal/common/backoff/retry.go:90\ngo.temporal.io/server/common/backoff.ThrottleRetry\n\t/home/runner/work/docker-builds/docker-builds/temporal/common/backoff/retry.go:64\ngo.temporal.io/server/common/tasks.(*FIFOScheduler[...]).executeTask\n\t/home/runner/work/docker-builds/docker-builds/temporal/common/tasks/fifo_scheduler.go:233\ngo.temporal.io/server/common/tasks.(*FIFOScheduler[...]).processTask\n\t/home/runner/work/docker-builds/docker-builds/temporal/common/tasks/fifo_scheduler.go:211"}
{"level":"error","ts":"2025-07-25T12:12:01.388Z","msg":"Operation failed with an error.","error":"context deadline exceeded","logging-call-at":"/home/runner/work/docker-builds/docker-builds/temporal/common/persistence/visibility/visiblity_manager_metrics.go:195","stacktrace":"go.temporal.io/server/common/log.(*zapLogger).Error\n\t/home/runner/work/docker-builds/docker-builds/temporal/common/log/zap_logger.go:155\ngo.temporal.io/server/common/persistence/visibility.(*visibilityManagerMetrics).updateErrorMetric\n\t/home/runner/work/docker-builds/docker-builds/temporal/common/persistence/visibility/visiblity_manager_metrics.go:195\ngo.temporal.io/server/common/persistence/visibility.(*visibilityManagerMetrics).DeleteWorkflowExecution\n\t/home/runner/work/docker-builds/docker-builds/temporal/common/persistence/visibility/visiblity_manager_metrics.go:129\ngo.temporal.io/server/service/history.(*visibilityQueueTaskExecutor).processDeleteExecution\n\t/home/runner/work/docker-builds/docker-builds/temporal/service/history/visibility_queue_task_executor.go:344\ngo.temporal.io/server/service/history.(*visibilityQueueTaskExecutor).Execute\n\t/home/runner/work/docker-builds/docker-builds/temporal/service/history/visibility_queue_task_executor.go:127\ngo.temporal.io/server/service/history/queues.(*executableImpl).Execute\n\t/home/runner/work/docker-builds/docker-builds/temporal/service/history/queues/executable.go:330\ngo.temporal.io/server/common/tasks.(*FIFOScheduler[...]).executeTask.func1\n\t/home/runner/work/docker-builds/docker-builds/temporal/common/tasks/fifo_scheduler.go:223\ngo.temporal.io/server/common/backoff.ThrottleRetry.func1\n\t/home/runner/work/docker-builds/docker-builds/temporal/common/backoff/retry.go:63\ngo.temporal.io/server/common/backoff.ThrottleRetryContext\n\t/home/runner/work/docker-builds/docker-builds/temporal/common/backoff/retry.go:90\ngo.temporal.io/server/common/backoff.ThrottleRetry\n\t/home/runner/work/docker-builds/docker-builds/temporal/common/backoff/retry.go:64\ngo.temporal.io/server/common/tasks.(*FIFOScheduler[...]).executeTask\n\t/home/runner/work/docker-builds/docker-builds/temporal/common/tasks/fifo_scheduler.go:233\ngo.temporal.io/server/common/tasks.(*FIFOScheduler[...]).processTask\n\t/home/runner/work/docker-builds/docker-builds/temporal/common/tasks/fifo_scheduler.go:211"}

There are lots of those logs per second.

Some metrics I’m checking (inspired by Timeouts on visibility-tasks but workflows still completing):

Screenshot 2025-07-25 at 09.22.51
Screenshot 2025-07-25 at 09.22.51719×266 19.7 KB

I’m not sure why the rate of execution is so low if there are 50+M tasks to be executed.

This is the persistence layer metrics from the history service:

Screenshot 2025-07-25 at 09.25.55
Screenshot 2025-07-25 at 09.25.552862×844 268 KB

(seems like it is not having any database errors here)

This is the history client on the frontend service:

Screenshot 2025-07-25 at 09.26.25
Screenshot 2025-07-25 at 09.26.254052×770 311 KB

(seems like maybe those are the errors I’m seeing in the logs)

The environment should have around 600k “running” workflows (most stopped on timers).

Any help on how to properly debug this would be greatly appreciated.

Greetings,
Vinicius

2

"Operation failed with an error.
,“error”:“context deadline exceeded”,
visiblity_manager_metrics.go:

try increasing connections

see if this reduces

3

Hi @tihomir, how are you?
Thanks a lot for the reply.

I was running each history service with 100 connections and around 5 pods, so that was 500 connections. What kind of numbers would be expected?

It was:

maxConnLifetime: 1h
maxConns: 100
maxIdleConns: 100

I’ve changed this yesterday to:

maxConnLifetime: 10m
maxConns: 50
maxIdleConns: 50

This actually improved things, as I was seeing errors on persistence metrics before that change, but not right now.

The persistence layer is MySQL 8.0.40.

Greetings.

4

I’m having a similar issue with MySQL and I can’t seem to find out what the bottleneck is. Did you ever track down any more information on what was going on?