diff --git a/neutron/agent/common/resource_processing_queue.py b/neutron/agent/common/resource_processing_queue.py index 96404c40c73..c51b92ffa27 100644 --- a/neutron/agent/common/resource_processing_queue.py +++ b/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) diff --git a/neutron/agent/l3/agent.py b/neutron/agent/l3/agent.py index 1c426e52e05..0f3d7887904 100644 --- a/neutron/agent/l3/agent.py +++ b/neutron/agent/l3/agent.py @@ -593,11 +593,17 @@ class L3NATAgent(ha.AgentMixin, def _process_router_update(self): for rp, update in self._queue.each_update_to_next_resource(): - LOG.debug("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.debug("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 [] @@ -633,7 +639,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.debug("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): @@ -641,7 +650,10 @@ class L3NATAgent(ha.AgentMixin, continue rp.fetched_and_processed(update.timestamp) - LOG.debug("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