x/vmware-nsx
Code Issues Proposed changes

Improve OVS agent logging for profiling

Browse Source 
This patch adds some debug logging statements aimed at profiling
tasks in the agent's main rpc loop.
These logging capabilities will help gain some better insights into
the performance bottlenecks of the agent.

Part of blueprint neutron-tempest-parallel

Change-Id: Ied04b906dbbb9993283981bdee6c96e43a7d19a3
This commit is contained in:
Salvatore Orlando 2013-11-29 05:50:04 -08:00
parent 1b33844d5f
commit 2a2ed2558f
1 changed files with 68 additions and 4 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

72
neutron/plugins/openvswitch/agent/ovs_neutron_agent.py
View File

@ -228,6 +228,8 @@ class OVSNeutronAgent(sg_rpc.SecurityGroupAgentRpcCallbackMixin,
self.sg_agent = OVSSecurityGroupAgent(self.context, self.sg_agent = OVSSecurityGroupAgent(self.context,
self.plugin_rpc, self.plugin_rpc,
root_helper) root_helper)
# Initialize iteration counter
self.iter_num = 0
def _check_ovs_version(self): def _check_ovs_version(self):
if constants.TYPE_VXLAN in self.tunnel_types: if constants.TYPE_VXLAN in self.tunnel_types:
@ -1015,9 +1017,19 @@ class OVSNeutronAgent(sg_rpc.SecurityGroupAgentRpcCallbackMixin,
resync_a = False resync_a = False
resync_b = False resync_b = False
if 'added' in port_info: if 'added' in port_info:
start = time.time()
resync_a = self.treat_devices_added(port_info['added']) resync_a = self.treat_devices_added(port_info['added'])
LOG.debug(_("process_network_ports - iteration:%(iter_num)d -"
"treat_devices_added completed in %(elapsed).3f"),
{'iter_num': self.iter_num,
'elapsed': time.time() - start})
if 'removed' in port_info: if 'removed' in port_info:
start = time.time()
resync_b = self.treat_devices_removed(port_info['removed']) resync_b = self.treat_devices_removed(port_info['removed'])
LOG.debug(_("process_network_ports - iteration:%(iter_num)d -"
"treat_devices_removed completed in %(elapsed).3f"),
{'iter_num': self.iter_num,
'elapsed': time.time() - start})
# If one of the above opertaions fails => resync with plugin # If one of the above opertaions fails => resync with plugin
return (resync_a | resync_b) return (resync_a | resync_b)
@ -1025,10 +1037,23 @@ class OVSNeutronAgent(sg_rpc.SecurityGroupAgentRpcCallbackMixin,
resync_a = False resync_a = False
resync_b = False resync_b = False
if 'added' in port_info: if 'added' in port_info:
start = time.time()
resync_a = self.treat_ancillary_devices_added(port_info['added']) resync_a = self.treat_ancillary_devices_added(port_info['added'])
LOG.debug(_("process_ancillary_network_ports - iteration: "
"%(iter_num)d - treat_ancillary_devices_added "
"completed in %(elapsed).3f"),
{'iter_num': self.iter_num,
'elapsed': time.time() - start})
if 'removed' in port_info: if 'removed' in port_info:
start = time.time()
resync_b = self.treat_ancillary_devices_removed( resync_b = self.treat_ancillary_devices_removed(
port_info['removed']) port_info['removed'])
LOG.debug(_("process_ancillary_network_ports - iteration: "
"%(iter_num)d - treat_ancillary_devices_removed "
"completed in %(elapsed).3f"),
{'iter_num': self.iter_num,
'elapsed': time.time() - start})
# If one of the above opertaions fails => resync with plugin # If one of the above opertaions fails => resync with plugin
return (resync_a | resync_b) return (resync_a | resync_b)
@ -1062,10 +1087,13 @@ class OVSNeutronAgent(sg_rpc.SecurityGroupAgentRpcCallbackMixin,
ports = set() ports = set()
ancillary_ports = set() ancillary_ports = set()
tunnel_sync = True tunnel_sync = True
while True: while True:
try: try:
start = time.time() start = time.time()
port_stats = {'regular': {'added': 0, 'removed': 0},
'ancillary': {'added': 0, 'removed': 0}}
LOG.debug(_("Agent rpc_loop - iteration:%d started"),
self.iter_num)
if sync: if sync:
LOG.info(_("Agent out of sync with plugin!")) LOG.info(_("Agent out of sync with plugin!"))
ports.clear() ports.clear()
@ -1077,25 +1105,54 @@ class OVSNeutronAgent(sg_rpc.SecurityGroupAgentRpcCallbackMixin,
if self.enable_tunneling and tunnel_sync: if self.enable_tunneling and tunnel_sync:
LOG.info(_("Agent tunnel out of sync with plugin!")) LOG.info(_("Agent tunnel out of sync with plugin!"))
tunnel_sync = self.tunnel_sync() tunnel_sync = self.tunnel_sync()
if polling_manager.is_polling_required: if polling_manager.is_polling_required:
LOG.debug(_("Agent rpc_loop - iteration:%(iter_num)d - "
"starting polling. Elapsed:%(elapsed).3f"),
{'iter_num': self.iter_num,
'elapsed': time.time() - start})
port_info = self.update_ports(ports) port_info = self.update_ports(ports)
LOG.debug(_("Agent rpc_loop - iteration:%(iter_num)d - "
"port information retrieved. "
"Elapsed:%(elapsed).3f"),
{'iter_num': self.iter_num,
'elapsed': time.time() - start})
# notify plugin about port deltas # notify plugin about port deltas
if port_info: if port_info:
LOG.debug(_("Agent loop has new devices!")) LOG.debug(_("Agent loop has new devices!"))
# If treat devices fails - must resync with plugin # If treat devices fails - must resync with plugin
sync = self.process_network_ports(port_info) sync = self.process_network_ports(port_info)
LOG.debug(_("Agent rpc_loop - iteration:%(iter_num)d -"
"ports processed. Elapsed:%(elapsed).3f"),
{'iter_num': self.iter_num,
'elapsed': time.time() - start})
ports = port_info['current'] ports = port_info['current']
port_stats['regular']['added'] = (
len(port_info.get('added', [])))
port_stats['regular']['removed'] = (
len(port_info.get('removed', [])))
# Treat ancillary devices if they exist # Treat ancillary devices if they exist
if self.ancillary_brs: if self.ancillary_brs:
port_info = self.update_ancillary_ports( port_info = self.update_ancillary_ports(
ancillary_ports) ancillary_ports)
LOG.debug(_("Agent rpc_loop - iteration:%(iter_num)d -"
"ancillary port info retrieved. "
"Elapsed:%(elapsed).3f"),
{'iter_num': self.iter_num,
'elapsed': time.time() - start})
if port_info: if port_info:
rc = self.process_ancillary_network_ports( rc = self.process_ancillary_network_ports(
port_info) port_info)
LOG.debug(_("Agent rpc_loop - iteration:"
"%(iter_num)d - ancillary ports "
"processed. Elapsed:%(elapsed).3f"),
{'iter_num': self.iter_num,
'elapsed': time.time() - start})
ancillary_ports = port_info['current'] ancillary_ports = port_info['current']
port_stats['ancillary']['added'] = (
len(port_info.get('added', [])))
port_stats['ancillary']['removed'] = (
len(port_info.get('removed', [])))
sync = sync | rc sync = sync | rc
polling_manager.polling_completed() polling_manager.polling_completed()
@ -1107,6 +1164,12 @@ class OVSNeutronAgent(sg_rpc.SecurityGroupAgentRpcCallbackMixin,
# sleep till end of polling interval # sleep till end of polling interval
elapsed = (time.time() - start) elapsed = (time.time() - start)
LOG.debug(_("Agent rpc_loop - iteration:%(iter_num)d "
"completed. Processed ports statistics: "
"%(port_stats)s. Elapsed:%(elapsed).3f"),
{'iter_num': self.iter_num,
'port_stats': port_stats,
'elapsed': elapsed})
if (elapsed < self.polling_interval): if (elapsed < self.polling_interval):
time.sleep(self.polling_interval - elapsed) time.sleep(self.polling_interval - elapsed)
else: else:
@ -1114,6 +1177,7 @@ class OVSNeutronAgent(sg_rpc.SecurityGroupAgentRpcCallbackMixin,
"(%(polling_interval)s vs. %(elapsed)s)!"), "(%(polling_interval)s vs. %(elapsed)s)!"),
{'polling_interval': self.polling_interval, {'polling_interval': self.polling_interval,
'elapsed': elapsed}) 'elapsed': elapsed})
self.iter_num = self.iter_num + 1
def daemon_loop(self): def daemon_loop(self):
with polling.get_polling_manager( with polling.get_polling_manager(