Browse code

add timing infrastructure to devstack

this adds a timing infrastructure to devstack to account for time
taken up by set of operations. The first instance of this is
accounting the time taken up by doing apt_get calls.

Change-Id: I855ffe9c7a75e9943106af0f70cf715c34ae25c5

Sean Dague authored on 2015/10/08 00:05:59
Showing 2 changed files
... ...
@@ -976,12 +976,18 @@ function apt_get {
976 976
     local sudo="sudo"
977 977
     [[ "$(id -u)" = "0" ]] && sudo="env"
978 978
 
979
+    # time all the apt operations
980
+    time_start "apt-get"
981
+
979 982
     $xtrace
980 983
 
981 984
     $sudo DEBIAN_FRONTEND=noninteractive \
982 985
         http_proxy=${http_proxy:-} https_proxy=${https_proxy:-} \
983 986
         no_proxy=${no_proxy:-} \
984 987
         apt-get --option "Dpkg::Options::=--force-confold" --assume-yes "$@"
988
+
989
+    # stop the clock
990
+    time_stop "apt-get"
985 991
 }
986 992
 
987 993
 function _parse_package_files {
... ...
@@ -2115,6 +2121,70 @@ function test_with_retry {
2115 2115
     fi
2116 2116
 }
2117 2117
 
2118
+# Timing infrastructure - figure out where large blocks of time are
2119
+# used in DevStack
2120
+#
2121
+# The timing infrastructure for DevStack is about collecting buckets
2122
+# of time that are spend in some subtask. For instance, that might be
2123
+# 'apt', 'pip', 'osc', even database migrations. We do this by a pair
2124
+# of functions: time_start / time_stop.
2125
+#
2126
+# These take a single parameter: $name - which specifies the name of
2127
+# the bucket to be accounted against. time_totals function spits out
2128
+# the results.
2129
+#
2130
+# Resolution is only in whole seconds, so should be used for long
2131
+# running activities.
2132
+
2133
+declare -A TOTAL_TIME
2134
+declare -A START_TIME
2135
+
2136
+# time_start $name
2137
+#
2138
+# starts the clock for a timer by name. Errors if that clock is
2139
+# already started.
2140
+function time_start {
2141
+    local name=$1
2142
+    local start_time=${START_TIME[$name]}
2143
+    if [[ -n "$start_time" ]]; then
2144
+        die $LINENO "Trying to start the clock on $name, but it's already been started"
2145
+    fi
2146
+    START_TIME[$name]=$(date +%s)
2147
+}
2148
+
2149
+# time_stop $name
2150
+#
2151
+# stops the clock for a timer by name, and accumulate that time in the
2152
+# global counter for that name. Errors if that clock had not
2153
+# previously been started.
2154
+function time_stop {
2155
+    local name=$1
2156
+    local start_time=${START_TIME[$name]}
2157
+    if [[ -z "$start_time" ]]; then
2158
+        die $LINENO "Trying to stop the clock on $name, but it was never started"
2159
+    fi
2160
+    local end_time=$(date +%s)
2161
+    local elapsed_time=$(($end_time - $start_time))
2162
+    local total=${TOTAL_TIME[$name]:-0}
2163
+    # reset the clock so we can start it in the future
2164
+    START_TIME[$name]=""
2165
+    TOTAL_TIME[$name]=$(($total + $elapsed_time))
2166
+}
2167
+
2168
+# time_totals
2169
+#
2170
+# prints out total time
2171
+function time_totals {
2172
+    echo
2173
+    echo "========================"
2174
+    echo "DevStack Components Timed"
2175
+    echo "========================"
2176
+    echo
2177
+    for t in ${!TOTAL_TIME[*]}; do
2178
+        local v=${TOTAL_TIME[$t]}
2179
+        echo "$t - $v secs"
2180
+    done
2181
+}
2118 2182
 
2119 2183
 # Restore xtrace
2120 2184
 $XTRACE
... ...
@@ -1366,6 +1366,8 @@ else
1366 1366
     exec 1>&3
1367 1367
 fi
1368 1368
 
1369
+# Dump out the time totals
1370
+time_totals
1369 1371
 
1370 1372
 # Using the cloud
1371 1373
 # ===============