From 2378f04c1b6d333c322f93e44387c6f224dffe3e Mon Sep 17 00:00:00 2001 From: Julien Date: Tue, 27 Dec 2016 23:28:21 +0800 Subject: 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 --- tests/inspector.py | 2 ++ tests/profiler-poc.py | 4 ++-- tests/run.sh | 28 ++++++++++++++++++++++------ 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 -- cgit 1.2.3-korg