builds: track queue time separately from build duration

readthedocs/api/v3/serializers.py

@@ -189,6 +189,7 @@ class Meta:
             "created",
             "finished",
             "duration",
+            "queue_time",
             "state",
             "success",
             "error",
@@ -203,8 +204,13 @@ def get_error(self, obj):
         return ""
 
     def get_finished(self, obj):
-        if obj.date and obj.length:
-            return obj.date + datetime.timedelta(seconds=obj.length)
+        if obj.length:
+            # ``length`` is the build duration, measured from when the build
+            # actually started running (``task_executed_at``), so it excludes
+            # the time the build spent queued. Fall back to ``date`` for builds
+            # created before ``task_executed_at`` was tracked.
+            started = obj.task_executed_at or obj.date
+            return started + datetime.timedelta(seconds=obj.length)
 
     def get_success(self, obj):
         """

readthedocs/api/v3/tests/responses/projects-builds-detail.json

@@ -2,6 +2,7 @@
     "commit": "a1b2c3",
     "created": "2019-04-29T10:00:00Z",
     "duration": 60,
+    "queue_time": null,
     "error": "",
     "finished": "2019-04-29T10:01:00Z",
     "id": 1,

readthedocs/api/v3/tests/responses/projects-builds-list.json

@@ -7,6 +7,7 @@
       "commit": "a1b2c3",
       "created": "2019-04-29T10:00:00Z",
       "duration": 60,
+      "queue_time": null,
       "error": "",
       "finished": "2019-04-29T10:01:00Z",
       "id": 1,

readthedocs/api/v3/tests/responses/projects-versions-builds-list_POST.json

@@ -3,6 +3,7 @@
         "commit": null,
         "created": "2019-04-29T14:00:00Z",
         "duration": null,
+        "queue_time": null,
         "error": "",
         "finished": null,
         "id": 3,

readthedocs/api/v3/tests/test_builds.py

@@ -1,3 +1,4 @@
+import datetime
 from unittest import mock
 
 from django.test import override_settings
@@ -239,6 +240,32 @@ def test_projects_builds_detail(self):
         self.assertEqual(response.status_code, 200)
         self.assertDictEqual(response.json(), expected_response)
 
+    def test_projects_builds_detail_queue_time(self):
+        # The build was queued for 30s before it started running, then took
+        # ``length`` (60s) to build.
+        self.build.queue_time = 30
+        self.build.task_executed_at = self.created + datetime.timedelta(seconds=30)
+        self.build.save()
+
+        url = reverse(
+            "projects-builds-detail",
+            kwargs={
+                "parent_lookup_project__slug": self.project.slug,
+                "build_pk": self.build.pk,
+            },
+        )
+        self.client.credentials(HTTP_AUTHORIZATION=f"Token {self.token.key}")
+        response = self.client.get(url)
+        self.assertEqual(response.status_code, 200)
+
+        data = response.json()
+        # Queue time is reported separately and does not inflate the duration.
+        self.assertEqual(data["queue_time"], 30)
+        self.assertEqual(data["duration"], 60)
+        # ``finished`` is execution start (task_executed_at) + duration, so the
+        # queue wait is not counted towards it.
+        self.assertEqual(data["finished"], "2019-04-29T10:01:30Z")
+
     def test_projects_builds_detail_other_user(self):
         url = reverse(
             "projects-builds-detail",

readthedocs/builds/migrations/0074_build_queue_time.py

@@ -0,0 +1,21 @@
+# Generated by Django 5.2.13 on 2026-06-01 09:11
+
+from django.db import migrations
+from django.db import models
+from django_safemigrate import Safe
+
+
+class Migration(migrations.Migration):
+    safe = Safe.before_deploy()
+
+    dependencies = [
+        ("builds", "0073_remove_deprecated_build_fields"),
+    ]
+
+    operations = [
+        migrations.AddField(
+            model_name="build",
+            name="queue_time",
+            field=models.IntegerField(blank=True, null=True, verbose_name="Queue time"),
+        ),
+    ]

readthedocs/builds/models.py

@@ -792,6 +792,13 @@ class Build(models.Model):
 
     length = models.IntegerField(_("Build Length"), null=True, blank=True)
 
+    # Number of seconds the build spent queued before it started running,
+    # measured from when the build was originally triggered (``date``) to when
+    # the task started running on a builder (``task_executed_at``). Stored
+    # separately from ``length`` so queue wait time does not inflate the build
+    # duration. Null for builds triggered before this was tracked.
+    queue_time = models.IntegerField(_("Queue time"), null=True, blank=True)
+
     builder = models.CharField(
         _("Builder"),
         max_length=255,

readthedocs/builds/tests/test_models.py

@@ -0,0 +1,31 @@
+from django.test import TestCase
+from django_dynamic_fixture import get
+
+from readthedocs.builds.models import Build
+from readthedocs.builds.models import Version
+from readthedocs.projects.models import Project
+
+
+class BuildQueueTimeTests(TestCase):
+    def setUp(self):
+        self.project = get(Project)
+        self.version = get(Version, project=self.project)
+
+    def test_queue_time_defaults_to_none(self):
+        # Builds triggered before queue time was tracked have no value.
+        build = get(Build, project=self.project, version=self.version, queue_time=None)
+        assert build.queue_time is None
+
+    def test_queue_time_is_stored_independently_from_duration(self):
+        # Queue wait time is stored separately so it does not inflate the
+        # build duration (``length``).
+        build = get(
+            Build,
+            project=self.project,
+            version=self.version,
+            queue_time=30,
+            length=60,
+        )
+        build.refresh_from_db()
+        assert build.queue_time == 30
+        assert build.length == 60

readthedocs/projects/tasks/builds.py

@@ -389,6 +389,9 @@ def before_start(self, task_id, args, kwargs):
         structlog.contextvars.bind_contextvars(build_id=self.data.build_pk)
         log.info("Running task.", name=self.name)
 
+        # Track when the build task starts running on the builder. This is used
+        # to compute the build duration (``length``), so it does not include the
+        # time the build spent waiting in the queue (see ``Build.queue_time``).
         self.data.start_time = timezone.now()
         self.data.environment_class = DockerBuildEnvironment
         if not settings.DOCKER_ENABLE:
@@ -432,7 +435,16 @@ def before_start(self, task_id, args, kwargs):
                 )
 
         # Save when the task was executed by a builder
-        self.data.build["task_executed_at"] = timezone.now()
+        task_executed_at = timezone.now()
+        self.data.build["task_executed_at"] = task_executed_at
+
+        # Store the total time the build spent queued, measured from when it was
+        # originally triggered (``date``) to now. ``date`` is set once at
+        # creation and is not reset on retries, so this captures the full wait
+        # even across retries. It's stored separately from ``length`` so queue
+        # time does not inflate the build duration.
+        triggered_at = datetime.datetime.fromisoformat(self.data.build["date"])
+        self.data.build["queue_time"] = int((task_executed_at - triggered_at).total_seconds())
 
         # Enable scale-in protection on this instance
         #

readthedocs/projects/tests/mockers.py

@@ -186,6 +186,7 @@ def _mock_api(self):
                 "id": self.build.pk,
                 "state": BUILD_STATE_TRIGGERED,
                 "commit": self.build.commit,
+                "date": self.build.date.isoformat(),
                 "task_executed_at": self.build.task_executed_at,
             },
             headers=headers,

readthedocs/projects/tests/test_build_tasks.py

@@ -1,3 +1,4 @@
+import datetime
 import os
 import pathlib
 import textwrap
@@ -10,6 +11,7 @@
 import pytest
 from django.conf import settings
 from django.test.utils import override_settings
+from django.utils import timezone
 
 from readthedocs.allauth.providers.githubapp.provider import GitHubAppProvider
 from readthedocs.builds.constants import (
@@ -556,6 +558,8 @@ def test_successful_build(
             "commit": "a1b2c3",
             "builder": mock.ANY,
             "task_executed_at": mock.ANY,
+            "queue_time": mock.ANY,
+            "date": mock.ANY,
         }
 
         # Update build state: installing
@@ -565,6 +569,8 @@ def test_successful_build(
             "commit": "a1b2c3",
             "builder": mock.ANY,
             "task_executed_at": mock.ANY,
+            "queue_time": mock.ANY,
+            "date": mock.ANY,
             "readthedocs_yaml_path": None,
             # We update the `config` field at the same time we send the
             # `installing` state, to reduce one API call
@@ -646,6 +652,8 @@ def test_successful_build(
             "config": mock.ANY,
             "builder": mock.ANY,
             "task_executed_at": mock.ANY,
+            "queue_time": mock.ANY,
+            "date": mock.ANY,
         }
         # Update build state: uploading
         assert self.requests_mock.request_history[8].json() == {
@@ -656,6 +664,8 @@ def test_successful_build(
             "config": mock.ANY,
             "builder": mock.ANY,
             "task_executed_at": mock.ANY,
+            "queue_time": mock.ANY,
+            "date": mock.ANY,
         }
 
         # Get temporary credentials
@@ -692,6 +702,8 @@ def test_successful_build(
             "config": mock.ANY,
             "builder": mock.ANY,
             "task_executed_at": mock.ANY,
+            "queue_time": mock.ANY,
+            "date": mock.ANY,
             "length": mock.ANY,
             "success": True,
         }
@@ -711,6 +723,37 @@ def test_successful_build(
             ]
         )
 
+    @mock.patch("readthedocs.projects.tasks.builds.build_complete")
+    @mock.patch("readthedocs.projects.tasks.builds.send_external_build_status")
+    @mock.patch("readthedocs.projects.tasks.builds.UpdateDocsTask.execute")
+    @mock.patch("readthedocs.projects.tasks.builds.UpdateDocsTask.send_notifications")
+    @mock.patch("readthedocs.projects.tasks.builds.clean_build")
+    def test_build_stores_queue_time(
+        self,
+        clean_build,
+        send_notifications,
+        execute,
+        send_external_build_status,
+        build_complete,
+    ):
+        # The build was triggered a while ago and is only now picked up by a
+        # builder. The queued time is measured from the original trigger date.
+        self.build.date = timezone.now() - datetime.timedelta(seconds=45)
+        self.build.save()
+
+        # The queue time is computed in ``before_start``, so the actual build
+        # outcome doesn't matter; force a clean stop to reach the final PATCH.
+        execute.side_effect = BuildUserError(message_id=BuildUserError.GENERIC)
+
+        self._trigger_update_docs_task()
+
+        # The last PATCH to the build stores the queued time, measured from the
+        # original trigger date to when the task started running.
+        build_status_request = self.requests_mock.request_history[-2]
+        assert build_status_request._request.method == "PATCH"
+        assert build_status_request.path == "/api/v2/build/1/"
+        assert build_status_request.json()["queue_time"] >= 45
+
     @mock.patch("readthedocs.projects.tasks.builds.build_complete")
     @mock.patch("readthedocs.projects.tasks.builds.send_external_build_status")
     @mock.patch("readthedocs.projects.tasks.builds.UpdateDocsTask.execute")
@@ -779,6 +822,8 @@ def test_failed_build(
         assert build_status_request.json() == {
             "builder": mock.ANY,
             "task_executed_at": mock.ANY,
+            "queue_time": mock.ANY,
+            "date": mock.ANY,
             "commit": self.build.commit,
             "id": self.build.pk,
             "length": mock.ANY,
@@ -833,6 +878,8 @@ def test_cancelled_build(
         assert build_status_request.json() == {
             "builder": mock.ANY,
             "task_executed_at": mock.ANY,
+            "queue_time": mock.ANY,
+            "date": mock.ANY,
             "commit": self.build.commit,
             "id": self.build.pk,
             "length": mock.ANY,
@@ -2986,6 +3033,8 @@ def test_config_file_exception(self, load_yaml_config):
             "success": False,
             "builder": mock.ANY,
             "task_executed_at": mock.ANY,
+            "queue_time": mock.ANY,
+            "date": mock.ANY,
             "length": 0,
         }
 

readthedocs/proxito/tests/responses/v1.json

@@ -94,6 +94,7 @@
       "finished": "2019-04-29T10:01:00Z",
       "id": 1,
       "project": "project",
+      "queue_time": null,
       "state": {
         "code": "finished",
         "name": "Finished"