openstack/neutron-lbaas
Code Issues Proposed changes

Merge "Improve OVS agent logging for profiling"

Browse Source
This commit is contained in:
Jenkins 2013-12-02 04:02:35 +00:00 committed by Gerrit Code Review
commit 4e0ad6e09a
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(