Fix NSB NFVi metrics accuracy

JIRA: YARDSTICK-1212

Change-Id: Ic4d4a3c00e4e278f4de06cc176ff663892895569
Signed-off-by: Xavier Simonart <xavier.simonart@intel.com>

6 files changed, 82 insertions, 62 deletions

diff --git a/tests/unit/network_services/vnf_generic/vnf/test_prox_helpers.py b/tests/unit/network_services/vnf_generic/vnf/test_prox_helpers.py
index bc48f994c..301a90cfe 100644
--- a/tests/unit/network_services/vnf_generic/vnf/test_prox_helpers.py
+++ b/tests/unit/network_services/vnf_generic/vnf/test_prox_helpers.py
@@ -1,3 +1,4 @@
+
 # Copyright (c) 2016-2017 Intel Corporation
 #
 # Licensed under the Apache License, Version 2.0 (the "License");
@@ -151,12 +152,12 @@ class TestProxTestDataTuple(unittest.TestCase):
         self.assertEqual(prox_test_data.latency, 6)
         self.assertEqual(prox_test_data.rx_total, 7)
         self.assertEqual(prox_test_data.tx_total, 8)
-        self.assertEqual(prox_test_data.pps, 9)
+        self.assertEqual(prox_test_data.requested_pps, 9)
 
     def test_properties(self):
         prox_test_data = ProxTestDataTuple(1, 2, 3, 4, 5, 6, 7, 8, 9)
         self.assertEqual(prox_test_data.pkt_loss, 12.5)
-        self.assertEqual(prox_test_data.mpps, 1.6 / 1e6)
+        self.assertEqual(prox_test_data.tx_mpps, 1.6 / 1e6)
         self.assertEqual(prox_test_data.can_be_lost, 0)
         self.assertEqual(prox_test_data.drop_total, 1)
         self.assertFalse(prox_test_data.success)
@@ -172,11 +173,12 @@ class TestProxTestDataTuple(unittest.TestCase):
         prox_test_data = ProxTestDataTuple(1, 2, 3, 4, 5, [6.1, 6.9, 6.4], 7, 8, 9)
 
         expected = {
-            "Throughput": 1.6 / 1e6,
+            "Throughput": 1.2 / 1e6,
             "DropPackets": 12.5,
             "CurrentDropPackets": 12.5,
-            "TxThroughput": 9 / 1e6,
-            "RxThroughput": 1.6 / 1e6,
+            "RequestedTxThroughput": 9 / 1e6,
+            "TxThroughput": 1.6 / 1e6,
+            "RxThroughput": 1.2 / 1e6,
             "PktSize": 64,
             "PortSample": 1,
             "LatencyMin": 6.1,
@@ -187,11 +189,12 @@ class TestProxTestDataTuple(unittest.TestCase):
         self.assertDictEqual(result, expected)
 
         expected = {
-            "Throughput": 1.6 / 1e6,
+            "Throughput": 1.2 / 1e6,
             "DropPackets": 0.123,
             "CurrentDropPackets": 0.123,
-            "TxThroughput": 9 / 1e6,
-            "RxThroughput": 1.6 / 1e6,
+            "RequestedTxThroughput": 9 / 1e6,
+            "TxThroughput": 1.6 / 1e6,
+            "RxThroughput": 1.2 / 1e6,
             "PktSize": 64,
             "LatencyMin": 6.1,
             "LatencyMax": 6.9,
@@ -200,17 +203,17 @@ class TestProxTestDataTuple(unittest.TestCase):
         result = prox_test_data.get_samples(64, 0.123)
         self.assertDictEqual(result, expected)
 
-    @mock.patch('yardstick.network_services.vnf_generic.vnf.prox_helpers.LOG')
+    @mock.patch('yardstick.LOG_RESULT', create=True)
     def test_log_data(self, mock_logger):
         my_mock_logger = mock.MagicMock()
         prox_test_data = ProxTestDataTuple(1, 2, 3, 4, 5, [6.1, 6.9, 6.4], 7, 8, 9)
         prox_test_data.log_data()
         self.assertEqual(my_mock_logger.debug.call_count, 0)
-        self.assertEqual(mock_logger.debug.call_count, 2)
+        self.assertEqual(mock_logger.debug.call_count, 0)
 
         mock_logger.debug.reset_mock()
         prox_test_data.log_data(my_mock_logger)
-        self.assertEqual(my_mock_logger.debug.call_count, 2)
+        self.assertEqual(my_mock_logger.debug.call_count, 0)
         self.assertEqual(mock_logger.debug.call_count, 0)
 
 
@@ -334,17 +337,17 @@ class TestProxSocketHelper(unittest.TestCase):
         mock_select.select.side_effect = chain([[object()], [None]], repeat([1], 3))
         mock_recv.decode.return_value = PACKET_DUMP_2
         ret = prox.get_data()
-        self.assertEqual(mock_select.select.call_count, 2)
+        self.assertEqual(mock_select.select.call_count, 1)
         self.assertEqual(ret, 'jumped over')
         self.assertEqual(len(prox._pkt_dumps), 3)
 
     def test__parse_socket_data_mixed_data(self):
         prox = ProxSocketHelper(mock.MagicMock())
-        ret = prox._parse_socket_data(PACKET_DUMP_NON_1, False)
+        ret, _ = prox._parse_socket_data(PACKET_DUMP_NON_1, False)
         self.assertEqual(ret, 'not_a_dump,1,2')
         self.assertEqual(len(prox._pkt_dumps), 0)
 
-        ret = prox._parse_socket_data(PACKET_DUMP_MIXED_1, False)
+        ret, _ = prox._parse_socket_data(PACKET_DUMP_MIXED_1, False)
         self.assertEqual(ret, 'not_a_dump,1,2')
         self.assertEqual(len(prox._pkt_dumps), 1)
 
@@ -356,18 +359,18 @@ class TestProxSocketHelper(unittest.TestCase):
         with self.assertRaises(ValueError):
             prox._parse_socket_data(PACKET_DUMP_BAD_2, False)
 
-        ret = prox._parse_socket_data(PACKET_DUMP_BAD_3, False)
+        ret, _ = prox._parse_socket_data(PACKET_DUMP_BAD_3, False)
         self.assertEqual(ret, 'pktdump,3')
 
     def test__parse_socket_data_pkt_dump_only(self):
         prox = ProxSocketHelper(mock.MagicMock())
-        ret = prox._parse_socket_data('', True)
+        ret, _ = prox._parse_socket_data('', True)
         self.assertFalse(ret)
 
-        ret = prox._parse_socket_data(PACKET_DUMP_1, True)
+        ret, _ = prox._parse_socket_data(PACKET_DUMP_1, True)
         self.assertTrue(ret)
 
-        ret = prox._parse_socket_data(PACKET_DUMP_2, True)
+        ret, _ = prox._parse_socket_data(PACKET_DUMP_2, True)
         self.assertTrue(ret)
 
     def test_put_command(self):
@@ -1542,7 +1545,7 @@ class TestProxDataHelper(unittest.TestCase):
 
         self.assertEqual(data_helper.rx_total, 6)
         self.assertEqual(data_helper.tx_total, 7)
-        self.assertEqual(data_helper.pps, 6.25e6)
+        self.assertEqual(data_helper.requested_pps, 6.25e6)
 
     def test_samples(self):
         vnfd_helper = mock.MagicMock()
diff --git a/yardstick/network_services/traffic_profile/prox_binsearch.py b/yardstick/network_services/traffic_profile/prox_binsearch.py
index 1e926aca2..225ee4356 100644
--- a/yardstick/network_services/traffic_profile/prox_binsearch.py
+++ b/yardstick/network_services/traffic_profile/prox_binsearch.py
@@ -108,7 +108,6 @@ class ProxBinSearchProfile(ProxProfile):
                                                                  self.tolerated_loss,
                                                                  line_speed)
             self.curr_time = time.time()
-            diff_time = self.curr_time - self.prev_time
             self.prev_time = self.curr_time
 
             if result.success:
@@ -120,10 +119,11 @@ class ProxBinSearchProfile(ProxProfile):
                 # store results with success tag in influxdb
                 success_samples = {'Success_' + key: value for key, value in samples.items()}
 
-                success_samples["Success_rx_total"] = int(result.rx_total / diff_time)
-                success_samples["Success_tx_total"] = int(result.tx_total / diff_time)
-                success_samples["Success_can_be_lost"] = int(result.can_be_lost / diff_time)
-                success_samples["Success_drop_total"] = int(result.drop_total / diff_time)
+                # Store number of packets based statistics (we already have throughput)
+                success_samples["Success_rx_total"] = int(result.rx_total)
+                success_samples["Success_tx_total"] = int(result.tx_total)
+                success_samples["Success_can_be_lost"] = int(result.can_be_lost)
+                success_samples["Success_drop_total"] = int(result.drop_total)
                 self.queue.put(success_samples)
 
                 # Store Actual throughput for result samples
@@ -133,20 +133,16 @@ class ProxBinSearchProfile(ProxProfile):
                 LOG.debug("Failure... Decreasing upper bound")
                 self.current_upper = test_value
                 samples = result.get_samples(pkt_size, successful_pkt_loss, port_samples)
+                # samples  contains data such as Latency, Throughput, number of packets
+                # Hence they should not be divided by the time difference
 
-            for k in samples:
-                    tmp = samples[k]
-                    if isinstance(tmp, dict):
-                        for k2 in tmp:
-                            samples[k][k2] = int(samples[k][k2] / diff_time)
-
-            if theor_max_thruput < samples["TxThroughput"]:
-                theor_max_thruput = samples['TxThroughput']
+            if theor_max_thruput < samples["RequestedTxThroughput"]:
+                theor_max_thruput = samples['RequestedTxThroughput']
                 self.queue.put({'theor_max_throughput': theor_max_thruput})
 
             LOG.debug("Collect TG KPIs %s %s", datetime.datetime.now(), samples)
             self.queue.put(samples)
 
         result_samples["Result_pktSize"] = pkt_size
-        result_samples["Result_theor_max_throughput"] = theor_max_thruput/(1000 * 1000)
+        result_samples["Result_theor_max_throughput"] = theor_max_thruput
         self.queue.put(result_samples)
diff --git a/yardstick/network_services/vnf_generic/vnf/prox_helpers.py b/yardstick/network_services/vnf_generic/vnf/prox_helpers.py
index 31ed30140..7816c6d91 100644
--- a/yardstick/network_services/vnf_generic/vnf/prox_helpers.py
+++ b/yardstick/network_services/vnf_generic/vnf/prox_helpers.py
@@ -44,6 +44,8 @@ SECTION_CONTENTS = 1
 
 LOG = logging.getLogger(__name__)
 LOG.setLevel(logging.DEBUG)
+LOG_RESULT = logging.getLogger('yardstick')
+LOG_RESULT.setLevel(logging.DEBUG)
 
 BITS_PER_BYTE = 8
 RETRY_SECONDS = 60
@@ -123,7 +125,8 @@ class TotStatsTuple(namedtuple('TotStats', 'rx,tx,tsc,hz')):
 
 class ProxTestDataTuple(namedtuple('ProxTestDataTuple', 'tolerated,tsc_hz,delta_rx,'
                                                         'delta_tx,delta_tsc,'
-                                                        'latency,rx_total,tx_total,pps')):
+                                                        'latency,rx_total,tx_total,'
+                                                        'requested_pps')):
     @property
     def pkt_loss(self):
         try:
