Trace node request phase

Since we are mainly interested in the time taken until the request is
failed or fulfilled we won't create a span for full the lifetime of the
node request.

Change-Id: Ia8d9aaaac3ab4a4791eace2024c1ecb1b9c7a6bd

zuul/manager/__init__.py

@@ -879,8 +879,11 @@ class PipelineManager(metaclass=ABCMeta):
             relative_priority = item.getNodePriority()
         else:
             relative_priority = 0
-        for job in jobs:
-            self._makeNodepoolRequest(log, build_set, job, relative_priority)
+        parent_span = tracing.restoreSpan(build_set.span_info)
+        with trace.use_span(parent_span):
+            for job in jobs:
+                self._makeNodepoolRequest(
+                    log, build_set, job, relative_priority)
         return True
 
     def _makeNodepoolRequest(self, log, build_set, job, relative_priority,

zuul/model.py

@@ -1512,7 +1512,7 @@ class NodeRequest(object):
 
     def __init__(self, requestor, build_set_uuid, tenant_name, pipeline_name,
                  job_name, labels, provider, relative_priority,
-                 event_id=None):
+                 event_id=None, span_info=None):
         self.requestor = requestor
         self.build_set_uuid = build_set_uuid
         self.tenant_name = tenant_name
@@ -1530,6 +1530,7 @@ class NodeRequest(object):
         self.id = None
         self._zk_data = {}  # Data that we read back from ZK
         self.event_id = event_id
+        self.span_info = span_info
         # Zuul internal flags (not stored in ZK so they are not
         # overwritten).
         self.failed = False
@@ -1580,6 +1581,7 @@ class NodeRequest(object):
             "tenant_name": self.tenant_name,
             "pipeline_name": self.pipeline_name,
             "job_name": self.job_name,
+            "span_info": self.span_info,
         }
         d.setdefault('node_types', self.labels)
         d.setdefault('requestor', self.requestor)
@@ -1628,6 +1630,7 @@ class NodeRequest(object):
             labels=data["node_types"],
             provider=data["provider"],
             relative_priority=data.get("relative_priority", 0),
+            span_info=requestor_data.get("span_info"),
         )
 
         request.updateFromDict(data)

zuul/nodepool.py

@@ -16,6 +16,7 @@ import time
 
 from collections import defaultdict
 from zuul import model
+from zuul.lib import tracing
 from zuul.lib.logutil import get_annotated_logger
 from zuul.zk.event_queues import (
     PipelineResultEventQueue,
@@ -100,6 +101,10 @@ class Nodepool(object):
                     continue
                 if (request.state in {model.STATE_FULFILLED,
                                       model.STATE_FAILED}):
+                    tracing.endSavedSpan(request.span_info, attributes={
+                        "request_id": request.id,
+                        "state": request.state,
+                    })
                     self._sendNodesProvisionedEvent(request)
             # Now resume normal event processing.
             self.stop_watcher_event.wait()

zuul/zk/nodepool.py

@@ -23,6 +23,7 @@ from kazoo.recipe.cache import TreeCache, TreeEvent
 from kazoo.recipe.lock import Lock
 
 import zuul.model
+from zuul.lib import tracing
 from zuul.lib.jsonutil import json_dumps
 from zuul.model import HoldRequest, NodeRequest, Node
 from zuul.zk import ZooKeeperBase
@@ -456,6 +457,8 @@ class ZooKeeperNodepool(ZooKeeperBase):
             contents of the request.
         """
         node_request.created_time = time.time()
+        node_request.span_info = tracing.startSavedSpan(
+            "RequestNodes", start_time=node_request.created_time)
         data = node_request.toDict()
 
         path = '{}/{:0>3}-'.format(self.REQUEST_ROOT, priority)