Merge branch 'ONOS-ONRC2014-Measurements' of github.com:OPENNETWORKINGLAB/ONOS into RAMCloud-merge
diff --git a/perf-scripts/flow-manager-perf.py b/perf-scripts/flow-manager-perf.py
new file mode 100644
index 0000000..3168f63
--- /dev/null
+++ b/perf-scripts/flow-manager-perf.py
@@ -0,0 +1,78 @@
+#!/usr/bin/python
+'''
+ Script that tests Flow Manager performance
+ Author: Brian O'Connor <bocon@onlab.us>
+
+'''
+
+import csv
+import os
+import sys
+from time import sleep, strftime
+from subprocess import Popen, call, check_output, PIPE
+from datetime import datetime
+
+try:
+ import pexpect
+except:
+ # install pexpect if it cannot be found and re-import
+ print '* Installing Pexpect'
+ call( 'apt-get install -y python-pexpect', stdout=PIPE, shell=True )
+ import pexpect
+
+ONOS_HOME = '..'
+ONOS_LOG = '%s/onos-logs/onos.%s.log' % ( ONOS_HOME, check_output( 'hostname').strip() )
+ONOS_LOG = '/tmp/onos-1.logs/onos.onos-vm.log'
+print "ONOS Log File:", ONOS_LOG
+
+PORT = 's1-eth2'
+N = 100
+
+# ----------------- Running the test and output -------------------------
+
+# 17:43:37.206 [main] ERROR n.o.o.o.f.PerformanceMonitor - Performance Results: {a=0.001ms, b=0.0ms, c=0.0ms} with measurement overhead: 0.022 ms
+
+def test():
+ # Start tailing the onos log
+ tail = pexpect.spawn( "tail -0f %s" % ONOS_LOG )
+
+ # Take link down
+ call( 'ifconfig %s down' % PORT, shell=True )
+
+ # Wait for performance results in the log
+ tail.expect('Performance Results: \{([^\}]*)\} with measurement overhead: ([\d.]+) ms', timeout=6000)
+ s = tail.match.group(1)
+ overhead = float( tail.match.group(2) )
+ results = dict( re.findall(r'(\w[\w\s]*)=([\d.]+)', s) )
+
+ # Output results
+ print "* Results:", results, "Overhead:", overhead
+
+ # Bring port back up
+ call( 'ifconfig %s up' % PORT, shell=True )
+
+ tail.terminate()
+ return results
+
+def outputResults(filename, results):
+ with open(filename, 'a') as csvfile:
+ writer = csv.writer(csvfile)
+ writer.writerow(results)
+
+def runPerf(n):
+ filename = 'results-flowmanager-%s.csv' % strftime( '%Y%m%d-%H%M%S' )
+ print 'Starting experiments:'
+ start = datetime.now()
+ for i in range(n):
+ results = test()
+ outputResults(filename, results)
+ sys.stdout.write('.')
+ sys.stdout.flush()
+ sleep(5000) # sleep for 5 seconds between tests
+ totalTime = datetime.now() - start
+ print '\nExperiments complete in %s (h:m:s.s)' % totalTime
+
+if __name__ == '__main__':
+ n = N
+ runPerf(n)
+
diff --git a/src/main/java/net/onrc/onos/datagrid/HazelcastDatagrid.java b/src/main/java/net/onrc/onos/datagrid/HazelcastDatagrid.java
index c195f82..b76aa58 100644
--- a/src/main/java/net/onrc/onos/datagrid/HazelcastDatagrid.java
+++ b/src/main/java/net/onrc/onos/datagrid/HazelcastDatagrid.java
@@ -44,6 +44,8 @@
import com.hazelcast.core.IMap;
import com.hazelcast.instance.GroupProperties;
+import net.onrc.onos.ofcontroller.flowmanager.PerformanceMonitor;
+
/**
* A datagrid service that uses Hazelcast as a datagrid.
* The relevant data is stored in the Hazelcast datagrid and shared as
@@ -448,6 +450,8 @@
*/
@Override
public void entryRemoved(EntryEvent<String, byte[]> event) {
+ String tag = "TopologyEntryRemoved.NotificationReceived." + event.getKey();
+ PerformanceMonitor.start(tag);
byte[] valueBytes = event.getValue();
//
@@ -459,6 +463,8 @@
kryo.readObject(input, TopologyElement.class);
kryoFactory.deleteKryo(kryo);
flowEventHandlerService.notificationRecvTopologyElementRemoved(topologyElement);
+ PerformanceMonitor.stop(tag);
+ PerformanceMonitor.report(tag);
}
/**
diff --git a/src/main/java/net/onrc/onos/ofcontroller/floodlightlistener/NetworkGraphPublisher.java b/src/main/java/net/onrc/onos/ofcontroller/floodlightlistener/NetworkGraphPublisher.java
index 456b69c..0d352f8 100644
--- a/src/main/java/net/onrc/onos/ofcontroller/floodlightlistener/NetworkGraphPublisher.java
+++ b/src/main/java/net/onrc/onos/ofcontroller/floodlightlistener/NetworkGraphPublisher.java
@@ -44,6 +44,8 @@
import net.onrc.onos.registry.controller.IControllerRegistryService.ControlChangeCallback;
import net.onrc.onos.registry.controller.RegistryException;
+import net.onrc.onos.ofcontroller.flowmanager.PerformanceMonitor;
+
import org.openflow.protocol.OFPhysicalPort;
import org.openflow.util.HexString;
import org.slf4j.Logger;
@@ -354,12 +356,16 @@
@Override
public void switchPortRemoved(Long switchId, OFPhysicalPort port) {
// Remove all links that might be connected already
+ PerformanceMonitor.start("SwitchPortRemoved.DbAccess");
+
List<Link> links = linkStore.getLinks(switchId, port.getPortNumber());
// Remove all reverse links as well
List<Link> reverseLinks = linkStore.getReverseLinks(switchId, port.getPortNumber());
links.addAll(reverseLinks);
if (swStore.deletePort(HexString.toHexString(switchId), port.getPortNumber())) {
+ PerformanceMonitor.stop("SwitchPortRemoved.DbAccess");
+ PerformanceMonitor.start("SwitchPortRemoved.NotificationSend");
// TODO publish DELETE_PORT event here
TopologyElement topologyElement =
new TopologyElement(switchId, port.getPortNumber());
@@ -374,6 +380,9 @@
link.getDstPort());
datagridService.notificationSendTopologyElementRemoved(topologyElementLink);
}
+ PerformanceMonitor.stop("SwitchPortRemoved.NotificationSend");
+ PerformanceMonitor.report("SwitchPortRemoved.DbAccess");
+ PerformanceMonitor.report("TopologyEntryRemoved.NotificationReceived");
}
}
diff --git a/src/main/java/net/onrc/onos/ofcontroller/flowmanager/FlowEventHandler.java b/src/main/java/net/onrc/onos/ofcontroller/flowmanager/FlowEventHandler.java
index cf9b67d..1471c49 100644
--- a/src/main/java/net/onrc/onos/ofcontroller/flowmanager/FlowEventHandler.java
+++ b/src/main/java/net/onrc/onos/ofcontroller/flowmanager/FlowEventHandler.java
@@ -290,6 +290,8 @@
if (enableOnrc2014MeasurementsFlows) {
+ PerformanceMonitor.start("EventHandler.ProcessAllEvents");
+
if (topologyEvents.isEmpty() && flowIdEvents.isEmpty() &&
switchDpidEvents.isEmpty()) {
return; // Nothing to do
@@ -298,15 +300,22 @@
Map<Long, IOFSwitch> mySwitches = flowManager.getMySwitches();
// Process the Switch Dpid events
+ PerformanceMonitor.start("EventHandler.SwitchDpidEvents");
processSwitchDpidEvents();
+ PerformanceMonitor.stop("EventHandler.SwitchDpidEvents");
// Process the Flow ID events
+ PerformanceMonitor.start("EventHandler.FlowIdEvents");
processFlowIdEvents(mySwitches);
+ PerformanceMonitor.stop("EventHandler.FlowIdEvents");
// Fetch the topology
+ PerformanceMonitor.start("EventHandler.ReadTopology");
processTopologyEvents();
+ PerformanceMonitor.stop("EventHandler.ReadTopology");
// Recompute all affected Flow Paths and keep only the modified
+ PerformanceMonitor.start("EventHandler.RecomputeFlows");
for (FlowPath flowPath : shouldRecomputeFlowPaths.values()) {
if (recomputeFlowPath(flowPath))
modifiedFlowPaths.put(flowPath.flowId().value(), flowPath);
@@ -321,10 +330,12 @@
}
}
}
+ PerformanceMonitor.stop("EventHandler.RecomputeFlows");
//
// Push the modified state to the database
//
+ PerformanceMonitor.start("EventHandler.WriteFlowsToDb");
for (FlowPath flowPath : modifiedFlowPaths.values()) {
//
// Delete the Flow Path from the Network Map
@@ -335,10 +346,17 @@
// TODO: For now the deleting of a Flow Path is blocking
ParallelFlowDatabaseOperation.deleteFlow(dbHandler,
flowPath.flowId());
+ //
+ // NOTE: For now the sending of the notifications
+ // is outside of this loop, so the performance measurements
+ // are more accurate.
+ //
+ /*
// Send the notifications for the deleted Flow Entries
for (FlowEntry flowEntry : flowPath.flowEntries()) {
datagridService.notificationSendFlowEntryRemoved(flowEntry.flowEntryId());
}
+ */
continue;
}
@@ -350,6 +368,23 @@
ParallelFlowDatabaseOperation.addFlow(dbHandler, flowPath,
datagridService);
}
+ PerformanceMonitor.stop("EventHandler.WriteFlowsToDb");
+
+ //
+ // Send the notifications for the deleted Flow Entries
+ // NOTE: This code was pulled outside of the above loop,
+ // so the performance measurements are more accurate.
+ //
+ PerformanceMonitor.start("EventHandler.NotificationSend.FlowEntryRemoved");
+ for (FlowPath flowPath : modifiedFlowPaths.values()) {
+ if (flowPath.flowPathUserState() ==
+ FlowPathUserState.FP_USER_DELETE) {
+ for (FlowEntry flowEntry : flowPath.flowEntries()) {
+ datagridService.notificationSendFlowEntryRemoved(flowEntry.flowEntryId());
+ }
+ }
+ }
+ PerformanceMonitor.stop("EventHandler.NotificationSend.FlowEntryRemoved");
// Cleanup
topologyEvents.clear();
@@ -361,6 +396,17 @@
shouldRecomputeFlowPaths.clear();
modifiedFlowPaths.clear();
+ PerformanceMonitor.stop("EventHandler.ProcessAllEvents");
+
+
+ PerformanceMonitor.report("EventHandler.SwitchDpidEvents");
+ PerformanceMonitor.report("EventHandler.FlowIdEvents");
+ PerformanceMonitor.report("EventHandler.ReadTopology");
+ PerformanceMonitor.report("EventHandler.RecomputeFlows");
+ PerformanceMonitor.report("EventHandler.WriteFlowsToDb");
+ PerformanceMonitor.report("EventHandler.NotificationSend.FlowEntryRemoved");
+ PerformanceMonitor.report("EventHandler.ProcessAllEvents");
+
return;
}
@@ -1375,9 +1421,13 @@
@Override
public void notificationRecvFlowEntryAdded(FlowEntry flowEntry) {
if (enableOnrc2014MeasurementsFlows) {
+ String tag = "EventHandler.AddFlowEntryToSwitch." + flowEntry.flowEntryId();
+ PerformanceMonitor.start(tag);
Collection entries = new ArrayList();
entries.add(flowEntry);
flowManager.pushModifiedFlowEntriesToSwitches(entries);
+ PerformanceMonitor.stop(tag);
+ PerformanceMonitor.report(tag);
return;
}
@@ -1394,6 +1444,8 @@
@Override
public void notificationRecvFlowEntryRemoved(FlowEntry flowEntry) {
if (enableOnrc2014MeasurementsFlows) {
+ String tag = "EventHandler.RemoveFlowEntryFromSwitch." + flowEntry.flowEntryId();
+ PerformanceMonitor.start(tag);
//
// NOTE: Must update the state to DELETE, because
// the notification contains the original state.
@@ -1403,6 +1455,8 @@
Collection entries = new ArrayList();
entries.add(flowEntry);
flowManager.pushModifiedFlowEntriesToSwitches(entries);
+ PerformanceMonitor.stop(tag);
+ PerformanceMonitor.report(tag);
return;
}
diff --git a/src/main/java/net/onrc/onos/ofcontroller/flowmanager/ParallelFlowDatabaseOperation.java b/src/main/java/net/onrc/onos/ofcontroller/flowmanager/ParallelFlowDatabaseOperation.java
index 212c59f..fff89dc 100644
--- a/src/main/java/net/onrc/onos/ofcontroller/flowmanager/ParallelFlowDatabaseOperation.java
+++ b/src/main/java/net/onrc/onos/ofcontroller/flowmanager/ParallelFlowDatabaseOperation.java
@@ -261,7 +261,12 @@
@Override
public Boolean call() throws Exception {
+ String tag1 = "FlowDatabaseOperation.AddFlow." + flowPath.flowId();
+ String tag2 = "FlowDatabaseOperation.NotificationSend.FlowEntry." + flowPath.flowId();
+ PerformanceMonitor.start(tag1);
boolean success = FlowDatabaseOperation.addFlow(dbHandler, flowPath);
+ PerformanceMonitor.stop(tag1);
+ PerformanceMonitor.start(tag2);
if(success) {
if(datagridService != null) {
// Send notifications for each Flow Entry
@@ -293,6 +298,9 @@
else {
log.error("Error adding flow path {} to database", flowPath);
}
+ PerformanceMonitor.stop(tag2);
+ PerformanceMonitor.report(tag1);
+ PerformanceMonitor.report(tag2);
return success;
}
diff --git a/src/main/java/net/onrc/onos/ofcontroller/flowmanager/PerformanceMonitor.java b/src/main/java/net/onrc/onos/ofcontroller/flowmanager/PerformanceMonitor.java
index 13319e7..293b426 100644
--- a/src/main/java/net/onrc/onos/ofcontroller/flowmanager/PerformanceMonitor.java
+++ b/src/main/java/net/onrc/onos/ofcontroller/flowmanager/PerformanceMonitor.java
@@ -82,7 +82,22 @@
double overheadMilli = overhead / Math.pow(10, 6);
log.error("Performance Results: {} with measurement overhead: {} ms", map, overheadMilli);
}
-
+
+ /**
+ * Write the performance measurement for a tag to the log
+ *
+ * @param tag the tag name.
+ */
+ public static void report(String tag) {
+ Measurement m = map.get(tag);
+ if (m != null) {
+ log.error("Performance Results: tag = {} start = {} stop = {} elapsed = {}",
+ tag, m.start, m.stop, m.toString());
+ } else {
+ log.error("Performance Results: unknown tag {}", tag);
+ }
+ }
+
/**
* A single performance measurement
*/
@@ -131,7 +146,7 @@
*/
public String toString() {
double milli = elapsed() / Math.pow(10, 6);
- return Double.toString(milli) + "ms";
+ return Double.toString(milli) + " ms";
}
}