From 84b8f0cc8b2e10a32452c4979770c08e549806a5 Mon Sep 17 00:00:00 2001
From: Daniel Verkamp <daniel.verkamp@intel.com>
Date: Thu, 8 Oct 2015 12:40:44 -0700
Subject: [PATCH] autotest: output timing in flamegraph format

Change-Id: I9f571ce635431613fc6a84e106e5052cce2dbf54
Signed-off-by: Daniel Verkamp <daniel.verkamp@intel.com>
---
 autobuild.sh               | 21 ++++++++++++++++-----
 autopackage.sh             | 12 +++++++++---
 scripts/autotest_common.sh | 28 +++++++++++++++++++++-------
 test/lib/memory/memory.sh  |  6 ++++++
 test/lib/nvme/nvme.sh      | 12 ++++++++++++
 5 files changed, 64 insertions(+), 15 deletions(-)

diff --git a/autobuild.sh b/autobuild.sh
index f1b6c570b..fb7aa9460 100755
--- a/autobuild.sh
+++ b/autobuild.sh
@@ -2,16 +2,20 @@
 
 set -e
 
-src=$(readlink -f $(dirname $0))
-source "$src/scripts/autotest_common.sh"
+rootdir=$(readlink -f $(dirname $0))
+source "$rootdir/scripts/autotest_common.sh"
 
 out=$PWD
 
 umask 022
 
-cd $src
+cd $rootdir
 
+timing_enter autobuild
+
+timing_enter check_format
 ./scripts/check_format.sh
+timing_exit check_format
 
 scanbuild=''
 if hash scan-build; then
@@ -19,8 +23,11 @@ if hash scan-build; then
 fi
 
 $MAKE $MAKEFLAGS clean
+
+timing_enter scanbuild_make
 fail=0
 time $scanbuild $MAKE $MAKEFLAGS DPDK_DIR=$DPDK_DIR || fail=1
+timing_exit scanbuild_make
 
 # Check that header file dependencies are working correctly by
 #  capturing a binary's stat data before and after touching a
@@ -41,14 +48,18 @@ if [ -d $out/scan-build-tmp ]; then
 	chmod -R a+rX $out/scan-build
 fi
 
+timing_enter doxygen
 if hash doxygen; then
-	(cd "$src"/doc; $MAKE $MAKEFLAGS)
+	(cd "$rootdir"/doc; $MAKE $MAKEFLAGS)
 	mkdir -p "$out"/doc
-	for d in "$src"/doc/output.*; do
+	for d in "$rootdir"/doc/output.*; do
 		component=$(basename "$d" | sed -e 's/^output.//')
 		mv "$d"/html "$out"/doc/$component
 		rm -rf "$d"
 	done
 fi
+timing_exit doxygen
+
+timing_exit autobuild
 
 exit $fail
diff --git a/autopackage.sh b/autopackage.sh
index 08a092fa9..09cf1271f 100755
--- a/autopackage.sh
+++ b/autopackage.sh
@@ -2,13 +2,15 @@
 
 set -xe
 
-src=$(readlink -f $(dirname $0))
-source "$src/scripts/autotest_common.sh"
+rootdir=$(readlink -f $(dirname $0))
+source "$rootdir/scripts/autotest_common.sh"
 
 out=$PWD
 
 MAKEFLAGS=${MAKEFLAGS:--j16}
-cd $src
+cd $rootdir
+
+timing_enter autopackage
 
 $MAKE clean
 
@@ -39,3 +41,7 @@ tar -C "$tmpdir" -xf $out/$tarball
 	time $MAKE ${MAKEFLAGS} DPDK_DIR=$DPDK_DIR
 )
 rm -rf "$tmpdir"
