Add more timestamps and export them for profiler

Add timestamps when mark host and vm down(T03/T04).
Update the sequence for host down and vm error
Export more time tags for profiler:
    1. Calculate and export  T01,T03,T04 timestamps
    2. Use regex to get time from log instead fixed column
    3. Fix var usage without a '$'

info: merge gerrit ticket 26551 into 26531.

JIRA: DOCTOR-88

Change-Id: I3e6ccba667f470b4a00219f1e9830bb0da3d4ae5
Signed-off-by: Julien <zhang.jun3g@zte.com.cn>

3 files changed, 26 insertions, 8 deletions

diff --git a/tests/inspector.py b/tests/inspector.py
index 3a0e9ade..c1f95697 100644
--- a/tests/inspector.py
+++ b/tests/inspector.py
@@ -54,6 +54,7 @@ class DoctorInspectorSample(object):
     def disable_compute_host(self, hostname):
         for server in self.servers[hostname]:
             self.nova.servers.reset_state(server, 'error')
+            LOG.info('doctor mark vm(%s) error at %s' % (server, time.time()))
 
         # NOTE: We use our own client here instead of this novaclient for a
         #       workaround.  Once keystone provides v2.1 nova api endpoint
@@ -63,6 +64,7 @@ class DoctorInspectorSample(object):
         # self.nova.services.force_down(hostname, 'nova-compute', True)
         #
         nova_force_down.force_down(hostname)
+        LOG.info('doctor mark host(%s) down at %s' % (hostname, time.time()))
 
 
 app = Flask(__name__)
diff --git a/tests/profiler-poc.py b/tests/profiler-poc.py
index f20cad1c..1b4379d4 100644
--- a/tests/profiler-poc.py
+++ b/tests/profiler-poc.py
@@ -34,8 +34,8 @@ Total time cost: {total}(ms)
 host down:{T00}|      |      |      |          |        |      |      |      |
      raw failure:{T01}|      |      |          |        |      |      |      |
          found affected:{T02}|      |          |        |      |      |      |
-              marked host down:{T03}|          |        |      |      |      |
-                         set VM error:{T04}    |        |      |      |      |
+                  set VM error:{T03}|          |        |      |      |      |
+                         marked host down:{T04}|        |      |      |      |
                                notified VM error:{T05}  |      |      |      |
                                         transformed event:{T06}|      |      |
                                                  evaluated event:{T07}|      |
diff --git a/tests/run.sh b/tests/run.sh
index 1b21f09f..206f6a40 100755
--- a/tests/run.sh
+++ b/tests/run.sh
@@ -27,6 +27,7 @@ DOCTOR_PW=doctor
 DOCTOR_PROJECT=doctor
 #TODO: change back to `_member_` when JIRA DOCTOR-55 is done
 DOCTOR_ROLE=admin
+PROFILER_TYPE=${PROFILER_TYPE:-none}
 
 TOP_DIR=$(cd $(dirname "$0") && pwd)
 
@@ -248,21 +249,36 @@ END_TXT
 }
 
 profile_performance_poc() {
-    total=`python -c "print(int(($notified-$detected)*1000))"`
-
+    triggered=$(grep "^doctor set host down at" disable_network.log |\
+                sed -e "s/^.* at //")
+    vmdown=$(grep "doctor mark vm.* error at" inspector.log |tail -n 1 |\
+               sed -e "s/^.* at //")
+    hostdown=$(grep "doctor mark host.* down at" inspector.log |\
+               sed -e "s/^.* at //")
+
+    #calculate the relative interval to triggered(T00)
     export DOCTOR_PROFILER_T00=0
-    export DOCTOR_PROFILER_T09=$((total))
+    export DOCTOR_PROFILER_T01=$(echo "($detected-$triggered)*1000/1" |bc)
+    export DOCTOR_PROFILER_T03=$(echo "($vmdown-$triggered)*1000/1" |bc)
+    export DOCTOR_PROFILER_T04=$(echo "($hostdown-$triggered)*1000/1" |bc)
+    export DOCTOR_PROFILER_T09=$(echo "($notified-$triggered)*1000/1" |bc)
+
     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
+    #keep 'at' as the last keyword just before the value, and
+    #use regex to get value instead of the fixed column
+    detected=$(grep "doctor monitor detected at" monitor.log |\
+               sed -e "s/^.* at //")
+    notified=$(grep "doctor consumer notified at" consumer.log |\
+               sed -e "s/^.* at //")
+
+    if [[ "$PROFILER_TYPE" == "poc" ]]; then
         profile_performance_poc
     fi