diff --git a/readthedocs/api/v3/serializers.py b/readthedocs/api/v3/serializers.py index 69c98472f3e..514262630ca 100644 --- a/readthedocs/api/v3/serializers.py +++ b/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): """ diff --git a/readthedocs/api/v3/tests/responses/projects-builds-detail.json b/readthedocs/api/v3/tests/responses/projects-builds-detail.json index 996bcef6e61..f749cee844b 100644 --- a/readthedocs/api/v3/tests/responses/projects-builds-detail.json +++ b/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, diff --git a/readthedocs/api/v3/tests/responses/projects-builds-list.json b/readthedocs/api/v3/tests/responses/projects-builds-list.json index df60e9912fe..dd4dbb85b95 100644 --- a/readthedocs/api/v3/tests/responses/projects-builds-list.json +++ b/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, diff --git a/readthedocs/api/v3/tests/responses/projects-versions-builds-list_POST.json b/readthedocs/api/v3/tests/responses/projects-versions-builds-list_POST.json index fbda2e3a255..5a88021aa29 100644 --- a/readthedocs/api/v3/tests/responses/projects-versions-builds-list_POST.json +++ b/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, diff --git a/readthedocs/api/v3/tests/test_builds.py b/readthedocs/api/v3/tests/test_builds.py index 37d451133fb..a96ddd3c588 100644 --- a/readthedocs/api/v3/tests/test_builds.py +++ b/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", diff --git a/readthedocs/builds/migrations/0074_build_queue_time.py b/readthedocs/builds/migrations/0074_build_queue_time.py new file mode 100644 index 00000000000..fa08d9670b2 --- /dev/null +++ b/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"), + ), + ] diff --git a/readthedocs/builds/models.py b/readthedocs/builds/models.py index 219bf68fdeb..473b4af33a2 100644 --- a/readthedocs/builds/models.py +++ b/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, diff --git a/readthedocs/builds/tests/test_models.py b/readthedocs/builds/tests/test_models.py new file mode 100644 index 00000000000..9cd6bcc627d --- /dev/null +++ b/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 diff --git a/readthedocs/projects/tasks/builds.py b/readthedocs/projects/tasks/builds.py index 30793ed5606..a46d9646a16 100644 --- a/readthedocs/projects/tasks/builds.py +++ b/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 # diff --git a/readthedocs/projects/tests/mockers.py b/readthedocs/projects/tests/mockers.py index da83061c40c..edc37298f3f 100644 --- a/readthedocs/projects/tests/mockers.py +++ b/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, diff --git a/readthedocs/projects/tests/test_build_tasks.py b/readthedocs/projects/tests/test_build_tasks.py index 7350324b064..435e5a1ac67 100644 --- a/readthedocs/projects/tests/test_build_tasks.py +++ b/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, } diff --git a/readthedocs/proxito/tests/responses/v1.json b/readthedocs/proxito/tests/responses/v1.json index fee8417131a..325827dcfe0 100644 --- a/readthedocs/proxito/tests/responses/v1.json +++ b/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"