Merge pull request #7 from y-higuchi/RAMCloud-yoshi

Add measurement code to AddFlow
diff --git a/src/main/java/net/onrc/onos/graph/DBOperation.java b/src/main/java/net/onrc/onos/graph/DBOperation.java
index 4512b48..0b91dd2 100644
--- a/src/main/java/net/onrc/onos/graph/DBOperation.java
+++ b/src/main/java/net/onrc/onos/graph/DBOperation.java
@@ -33,7 +33,7 @@
 
 	/**
 	 * Search and get an active switch object with DPID.
-	 * @param dpid DPID of the switch 
+	 * @param dpid DPID of the switch
 	 */
 	@Override
 	public ISwitchObject searchActiveSwitch(String dpid) {
@@ -44,7 +44,7 @@
 	    }
 	    return null;
 	}
-	
+
 	/**
 	 * Create a new switch and return the created switch object.
 	 * @param dpid DPID of the switch
@@ -59,7 +59,7 @@
 	    }
 	    return obj;
 	}
-	
+
 	/**
 	 * Get all switch objects.
 	 */
@@ -86,7 +86,7 @@
 	    }
 	    return inactiveSwitches;
 	}
-	
+
 	/**
 	 * Get all flow entries objects where their switches are not updated.
 	 */
@@ -125,6 +125,7 @@
 	*
 	* @param portNumber port number
 	*/
+	@Override
 	@Deprecated
 	public IPortObject newPort(Short portNumber) {
 	    IPortObject obj = (IPortObject) conn.getFramedGraph().addVertex(null, IPortObject.class);
@@ -145,7 +146,7 @@
 	    FramedGraph fg = conn.getFramedGraph();
 	    if ( fg == null ) return null;
 	    String id = dpid + number.toString();
-	    Iterator<IPortObject> it = conn.getFramedGraph().getVertices("port_id", id, IPortObject.class).iterator();
+	    Iterator<IPortObject> it = fg.getVertices("port_id", id, IPortObject.class).iterator();
 	    return (it.hasNext()) ? it.next() : null;
 
 	}
@@ -195,7 +196,7 @@
 		conn.getFramedGraph().removeVertex(dev.asVertex());
 	    }
 	}
-	
+
 	/**
 	* Create and return a flow path object.
 	*/
@@ -219,7 +220,7 @@
 	    GremlinPipeline<Vertex, IFlowPath> pipe = new GremlinPipeline<Vertex, IFlowPath>();
 	    pipe.start(flowEntry.asVertex());
 	    pipe.out("flow");
-	    FramedVertexIterable<IFlowPath> r = new FramedVertexIterable(conn.getFramedGraph(), (Iterable) pipe, IFlowPath.class);
+	    FramedVertexIterable<IFlowPath> r = new FramedVertexIterable(conn.getFramedGraph(), pipe, IFlowPath.class);
 	    return r.iterator().hasNext() ? r.iterator().next() : null;
 	}
 
@@ -233,7 +234,7 @@
 	public ISwitchObject searchSwitch(final String dpid) {
 	    FramedGraph fg = conn.getFramedGraph();
 	    if ( fg == null ) return null;
-	    Iterator<ISwitchObject> it = conn.getFramedGraph().getVertices("dpid", dpid, ISwitchObject.class).iterator();
+	    Iterator<ISwitchObject> it = fg.getVertices("dpid", dpid, ISwitchObject.class).iterator();
 	    return (it.hasNext()) ? it.next() : null;
 	}
 
@@ -261,7 +262,7 @@
 	public IDeviceObject searchDevice(String macAddr) {
 	    FramedGraph fg = conn.getFramedGraph();
 	    if ( fg == null ) return null;
-	    Iterator<IDeviceObject> it = conn.getFramedGraph().getVertices("dl_addr", macAddr, IDeviceObject.class).iterator();
+	    Iterator<IDeviceObject> it = fg.getVertices("dl_addr", macAddr, IDeviceObject.class).iterator();
 	    return (it.hasNext()) ? it.next() : null;
 	}
 
@@ -273,7 +274,7 @@
 	public IFlowPath searchFlowPath(final FlowId flowId) {
 	    FramedGraph fg = conn.getFramedGraph();
 	    if ( fg == null ) return null;
-	    Iterator<IFlowPath> it = conn.getFramedGraph().getVertices("flow_id", flowId.toString(), IFlowPath.class).iterator();
+	    Iterator<IFlowPath> it = fg.getVertices("flow_id", flowId.toString(), IFlowPath.class).iterator();
 	    return (it.hasNext()) ? it.next() : null;
 	}
 
@@ -294,7 +295,7 @@
 	    }
 	    return nonNullFlows;
 	}
-	
+
 	/**
 	 * Remove the specified flow path.
 	 * @param flowPath flow path object to remove
@@ -304,7 +305,7 @@
 	    //System.out.println("removeFlowPath");
 	    conn.getFramedGraph().removeVertex(flowPath.asVertex());
 	}
-	
+
 	/**
 	 * Search and get a flow entry object with flow entry ID.
 	 * @param flowEntryId flow entry ID to search
@@ -313,7 +314,7 @@
 	public IFlowEntry searchFlowEntry(FlowEntryId flowEntryId) {
 	    FramedGraph fg = conn.getFramedGraph();
 	    if ( fg == null ) return null;
-	    Iterator<IFlowEntry> it = conn.getFramedGraph().getVertices("flow_entry_id", flowEntryId.toString(), IFlowEntry.class).iterator();
+	    Iterator<IFlowEntry> it = fg.getVertices("flow_entry_id", flowEntryId.toString(), IFlowEntry.class).iterator();
 	    return (it.hasNext()) ? it.next() : null;
 	}
 
@@ -334,7 +335,7 @@
 	    //System.out.println("removeFlowEntry");
 	    conn.getFramedGraph().removeVertex(flowEntry.asVertex());
 	}
-	
+
 	/**
 	 * Create and return a flow entry object.
 	 */
@@ -352,7 +353,7 @@
 	public IIpv4Address newIpv4Address() {
 		return newVertex("ipv4Address", IIpv4Address.class);
 	}
