Fix NSB NFVi metrics accuracy

JIRA: YARDSTICK-1212

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

3 files changed, 46 insertions, 26 deletions

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: