Add update_id for ResourceUpdate

Add a unique id for resource update, then we can calculate
the resource processing time and track it.

Related-Bug: #1825152
Related-Bug: #1824911
Related-Bug: #1821912
Related-Bug: #1813787

Change-Id: Ib4d197c6c180c32860964440882393794aabb6ef
(cherry picked from commit 9d60716cf1)

neutron/agent/common/resource_processing_queue.py

@@ -14,8 +14,10 @@
 #
 
 import datetime
+import time
 
 from oslo_utils import timeutils
+from oslo_utils import uuidutils
 from six.moves import queue as Queue
 
 
@@ -38,6 +40,25 @@ class ResourceUpdate(object):
         self.action = action
         self.resource = resource
         self.tries = tries
+        # NOTE: Because one resource can be processed multiple times, this
+        # update_id will be used for tracking one resource processing
+        # procedure.
+        self.update_id = uuidutils.generate_uuid()
+        self.create_time = self.start_time = time.time()
+
+    def set_start_time(self):
+        # Set the start_time to 'now' - can be used by callers to help
+        # track time spent in procedures.
+        self.start_time = time.time()
+
+    @property
+    def time_elapsed_since_create(self):
+        return time.time() - self.create_time
+
+    @property
+    def time_elapsed_since_start(self):
+        # Time elapsed between processing start and end.
+        return time.time() - self.start_time
 
     def __lt__(self, other):
         """Implements priority among updates
@@ -163,4 +184,5 @@ class ResourceProcessingQueue(object):
             # rp.updates() will not yield and so this will essentially be a
             # noop.
             for update in rp.updates():
+                update.set_start_time()
                 yield (rp, update)

neutron/agent/l3/agent.py

@@ -619,11 +619,17 @@ class L3NATAgent(ha.AgentMixin,
 
     def _process_router_update(self):
         for rp, update in self._queue.each_update_to_next_resource():
-            LOG.info("Starting router update for %s, action %s, priority %s",
-                     update.id, update.action, update.priority)
+            LOG.info("Starting router update for %s, action %s, priority %s, "
+                     "update_id %s. Wait time elapsed: %.3f",
+                     update.id, update.action, update.priority,
+                     update.update_id,
+                     update.time_elapsed_since_create)
             if update.action == PD_UPDATE:
                 self.pd.process_prefix_update()
-                LOG.info("Finished a router update for %s", update.id)
+                LOG.info("Finished a router update for %s IPv6 PD, "
+                         "update_id. %s. Time elapsed: %.3f",
+                         update.id, update.update_id,
+                         update.time_elapsed_since_start)
                 continue
 
             routers = [update.resource] if update.resource else []
@@ -659,7 +665,10 @@ class L3NATAgent(ha.AgentMixin,
                     # processing queue (like events from fullsync) in order to
                     # prevent deleted router re-creation
                     rp.fetched_and_processed(update.timestamp)
-                LOG.info("Finished a router update for %s", update.id)
+                LOG.info("Finished a router update for %s, update_id %s. "
+                         "Time elapsed: %.3f",
+                         update.id, update.update_id,
+                         update.time_elapsed_since_start)
                 continue
 
             if not self._process_routers_if_compatible(routers, update):
@@ -667,7 +676,10 @@ class L3NATAgent(ha.AgentMixin,
                 continue
 
             rp.fetched_and_processed(update.timestamp)
-            LOG.info("Finished a router update for %s", update.id)
+            LOG.info("Finished a router update for %s, update_id %s. "
+                     "Time elapsed: %.3f",
+                     update.id, update.update_id,
+                     update.time_elapsed_since_start)
 
     def _process_routers_if_compatible(self, routers, update):
         process_result = True