-	
+
 	private <T extends IBaseObject> T newVertex(String type, Class<T> vertexType) {
 		T newVertex = (T) conn.getFramedGraph().addVertex(null, vertexType);
 		if (newVertex != null) {
@@ -364,8 +365,8 @@
 	public IIpv4Address searchIpv4Address(int intIpv4Address) {
 		return searchForVertex("ipv4_address", intIpv4Address, IIpv4Address.class);
 	}
-	
-	
+
+
 	public IIpv4Address ensureIpv4Address(int intIpv4Address) {
 		IIpv4Address ipv4Vertex = searchIpv4Address(intIpv4Address);
 		if (ipv4Vertex == null) {
@@ -373,9 +374,9 @@
 			ipv4Vertex.setIpv4Address(intIpv4Address);
 		}
 		return ipv4Vertex;
-	}	
+	}
 
-	
+
 	private <T> T searchForVertex(String propertyName, Object propertyValue, Class<T> vertexType) {
 		if (conn.getFramedGraph() != null) {
 			Iterator<T> it = conn.getFramedGraph().getVertices(propertyName, propertyValue, vertexType).iterator();
@@ -397,8 +398,8 @@
 	@Override
 	public IDBConnection getDBConnection() {
 	    return conn;
-	}	
-	
+	}
+
 	@Override
 	public void commit() {
 	    conn.commit();
diff --git a/src/main/java/net/onrc/onos/ofcontroller/flowmanager/FlowDatabaseOperation.java b/src/main/java/net/onrc/onos/ofcontroller/flowmanager/FlowDatabaseOperation.java
index 194922b..a05abab 100644
--- a/src/main/java/net/onrc/onos/ofcontroller/flowmanager/FlowDatabaseOperation.java
+++ b/src/main/java/net/onrc/onos/ofcontroller/flowmanager/FlowDatabaseOperation.java
@@ -8,7 +8,6 @@
 
 import net.floodlightcontroller.util.MACAddress;
 import net.onrc.onos.graph.DBOperation;
-
 import net.onrc.onos.ofcontroller.core.INetMapTopologyObjects.IFlowEntry;
 import net.onrc.onos.ofcontroller.core.INetMapTopologyObjects.IFlowPath;
 import net.onrc.onos.ofcontroller.core.INetMapTopologyObjects.IPortObject;
@@ -23,6 +22,7 @@
  */
 public class FlowDatabaseOperation {
     private final static Logger log = LoggerFactory.getLogger(FlowDatabaseOperation.class);
+    public static final boolean measureONOSFlowTimeProp = Long.valueOf(System.getProperty("benchmark.measureONOSFlow", "0")) != 0;
 
     /**
      * Add a flow.
@@ -34,12 +34,36 @@
     static boolean addFlow(DBOperation dbHandler, FlowPath flowPath) {
 	IFlowPath flowObj = null;
 	boolean found = false;
+	long startAddFlow = 0;
+	long endAddFlow = 0;
+	long endSearchExistingFlowPathTime = 0;
+	long endCreateNewFlowPathTime = 0;
+	long startFollowExistingFlowEntries = 0;
+	long endFollowExistingFlowEntries = 0;
+	long accTimeRemovingFlowEntriesFromFlowPath = 0;
+	long accTimeRemovingFlowEntriesFromDB = 0;
+	long startSettingFlowPathProps = 0;
+	long endSettingFlowPathProps = 0;
+	int numPropsSet = 0;
+	long accTimeAddFlowEntries = 0;
+	int numNewFlowEntries = 0;
+	LinkedList<long[]> flowEntryTimes = new LinkedList<>();
+
 	try {
+	    if ( measureONOSFlowTimeProp ) {
+		startAddFlow = System.nanoTime();
+	    }
 	    flowObj = dbHandler.searchFlowPath(flowPath.flowId());
+	    if ( measureONOSFlowTimeProp ) {
+		endSearchExistingFlowPathTime = System.nanoTime();
+	    }
 	    if (flowObj != null) {
 		found = true;
 	    } else {
 		flowObj = dbHandler.newFlowPath();
+		if ( measureONOSFlowTimeProp ) {
+			endCreateNewFlowPathTime = System.nanoTime();
+		}
 	    }
 	} catch (Exception e) {
 	    dbHandler.rollback();
@@ -64,23 +88,46 @@
 	// Remove the old Flow Entries
 	//
 	if (found) {
+	    if ( measureONOSFlowTimeProp ) {
+		startFollowExistingFlowEntries = System.nanoTime();
+	    }
 	    Iterable<IFlowEntry> flowEntries = flowObj.getFlowEntries();
+	    if ( measureONOSFlowTimeProp ) {
+		endFollowExistingFlowEntries = System.nanoTime();
+	    }
 	    LinkedList<IFlowEntry> deleteFlowEntries =
 		new LinkedList<IFlowEntry>();
 	    for (IFlowEntry flowEntryObj : flowEntries)
 		deleteFlowEntries.add(flowEntryObj);
-	    for (IFlowEntry flowEntryObj : deleteFlowEntries) {
-		flowObj.removeFlowEntry(flowEntryObj);
-		dbHandler.removeFlowEntry(flowEntryObj);
+	    if( measureONOSFlowTimeProp ) {
+		    for (IFlowEntry flowEntryObj : deleteFlowEntries) {
+			long start = System.nanoTime();
+			flowObj.removeFlowEntry(flowEntryObj);
+			accTimeRemovingFlowEntriesFromFlowPath += System.nanoTime() - start;
+			start = System.nanoTime();
+			dbHandler.removeFlowEntry(flowEntryObj);
+			accTimeRemovingFlowEntriesFromDB += System.nanoTime() - start;
+		    }
+	    } else {
+		    for (IFlowEntry flowEntryObj : deleteFlowEntries) {
+			flowObj.removeFlowEntry(flowEntryObj);
+			dbHandler.removeFlowEntry(flowEntryObj);
+		    }
 	    }
 	}
 
+	if ( measureONOSFlowTimeProp ) {
+		startSettingFlowPathProps = System.nanoTime();
+	}
 	//
 	// Set the Flow key:
 	// - flowId
 	//
 	flowObj.setFlowId(flowPath.flowId().toString());
 	flowObj.setType("flow");
+	if ( measureONOSFlowTimeProp ) {
+	    numPropsSet += 2;
+	}
 
 	//
 	// Set the Flow attributes:
@@ -115,49 +162,99 @@
 	flowObj.setSrcPort(flowPath.dataPath().srcPort().port().value());
 	flowObj.setDstSwitch(flowPath.dataPath().dstPort().dpid().toString());
 	flowObj.setDstPort(flowPath.dataPath().dstPort().port().value());
+	if ( measureONOSFlowTimeProp ) {
+	    numPropsSet += 10;
+	}
+
 	if (flowPath.flowEntryMatch().matchSrcMac()) {
 	    flowObj.setMatchSrcMac(flowPath.flowEntryMatch().srcMac().toString());
+		if ( measureONOSFlowTimeProp ) {
+		    ++numPropsSet;
+		}
 	}
 	if (flowPath.flowEntryMatch().matchDstMac()) {
 	    flowObj.setMatchDstMac(flowPath.flowEntryMatch().dstMac().toString());
+		if ( measureONOSFlowTimeProp ) {
+		    ++numPropsSet;
+		}
 	}
 	if (flowPath.flowEntryMatch().matchEthernetFrameType()) {
 	    flowObj.setMatchEthernetFrameType(flowPath.flowEntryMatch().ethernetFrameType());
+		if ( measureONOSFlowTimeProp ) {
+		    ++numPropsSet;
+		}
 	}
 	if (flowPath.flowEntryMatch().matchVlanId()) {
 	    flowObj.setMatchVlanId(flowPath.flowEntryMatch().vlanId());
+		if ( measureONOSFlowTimeProp ) {
+		    ++numPropsSet;
+		}
 	}
 	if (flowPath.flowEntryMatch().matchVlanPriority()) {
 	    flowObj.setMatchVlanPriority(flowPath.flowEntryMatch().vlanPriority());
+		if ( measureONOSFlowTimeProp ) {
+		    ++numPropsSet;
+		}
 	}
 	if (flowPath.flowEntryMatch().matchSrcIPv4Net()) {
 	    flowObj.setMatchSrcIPv4Net(flowPath.flowEntryMatch().srcIPv4Net().toString());
+		if ( measureONOSFlowTimeProp ) {
+		    ++numPropsSet;
+		}
 	}
 	if (flowPath.flowEntryMatch().matchDstIPv4Net()) {
 	    flowObj.setMatchDstIPv4Net(flowPath.flowEntryMatch().dstIPv4Net().toString());
+		if ( measureONOSFlowTimeProp ) {
+		    ++numPropsSet;
+		}
 	}
 	if (flowPath.flowEntryMatch().matchIpProto()) {
 	    flowObj.setMatchIpProto(flowPath.flowEntryMatch().ipProto());
+		if ( measureONOSFlowTimeProp ) {
+		    ++numPropsSet;
+		}
 	}
 	if (flowPath.flowEntryMatch().matchIpToS()) {
 	    flowObj.setMatchIpToS(flowPath.flowEntryMatch().ipToS());
+		if ( measureONOSFlowTimeProp ) {
+		    ++numPropsSet;
+		}
 	}
 	if (flowPath.flowEntryMatch().matchSrcTcpUdpPort()) {
 	    flowObj.setMatchSrcTcpUdpPort(flowPath.flowEntryMatch().srcTcpUdpPort());
+		if ( measureONOSFlowTimeProp ) {
+		    ++numPropsSet;
+		}
 	}
 	if (flowPath.flowEntryMatch().matchDstTcpUdpPort()) {
 	    flowObj.setMatchDstTcpUdpPort(flowPath.flowEntryMatch().dstTcpUdpPort());
+		if ( measureONOSFlowTimeProp ) {
+		    ++numPropsSet;
+		}
 	}
 	if (! flowPath.flowEntryActions().actions().isEmpty()) {
 	    flowObj.setActions(flowPath.flowEntryActions().toString());
+		if ( measureONOSFlowTimeProp ) {
+		    ++numPropsSet;
+		}
 	}
 	flowObj.setDataPathSummary(flowPath.dataPath().dataPathSummary());
+	if ( measureONOSFlowTimeProp ) {
+	    ++numPropsSet;
+	}
 
 	if (found)
 	    flowObj.setFlowPathUserState("FP_USER_MODIFY");
 	else
 	    flowObj.setFlowPathUserState("FP_USER_ADD");
 
+	if ( measureONOSFlowTimeProp ) {
+	    ++numPropsSet;
+	}
+
+	if ( measureONOSFlowTimeProp ) {
+		endSettingFlowPathProps = System.nanoTime();
+	}
 	// Flow edges:
 	//   HeadFE
 
@@ -170,13 +267,60 @@
 	    if (flowEntry.flowEntryUserState() == FlowEntryUserState.FE_USER_DELETE)
 		continue;	// Skip: all Flow Entries were deleted earlier
 
-	    if (addFlowEntry(dbHandler, flowObj, flowEntry) == null) {
+	    long startAddFlowEntry = 0, endAddFlowEntry;
+	    if( measureONOSFlowTimeProp ) {
+		startAddFlowEntry = System.nanoTime();
+	    }
+	    IFlowEntry iFlowEntry = addFlowEntry(dbHandler, flowObj, flowEntry);
+	    if( measureONOSFlowTimeProp ) {
+		endAddFlowEntry = System.nanoTime();
+		accTimeAddFlowEntries += endAddFlowEntry - startAddFlowEntry;
+
+		flowEntryTimes.addLast( new long[]{flowEntry.flowId().value(), endAddFlowEntry - startAddFlowEntry} );
+	    }
+	    if ( iFlowEntry == null) {
 		dbHandler.rollback();
 		return false;
 	    }
 	}
 	dbHandler.commit();
 
+
+	if ( measureONOSFlowTimeProp ) {
+	    endAddFlow = System.nanoTime();
+
+	    log.debug("Performance addFlow(_,{}) -- "
+		    + "GrandTotal: {} "
+		    + "only FlowPathTotal: {} "
+		    + "searchExistingFlowPath: {} "
+		    + "createNewFlowPathTime: {}"
+		    + "followExistingFlowEntries: {} "
+		    + "accTimeRemovingFlowEntriesFromFlowPath: {} "
+		    + "accTimeRemovingFlowEntriesFromDB: {} "
+		    + "settingFlowPathProps: {} #Props: {} "
+		    + "accFlowEntries: {} #FEs: {}",
+		    flowPath.flowId(),
+		    (endAddFlow - startAddFlow),
+		    (endSettingFlowPathProps - startAddFlow),
+		    (endSearchExistingFlowPathTime - startAddFlow),
+		    (endCreateNewFlowPathTime - endSearchExistingFlowPathTime),
+		    (endFollowExistingFlowEntries - startFollowExistingFlowEntries),
+		    (accTimeRemovingFlowEntriesFromFlowPath),
+		    (accTimeRemovingFlowEntriesFromDB),
+		    (endSettingFlowPathProps - startSettingFlowPathProps), numPropsSet,
+		    accTimeAddFlowEntries, numNewFlowEntries
+		    );
+
+	    // Each FlowEntries
+	    final String strFlowId = flowPath.flowId().toString();
+	    for ( long[] idFE_Time : flowEntryTimes ) {
+		log.debug("Performance addFlowEntry(_,{},{})@addFlow -- FlowEntryTotal: {}",
+			strFlowId,
+			"0x" + Long.toHexString(idFE_Time[0]),
+			idFE_Time[1]);
+	    }
+	}
+
 	return true;
     }
 
@@ -221,7 +365,7 @@
 	flowEntryObj.setFlowEntryId(flowEntry.flowEntryId().toString());
 	flowEntryObj.setType("flow_entry");
 
-	// 
+	//
 	// Set the Flow Entry Edges and attributes:
 	// - Switch edge
 	// - InPort edge