PoC of performance profiler

- export environment variables to set check points in millisecond
- valid check points are: DOCTOR_PROFILER_T{00-09}

See also https://gerrit.opnfv.org/gerrit/#/c/26439

JIRA: DOCTOR-72

Change-Id: I5a63309fbb23934ac468c05a2e91881ec3f87b4a
Signed-off-by: Yujun Zhang <zhang.yujunz@zte.com.cn>

2 files changed, 95 insertions, 0 deletions

diff --git a/tests/profiler-poc.py b/tests/profiler-poc.py
new file mode 100644
index 00000000..f20cad1c
--- /dev/null
+++ b/tests/profiler-poc.py
@@ -0,0 +1,82 @@
+##############################################################################
+# Copyright (c) 2016 ZTE Corporation and others.
+#
+# All rights reserved. This program and the accompanying materials
+# are made available under the terms of the Apache License, Version 2.0
+# which accompanies this distribution, and is available at
+# http://www.apache.org/licenses/LICENSE-2.0
+##############################################################################
+
+"""
+PoC of performance profiler for OPNFV doctor project
+
+Usage:
+
+Export environment variables to set timestamp at each checkpoint in millisecond.
+Valid check points are: DOCTOR_PROFILER_T{00-09}
+
+See also: https://goo.gl/98Osig
+"""
+
+import os
+
+PREFIX = 'DOCTOR_PROFILER'
+TOTAL_CHECK_POINTS = 10
+MODULE_CHECK_POINTS = ['T00', 'T01', 'T04', 'T05', 'T06', 'T09']
+TAG_FORMAT = "{:<5}"
+# Inspired by https://github.com/reorx/httpstat
+TEMPLATE = """
+Total time cost: {total}(ms)
+==============================================================================>
+       |Monitor|Inspector           |Controller|Notifier|Evaluator           |
+       |{M00}  |{M01}               |{M02}     |{M03}   |{M04}               |
+       |       |      |      |      |          |        |      |      |      |
+host down:{T00}|      |      |      |          |        |      |      |      |
+     raw failure:{T01}|      |      |          |        |      |      |      |
+         found affected:{T02}|      |          |        |      |      |      |
+              marked host down:{T03}|          |        |      |      |      |
+                         set VM error:{T04}    |        |      |      |      |
+                               notified VM error:{T05}  |      |      |      |
+                                        transformed event:{T06}|      |      |
+                                                 evaluated event:{T07}|      |
+                                                            fired alarm:{T08}|
+                                                                received alarm:{T09}
+"""
+
+
+def main():
+    check_points = ["T{:02d}".format(i) for i in range(TOTAL_CHECK_POINTS)]
+    module_map = {"M{:02d}".format(i):
+                  (MODULE_CHECK_POINTS[i], MODULE_CHECK_POINTS[i + 1])
+                  for i in range(len(MODULE_CHECK_POINTS) - 1)}
+
+    # check point tags
+    elapsed_ms = {cp: os.getenv("{}_{}".format(PREFIX, cp))
+                  for cp in check_points}
+
+    def format_tag(tag):
+        return TAG_FORMAT.format(tag or '?')
+
+    tags = {cp: format_tag(ms) for cp, ms in elapsed_ms.iteritems()}
+
+    def time_cost(cp):
+        if elapsed_ms[cp[0]] and elapsed_ms[cp[1]]:
+            return int(elapsed_ms[cp[1]]) - int(elapsed_ms[cp[0]])
+        else:
+            return None
+
+    # module time cost tags
+    modules_cost_ms = {module: time_cost(cp)
+                       for module, cp in module_map.iteritems()}
+
+    tags.update({module: format_tag(cost)
+                 for module, cost in modules_cost_ms.iteritems()})
+
+    tags.update({'total': time_cost((check_points[0], check_points[-1]))})
+
+    profile = TEMPLATE.format(**tags)
+
+    print profile
+
+if __name__ == '__main__':
+    main()
diff --git a/tests/run.sh b/tests/run.sh
index 1f73f555..49011201 100755
--- a/tests/run.sh
+++ b/tests/run.sh
@@ -246,12 +246,25 @@ END_TXT
     ssh $ssh_opts_cpu "$COMPUTE_USER@$COMPUTE_IP" 'nohup ./disable_network.sh > disable_network.log 2>&1 &'
 }
 
+profile_performance_poc() {
+    total=`python -c "print(int(($notified-$detected)*1000))"`
+
+    export DOCTOR_PROFILER_T00=0
+    export DOCTOR_PROFILER_T09=$((total))
+    python profiler-poc.py
+}
+
 calculate_notification_time() {
     detected=$(grep "doctor monitor detected at" monitor.log | awk '{print $10}')
     notified=$(grep "doctor consumer notified at" consumer.log | awk '{print $10}')
     if ! grep -q "doctor consumer notified at" consumer.log ; then
         die $LINENO "Consumer hasn't received fault notification."
     fi
+
+    if [[ PROFILER == 'poc' ]]; then
+        profile_performance_poc
+    fi
+
     echo "$notified $detected" | \
         awk '{
             d = $1 - $2;