diff --git a/common/code_spelling_ignore_words.txt b/common/code_spelling_ignore_words.txt index 20c4a15210a2..eb4ced669074 100644 --- a/common/code_spelling_ignore_words.txt +++ b/common/code_spelling_ignore_words.txt @@ -1669,6 +1669,7 @@ workerdir workerenvironment workerforbuilder workerforbuilders +workerid workerlock workermanager workername diff --git a/master/buildbot/data/builds.py b/master/buildbot/data/builds.py index 46e3e1f67132..2905a82aa3d0 100644 --- a/master/buildbot/data/builds.py +++ b/master/buildbot/data/builds.py @@ -51,6 +51,7 @@ def db2data(self, dbdict): 'masterid': dbdict['masterid'], 'started_at': dbdict['started_at'], 'complete_at': dbdict['complete_at'], + "locks_duration_s": dbdict["locks_duration_s"], 'complete': dbdict['complete_at'] is not None, 'state_string': dbdict['state_string'], 'results': dbdict['results'], @@ -66,6 +67,7 @@ def db2data(self, dbdict): 'masterid': 'builds.masterid', 'started_at': 'builds.started_at', 'complete_at': 'builds.complete_at', + "locks_duration_s": "builds.locks_duration_s", 'state_string': 'builds.state_string', 'results': 'builds.results', } @@ -210,6 +212,7 @@ class EntityType(types.Entity): started_at = types.DateTime() complete = types.Boolean() complete_at = types.NoneOk(types.DateTime()) + locks_duration_s = types.Integer() results = types.NoneOk(types.Integer()) state_string = types.String() properties = types.NoneOk(types.SourcedProperties()) @@ -244,6 +247,12 @@ def setBuildStateString(self, buildid, state_string): yield self.generateEvent(buildid, "update") return res + @base.updateMethod + @defer.inlineCallbacks + def add_build_locks_duration(self, buildid, duration_s): + yield self.master.db.builds.add_build_locks_duration(buildid=buildid, duration_s=duration_s) + yield self.generateEvent(buildid, "update") + @base.updateMethod @defer.inlineCallbacks def finishBuild(self, buildid, results): diff --git a/master/buildbot/data/steps.py b/master/buildbot/data/steps.py index 11110813f9e6..72f45fdddb38 100644 --- a/master/buildbot/data/steps.py +++ b/master/buildbot/data/steps.py @@ -140,14 +140,25 @@ def addStep(self, buildid, name): @base.updateMethod @defer.inlineCallbacks - def startStep(self, stepid): - yield self.master.db.steps.startStep(stepid=stepid) + def startStep(self, stepid, started_at=None, locks_acquired=False): + if started_at is None: + started_at = int(self.master.reactor.seconds()) + yield self.master.db.steps.startStep( + stepid=stepid, + started_at=started_at, + locks_acquired=locks_acquired + ) yield self.generateEvent(stepid, 'started') @base.updateMethod @defer.inlineCallbacks - def set_step_locks_acquired_at(self, stepid): - yield self.master.db.steps.set_step_locks_acquired_at(stepid=stepid) + def set_step_locks_acquired_at(self, stepid, locks_acquired_at=None): + if locks_acquired_at is None: + locks_acquired_at = int(self.master.reactor.seconds()) + + yield self.master.db.steps.set_step_locks_acquired_at( + stepid=stepid, locks_acquired_at=locks_acquired_at + ) yield self.generateEvent(stepid, 'updated') @base.updateMethod diff --git a/master/buildbot/db/builds.py b/master/buildbot/db/builds.py index 34e48766162e..3c1b866baad8 100644 --- a/master/buildbot/db/builds.py +++ b/master/buildbot/db/builds.py @@ -176,6 +176,7 @@ def thd(conn): "masterid": masterid, "started_at": started_at, "complete_at": None, + "locks_duration_s": 0, "state_string": state_string }) except (sa.exc.IntegrityError, sa.exc.ProgrammingError) as e: @@ -251,6 +252,17 @@ def thd(conn): {"value": value_js, "source": source}) yield self.db.pool.do(thd) + @defer.inlineCallbacks + def add_build_locks_duration(self, buildid, duration_s): + def thd(conn): + builds_tbl = self.db.model.builds + conn.execute( + builds_tbl.update(builds_tbl.c.id == buildid).values( + locks_duration_s=builds_tbl.c.locks_duration_s + duration_s + ) + ) + yield self.db.pool.do(thd) + def _builddictFromRow(self, row): return { "id": row.id, @@ -261,6 +273,7 @@ def _builddictFromRow(self, row): "masterid": row.masterid, "started_at": epoch2datetime(row.started_at), "complete_at": epoch2datetime(row.complete_at), + "locks_duration_s": row.locks_duration_s, "state_string": row.state_string, "results": row.results } diff --git a/master/buildbot/db/migrations/versions/066_2023-11-28_add_build_locks_duration_s.py b/master/buildbot/db/migrations/versions/066_2023-11-28_add_build_locks_duration_s.py new file mode 100644 index 000000000000..b5fc1a40f43d --- /dev/null +++ b/master/buildbot/db/migrations/versions/066_2023-11-28_add_build_locks_duration_s.py @@ -0,0 +1,50 @@ +# This file is part of Buildbot. Buildbot is free software: you can +# redistribute it and/or modify it under the terms of the GNU General Public +# License as published by the Free Software Foundation, version 2. +# +# This program is distributed in the hope that it will be useful, but WITHOUT +# ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or FITNESS +# FOR A PARTICULAR PURPOSE. See the GNU General Public License for more +# details. +# +# You should have received a copy of the GNU General Public License along with +# this program; if not, write to the Free Software Foundation, Inc., 51 +# Franklin Street, Fifth Floor, Boston, MA 02110-1301 USA. +# +# Copyright Buildbot Team Members + +"""add pause_reason column to workers table + +Revision ID: 066 +Revises: 065 + +""" +import sqlalchemy as sa +from alembic import op + +from buildbot.util import sautils + +# revision identifiers, used by Alembic. +revision = "066" +down_revision = "065" +branch_labels = None +depends_on = None + + +def upgrade(): + op.add_column("builds", sa.Column("locks_duration_s", sa.Integer, nullable=True)) + + metadata = sa.MetaData() + builds_tbl = sautils.Table( + "builds", metadata, + sa.Column("locks_duration_s", sa.Integer, nullable=True) + ) + + op.execute(builds_tbl.update(values={builds_tbl.c.locks_duration_s: 0})) + + with op.batch_alter_table("builds") as batch_op: + batch_op.alter_column("locks_duration_s", existing_type=sa.Integer, nullable=False) + + +def downgrade(): + op.drop_column("builds", "locks_duration_s") diff --git a/master/buildbot/db/model.py b/master/buildbot/db/model.py index bf7e3cc4dfab..d86bd2c0c293 100644 --- a/master/buildbot/db/model.py +++ b/master/buildbot/db/model.py @@ -186,6 +186,9 @@ class Model(base.DBConnectorComponent): # start/complete times sa.Column('started_at', sa.Integer, nullable=False), sa.Column('complete_at', sa.Integer), + # Contains total duration that completed steps spent waiting for locks. Currently running + # step is not included. + sa.Column("locks_duration_s", sa.Integer, nullable=False), sa.Column('state_string', sa.Text, nullable=False), sa.Column('results', sa.Integer), ) diff --git a/master/buildbot/db/steps.py b/master/buildbot/db/steps.py index 7f2d52386817..6daed0ce6a62 100644 --- a/master/buildbot/db/steps.py +++ b/master/buildbot/db/steps.py @@ -118,19 +118,18 @@ def thd(conn): return self.db.pool.do(thd) @defer.inlineCallbacks - def startStep(self, stepid): - started_at = int(self.master.reactor.seconds()) - + def startStep(self, stepid, started_at, locks_acquired): def thd(conn): tbl = self.db.model.steps q = tbl.update(whereclause=tbl.c.id == stepid) - conn.execute(q, started_at=started_at) + if locks_acquired: + conn.execute(q, started_at=started_at, locks_acquired_at=started_at) + else: + conn.execute(q, started_at=started_at) yield self.db.pool.do(thd) @defer.inlineCallbacks - def set_step_locks_acquired_at(self, stepid): - locks_acquired_at = int(self.master.reactor.seconds()) - + def set_step_locks_acquired_at(self, stepid, locks_acquired_at): def thd(conn): tbl = self.db.model.steps q = tbl.update(whereclause=tbl.c.id == stepid) diff --git a/master/buildbot/process/build.py b/master/buildbot/process/build.py index e9c327c8d705..ab7e936359c1 100644 --- a/master/buildbot/process/build.py +++ b/master/buildbot/process/build.py @@ -86,7 +86,10 @@ def __init__(self, requests): self.sources = requests[0].mergeSourceStampsWith(requests[1:]) self.reason = requests[0].mergeReasons(requests[1:]) + self._preparation_step = None + self._locks_acquire_step = None self.currentStep = None + self.workerEnvironment = {} self.buildid = None self._buildid_notifier = Notifier() @@ -339,28 +342,32 @@ def startBuild(self, workerforbuilder): # the preparation step counts the time needed for preparing the worker and getting the # locks. # we cannot use a real step as we don't have a worker yet. - self.preparation_step = buildstep.create_step_from_step_or_factory( + self._preparation_step = buildstep.create_step_from_step_or_factory( buildstep.BuildStep(name="worker_preparation") ) - self.preparation_step.setBuild(self) - yield self.preparation_step.addStep() - - # TODO: the time consuming actions during worker preparation are as follows: - # - worker substantiation - # - acquiring build locks - # Since locks_acquire_at calculates the time since beginning of the step until the end, - # it's impossible to represent this sequence using a single step. In the future it makes - # sense to add two steps: one for worker substantiation and another for acquiring build - # locks. - yield self.master.data.updates.set_step_locks_acquired_at(self.preparation_step.stepid) + self._preparation_step.setBuild(self) + yield self._preparation_step.addStep() + yield self.master.data.updates.startStep( + self._preparation_step.stepid, locks_acquired=True + ) Build.setupBuildProperties(self.getProperties(), self.requests, self.sources, self.number) - # then narrow WorkerLocks down to the right worker yield self._setup_locks() metrics.MetricCountEvent.log('active_builds', 1) + if self._locks_to_acquire: + # Note that most of the time locks will already free because build distributor does + # not start builds that cannot acquire locks immediately. However on a loaded master + # it may happen that more builds are cleared to start than there are free locks. In + # such case some of the builds will be blocked and wait for the locks. + self._locks_acquire_step = buildstep.create_step_from_step_or_factory( + buildstep.BuildStep(name="locks_acquire") + ) + self._locks_acquire_step.setBuild(self) + yield self._locks_acquire_step.addStep() + # make sure properties are available to people listening on 'new' # events yield self.master.data.updates.setBuildProperties(self.buildid, self) @@ -422,6 +429,11 @@ def startBuild(self, workerforbuilder): yield self.buildFinished(["worker", "not", "pinged"], RETRY) return + yield self.master.data.updates.setStepStateString( + self._preparation_step.stepid, f"worker {self.getWorkerName()} ready" + ) + yield self.master.data.updates.finishStep(self._preparation_step.stepid, SUCCESS, False) + self.conn = workerforbuilder.worker.conn # To retrieve the builddir property, the worker must be attached as we @@ -440,13 +452,25 @@ def startBuild(self, workerforbuilder): yield self.buildFinished(["worker", "not", "building"], RETRY) return - yield self.master.data.updates.setBuildStateString(self.buildid, - 'acquiring locks') - yield self.acquireLocks() - - readymsg = f"worker {self.getWorkerName()} ready" - yield self.master.data.updates.setStepStateString(self.preparation_step.stepid, readymsg) - yield self.master.data.updates.finishStep(self.preparation_step.stepid, SUCCESS, False) + if self._locks_to_acquire: + yield self.master.data.updates.setBuildStateString(self.buildid, "acquiring locks") + locks_acquire_start_at = int(self.master.reactor.seconds()) + yield self.master.data.updates.startStep( + self._locks_acquire_step.stepid, started_at=locks_acquire_start_at + ) + yield self.acquireLocks() + locks_acquired_at = int(self.master.reactor.seconds()) + yield self.master.data.updates.set_step_locks_acquired_at( + self._locks_acquire_step.stepid, locks_acquired_at=locks_acquired_at + ) + yield self.master.data.updates.add_build_locks_duration( + self.buildid, duration_s=locks_acquired_at - locks_acquire_start_at + ) + yield self.master.data.updates.setStepStateString( + self._locks_acquire_step.stepid, "locks acquired") + yield self.master.data.updates.finishStep( + self._locks_acquire_step.stepid, SUCCESS, False + ) yield self.master.data.updates.setBuildStateString(self.buildid, 'building') @@ -460,18 +484,18 @@ def buildPreparationFailure(self, why, state_string): # if self.stopped, then this failure is a LatentWorker's failure to substantiate # which we triggered on purpose in stopBuild() log.msg("worker stopped while " + state_string, why) - yield self.master.data.updates.finishStep(self.preparation_step.stepid, + yield self.master.data.updates.finishStep(self._preparation_step.stepid, CANCELLED, False) else: log.err(why, "while " + state_string) self.workerforbuilder.worker.putInQuarantine() if isinstance(why, failure.Failure): - yield self.preparation_step.addLogWithFailure(why) + yield self._preparation_step.addLogWithFailure(why) elif isinstance(why, Exception): - yield self.preparation_step.addLogWithException(why) - yield self.master.data.updates.setStepStateString(self.preparation_step.stepid, + yield self._preparation_step.addLogWithException(why) + yield self.master.data.updates.setStepStateString(self._preparation_step.stepid, "error while " + state_string) - yield self.master.data.updates.finishStep(self.preparation_step.stepid, + yield self.master.data.updates.finishStep(self._preparation_step.stepid, EXCEPTION, False) def acquireLocks(self, res=None): diff --git a/master/buildbot/process/buildstep.py b/master/buildbot/process/buildstep.py index f950f5972e0f..d9c8510a1b75 100644 --- a/master/buildbot/process/buildstep.py +++ b/master/buildbot/process/buildstep.py @@ -502,13 +502,14 @@ def addStep(self): self.stepid, self.number, self.name = yield self.master.data.updates.addStep( buildid=self.build.buildid, name=util.bytes2unicode(self.name)) - yield self.master.data.updates.startStep(self.stepid) @defer.inlineCallbacks def startStep(self, remote): self.remote = remote yield self.addStep() + started_at = int(self.master.reactor.seconds()) + yield self.master.data.updates.startStep(self.stepid, started_at=started_at) try: yield self._render_renderables() @@ -525,12 +526,30 @@ def startStep(self, remote): yield self._setup_locks() # set up locks - yield self.acquireLocks() - - if self.stopped: - raise BuildStepCancelled - - yield self.master.data.updates.set_step_locks_acquired_at(self.stepid) + if self._locks_to_acquire: + yield self.acquireLocks() + + if self.stopped: + raise BuildStepCancelled + + locks_acquired_at = int(self.master.reactor.seconds()) + yield defer.DeferredList( + [ + self.master.data.updates.set_step_locks_acquired_at( + self.stepid, locks_acquired_at=locks_acquired_at + ), + self.master.data.updates.add_build_locks_duration( + self.build.buildid, duration_s=locks_acquired_at - started_at + ) + ] + ) + else: + yield self.master.data.updates.set_step_locks_acquired_at( + self.stepid, locks_acquired_at=started_at + ) + + if self.stopped: + raise BuildStepCancelled yield self.addTestResultSets() try: diff --git a/master/buildbot/spec/types/build.raml b/master/buildbot/spec/types/build.raml index ef37b7bb6ede..803f34eabdee 100644 --- a/master/buildbot/spec/types/build.raml +++ b/master/buildbot/spec/types/build.raml @@ -82,6 +82,9 @@ properties: complete_at?: description: time at which this build was complete, or None if it's still running type: date + locks_duration_s: + description: time spent acquiring locks so far, not including any running steps + type: integer properties?: description: a dictionary of properties attached to build. type: sourcedproperties diff --git a/master/buildbot/spec/types/step.raml b/master/buildbot/spec/types/step.raml index 1d7263bb1e2d..8b67fdcc4afe 100644 --- a/master/buildbot/spec/types/step.raml +++ b/master/buildbot/spec/types/step.raml @@ -23,15 +23,21 @@ description: | Note that the name may be different from the requested name if that name was already in use. The state strings for the new step will be set to 'pending'. - .. py:method:: startStep(stepid) + .. py:method:: startStep(stepid, started_at=None, locks_acquired=False) :param integer stepid: the step to modify + :param integer started_at: optionally specify the startup time value. If not + specified, then `int(self.master.reactor.seconds())` will be used. + :param boolean locks_acquired: `True` if all locks are already acquired at the step + startup. This effectively calls `set_step_locks_acquired_at(stepid, locks_acquired_at=started_at)` Start the step. - .. py:method:: set_step_locks_acquired_at(stepid) + .. py:method:: set_step_locks_acquired_at(stepid, locks_acquired_at=None) :param integer stepid: the step to modify + :param integer locks_acquired_at: optionally specify the timestamp value. If not + specified, then `int(self.master.reactor.seconds())` will be used. Update step locks_acquired_at timestamp. diff --git a/master/buildbot/test/fake/fakedata.py b/master/buildbot/test/fake/fakedata.py index 9f52229479cc..90cc238a6726 100644 --- a/master/buildbot/test/fake/fakedata.py +++ b/master/buildbot/test/fake/fakedata.py @@ -314,6 +314,13 @@ def setBuildStateString(self, buildid, state_string): validation.StringValidator()) return defer.succeed(None) + def add_build_locks_duration(self, buildid, duration_s): + validation.verifyType(self.testcase, 'buildid', buildid, + validation.IntValidator()) + validation.verifyType(self.testcase, 'duration_s', duration_s, + validation.IntValidator()) + return defer.succeed(None) + def finishBuild(self, buildid, results): validation.verifyType(self.testcase, 'buildid', buildid, validation.IntValidator()) @@ -357,14 +364,32 @@ def addStepURL(self, stepid, name, url): self.stepUrls.setdefault(stepid, []).append((name, url)) return defer.succeed(None) - def startStep(self, stepid): + def startStep(self, stepid, started_at=None, locks_acquired=False): validation.verifyType(self.testcase, 'stepid', stepid, validation.IntValidator()) + validation.verifyType( + self.testcase, + "started_at", + started_at, + validation.NoneOk(validation.IntValidator()) + ) + validation.verifyType( + self.testcase, + "locks_acquired", + locks_acquired, + validation.BooleanValidator() + ) return defer.succeed(None) - def set_step_locks_acquired_at(self, stepid): + def set_step_locks_acquired_at(self, stepid, locks_acquired_at=None): validation.verifyType(self.testcase, 'stepid', stepid, validation.IntValidator()) + validation.verifyType( + self.testcase, + "locks_acquired_at", + locks_acquired_at, + validation.NoneOk(validation.IntValidator()) + ) return defer.succeed(None) def setStepStateString(self, stepid, state_string): diff --git a/master/buildbot/test/fakedb/builds.py b/master/buildbot/test/fakedb/builds.py index b91db13d5c99..8024672eea24 100644 --- a/master/buildbot/test/fakedb/builds.py +++ b/master/buildbot/test/fakedb/builds.py @@ -32,9 +32,19 @@ class Build(Row): def __init__(self, id=None, number=29, buildrequestid=None, builderid=None, workerid=-1, masterid=None, started_at=1304262222, complete_at=None, state_string="test", results=None): - super().__init__(id=id, number=number, buildrequestid=buildrequestid, builderid=builderid, - workerid=workerid, masterid=masterid, started_at=started_at, - complete_at=complete_at, state_string=state_string, results=results) + super().__init__( + id=id, + number=number, + buildrequestid=buildrequestid, + builderid=builderid, + workerid=workerid, + masterid=masterid, + started_at=started_at, + complete_at=complete_at, + locks_duration_s=0, + state_string=state_string, + results=results + ) class BuildProperty(Row): @@ -82,6 +92,7 @@ def _row2dict(self, row): "workerid": row['workerid'], "started_at": epoch2datetime(row['started_at']), "complete_at": epoch2datetime(row['complete_at']), + "locks_duration_s": row["locks_duration_s"], "state_string": row['state_string'], "results": row['results'] } @@ -131,6 +142,7 @@ def addBuild(self, builderid, buildrequestid, workerid, masterid, "masterid": masterid, "state_string": state_string, "started_at": self.reactor.seconds(), + "locks_duration_s": 0, "complete_at": None, "results": None } @@ -197,6 +209,7 @@ def getBuildsForChange(self, changeid): result['masterid'] = build['masterid'] result['started_at'] = epoch2datetime(1304262222) result['complete_at'] = build['complete_at'] + result["locks_duration_s"] = build["locks_duration_s"] result['state_string'] = build['state_string'] result['results'] = build['results'] @@ -204,3 +217,9 @@ def getBuildsForChange(self, changeid): del result['buildsetid'] return results + + def add_build_locks_duration(self, buildid, duration_s): + b = self.builds.get(buildid) + if b: + b["locks_duration_s"] += duration_s + return defer.succeed(None) diff --git a/master/buildbot/test/fakedb/steps.py b/master/buildbot/test/fakedb/steps.py index d4655736b11e..7df69eac4166 100644 --- a/master/buildbot/test/fakedb/steps.py +++ b/master/buildbot/test/fakedb/steps.py @@ -137,16 +137,18 @@ def addStep(self, buildid, name, state_string): return defer.succeed((id, number, name)) - def startStep(self, stepid): + def startStep(self, stepid, started_at, locks_acquired): b = self.steps.get(stepid) if b: - b['started_at'] = self.reactor.seconds() + b['started_at'] = started_at + if locks_acquired: + b["locks_acquired_at"] = started_at return defer.succeed(None) - def set_step_locks_acquired_at(self, stepid): + def set_step_locks_acquired_at(self, stepid, locks_acquired_at): b = self.steps.get(stepid) if b: - b['locks_acquired_at'] = self.reactor.seconds() + b['locks_acquired_at'] = locks_acquired_at return defer.succeed(None) def setStepStateString(self, stepid, state_string): diff --git a/master/buildbot/test/unit/data/test_builds.py b/master/buildbot/test/unit/data/test_builds.py index bddec093455a..43e06b2cdeec 100644 --- a/master/buildbot/test/unit/data/test_builds.py +++ b/master/buildbot/test/unit/data/test_builds.py @@ -297,6 +297,7 @@ class Build(interfaces.InterfaceTests, TestReactorMixin, unittest.TestCase): 'workerid': 20, 'complete': False, 'complete_at': None, + "locks_duration_s": 0, 'masterid': 824, 'number': 1, 'results': None, @@ -311,13 +312,20 @@ def setUp(self): self.rtype = builds.Build(self.master) @defer.inlineCallbacks - def do_test_callthrough(self, dbMethodName, method, exp_args=None, - exp_kwargs=None, *args, **kwargs): - rv = (1, 2) - m = mock.Mock(return_value=defer.succeed(rv)) + def do_test_callthrough( + self, + dbMethodName, + method, + exp_retval=(1, 2), + exp_args=None, + exp_kwargs=None, + *args, + **kwargs + ): + m = mock.Mock(return_value=defer.succeed(exp_retval)) setattr(self.master.db.builds, dbMethodName, m) res = yield method(*args, **kwargs) - self.assertIdentical(res, rv) + self.assertIdentical(res, exp_retval) m.assert_called_with(*(exp_args or args), **(exp_kwargs or kwargs)) @defer.inlineCallbacks @@ -376,6 +384,22 @@ def test_setBuildStateString(self): self.rtype.setBuildStateString, buildid=10, state_string='a b') + def test_signature_add_build_locks_duration(self): + @self.assertArgSpecMatches( + self.master.data.updates.add_build_locks_duration, + self.rtype.add_build_locks_duration) + def add_build_locks_duration(self, buildid, duration_s): + pass + + def test_add_build_locks_duration(self): + return self.do_test_callthrough( + "add_build_locks_duration", + self.rtype.add_build_locks_duration, + exp_retval=None, + buildid=10, + duration_s=5 + ) + def test_signature_finishBuild(self): @self.assertArgSpecMatches( self.master.data.updates.finishBuild, # fake diff --git a/master/buildbot/test/unit/data/test_steps.py b/master/buildbot/test/unit/data/test_steps.py index 4a74f8bc9bd6..9b1d9e5f1b06 100644 --- a/master/buildbot/test/unit/data/test_steps.py +++ b/master/buildbot/test/unit/data/test_steps.py @@ -237,9 +237,9 @@ def test_fake_addStep(self): def test_signature_startStep(self): @self.assertArgSpecMatches( - self.master.data.updates.startStep, # fake - self.rtype.startStep) # real - def addStep(self, stepid): + self.master.data.updates.startStep, + self.rtype.startStep) + def addStep(self, stepid, started_at=None, locks_acquired=False): pass @defer.inlineCallbacks @@ -282,6 +282,50 @@ def test_startStep(self): 'hidden': False, }) + @defer.inlineCallbacks + def test_startStep_no_locks(self): + self.reactor.advance(TIME1) + yield self.master.db.steps.addStep(buildid=10, name="ten", state_string="pending") + yield self.rtype.startStep(stepid=100, locks_acquired=True) + + msgBody = { + "buildid": 10, + "complete": False, + "complete_at": None, + "name": "ten", + "number": 0, + "results": None, + "started_at": epoch2datetime(TIME1), + "locks_acquired_at": epoch2datetime(TIME1), + "state_string": "pending", + "stepid": 100, + "urls": [], + "hidden": False, + } + self.master.mq.assertProductions( + [ + (("builds", "10", "steps", str(100), "started"), msgBody), + (("steps", str(100), "started"), msgBody), + ] + ) + step = yield self.master.db.steps.getStep(100) + self.assertEqual( + step, + { + "buildid": 10, + "complete_at": None, + "id": 100, + "name": "ten", + "number": 0, + "results": None, + "started_at": epoch2datetime(TIME1), + "locks_acquired_at": epoch2datetime(TIME1), + "state_string": "pending", + "urls": [], + "hidden": False, + } + ) + @defer.inlineCallbacks def test_startStep_acquire_locks(self): self.reactor.advance(TIME1) diff --git a/master/buildbot/test/unit/db/test_builds.py b/master/buildbot/test/unit/db/test_builds.py index bdc5df99eaa9..aeee5808982e 100644 --- a/master/buildbot/test/unit/db/test_builds.py +++ b/master/buildbot/test/unit/db/test_builds.py @@ -61,22 +61,45 @@ class Tests(interfaces.InterfaceTests): ] threeBdicts = { - 50: {'id': 50, 'buildrequestid': 42, 'builderid': 77, - 'masterid': 88, 'number': 5, 'workerid': 13, - 'started_at': epoch2datetime(TIME1), - 'complete_at': None, 'state_string': 'build 5', - 'results': None}, - 51: {'id': 51, 'buildrequestid': 41, 'builderid': 88, - 'masterid': 88, 'number': 6, 'workerid': 13, - 'started_at': epoch2datetime(TIME2), - 'complete_at': None, 'state_string': 'build 6', - 'results': None}, - 52: {'id': 52, 'buildrequestid': 42, 'builderid': 77, - 'masterid': 88, 'number': 7, 'workerid': 12, - 'started_at': epoch2datetime(TIME3), - 'complete_at': epoch2datetime(TIME4), - 'state_string': 'build 7', - 'results': 5}, + 50: { + "id": 50, + "buildrequestid": 42, + "builderid": 77, + "masterid": 88, + "number": 5, + "workerid": 13, + "started_at": epoch2datetime(TIME1), + "complete_at": None, + "locks_duration_s": 0, + "state_string": "build 5", + "results": None, + }, + 51: { + "id": 51, + "buildrequestid": 41, + "builderid": 88, + "masterid": 88, + "number": 6, + "workerid": 13, + "started_at": epoch2datetime(TIME2), + "complete_at": None, + "locks_duration_s": 0, + "state_string": "build 6", + "results": None, + }, + 52: { + "id": 52, + "buildrequestid": 42, + "builderid": 77, + "masterid": 88, + "number": 7, + "workerid": 12, + "started_at": epoch2datetime(TIME3), + "complete_at": epoch2datetime(TIME4), + "locks_duration_s": 0, + "state_string": "build 7", + "results": 5, + }, } # signature tests @@ -108,6 +131,11 @@ def test_signature_setBuildStateString(self): def setBuildStateString(self, buildid, state_string): pass + def test_signature_add_build_locks_duration(self): + @self.assertArgSpecMatches(self.db.builds.add_build_locks_duration) + def setBuildStateString(self, buildid, duration_s): + pass + def test_signature_finishBuild(self): @self.assertArgSpecMatches(self.db.builds.finishBuild) def finishBuild(self, buildid, results): @@ -130,18 +158,22 @@ def test_getBuild(self): yield self.insert_test_data(self.backgroundData + [self.threeBuilds[0]]) bdict = yield self.db.builds.getBuild(50) validation.verifyDbDict(self, 'dbbuilddict', bdict) - self.assertEqual(bdict, { - "id": 50, - "number": 5, - "buildrequestid": 42, - "masterid": 88, - "builderid": 77, - "workerid": 13, - "started_at": epoch2datetime(TIME1), - "complete_at": None, - "state_string": 'build 5', - "results": None - }) + self.assertEqual( + bdict, + { + "id": 50, + "number": 5, + "buildrequestid": 42, + "masterid": 88, + "builderid": 77, + "workerid": 13, + "started_at": epoch2datetime(TIME1), + "complete_at": None, + "locks_duration_s": 0, + "state_string": 'build 5', + "results": None + } + ) @defer.inlineCallbacks def test_getBuild_missing(self): @@ -222,17 +254,21 @@ def test_getBuildsForChange_OneCodebase(self): builderid=77, state_string="test", workerid=13, started_at=1304262222, results=1), ] - expected = [{ - 'id': 50, - 'number': 5, - 'builderid': 77, - 'buildrequestid': 19, - 'workerid': 13, - 'masterid': 88, - 'started_at': epoch2datetime(1304262222), - 'complete_at': None, - 'state_string': 'test', - 'results': 1}] + expected = [ + { + 'id': 50, + 'number': 5, + 'builderid': 77, + 'buildrequestid': 19, + 'workerid': 13, + 'masterid': 88, + 'started_at': epoch2datetime(1304262222), + 'complete_at': None, + "locks_duration_s": 0, + 'state_string': 'test', + 'results': 1 + } + ] return self.do_test_getBuildsForChange(rows, 14, expected) @@ -255,11 +291,22 @@ def test_addBuild_first(self): state_string='test test2') bdict = yield self.db.builds.getBuild(id) validation.verifyDbDict(self, 'dbbuilddict', bdict) - self.assertEqual(bdict, {'buildrequestid': 41, 'builderid': 77, - 'id': id, 'masterid': 88, 'number': number, 'workerid': 13, - 'started_at': epoch2datetime(TIME1), - 'complete_at': None, 'state_string': 'test test2', - 'results': None}) + self.assertEqual( + bdict, + { + "buildrequestid": 41, + "builderid": 77, + "id": id, + "masterid": 88, + "number": number, + "workerid": 13, + "started_at": epoch2datetime(TIME1), + "complete_at": None, + "locks_duration_s": 0, + "state_string": "test test2", + "results": None, + }, + ) @defer.inlineCallbacks def test_addBuild_existing(self): @@ -275,11 +322,22 @@ def test_addBuild_existing(self): bdict = yield self.db.builds.getBuild(id) validation.verifyDbDict(self, 'dbbuilddict', bdict) self.assertEqual(number, 11) - self.assertEqual(bdict, {'buildrequestid': 41, 'builderid': 77, - 'id': id, 'masterid': 88, 'number': number, 'workerid': 13, - 'started_at': epoch2datetime(TIME1), - 'complete_at': None, 'state_string': 'test test2', - 'results': None}) + self.assertEqual( + bdict, + { + "buildrequestid": 41, + "builderid": 77, + "id": id, + "masterid": 88, + "number": number, + "workerid": 13, + "started_at": epoch2datetime(TIME1), + "complete_at": None, + "locks_duration_s": 0, + "state_string": "test test2", + "results": None, + }, + ) @defer.inlineCallbacks def test_setBuildStateString(self): @@ -297,10 +355,34 @@ def test_setBuildStateString(self): "workerid": 13, "started_at": epoch2datetime(TIME1), "complete_at": None, + "locks_duration_s": 0, "state_string": 'test test2', "results": None }) + @defer.inlineCallbacks + def test_add_build_locks_duration(self): + yield self.insert_test_data(self.backgroundData + [self.threeBuilds[0]]) + yield self.db.builds.add_build_locks_duration(buildid=50, duration_s=12) + bdict = yield self.db.builds.getBuild(50) + validation.verifyDbDict(self, 'dbbuilddict', bdict) + self.assertEqual( + bdict, + { + "id": 50, + "number": 5, + "buildrequestid": 42, + "masterid": 88, + "builderid": 77, + "workerid": 13, + "started_at": epoch2datetime(TIME1), + "complete_at": None, + "locks_duration_s": 12, + "state_string": "build 5", + "results": None + } + ) + @defer.inlineCallbacks def test_finishBuild(self): self.reactor.advance(TIME4) @@ -317,6 +399,7 @@ def test_finishBuild(self): "workerid": 13, "started_at": epoch2datetime(TIME1), "complete_at": epoch2datetime(TIME4), + "locks_duration_s": 0, "state_string": 'build 5', "results": 7 }) @@ -393,10 +476,19 @@ def test_addBuild_existing_race(self): def raceHook(conn): if not numbers: return - conn.execute(self.db.model.builds.insert(), - {'number': numbers.pop(0), 'buildrequestid': 41, - 'masterid': 88, 'workerid': 13, 'builderid': 77, - 'started_at': TIME1, 'state_string': "hi"}) + conn.execute( + self.db.model.builds.insert(), + { + "number": numbers.pop(0), + "buildrequestid": 41, + "masterid": 88, + "workerid": 13, + "builderid": 77, + "started_at": TIME1, + "locks_duration_s": 0, + "state_string": "hi", + }, + ) id, number = yield self.db.builds.addBuild(builderid=77, buildrequestid=41, @@ -406,11 +498,22 @@ def raceHook(conn): bdict = yield self.db.builds.getBuild(id) validation.verifyDbDict(self, 'dbbuilddict', bdict) self.assertEqual(number, 8) - self.assertEqual(bdict, {'buildrequestid': 41, 'builderid': 77, - 'id': id, 'masterid': 88, 'number': number, 'workerid': 13, - 'started_at': epoch2datetime(TIME1), - 'complete_at': None, 'state_string': 'test test2', - 'results': None}) + self.assertEqual( + bdict, + { + "buildrequestid": 41, + "builderid": 77, + "id": id, + "masterid": 88, + "number": number, + "workerid": 13, + "started_at": epoch2datetime(TIME1), + "complete_at": None, + "locks_duration_s": 0, + "state_string": "test test2", + "results": None, + }, + ) @defer.inlineCallbacks def test_getBuilds_resultSpecFilter(self): diff --git a/master/buildbot/test/unit/db/test_steps.py b/master/buildbot/test/unit/db/test_steps.py index 6b8dca11a842..b0e9265d82f6 100644 --- a/master/buildbot/test/unit/db/test_steps.py +++ b/master/buildbot/test/unit/db/test_steps.py @@ -107,7 +107,7 @@ def addStep(self, buildid, name, state_string): def test_signature_startStep(self): @self.assertArgSpecMatches(self.db.steps.startStep) - def addStep(self, stepid): + def addStep(self, stepid, started_at, locks_acquired): pass def test_signature_setStepStateString(self): @@ -184,12 +184,11 @@ def test_getSteps_none(self): @defer.inlineCallbacks def test_addStep_getStep(self): - self.reactor.advance(TIME1) yield self.insert_test_data(self.backgroundData) stepid, number, name = yield self.db.steps.addStep(buildid=30, name='new', state_string='new') - yield self.db.steps.startStep(stepid=stepid) + yield self.db.steps.startStep(stepid=stepid, started_at=TIME1, locks_acquired=False) self.assertEqual((number, name), (0, 'new')) stepdict = yield self.db.steps.getStep(stepid=stepid) validation.verifyDbDict(self, 'stepdict', stepdict) @@ -207,15 +206,40 @@ def test_addStep_getStep(self): 'hidden': False}) @defer.inlineCallbacks - def test_addStep_getStep_locks_acquiced(self): - self.reactor.advance(TIME1) + def test_addStep_getStep_locks_acquired_already(self): yield self.insert_test_data(self.backgroundData) stepid, number, name = yield self.db.steps.addStep(buildid=30, name='new', state_string='new') - yield self.db.steps.startStep(stepid=stepid) - self.reactor.advance(TIME2 - TIME1) - yield self.db.steps.set_step_locks_acquired_at(stepid=stepid) + yield self.db.steps.startStep(stepid=stepid, started_at=TIME1, locks_acquired=True) + self.assertEqual((number, name), (0, 'new')) + stepdict = yield self.db.steps.getStep(stepid=stepid) + validation.verifyDbDict(self, 'stepdict', stepdict) + self.assertEqual( + stepdict, + { + "id": stepid, + "buildid": 30, + "name": "new", + "number": 0, + "started_at": epoch2datetime(TIME1), + "locks_acquired_at": epoch2datetime(TIME1), + "complete_at": None, + "results": None, + "state_string": "new", + "urls": [], + "hidden": False + } + ) + + @defer.inlineCallbacks + def test_addStep_getStep_locks_acquired_later(self): + yield self.insert_test_data(self.backgroundData) + stepid, number, name = yield self.db.steps.addStep(buildid=30, + name='new', + state_string='new') + yield self.db.steps.startStep(stepid=stepid, started_at=TIME1, locks_acquired=False) + yield self.db.steps.set_step_locks_acquired_at(stepid=stepid, locks_acquired_at=TIME2) self.assertEqual((number, name), (0, 'new')) stepdict = yield self.db.steps.getStep(stepid=stepid) validation.verifyDbDict(self, 'stepdict', stepdict) @@ -234,11 +258,10 @@ def test_addStep_getStep_locks_acquiced(self): @defer.inlineCallbacks def test_addStep_getStep_existing_step(self): - self.reactor.advance(TIME1) yield self.insert_test_data(self.backgroundData + [self.stepRows[0]]) stepid, number, name = yield self.db.steps.addStep( buildid=30, name='new', state_string='new') - yield self.db.steps.startStep(stepid=stepid) + yield self.db.steps.startStep(stepid=stepid, started_at=TIME1, locks_acquired=False) self.assertEqual((number, name), (1, 'new')) stepdict = yield self.db.steps.getStep(stepid=stepid) validation.verifyDbDict(self, 'stepdict', stepdict) @@ -247,7 +270,6 @@ def test_addStep_getStep_existing_step(self): @defer.inlineCallbacks def test_addStep_getStep_name_collisions(self): - self.reactor.advance(TIME1) yield self.insert_test_data(self.backgroundData + [ fakedb.Step(id=73, number=0, name='new', buildid=30), fakedb.Step(id=74, number=1, name='new_1', buildid=30), @@ -256,7 +278,7 @@ def test_addStep_getStep_name_collisions(self): ]) stepid, number, name = yield self.db.steps.addStep( buildid=30, name='new', state_string='new') - yield self.db.steps.startStep(stepid=stepid) + yield self.db.steps.startStep(stepid=stepid, started_at=TIME1, locks_acquired=False) self.assertEqual((number, name), (4, 'new_3')) stepdict = yield self.db.steps.getStep(stepid=stepid) validation.verifyDbDict(self, 'stepdict', stepdict) @@ -334,14 +356,13 @@ class RealTests(Tests): # the fake connector doesn't deal with this edge case @defer.inlineCallbacks def test_addStep_getStep_name_collisions_too_long(self): - self.reactor.advance(TIME1) yield self.insert_test_data(self.backgroundData + [ fakedb.Step(id=73, number=0, name='a' * 49, buildid=30), fakedb.Step(id=74, number=1, name='a' * 48 + '_1', buildid=30), ]) stepid, number, name = yield self.db.steps.addStep( buildid=30, name='a' * 49, state_string='new') - yield self.db.steps.startStep(stepid=stepid) + yield self.db.steps.startStep(stepid=stepid, started_at=TIME1, locks_acquired=False) self.assertEqual((number, name), (2, 'a' * 48 + '_2')) stepdict = yield self.db.steps.getStep(stepid=stepid) validation.verifyDbDict(self, 'stepdict', stepdict) @@ -350,7 +371,6 @@ def test_addStep_getStep_name_collisions_too_long(self): @defer.inlineCallbacks def test_addStep_getStep_name_collisions_too_long_extra_digits(self): - self.reactor.advance(TIME1) yield self.insert_test_data(self.backgroundData + [ fakedb.Step(id=73, number=0, name='a' * 50, buildid=30), ] + [fakedb.Step(id=73 + i, number=i, name='a' * 48 + (f'_{i}'), buildid=30) @@ -360,7 +380,7 @@ def test_addStep_getStep_name_collisions_too_long_extra_digits(self): ]) stepid, number, name = yield self.db.steps.addStep( buildid=30, name='a' * 50, state_string='new') - yield self.db.steps.startStep(stepid=stepid) + yield self.db.steps.startStep(stepid=stepid, started_at=TIME1, locks_acquired=False) self.assertEqual((number, name), (100, 'a' * 46 + '_100')) stepdict = yield self.db.steps.getStep(stepid=stepid) validation.verifyDbDict(self, 'stepdict', stepdict) diff --git a/master/buildbot/test/unit/db_migrate/test_versions_066_add_build_locks_duration_s.py b/master/buildbot/test/unit/db_migrate/test_versions_066_add_build_locks_duration_s.py new file mode 100644 index 000000000000..3b884b0cac78 --- /dev/null +++ b/master/buildbot/test/unit/db_migrate/test_versions_066_add_build_locks_duration_s.py @@ -0,0 +1,94 @@ +# This file is part of Buildbot. Buildbot is free software: you can +# redistribute it and/or modify it under the terms of the GNU General Public +# License as published by the Free Software Foundation, version 2. +# +# This program is distributed in the hope that it will be useful, but WITHOUT +# ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or FITNESS +# FOR A PARTICULAR PURPOSE. See the GNU General Public License for more +# details. +# +# You should have received a copy of the GNU General Public License along with +# this program; if not, write to the Free Software Foundation, Inc., 51 +# Franklin Street, Fifth Floor, Boston, MA 02110-1301 USA. +# +# Copyright Buildbot Team Members + +import sqlalchemy as sa + +from twisted.trial import unittest + +from buildbot.test.util import migration +from buildbot.util import sautils + + +class Migration(migration.MigrateTestMixin, unittest.TestCase): + + def setUp(self): + return self.setUpMigrateTest() + + def tearDown(self): + return self.tearDownMigrateTest() + + def create_tables_thd(self, conn): + metadata = sa.MetaData() + metadata.bind = conn + + # builderid, buildrequestid, workerid, masterid foreign keys are removed for the + # purposes of the test + builds = sautils.Table( + 'builds', metadata, + sa.Column('id', sa.Integer, primary_key=True), + sa.Column('number', sa.Integer, nullable=False), + sa.Column('started_at', sa.Integer, nullable=False), + sa.Column('complete_at', sa.Integer), + sa.Column('state_string', sa.Text, nullable=False), + sa.Column('results', sa.Integer), + ) + builds.create() + + conn.execute( + builds.insert(), + [ + { + "id": 4, + "number": 5, + "started_at": 1695730972, + "complete_at": 1695730975, + "state_string": "test build", + "results": 0, + } + ] + ) + + def test_update(self): + def setup_thd(conn): + self.create_tables_thd(conn) + + def verify_thd(conn): + metadata = sa.MetaData() + metadata.bind = conn + + builds = sautils.Table('builds', metadata, autoload=True) + self.assertIsInstance(builds.c.locks_duration_s.type, sa.Integer) + + conn.execute( + builds.insert(), + [ + { + "id": 5, + "number": 6, + "started_at": 1695730982, + "complete_at": 1695730985, + "locks_duration_s": 12, + "state_string": "test build", + "results": 0, + } + ] + ) + + durations = [] + for row in conn.execute(sa.select([builds.c.locks_duration_s])): + durations.append(row.locks_duration_s) + self.assertEqual(durations, [0, 12]) + + return self.do_test_migration('065', '066', setup_thd, verify_thd) diff --git a/master/buildbot/test/unit/process/test_buildstep.py b/master/buildbot/test/unit/process/test_buildstep.py index e8255c48d909..7d139edafeda 100644 --- a/master/buildbot/test/unit/process/test_buildstep.py +++ b/master/buildbot/test/unit/process/test_buildstep.py @@ -939,6 +939,7 @@ def testcheckWorkerHasCommandTooOld(self): def testRunRaisesException(self): step = create_step_from_step_or_factory(NewStyleStep()) step.master = mock.Mock() + step.master.reactor = self.reactor step.build = mock.Mock() step.build._locks_to_acquire = [] step.build.builder.botmaster.getLockFromLockAccesses = mock.Mock(return_value=[]) diff --git a/master/buildbot/test/unit/reporters/test_utils.py b/master/buildbot/test/unit/reporters/test_utils.py index f1eceae14af5..f477d4caeee4 100644 --- a/master/buildbot/test/unit/reporters/test_utils.py +++ b/master/buildbot/test/unit/reporters/test_utils.py @@ -201,6 +201,7 @@ def test_get_details_for_buildset_all(self): }, 'complete': False, 'complete_at': None, + "locks_duration_s": 0, 'masterid': 92, 'number': 2, 'prev_build': { @@ -209,6 +210,7 @@ def test_get_details_for_buildset_all(self): 'buildrequestid': 9, 'complete': False, 'complete_at': None, + "locks_duration_s": 0, 'masterid': 92, 'number': 0, 'properties': {}, @@ -308,6 +310,7 @@ def test_get_details_for_buildset_all(self): }, 'complete': False, 'complete_at': None, + "locks_duration_s": 0, 'masterid': 92, 'number': 3, 'prev_build': { @@ -316,6 +319,7 @@ def test_get_details_for_buildset_all(self): 'buildrequestid': 11, 'complete': False, 'complete_at': None, + "locks_duration_s": 0, 'masterid': 92, 'number': 2, 'properties': {}, diff --git a/master/buildbot/test/util/misc.py b/master/buildbot/test/util/misc.py index cff7375507ac..78147a2c79d2 100644 --- a/master/buildbot/test/util/misc.py +++ b/master/buildbot/test/util/misc.py @@ -148,11 +148,26 @@ class BuildDictLookAlike: def __init__(self, extra_keys=None, expected_missing_keys=None, **assertions): self.keys = [ - 'builder', 'builderid', 'buildid', 'buildrequest', 'buildrequestid', - 'buildset', 'complete', 'complete_at', 'masterid', 'number', - 'parentbuild', 'parentbuilder', 'properties', 'results', - 'started_at', 'state_string', 'url', 'workerid' - ] + "builder", + "builderid", + "buildid", + "buildrequest", + "buildrequestid", + "buildset", + "complete", + "complete_at", + "locks_duration_s", + "masterid", + "number", + "parentbuild", + "parentbuilder", + "properties", + "results", + "started_at", + "state_string", + "url", + "workerid", + ] if extra_keys: self.keys.extend(extra_keys) if expected_missing_keys is not None: diff --git a/master/buildbot/test/util/validation.py b/master/buildbot/test/util/validation.py index b21e0da01093..44c46cd70aba 100644 --- a/master/buildbot/test/util/validation.py +++ b/master/buildbot/test/util/validation.py @@ -586,6 +586,7 @@ def validate(self, name, arg_object): masterid=IntValidator(), started_at=DateTimeValidator(), complete_at=NoneOk(DateTimeValidator()), + locks_duration_s=IntValidator(), state_string=StringValidator(), results=NoneOk(IntValidator()), ) diff --git a/master/docs/developer/database/builds.rst b/master/docs/developer/database/builds.rst index a3d6cd692b80..fb3617f9d05b 100644 --- a/master/docs/developer/database/builds.rst +++ b/master/docs/developer/database/builds.rst @@ -25,6 +25,8 @@ Builds connector * ``masterid`` (the ID of the master on which this build was performed) * ``started_at`` (datetime at which this build began) * ``complete_at`` (datetime at which this build finished, or None if it is ongoing) + * ``locks_duration_s`` (the amount of time spent acquiring locks so far, not including + any running steps) * ``state_string`` (short string describing the build's state) * ``results`` (results of this build; see :ref:`Build-Result-Codes`) @@ -86,6 +88,14 @@ Builds connector Update the state strings for the given build. + .. py:method:: add_build_locks_duration(buildid, duration_s): + + :param integer buildid: build id + :param integer duration_s: time duration to add + :returns: Deferred + + Adds the given duration to the ``locks_duration_s`` field of the build. + .. py:method:: finishBuild(buildid, results) :param integer buildid: build id diff --git a/newsfragments/build-locks-duration.feature b/newsfragments/build-locks-duration.feature new file mode 100644 index 000000000000..38597f5cbeac --- /dev/null +++ b/newsfragments/build-locks-duration.feature @@ -0,0 +1 @@ +Buildbot now tracks total time that has been spent waiting for locks in a build. diff --git a/newsfragments/build-worker-preparation-step-split-locks.feature b/newsfragments/build-worker-preparation-step-split-locks.feature new file mode 100644 index 000000000000..1db7ca171461 --- /dev/null +++ b/newsfragments/build-worker-preparation-step-split-locks.feature @@ -0,0 +1,2 @@ +The ``worker_preparation`` dummy step that tracks various build startup overhead has been split +into two steps to track worker startup and locks wait times separately. diff --git a/newsfragments/data-set-step-locks-acquired-at.change b/newsfragments/data-set-step-locks-acquired-at.change new file mode 100644 index 000000000000..fef3c7da90c5 --- /dev/null +++ b/newsfragments/data-set-step-locks-acquired-at.change @@ -0,0 +1 @@ +Added optional ``locks_acquired_at`` argument to ``master.data.updates.set_step_locks_acquired_at()``. diff --git a/newsfragments/data-start-step-args.feature b/newsfragments/data-start-step-args.feature new file mode 100644 index 000000000000..f69c79644059 --- /dev/null +++ b/newsfragments/data-start-step-args.feature @@ -0,0 +1 @@ +Added optional ``started_at`` and ``locks_acquired`` arguments to ``master.data.updates.startStep()``. diff --git a/www/react-base/src/components/BuildSummary/BuildSummary.tsx b/www/react-base/src/components/BuildSummary/BuildSummary.tsx index d7422bc513b4..63a7933d1eb6 100644 --- a/www/react-base/src/components/BuildSummary/BuildSummary.tsx +++ b/www/react-base/src/components/BuildSummary/BuildSummary.tsx @@ -26,7 +26,8 @@ import { BadgeStatus, ConfigContext, analyzeStepUrls, - durationFormat, + buildDurationFormatWithLocks, + stepDurationFormatWithLocks, useCurrentTime, useStateWithParentTrackingWithDefaultIfNotSet, useStepUrlAnalyzer @@ -103,32 +104,6 @@ type BuildSummaryStepLineProps = { parentFullDisplay: boolean } -function getTimeTextForStep(step: Step, now: number) { - const lockDuration = step.locks_acquired_at !== null - ? step.locks_acquired_at - step.started_at! - : 0; - - if (step.complete) { - const stepDurationText = durationFormat(step.complete_at! - step.started_at!); - - if (lockDuration > 1) { - // Since lock delay includes general step setup overhead, then sometimes the started_at and locks_acquired_at - // may fall into different seconds. However, it's unlikely that step setup would take more than one second. - return `${stepDurationText} (${durationFormat(lockDuration)} spent waiting for locks)` - } - return stepDurationText; - } - - const ongoingStepDurationText = durationFormat(now - step.started_at!); - if (lockDuration > 1) { - // Since lock delay includes general step setup overhead, then sometimes the started_at and locks_acquired_at - // may fall into different seconds. However, it's unlikely that step setup would take more than one second. - return `${ongoingStepDurationText} (${durationFormat(lockDuration)} spent waiting for locks)` - } - - return ongoingStepDurationText; -} - const BuildSummaryStepLine = observer(({build, step, logs, parentFullDisplay}: BuildSummaryStepLineProps) => { const config = useContext(ConfigContext); const now = useCurrentTime(); @@ -149,7 +124,7 @@ const BuildSummaryStepLine = observer(({build, step, logs, parentFullDisplay}: B return ( - {getTimeTextForStep(step, now)} + {stepDurationFormatWithLocks(step, now)}   {step.state_string} @@ -303,6 +278,8 @@ export const BuildSummary = observer(({build, parentBuild, parentRelationship, parentFullDisplay={fullDisplay}/> )); + const durationString = buildDurationFormatWithLocks(build, now); + return ( @@ -324,11 +301,7 @@ export const BuildSummary = observer(({build, parentBuild, parentRelationship, } {reason !== null ? | {reason} : <>}
- { - build.complete - ? {durationFormat(build.complete_at! - build.started_at)}  - : {durationFormat(now - build.started_at)}  - } + {durationString}  {build.state_string}  {results2text(build)} {renderParentBuildLink()} diff --git a/www/react-base/src/components/BuildsTable/BuildsTable.tsx b/www/react-base/src/components/BuildsTable/BuildsTable.tsx index f2a203545032..53fc691d9cd1 100644 --- a/www/react-base/src/components/BuildsTable/BuildsTable.tsx +++ b/www/react-base/src/components/BuildsTable/BuildsTable.tsx @@ -27,8 +27,8 @@ import { } from "buildbot-data-js"; import { BuildLinkWithSummaryTooltip, + buildDurationFormatWithLocks, dateFormat, - durationFormat, durationFromNowFormat, useCurrentTime } from "buildbot-ui"; @@ -51,12 +51,9 @@ export const BuildsTable = observer(({builds, builders}: BuildsTableProps) => { ? <> : {builder === null ? "" : builder.name} + const durationString = buildDurationFormatWithLocks(build, now); const buildCompleteInfoElement = build.complete - ? ( - - {durationFormat(build.complete_at! - build.started_at)} - - ) + ? {durationString} : <>; return ( diff --git a/www/react-data-module/src/data/classes/Build.ts b/www/react-data-module/src/data/classes/Build.ts index 46be865a52be..7da5543d5ea4 100644 --- a/www/react-data-module/src/data/classes/Build.ts +++ b/www/react-data-module/src/data/classes/Build.ts @@ -23,6 +23,7 @@ export class Build extends BaseClass { @observable started_at!: number; @observable complete_at!: number|null; @observable complete!: boolean; + @observable locks_duration_s!: number; @observable state_string!: string; @observable results!: number|null; @observable properties!: {[key: string]: any}; // for subscription to properties use getProperties() @@ -43,6 +44,7 @@ export class Build extends BaseClass { this.started_at = object.started_at; this.complete_at = object.complete_at; this.complete = object.complete; + this.locks_duration_s = object.locks_duration_s; this.results = object.results; this.state_string = object.state_string; this.properties = object.properties ?? {}; @@ -59,6 +61,7 @@ export class Build extends BaseClass { started_at: this.started_at, complete_at: this.complete_at, complete: this.complete, + locks_duration_s: this.locks_duration_s, state_string: this.state_string, results: this.results, properties: this.properties diff --git a/www/react-ui/src/components/BuildSummaryTooltip/BuildSummaryTooltip.tsx b/www/react-ui/src/components/BuildSummaryTooltip/BuildSummaryTooltip.tsx index e637df39fff3..fbffa30f8d3c 100644 --- a/www/react-ui/src/components/BuildSummaryTooltip/BuildSummaryTooltip.tsx +++ b/www/react-ui/src/components/BuildSummaryTooltip/BuildSummaryTooltip.tsx @@ -29,7 +29,8 @@ import { results2text } from "buildbot-data-js"; import {ConfigContext} from "../../contexts/Config"; -import {durationFormat, useCurrentTime} from "../../util/Moment"; +import {buildDurationFormatWithLocks, stepDurationFormatWithLocks} from "../../util/DataUtils"; +import {useCurrentTime} from "../../util/Moment"; import {analyzeStepUrls, useStepUrlAnalyzer} from "../../util/StepUrls"; import {BadgeRound} from "../BadgeRound/BadgeRound"; import {BadgeStatus} from "../BadgeStatus/BadgeStatus"; @@ -91,11 +92,7 @@ export const BuildSummaryTooltip = observer(({build}: BuildSummaryTooltipProps) headerElements.push((
- { - build.complete - ? {durationFormat(build.complete_at! - build.started_at)} - : {durationFormat(now - build.started_at)} - } + { buildDurationFormatWithLocks(build, now) }   { limitStringLength(build.state_string, 80) }   @@ -128,11 +125,7 @@ export const BuildSummaryTooltip = observer(({build}: BuildSummaryTooltipProps) if (step.started_at !== null) { stepInfoWhenStarted = ( - { - step.complete - ? {durationFormat(step.complete_at! - step.started_at)} - : {durationFormat(now - step.started_at)} - } + { stepDurationFormatWithLocks(step, now) }   {limitStringLength(step.state_string, 40)} diff --git a/www/react-ui/src/util/DataUtils.ts b/www/react-ui/src/util/DataUtils.ts index 0e36c90be635..21ace19631ec 100644 --- a/www/react-ui/src/util/DataUtils.ts +++ b/www/react-ui/src/util/DataUtils.ts @@ -15,7 +15,8 @@ Copyright Buildbot Team Members */ -import {Builder, DataCollection, Master} from "../../../react-data-module"; +import {Build, Builder, DataCollection, Master, Step} from "buildbot-data-js"; +import {durationFormat} from "./Moment"; export function hasActiveMaster(builder: Builder, masters: DataCollection) { if ((builder.masterids == null)) { @@ -33,3 +34,42 @@ export function hasActiveMaster(builder: Builder, masters: DataCollection 0) { + res += ` (locks: ${durationFormat(build.locks_duration_s!)})`; + } + return res; +} + +export function stepDurationFormatWithLocks(step: Step, now: number) { + const lockDuration = step.locks_acquired_at !== null + ? step.locks_acquired_at - step.started_at! + : 0; + + if (step.complete) { + const stepDurationText = durationFormat(step.complete_at! - step.started_at!); + + if (lockDuration > 1) { + // Since lock delay includes general step setup overhead, then sometimes the started_at and + // locks_acquired_at may fall into different seconds. However, it's unlikely that step setup + // would take more than one second. + return `${stepDurationText} (locks: ${durationFormat(lockDuration)})` + } + return stepDurationText; + } + + const ongoingStepDurationText = durationFormat(now - step.started_at!); + if (lockDuration > 1) { + // Since lock delay includes general step setup overhead, then sometimes the started_at and + // locks_acquired_at may fall into different seconds. However, it's unlikely that step setup + // would take more than one second. + return `${ongoingStepDurationText} (locks: ${durationFormat(lockDuration)})` + } + + return ongoingStepDurationText; +}