@@ -132,11 +135,16 @@ class ProxTestDataTuple(namedtuple('ProxTestDataTuple', 'tolerated,tsc_hz,delta_
             return 100.0
 
     @property
-    def mpps(self):
+    def tx_mpps(self):
         # calculate the effective throughput in Mpps
         return float(self.delta_tx) * self.tsc_hz / self.delta_tsc / 1e6
 
     @property
+    def rx_mpps(self):
+        # calculate the effective throughput in Mpps
+        return float(self.delta_rx) * self.tsc_hz / self.delta_tsc / 1e6
+
+    @property
     def can_be_lost(self):
         return int(self.tx_total * self.tolerated / 1e2)
 
@@ -162,11 +170,12 @@ class ProxTestDataTuple(namedtuple('ProxTestDataTuple', 'tolerated,tsc_hz,delta_
         ]
 
         samples = {
-            "Throughput": self.mpps,
+            "Throughput": self.rx_mpps,
+            "RxThroughput": self.rx_mpps,
             "DropPackets": pkt_loss,
             "CurrentDropPackets": pkt_loss,
-            "TxThroughput": self.pps / 1e6,
-            "RxThroughput": self.mpps,
+            "RequestedTxThroughput": self.requested_pps / 1e6,
+            "TxThroughput": self.tx_mpps,
             "PktSize": pkt_size,
         }
         if port_samples:
@@ -177,11 +186,12 @@ class ProxTestDataTuple(namedtuple('ProxTestDataTuple', 'tolerated,tsc_hz,delta_
 
     def log_data(self, logger=None):
         if logger is None:
-            logger = LOG
+            logger = LOG_RESULT
 
         template = "RX: %d; TX: %d; dropped: %d (tolerated: %d)"
-        logger.debug(template, self.rx_total, self.tx_total, self.drop_total, self.can_be_lost)
-        logger.debug("Mpps configured: %f; Mpps effective %f", self.pps / 1e6, self.mpps)
+        logger.info(template, self.rx_total, self.tx_total, self.drop_total, self.can_be_lost)
+        logger.info("Mpps configured: %f; Mpps generated %f; Mpps received %f",
+                    self.requested_pps / 1e6, self.tx_mpps, self.rx_mpps)
 
 
 class PacketDump(object):
@@ -288,7 +298,7 @@ class ProxSocketHelper(object):
             if mode != 'pktdump':
                 # Regular 1-line message. Stop reading from the socket.
                 LOG.debug("Regular response read")
-                return ret_str
+                return ret_str, True
 
             LOG.debug("Packet dump header read: [%s]", ret_str)
 
@@ -309,11 +319,11 @@ class ProxSocketHelper(object):
                 # Return boolean instead of string to signal
                 # successful reception of the packet dump.
                 LOG.debug("Packet dump stored, returning")
-                return True
+                return True, False
 
             index = data_end + 1
 
-        return ret_str
+        return ret_str, False
 
     def get_data(self, pkt_dump_only=False, timeout=1):
         """ read data from the socket """
@@ -352,7 +362,9 @@ class ProxSocketHelper(object):
         ret_str = ""
         for status in iter(is_ready, False):
             decoded_data = self._sock.recv(256).decode('utf-8')
-            ret_str = self._parse_socket_data(decoded_data, pkt_dump_only)
+            ret_str, done = self._parse_socket_data(decoded_data, pkt_dump_only)
+            if (done):
+                break
 
         LOG.debug("Received data from socket: [%s]", ret_str)
         return ret_str if status else ''
@@ -1001,8 +1013,8 @@ class ProxDataHelper(object):
     def totals_and_pps(self):
         if self._totals_and_pps is None:
             rx_total, tx_total = self.sut.port_stats(range(self.port_count))[6:8]
-            pps = self.value / 100.0 * self.line_rate_to_pps()
-            self._totals_and_pps = rx_total, tx_total, pps
+            requested_pps = self.value / 100.0 * self.line_rate_to_pps()
+            self._totals_and_pps = rx_total, tx_total, requested_pps
         return self._totals_and_pps
 
     @property
@@ -1014,7 +1026,7 @@ class ProxDataHelper(object):
         return self.totals_and_pps[1]
 
     @property
-    def pps(self):
+    def requested_pps(self):
         return self.totals_and_pps[2]
 
     @property
@@ -1055,7 +1067,7 @@ class ProxDataHelper(object):
             self.latency,
             self.rx_total,
             self.tx_total,
-            self.pps,
+            self.requested_pps,
         )
         self.result_tuple.log_data()
 
@@ -1134,6 +1146,7 @@ class ProxProfileHelper(object):
             self.sut.set_pkt_size(self.test_cores, pkt_size)
             self.sut.set_speed(self.test_cores, value)
             self.sut.start_all()
+            time.sleep(1)
             yield
         finally:
             self.sut.stop_all()
@@ -1246,6 +1259,7 @@ class ProxMplsProfileHelper(ProxProfileHelper):
             ratio = 1.0 * (pkt_size - 4 + 20) / (pkt_size + 20)
             self.sut.set_speed(self.plain_cores, value * ratio)
             self.sut.start_all()
+            time.sleep(1)
             yield
         finally:
             self.sut.stop_all()
diff --git a/yardstick/network_services/vnf_generic/vnf/prox_vnf.py b/yardstick/network_services/vnf_generic/vnf/prox_vnf.py
index 285e08659..36f1a19d0 100644
--- a/yardstick/network_services/vnf_generic/vnf/prox_vnf.py
+++ b/yardstick/network_services/vnf_generic/vnf/prox_vnf.py
@@ -15,8 +15,6 @@
 import errno
 import logging
 import datetime
-import time
-
 
 from yardstick.common.process import check_if_process_failed
 from yardstick.network_services.vnf_generic.vnf.prox_helpers import ProxDpdkVnfSetupEnvHelper
@@ -44,7 +42,8 @@ class ProxApproxVnf(SampleVNF):
 
         self.prev_packets_in = 0
         self.prev_packets_sent = 0
-        self.prev_time = time.time()
+        self.prev_tsc = 0
+        self.tsc_hz = 0
         super(ProxApproxVnf, self).__init__(name, vnfd, setup_env_helper_type,
                                             resource_helper_type)
 
@@ -68,8 +67,7 @@ class ProxApproxVnf(SampleVNF):
 
     def collect_kpi(self):
         # we can't get KPIs if the VNF is down
-        check_if_process_failed(self._vnf_process)
-
+        check_if_process_failed(self._vnf_process, 0.01)
         if self.resource_helper is None:
             result = {
                 "packets_in": 0,
@@ -79,6 +77,12 @@ class ProxApproxVnf(SampleVNF):
             }
             return result
 
+        if (self.tsc_hz == 0):
+            self.tsc_hz = float(self.resource_helper.sut.hz())
+            LOG.debug("TSC = %f", self.tsc_hz)
+            if (self.tsc_hz == 0):
+                raise RuntimeError("Unable to retrieve TSC")
+
         # use all_ports so we only use ports matched in topology
         port_count = len(self.vnfd_helper.port_pairs.all_ports)
         if port_count not in {1, 2, 4}:
@@ -86,10 +90,10 @@ class ProxApproxVnf(SampleVNF):
                                "1, 2 or 4 ports only supported at this time")
 
         self.port_stats = self.vnf_execute('port_stats', range(port_count))
-        curr_time = time.time()
         try:
             rx_total = self.port_stats[6]
             tx_total = self.port_stats[7]
+            tsc = self.port_stats[10]
         except IndexError:
             LOG.debug("port_stats parse fail ")
             # return empty dict so we don't mess up existing KPIs
@@ -103,15 +107,17 @@ class ProxApproxVnf(SampleVNF):
             # collectd KPIs here and not TG KPIs, so use a different method name
             "collect_stats": self.resource_helper.collect_collectd_kpi(),
         }
-        curr_packets_in = int((rx_total - self.prev_packets_in) / (curr_time - self.prev_time))
-        curr_packets_fwd = int((tx_total - self.prev_packets_sent) / (curr_time - self.prev_time))
+        curr_packets_in = int(((rx_total - self.prev_packets_in) * self.tsc_hz)
+                                / (tsc - self.prev_tsc) * port_count)
+        curr_packets_fwd = int(((tx_total - self.prev_packets_sent) * self.tsc_hz)
+                                / (tsc - self.prev_tsc) * port_count)
 
         result["curr_packets_in"] = curr_packets_in
         result["curr_packets_fwd"] = curr_packets_fwd
 
         self.prev_packets_in = rx_total
         self.prev_packets_sent = tx_total
-        self.prev_time = curr_time
+        self.prev_tsc = tsc
 
         LOG.debug("%s collect KPIs %s %s", self.APP_NAME, datetime.datetime.now(), result)
         return result
diff --git a/yardstick/network_services/vnf_generic/vnf/sample_vnf.py b/yardstick/network_services/vnf_generic/vnf/sample_vnf.py
index 16873611e..ef8b3f126 100644
--- a/yardstick/network_services/vnf_generic/vnf/sample_vnf.py
+++ b/yardstick/network_services/vnf_generic/vnf/sample_vnf.py
@@ -825,7 +825,7 @@ class SampleVNF(GenericVNF):
 
     def collect_kpi(self):
         # we can't get KPIs if the VNF is down
-        check_if_process_failed(self._vnf_process)
+        check_if_process_failed(self._vnf_process, 0.01)
         stats = self.get_stats()
         m = re.search(self.COLLECT_KPI, stats, re.MULTILINE)
         if m:
diff --git a/yardstick/tests/unit/network_services/traffic_profile/test_prox_binsearch.py b/yardstick/tests/unit/network_services/traffic_profile/test_prox_binsearch.py
index 58343ffb2..7bfd67fe0 100644
--- a/yardstick/tests/unit/network_services/traffic_profile/test_prox_binsearch.py
+++ b/yardstick/tests/unit/network_services/traffic_profile/test_prox_binsearch.py
@@ -65,9 +65,10 @@ class TestProxBinSearchProfile(unittest.TestCase):
         self.assertEqual(len(runs), 7)
 
         # Result Samples inc theor_max
-        result_tuple = {"Result_Actual_throughput": 7.5e-07,
-                        "Result_theor_max_throughput": 1.234e-10,
-                        "Result_pktSize": 200}
+        result_tuple = {'Result_Actual_throughput': 5e-07,
+                        'Result_theor_max_throughput': 0.00012340000000000002,
+                        'Result_pktSize': 200}
+
         profile.queue.put.assert_called_with(result_tuple)
 
         success_result_tuple = {"Success_CurrentDropPackets": 0.5,