Printing the total makes it easier to compare runs at a glance. Clean
up the output a little, and use some consistent, name-spaced globals
while we're there.
Note the total runtime is at the top to avoid giving the impression
that it is the sum of the components below, since you can nest/overlap
timers (I made that mistake in a prior change :). It might be a fun
exercise in tree building to one day track the overlaps and present a
nice nested breakdown.
Change-Id: I878ce03813d21138df493b82bceff3aaa7f83064
... | ... |
@@ -2322,8 +2322,9 @@ function sudo_with_proxies { |
2322 | 2322 |
# Resolution is only in whole seconds, so should be used for long |
2323 | 2323 |
# running activities. |
2324 | 2324 |
|
2325 |
-declare -A TOTAL_TIME |
|
2326 |
-declare -A START_TIME |
|
2325 |
+declare -A _TIME_TOTAL |
|
2326 |
+declare -A _TIME_START |
|
2327 |
+declare -r _TIME_BEGIN=$(date +%s) |
|
2327 | 2328 |
|
2328 | 2329 |
# time_start $name |
2329 | 2330 |
# |
... | ... |
@@ -2331,11 +2332,11 @@ declare -A START_TIME |
2331 | 2331 |
# already started. |
2332 | 2332 |
function time_start { |
2333 | 2333 |
local name=$1 |
2334 |
- local start_time=${START_TIME[$name]} |
|
2334 |
+ local start_time=${_TIME_START[$name]} |
|
2335 | 2335 |
if [[ -n "$start_time" ]]; then |
2336 | 2336 |
die $LINENO "Trying to start the clock on $name, but it's already been started" |
2337 | 2337 |
fi |
2338 |
- START_TIME[$name]=$(date +%s) |
|
2338 |
+ _TIME_START[$name]=$(date +%s) |
|
2339 | 2339 |
} |
2340 | 2340 |
|
2341 | 2341 |
# time_stop $name |
... | ... |
@@ -2351,32 +2352,53 @@ function time_stop { |
2351 | 2351 |
local start_time |
2352 | 2352 |
|
2353 | 2353 |
name=$1 |
2354 |
- start_time=${START_TIME[$name]} |
|
2354 |
+ start_time=${_TIME_START[$name]} |
|
2355 | 2355 |
|
2356 | 2356 |
if [[ -z "$start_time" ]]; then |
2357 | 2357 |
die $LINENO "Trying to stop the clock on $name, but it was never started" |
2358 | 2358 |
fi |
2359 | 2359 |
end_time=$(date +%s) |
2360 | 2360 |
elapsed_time=$(($end_time - $start_time)) |
2361 |
- total=${TOTAL_TIME[$name]:-0} |
|
2361 |
+ total=${_TIME_TOTAL[$name]:-0} |
|
2362 | 2362 |
# reset the clock so we can start it in the future |
2363 |
- START_TIME[$name]="" |
|
2364 |
- TOTAL_TIME[$name]=$(($total + $elapsed_time)) |
|
2363 |
+ _TIME_START[$name]="" |
|
2364 |
+ _TIME_TOTAL[$name]=$(($total + $elapsed_time)) |
|
2365 | 2365 |
} |
2366 | 2366 |
|
2367 | 2367 |
# time_totals |
2368 |
-# |
|
2369 |
-# prints out total time |
|
2368 |
+# Print out total time summary |
|
2370 | 2369 |
function time_totals { |
2370 |
+ local elapsed_time |
|
2371 |
+ local end_time |
|
2372 |
+ local len=15 |
|
2373 |
+ local xtrace |
|
2374 |
+ |
|
2375 |
+ end_time=$(date +%s) |
|
2376 |
+ elapsed_time=$(($end_time - $_TIME_BEGIN)) |
|
2377 |
+ |
|
2378 |
+ # pad 1st column this far |
|
2379 |
+ for t in ${!_TIME_TOTAL[*]}; do |
|
2380 |
+ if [[ ${#t} -gt $len ]]; then |
|
2381 |
+ len=${#t} |
|
2382 |
+ fi |
|
2383 |
+ done |
|
2384 |
+ |
|
2385 |
+ xtrace=$(set +o | grep xtrace) |
|
2386 |
+ set +o xtrace |
|
2387 |
+ |
|
2371 | 2388 |
echo |
2372 |
- echo "========================" |
|
2373 |
- echo "DevStack Components Timed" |
|
2374 |
- echo "========================" |
|
2389 |
+ echo "=========================" |
|
2390 |
+ echo "DevStack Component Timing" |
|
2391 |
+ echo "=========================" |
|
2392 |
+ printf "%-${len}s %3d\n" "Total runtime" "$elapsed_time" |
|
2375 | 2393 |
echo |
2376 |
- for t in ${!TOTAL_TIME[*]}; do |
|
2377 |
- local v=${TOTAL_TIME[$t]} |
|
2378 |
- echo "$t - $v secs" |
|
2394 |
+ for t in ${!_TIME_TOTAL[*]}; do |
|
2395 |
+ local v=${_TIME_TOTAL[$t]} |
|
2396 |
+ printf "%-${len}s %3d\n" "$t" "$v" |
|
2379 | 2397 |
done |
2398 |
+ echo "=========================" |
|
2399 |
+ |
|
2400 |
+ $xtrace |
|
2380 | 2401 |
} |
2381 | 2402 |
|
2382 | 2403 |
# Restore xtrace |