diff --git a/netbox/core/forms/filtersets.py b/netbox/core/forms/filtersets.py index 56a0861ea..747e1bbee 100644 --- a/netbox/core/forms/filtersets.py +++ b/netbox/core/forms/filtersets.py @@ -75,10 +75,10 @@ class JobFilterForm(SavedFiltersMixin, FilterForm): model = Job fieldsets = ( FieldSet('q', 'filter_id'), - FieldSet('object_type_id', 'status', 'queue_name', name=_('Attributes')), + FieldSet('object_type_id', 'status', 'queue_name', 'user', name=_('Attributes')), FieldSet( 'created__before', 'created__after', 'scheduled__before', 'scheduled__after', 'started__before', - 'started__after', 'completed__before', 'completed__after', 'user', name=_('Creation') + 'started__after', 'completed__before', 'completed__after', name=_('Scheduling') ), FieldSet('execution_time__gte', 'execution_time__lte', name=_('Execution')), ) diff --git a/netbox/core/migrations/0026_populate_job_execution_time.py b/netbox/core/migrations/0026_populate_job_execution_time.py new file mode 100644 index 000000000..e74182024 --- /dev/null +++ b/netbox/core/migrations/0026_populate_job_execution_time.py @@ -0,0 +1,46 @@ +from django.db import migrations +from django.db.models import DurationField, ExpressionWrapper, F + +BATCH_SIZE = 5000 + + +def populate_execution_time(apps, schema_editor): + """ + Populate execution_time for existing jobs which have both a start and completion time recorded. + Updates are performed in batches, as installations which retain job history indefinitely can + accumulate a very large number of rows. Rows which already have a value are skipped, so that an + interrupted run can simply be resumed. + """ + Job = apps.get_model("core", "Job") + queryset = Job.objects.filter( + started__isnull=False, completed__isnull=False, execution_time__isnull=True + ) + execution_time = ExpressionWrapper(F("completed") - F("started"), output_field=DurationField()) + + last_pk = 0 + while True: + pks = list( + queryset.filter(pk__gt=last_pk).order_by("pk").values_list("pk", flat=True)[:BATCH_SIZE] + ) + if not pks: + break + Job.objects.filter(pk__in=pks).update(execution_time=execution_time) + last_pk = pks[-1] + + +class Migration(migrations.Migration): + # The backfill is deliberately kept out of the migration which adds the column, so that the + # ACCESS EXCLUSIVE lock taken by ALTER TABLE is not held for its duration. Running without a + # wrapping transaction is what allows the batching above to bound the work actually held open. + atomic = False + + dependencies = [ + ("core", "0025_add_job_execution_time"), + ] + + operations = [ + migrations.RunPython( + code=populate_execution_time, + reverse_code=migrations.RunPython.noop, + ), + ] diff --git a/netbox/core/tables/jobs.py b/netbox/core/tables/jobs.py index caf4903e0..191835908 100644 --- a/netbox/core/tables/jobs.py +++ b/netbox/core/tables/jobs.py @@ -62,10 +62,11 @@ class JobTable(NetBoxTable): model = Job fields = ( 'pk', 'id', 'object_type', 'object', 'name', 'status', 'created', 'scheduled', 'interval', 'started', - 'completed', 'user', 'queue_name', 'log_entries', 'error', 'job_id', 'execution_time' + 'completed', 'execution_time', 'user', 'queue_name', 'log_entries', 'error', 'job_id', ) default_columns = ( - 'pk', 'id', 'object_type', 'object', 'name', 'status', 'created', 'started', 'completed', 'user', + 'pk', 'id', 'object_type', 'object', 'name', 'status', 'created', 'started', 'completed', 'execution_time', + 'user', ) def render_log_entries(self, value): @@ -74,6 +75,11 @@ class JobTable(NetBoxTable): def render_execution_time(self, value): return humanize_duration(value) + def value_execution_time(self, value): + # Export the recorded execution time as a raw number of seconds, rather than the humanized + # string, as an export is intended for analysis + return round(value.total_seconds(), 3) + class JobLogEntryTable(BaseTable): timestamp = columns.DateTimeColumn( diff --git a/netbox/core/tests/test_tables.py b/netbox/core/tests/test_tables.py index c938fd057..89ba6d193 100644 --- a/netbox/core/tests/test_tables.py +++ b/netbox/core/tests/test_tables.py @@ -1,4 +1,11 @@ -from core.models import ObjectChange +import uuid +from datetime import timedelta + +from django.test import TestCase +from django.utils import timezone + +from core.choices import JobStatusChoices +from core.models import Job, ObjectChange from core.tables import * from utilities.testing import TableTestCases @@ -15,6 +22,65 @@ class JobTableTestCase(TableTestCases.StandardTableTestCase): table = JobTable +class JobExecutionTimeColumnTestCase(TestCase): + """ + Test the rendering and export behavior of JobTable's execution_time column. + """ + @classmethod + def setUpTestData(cls): + now = timezone.now() + Job.objects.bulk_create(( + Job( + name='completed-90s', job_id=uuid.uuid4(), status=JobStatusChoices.STATUS_COMPLETED, + started=now - timedelta(seconds=90), completed=now, execution_time=timedelta(seconds=90), + ), + Job( + name='completed-subsecond', job_id=uuid.uuid4(), status=JobStatusChoices.STATUS_COMPLETED, + started=now - timedelta(milliseconds=430), completed=now, + execution_time=timedelta(milliseconds=430), + ), + Job( + name='completed-long', job_id=uuid.uuid4(), status=JobStatusChoices.STATUS_COMPLETED, + started=now - timedelta(days=2, hours=3), completed=now, + execution_time=timedelta(days=2, hours=3), + ), + Job(name='pending', job_id=uuid.uuid4(), status=JobStatusChoices.STATUS_PENDING), + )) + + def _table(self, name): + table = JobTable(Job.objects.filter(name=name)) + table.columns.show('execution_time') + return table + + def _render(self, name): + table = self._table(name) + return str(next(iter(table.rows)).get_cell('execution_time')) + + def test_render_completed_job(self): + self.assertEqual(self._render('completed-90s'), '1m 30s') + self.assertEqual(self._render('completed-long'), '2d 3h') + + def test_render_subsecond_job(self): + # Sub-second jobs report millisecond precision rather than reading as zero + self.assertEqual(self._render('completed-subsecond'), '0.43s') + + def test_render_job_without_execution_time(self): + table = self._table('pending') + self.assertEqual(str(next(iter(table.rows)).get_cell('execution_time')), table.default) + + def _export_value(self, name): + rows = list(self._table(name).as_values()) + return rows[1][rows[0].index('Execution Time')] + + def test_export_value_is_raw_seconds(self): + # Exports carry the recorded duration in seconds, not the humanized string + self.assertEqual(self._export_value('completed-90s'), 90.0) + self.assertEqual(self._export_value('completed-subsecond'), 0.43) + + def test_export_value_of_job_without_execution_time(self): + self.assertIsNone(self._export_value('pending')) + + class ObjectChangeTableTestCase(TableTestCases.StandardTableTestCase): table = ObjectChangeTable queryset_sources = [ diff --git a/netbox/utilities/string.py b/netbox/utilities/string.py index f19e1d313..dd4ace10c 100644 --- a/netbox/utilities/string.py +++ b/netbox/utilities/string.py @@ -11,15 +11,28 @@ __all__ = ( def humanize_duration(value): """ - Express a timedelta in a human-friendly format. Example: 1h 5m 23s. Returns an empty string - for None; zero-duration timedeltas render as "0s". + Express a timedelta in a human-friendly format. Example: 1h 5m 23s. Durations of a second or + more are rounded to whole seconds; shorter durations are rounded to the millisecond (e.g. + 0.43s). A negative duration is rendered with a leading minus sign, so that an anomalous value + remains recognizable as one. Returns an empty string for None; zero renders as "0s". """ if value is None: return '' + total_seconds = value.total_seconds() + magnitude = abs(total_seconds) + + # Render sub-second durations to the millisecond, as rounding them to whole seconds would + # report every short-lived duration as zero. Trailing zeros are stripped. + if 0 < magnitude < 1: + rendered = f'{magnitude:.3f}'.rstrip('0').rstrip('.') + # A magnitude below a millisecond has no representation here, so fall through to "0s". + # Rounding up to a whole second (e.g. 0.9996) likewise falls through, to "1s". + if rendered not in ('0', '1'): + return f'-{rendered}s' if total_seconds < 0 else f'{rendered}s' + # Round to whole seconds and decompose - total_seconds = int(value.total_seconds()) - days, remainder = divmod(total_seconds, 86400) + days, remainder = divmod(round(magnitude), 86400) hours, remainder = divmod(remainder, 3600) minutes, seconds = divmod(remainder, 60) @@ -32,7 +45,12 @@ def humanize_duration(value): ret += f'{minutes}m ' if seconds or not ret: ret += f'{seconds}s' - return ret.strip() + ret = ret.strip() + + # Zero carries no sign, however the original value was signed + if total_seconds < 0 and ret != '0s': + ret = f'-{ret}' + return ret def enum_key(value): diff --git a/netbox/utilities/tests/test_string.py b/netbox/utilities/tests/test_string.py index 620ee730d..ea45b01f6 100644 --- a/netbox/utilities/tests/test_string.py +++ b/netbox/utilities/tests/test_string.py @@ -28,6 +28,32 @@ class HumanizeDurationTest(TestCase): def test_whole_minute_omits_seconds(self): self.assertEqual(humanize_duration(timedelta(minutes=2)), '2m') - def test_sub_second_rounds_down_to_zero(self): - # Fractional seconds are truncated; a sub-second duration reads as 0s. - self.assertEqual(humanize_duration(timedelta(milliseconds=500)), '0s') + def test_sub_second_renders_decimal(self): + # Sub-second durations retain millisecond precision, with trailing zeros stripped. + self.assertEqual(humanize_duration(timedelta(milliseconds=500)), '0.5s') + self.assertEqual(humanize_duration(timedelta(milliseconds=430)), '0.43s') + self.assertEqual(humanize_duration(timedelta(milliseconds=4)), '0.004s') + + def test_sub_millisecond_rounds_to_zero(self): + # Anything below a millisecond has no decimal representation, so it reads as 0s. + self.assertEqual(humanize_duration(timedelta(microseconds=400)), '0s') + + def test_fractional_seconds_rounded_above_one_second(self): + self.assertEqual(humanize_duration(timedelta(seconds=1, milliseconds=999)), '2s') + self.assertEqual(humanize_duration(timedelta(seconds=1, milliseconds=100)), '1s') + self.assertEqual(humanize_duration(timedelta(seconds=59, milliseconds=600)), '1m') + + def test_negative_duration_retains_sign(self): + # A negative duration is anomalous (e.g. resulting from clock skew), so it is rendered as + # such rather than decomposed into a nonsensical value. + self.assertEqual(humanize_duration(timedelta(seconds=-5)), '-5s') + self.assertEqual(humanize_duration(timedelta(seconds=-1.5)), '-2s') + self.assertEqual(humanize_duration(timedelta(days=-2)), '-2d') + self.assertEqual(humanize_duration(timedelta(milliseconds=-430)), '-0.43s') + + def test_negative_duration_rounding_to_zero_carries_no_sign(self): + self.assertEqual(humanize_duration(timedelta(microseconds=-400)), '0s') + + def test_sub_second_rounding_up_to_one_second(self): + # A magnitude which rounds up to a whole second reads as "1s", not "1.0s" + self.assertEqual(humanize_duration(timedelta(seconds=0.9996)), '1s')