+
+timing_exit autopackage
+
+timing_finish
diff --git a/scripts/autotest_common.sh b/scripts/autotest_common.sh
index 5e752196e..14116ee07 100755
--- a/scripts/autotest_common.sh
+++ b/scripts/autotest_common.sh
@@ -38,16 +38,18 @@ function timing() {
 	now=$(date +%s)
 
 	if [ "$direction" = "enter" ]; then
-		export timing_stack="${timing_stack}/${now}"
-		export test_stack="${test_stack}/${testname}"
+		export timing_stack="${timing_stack};${now}"
+		export test_stack="${test_stack};${testname}"
 	else
-		start_time=$(echo "$timing_stack" | sed -e 's@^.*/@@')
-		timing_stack=$(echo "$timing_stack" | sed -e 's@/[^/]*$@@')
+		child_time=$(grep "^${test_stack:1};" $output_dir/timing.txt | awk '{s+=$2} END {print s}')
 
-		elapsed=$((now - start_time))
-		echo "$elapsed $test_stack" >> $output_dir/timing.txt
+		start_time=$(echo "$timing_stack" | sed -e 's@^.*;@@')
+		timing_stack=$(echo "$timing_stack" | sed -e 's@;[^;]*$@@')
 
-		test_stack=$(echo "$test_stack" | sed -e 's@/[^/]*$@@')
+		elapsed=$((now - start_time - child_time))
+		echo "${test_stack:1} $elapsed" >> $output_dir/timing.txt
+
+		test_stack=$(echo "$test_stack" | sed -e 's@;[^;]*$@@')
 	fi
 }
 
@@ -59,6 +61,18 @@ function timing_exit() {
 	timing "exit" "$1"
 }
 
+function timing_finish() {
+	flamegraph='/usr/local/FlameGraph/flamegraph.pl'
+	if [ -x "$flamegraph" ]; then
+		"$flamegraph" \
+			--title 'Build Timing' \
+			--nametype 'Step:' \
+			--countname seconds \
+			$output_dir/timing.txt \
+			>$output_dir/timing.svg
+	fi
+}
+
 function process_core() {
 	ret=0
 	for core in $(find . -type f -name 'core*'); do
diff --git a/test/lib/memory/memory.sh b/test/lib/memory/memory.sh
index abe76a10c..4b4f01f76 100755
--- a/test/lib/memory/memory.sh
+++ b/test/lib/memory/memory.sh
@@ -4,5 +4,11 @@ testdir=$(readlink -f $(dirname $0))
 rootdir="$testdir/../../.."
 source $rootdir/scripts/autotest_common.sh
 
+timing_enter memory
+
+timing_enter vtophys
 $testdir/vtophys
 process_core
+timing_exit vtophys
+
+timing_exit memory
diff --git a/test/lib/nvme/nvme.sh b/test/lib/nvme/nvme.sh
index 7750342ea..c854c2a79 100755
--- a/test/lib/nvme/nvme.sh
+++ b/test/lib/nvme/nvme.sh
@@ -4,17 +4,29 @@ testdir=$(readlink -f $(dirname $0))
 rootdir="$testdir/../../.."
 source $rootdir/scripts/autotest_common.sh
 
+timing_enter nvme
+
+timing_enter unit
 $valgrind $testdir/unit/nvme_ns_cmd_c/nvme_ns_cmd_ut
 $testdir/unit/nvme_c/nvme_ut
 $valgrind $testdir/unit/nvme_qpair_c/nvme_qpair_ut
 $valgrind $testdir/unit/nvme_ctrlr_c/nvme_ctrlr_ut
 $valgrind $testdir/unit/nvme_ctrlr_cmd_c/nvme_ctrlr_cmd_ut
+timing_exit unit
 
+timing_enter aer
 $testdir/aer/aer
 process_core
+timing_exit aer
 
+timing_enter identify
 $rootdir/examples/nvme/identify/identify
 process_core
+timing_exit identify
 
+timing_enter perf
 $rootdir/examples/nvme/perf/perf -q 128 -w read -s 4096 -t 5
 process_core
+timing_exit perf
+
+timing_exit nvme