From c6f4cb21a3ce29e1b012f91b2320280b0aa92695 Mon Sep 17 00:00:00 2001 From: Simon Westphahl Date: Wed, 17 Jul 2019 09:30:19 +0200 Subject: [PATCH] Record and report time for trigger events Sometimes, e.g. during reconfiguration, it can take quite some time between the trigger event and when a change is enqueued. This change allows tracking the time it takes from receiving the event until it is processed by the scheduler. Change-Id: I347acf56bc8d7671d96f6be444c71902563684be --- doc/source/admin/drivers/mqtt.rst | 2 ++ tests/unit/test_connection.py | 1 + zuul/driver/gerrit/gerritconnection.py | 1 + zuul/driver/git/gitconnection.py | 1 + zuul/driver/github/githubconnection.py | 1 + zuul/driver/mqtt/mqttreporter.py | 1 + zuul/driver/pagure/pagureconnection.py | 1 + zuul/driver/timer/__init__.py | 2 ++ zuul/driver/zuul/__init__.py | 2 ++ zuul/model.py | 1 + zuul/rpclistener.py | 2 ++ 11 files changed, 15 insertions(+) diff --git a/doc/source/admin/drivers/mqtt.rst b/doc/source/admin/drivers/mqtt.rst index 7a821a6ea9..afe4062d86 100644 --- a/doc/source/admin/drivers/mqtt.rst +++ b/doc/source/admin/drivers/mqtt.rst @@ -115,6 +115,7 @@ Here is an example of a start message: 'branch': 'master', 'change_url': 'https://gerrit.example.com/r/3', 'message': 'Starting check jobs.', + 'trigger_time': '1524801056.2545864', 'enqueue_time': '1524801093.5689457', 'change': '3', 'patchset': '1', @@ -142,6 +143,7 @@ Here is an example of a success message: 'branch': 'master', 'change_url': 'https://gerrit.example.com/r/3', 'message': 'Build succeeded.', + 'trigger_time': '1524801056.2545864', 'enqueue_time': '1524801093.5689457', 'change': '3', 'patchset': '1', diff --git a/tests/unit/test_connection.py b/tests/unit/test_connection.py index 493e90d38b..09c4795651 100644 --- a/tests/unit/test_connection.py +++ b/tests/unit/test_connection.py @@ -499,6 +499,7 @@ class TestMQTTConnection(ZuulTestCase): self.assertIn('execute_time', test_job) self.assertIn('timestamp', mqtt_payload) self.assertIn('enqueue_time', mqtt_payload) + self.assertIn('trigger_time', mqtt_payload) self.assertEquals(dependent_test_job['dependencies'], ['test']) def test_mqtt_invalid_topic(self): diff --git a/zuul/driver/gerrit/gerritconnection.py b/zuul/driver/gerrit/gerritconnection.py index 37b774ae3a..1c41730054 100644 --- a/zuul/driver/gerrit/gerritconnection.py +++ b/zuul/driver/gerrit/gerritconnection.py @@ -72,6 +72,7 @@ class GerritEventConnector(threading.Thread): now = time.time() time.sleep(max((ts + self.delay) - now, 0.0)) event = GerritTriggerEvent() + event.timestamp = ts # Gerrit events don't have an event id that could be used to globally # identify this event in the system so we have to generate one. diff --git a/zuul/driver/git/gitconnection.py b/zuul/driver/git/gitconnection.py index fcabfc48d7..2aa9efe628 100644 --- a/zuul/driver/git/gitconnection.py +++ b/zuul/driver/git/gitconnection.py @@ -80,6 +80,7 @@ class GitWatcher(threading.Thread): for pevent in partial_events: event = GitTriggerEvent() event.type = 'ref-updated' + event.timestamp = time.time() event.project_hostname = self.git_connection.canonical_hostname event.project_name = project for attr in ('ref', 'oldrev', 'newrev', 'branch_created', diff --git a/zuul/driver/github/githubconnection.py b/zuul/driver/github/githubconnection.py index 27efe83f63..ac03666014 100644 --- a/zuul/driver/github/githubconnection.py +++ b/zuul/driver/github/githubconnection.py @@ -386,6 +386,7 @@ class GithubEventProcessor(object): with self.connection.get_request_lock(installation_id): event.delivery = self.delivery event.zuul_event_id = self.delivery + event.timestamp = self.ts project = self.connection.source.getProject(event.project_name) if event.change_number: self.connection._getChange(project, diff --git a/zuul/driver/mqtt/mqttreporter.py b/zuul/driver/mqtt/mqttreporter.py index e042274da7..f5ab6e4a5e 100644 --- a/zuul/driver/mqtt/mqttreporter.py +++ b/zuul/driver/mqtt/mqttreporter.py @@ -43,6 +43,7 @@ class MQTTReporter(BaseReporter): 'ref': getattr(item.change, 'ref', ''), 'message': self._formatItemReport( item, with_jobs=False), + 'trigger_time': item.event.timestamp, 'enqueue_time': item.enqueue_time, 'buildset': { 'uuid': item.current_build_set.uuid, diff --git a/zuul/driver/pagure/pagureconnection.py b/zuul/driver/pagure/pagureconnection.py index f16d3094f8..055792503c 100644 --- a/zuul/driver/pagure/pagureconnection.py +++ b/zuul/driver/pagure/pagureconnection.py @@ -231,6 +231,7 @@ class PagureEventConnector(threading.Thread): event = None if event: + event.timestamp = ts if event.change_number: project = self.connection.source.getProject(event.project_name) self.connection._getChange(project, diff --git a/zuul/driver/timer/__init__.py b/zuul/driver/timer/__init__.py index 024116a499..c72c19e624 100644 --- a/zuul/driver/timer/__init__.py +++ b/zuul/driver/timer/__init__.py @@ -15,6 +15,7 @@ # under the License. import logging +import time from uuid import uuid4 from apscheduler.schedulers.background import BackgroundScheduler @@ -100,6 +101,7 @@ class TimerDriver(Driver, TriggerInterface): event.ref = 'refs/heads/%s' % branch event.branch = branch event.zuul_event_id = str(uuid4().hex) + event.timestamp = time.time() log = get_annotated_logger(self.log, event) log.debug("Adding event") self.sched.addEvent(event) diff --git a/zuul/driver/zuul/__init__.py b/zuul/driver/zuul/__init__.py index 070b2bbb4e..fe37e74fed 100644 --- a/zuul/driver/zuul/__init__.py +++ b/zuul/driver/zuul/__init__.py @@ -13,6 +13,7 @@ # under the License. import logging +import time from uuid import uuid4 from zuul.driver import Driver, TriggerInterface @@ -93,6 +94,7 @@ class ZuulDriver(Driver, TriggerInterface): event.patch_number = change.patchset event.ref = change.ref event.zuul_event_id = str(uuid4().hex) + event.timestamp = time.time() self.sched.addEvent(event) def _createParentChangeEnqueuedEvents(self, change, pipeline, tenant, diff --git a/zuul/model.py b/zuul/model.py index 505adf20e9..5eaa8896ab 100644 --- a/zuul/model.py +++ b/zuul/model.py @@ -3147,6 +3147,7 @@ class TriggerEvent(object): self.forced_pipeline = None # For logging self.zuul_event_id = None + self.timestamp = None @property def canonical_project_name(self): diff --git a/zuul/rpclistener.py b/zuul/rpclistener.py index 34a1de8cdf..998abc0494 100644 --- a/zuul/rpclistener.py +++ b/zuul/rpclistener.py @@ -15,6 +15,7 @@ import json import logging +import time from zuul import model from zuul.connection import BaseConnection @@ -151,6 +152,7 @@ class RPCListener(object): def _common_enqueue(self, job): args = json.loads(job.arguments) event = model.TriggerEvent() + event.timestamp = time.time() errors = '' tenant = None project = None