Provide timings for OSC during devstack run
The OSC number remain high, and it's useful to understand how much
time we spend making OSC calls, especially to surface it relative to
other items. The way we embed this in our code makes it hard to
instrument.
This patch creates a wrapper function for OSC which collects the timings
then aliases `openstack` to that function. This means any invocations of
the openstack utility goes through our function while devstack is
running. Because this is an alias it only affects the stack.sh shell and
any subshells.
This also moves the time tracking infrastructure to count in ms,
instead of s, because some of these operations are close enough to a
second that rounding early is losing way to many significant
digits. We divide by 1000 before reporting to the user.
Change-Id: Ic5f1844ce732d447ee980b3c9fdc417f72482609
diff --git a/functions-common b/functions-common
index ec68644..98e9a4b 100644
--- a/functions-common
+++ b/functions-common
@@ -2459,7 +2459,7 @@
if [[ -n "$start_time" ]]; then
die $LINENO "Trying to start the clock on $name, but it's already been started"
fi
- _TIME_START[$name]=$(date +%s)
+ _TIME_START[$name]=$(date +%s%3N)
}
# time_stop $name
@@ -2480,7 +2480,7 @@
if [[ -z "$start_time" ]]; then
die $LINENO "Trying to stop the clock on $name, but it was never started"
fi
- end_time=$(date +%s)
+ end_time=$(date +%s%3N)
elapsed_time=$(($end_time - $start_time))
total=${_TIME_TOTAL[$name]:-0}
# reset the clock so we can start it in the future
@@ -2488,6 +2488,49 @@
_TIME_TOTAL[$name]=$(($total + $elapsed_time))
}
+function oscwrap {
+ local out
+ local rc
+ local start
+ local end
+ # Cannot use timer_start and timer_stop as we run in subshells
+ # and those rely on modifying vars in the same process (which cannot
+ # happen from a subshell.
+ start=$(date +%s%3N)
+ out=$(command openstack "$@")
+ rc=$?
+ end=$(date +%s%3N)
+ echo $((end - start)) >> $OSCWRAP_TIMER_FILE
+
+ echo "$out"
+ return $rc
+}
+
+function install_oscwrap {
+ # File to accumulate our timing data
+ OSCWRAP_TIMER_FILE=$(mktemp)
+ # Bash by default doesn't expand aliases, allow it for the aliases
+ # we want to whitelist.
+ shopt -s expand_aliases
+ # Remove all aliases that might be expanded to preserve old unexpanded
+ # behavior
+ unalias -a
+ # Add only the alias we want for openstack
+ alias openstack=oscwrap
+}
+
+function cleanup_oscwrap {
+ local total=0
+ if python3_enabled ; then
+ local python=python3
+ else
+ local python=python
+ fi
+ total=$(cat $OSCWRAP_TIMER_FILE | $python -c "import sys; print(sum(int(l) for l in sys.stdin))")
+ _TIME_TOTAL["osc"]=$total
+ rm $OSCWRAP_TIMER_FILE
+}
+
# time_totals
# Print out total time summary
function time_totals {
@@ -2506,6 +2549,8 @@
fi
done
+ cleanup_oscwrap
+
xtrace=$(set +o | grep xtrace)
set +o xtrace
@@ -2517,6 +2562,8 @@
echo
for t in ${!_TIME_TOTAL[*]}; do
local v=${_TIME_TOTAL[$t]}
+ # because we're recording in milliseconds
+ v=$(($v / 1000))
printf "%-${len}s %3d\n" "$t" "$v"
done
echo "========================="
diff --git a/stack.sh b/stack.sh
index 20cdc1d..89b61fc 100755
--- a/stack.sh
+++ b/stack.sh
@@ -493,6 +493,11 @@
kill 2>&1 $jobs
fi
+ #Remove timing data file
+ if [ -f "$OSCWRAP_TIMER_FILE" ] ; then
+ rm "$OSCWRAP_TIMER_FILE"
+ fi
+
# Kill the last spinner process
kill_spinner
@@ -903,6 +908,10 @@
pip_install_gr python-openstackclient
fi
+# Installs alias for osc so that we can collect timing for all
+# osc commands. Alias dies with stack.sh.
+install_oscwrap
+
if [[ $TRACK_DEPENDS = True ]]; then
$DEST/.venv/bin/pip freeze > $DEST/requires-post-pip
if ! diff -Nru $DEST/requires-pre-pip $DEST/requires-post-pip > $DEST/requires.diff; then