Merge into master from pull request #121:
Profiling and configurable negative timeouts (https://github.com/floodlight/oftest/pull/121)
diff --git a/oft b/oft
index 4ef82eb..9d5df6a 100755
--- a/oft
+++ b/oft
@@ -77,12 +77,14 @@
"log_file" : "oft.log",
"log_dir" : None,
"debug" : "verbose",
+ "profile" : False,
# Test behavior options
"relax" : False,
"test_params" : "None",
"fail_skipped" : False,
- "default_timeout" : 2,
+ "default_timeout" : 2.0,
+ "default_negative_timeout" : 0.01,
"minsize" : 0,
"random_seed" : None,
"disable_ipv6" : False,
@@ -179,6 +181,7 @@
const="verbose", help="Shortcut for --debug=verbose")
group.add_option("-q", "--quiet", action="store_const", dest="debug",
const="warning", help="Shortcut for --debug=warning")
+ group.add_option("--profile", action="store_true", help="Write Python profile to profile.out")
parser.add_option_group(group)
group = optparse.OptionGroup(parser, "Test behavior options")
@@ -189,8 +192,10 @@
group.add_option("-t", "--test-params", help=test_params_help)
group.add_option("--fail-skipped", action="store_true",
help="Return failure if any test was skipped")
- group.add_option("--default-timeout", type="int",
+ group.add_option("--default-timeout", type=float,
help="Timeout in seconds for most operations")
+ group.add_option("--default-negative-timeout", type=float,
+ help="Timeout in seconds for negative checks")
group.add_option("--minsize", type="int",
help="Minimum allowable packet size on the dataplane.")
group.add_option("--random-seed", type="int",
@@ -491,6 +496,7 @@
logging.info("OF port map: " + str(config["port_map"]))
oftest.ofutils.default_timeout = config["default_timeout"]
+oftest.ofutils.default_negative_timeout = config["default_negative_timeout"]
oftest.testutils.MINSIZE = config['minsize']
if os.getuid() != 0 and not config["allow_user"]:
@@ -512,6 +518,11 @@
signal.signal(signal.SIGINT, signal.SIG_DFL)
if __name__ == "__main__":
+ if config["profile"]:
+ import cProfile
+ profiler = cProfile.Profile()
+ profiler.enable()
+
# Set up the dataplane
oftest.dataplane_instance = oftest.dataplane.DataPlane(config)
pcap_setup(config)
@@ -532,6 +543,10 @@
oftest.dataplane_instance.kill()
oftest.dataplane_instance = None
+ if config["profile"]:
+ profiler.disable()
+ profiler.dump_stats("profile.out")
+
if result.failures or result.errors:
# exit(1) hangs sometimes
os._exit(1)
diff --git a/src/python/oftest/ofutils.py b/src/python/oftest/ofutils.py
index 8cf2ae0..f81a2f5 100644
--- a/src/python/oftest/ofutils.py
+++ b/src/python/oftest/ofutils.py
@@ -10,6 +10,7 @@
import logging
default_timeout = None # set by oft
+default_negative_timeout = None # set by oft
def gen_xid():
return random.randrange(1,0xffffffff)
@@ -19,11 +20,9 @@
The condition variable must already be acquired.
The timeout value -1 means use the default timeout.
There is deliberately no support for an infinite timeout.
-TODO: get the default timeout from configuration
"""
def timed_wait(cv, fn, timeout=-1):
if timeout == -1:
- # TODO make this configurable
timeout = default_timeout
end_time = time.time() + timeout
diff --git a/src/python/oftest/testutils.py b/src/python/oftest/testutils.py
index 5b2e365..104d3b5 100644
--- a/src/python/oftest/testutils.py
+++ b/src/python/oftest/testutils.py
@@ -576,11 +576,6 @@
DEPRECATED in favor in verify_packets
"""
- # Wait this long for packets that we don't expect to receive.
- # 100ms is (rarely) too short for positive tests on slow
- # switches but is definitely not too short for a negative test.
- negative_timeout = 0.1
-
exp_pkt_arg = None
if oftest.config["relax"]:
exp_pkt_arg = pkt
@@ -598,7 +593,7 @@
"Received packet does not match expected packet " +
"on port " + str(ofport))
if len(no_ports) > 0:
- time.sleep(negative_timeout)
+ time.sleep(oftest.ofutils.default_negative_timeout)
for ofport in no_ports:
logging.debug("Negative check for pkt on port " + str(ofport))
(rcv_port, rcv_pkt, pkt_time) = dp.poll(
@@ -1605,7 +1600,7 @@
# Negative test, need to wait a short amount of time before checking we
# didn't receive the message.
- time.sleep(0.5)
+ time.sleep(oftest.ofutils.default_negative_timeout)
# Check every packet_in queued in the controller
while True:
@@ -1648,7 +1643,10 @@
Check that a particular packet is not received
"""
logging.debug("Negative check for pkt on port %r", ofport)
- (rcv_port, rcv_pkt, pkt_time) = test.dataplane.poll(port_number=ofport, exp_pkt=str(pkt), timeout=0.01)
+ (rcv_port, rcv_pkt, pkt_time) = \
+ test.dataplane.poll(
+ port_number=ofport, exp_pkt=str(pkt),
+ timeout=oftest.ofutils.default_negative_timeout)
test.assertTrue(rcv_pkt == None, "Received packet on %r" % ofport)
def verify_no_other_packets(test):
@@ -1660,7 +1658,7 @@
if oftest.config["relax"]:
return
logging.debug("Checking for unexpected packets on all ports")
- (rcv_port, rcv_pkt, pkt_time) = test.dataplane.poll(timeout=0.01)
+ (rcv_port, rcv_pkt, pkt_time) = test.dataplane.poll(timeout=oftest.ofutils.default_negative_timeout)
if rcv_pkt != None:
logging.debug("Received unexpected packet on port %r: %s", rcv_port, format_packet(rcv_pkt))
test.assertTrue(rcv_pkt == None, "Unexpected packet on port %r" % rcv_port)
diff --git a/tests/latency.py b/tests/latency.py
new file mode 100644
index 0000000..3cf8c5d
--- /dev/null
+++ b/tests/latency.py
@@ -0,0 +1,107 @@
+"""
+Latency tests
+
+These tests are mostly helpful for finding an optimal value for the
+--default-negative-timeout option. If this value is too large it will
+unnecessarily some down testing, but if it is too small then tests
+may pass when they should have failed.
+
+Most of this latency is caused by OFTest. Actual switch latency should be just
+a few microseconds, but OFTest can add milliseconds on top of that.
+"""
+
+import logging
+import unittest
+import time
+
+from oftest import config
+import ofp
+import oftest.base_tests as base_tests
+
+from oftest.testutils import *
+
+class DataplaneLatency(base_tests.SimpleDataPlane):
+ """
+ Measure and assert dataplane latency
+
+ All packets must arrive within the default timeout, and 90% must
+ arrive within the default negative timeout.
+ """
+ def runTest(self):
+ in_port, out_port = openflow_ports(2)
+
+ delete_all_flows(self.controller)
+
+ pkt = str(simple_tcp_packet())
+
+ request = ofp.message.flow_add(
+ match=ofp.match(wildcards=ofp.OFPFW_ALL),
+ buffer_id=0xffffffff,
+ actions=[ofp.action.output(out_port)])
+
+ self.controller.message_send(request)
+ do_barrier(self.controller)
+
+ latencies = []
+ for i in xrange(0, 1000):
+ start_time = time.time()
+ self.dataplane.send(in_port, pkt)
+ verify_packet(self, pkt, out_port)
+ end_time = time.time()
+ latencies.append(end_time - start_time)
+
+ latencies.sort()
+
+ latency_min = latencies[0]
+ latency_90 = latencies[int(len(latencies)*0.9)]
+ latency_max = latencies[-1]
+
+ logging.debug("Minimum latency: %f ms", latency_min * 1000.0)
+ logging.debug("90%% latency: %f ms", latency_90 * 1000.0)
+ logging.debug("Maximum latency: %f ms", latency_max * 1000.0)
+
+ self.assertGreater(config["default_timeout"], latency_max)
+ self.assertGreater(config["default_negative_timeout"], latency_90)
+
+class PktinLatency(base_tests.SimpleDataPlane):
+ """
+ Measure and assert packet-in latency
+
+ All packet-ins must arrive within the default timeout, and 90% must
+ arrive within the default negative timeout.
+ """
+ def runTest(self):
+ in_port, = openflow_ports(1)
+
+ delete_all_flows(self.controller)
+
+ pkt = str(simple_tcp_packet())
+
+ request = ofp.message.flow_add(
+ match=ofp.match(wildcards=ofp.OFPFW_ALL),
+ buffer_id=0xffffffff,
+ actions=[ofp.action.output(ofp.OFPP_CONTROLLER)])
+
+ self.controller.message_send(request)
+ do_barrier(self.controller)
+
+ latencies = []
+ for i in xrange(0, 1000):
+ start_time = time.time()
+ self.dataplane.send(in_port, pkt)
+ verify_packet_in(self, pkt, in_port, ofp.OFPR_ACTION)
+ end_time = time.time()
+ latencies.append(end_time - start_time)
+
+ latencies.sort()
+
+ latency_min = latencies[0]
+ latency_90 = latencies[int(len(latencies)*0.9)]
+ latency_max = latencies[-1]
+
+ logging.debug("Minimum latency: %f ms", latency_min * 1000.0)
+ logging.debug("90%% latency: %f ms", latency_90 * 1000.0)
+ logging.debug("Maximum latency: %f ms", latency_max * 1000.0)
+
+ self.assertGreater(config["default_timeout"], latency_max)
+ self.assertGreater(config["default_negative_timeout"], latency_90)