commit 363c395de791b41381c5390814c59d3c0500f34a
author David Riley <davidriley@chromium.org> Fri Dec 01 16:23:59 2017 -0800
committer chrome-bot <chrome-bot@chromium.org> Tue Dec 12 11:09:10 2017 -0800
tree e8c31c0f68a7a7393f961ad1a95e48160b4e5045
parent 6c46725190160d9fe677852864551564cc9cab93

quick-provision: Add timing keyvals.

BUG=chromium:779870
TEST=curl "http://${ds}/stage?archive_url=gs://chromeos-image-archive/${buil d}&artifacts=quick_provision,stateful"; curl "http://${ds}/cros_au?full_update=False&force_update=True&build_name=${build}&host_name=${dut}&async=False&clobber_stateful=True&quick_provision=True"

Change-Id: Id06ff73178f9e16abfabdc392c8b598104efac78
Reviewed-on: https://chromium-review.googlesource.com/804962
Commit-Ready: David Riley <davidriley@chromium.org>
Tested-by: David Riley <davidriley@chromium.org>
Reviewed-by: Mike Frysinger <vapier@chromium.org>

quick-provision/quick-provision

diff --git a/quick-provision/quick-provision b/quick-provision/quick-provision
index f0fad1d..e384ed9 100644
--- a/quick-provision/quick-provision
+++ b/quick-provision/quick-provision
@@ -67,6 +67,32 @@
   exit 1
 }
 
+# Get the current time as a timestamp.
+get_timestamp() {
+  date +%s
+}
+
+# Generate keyvals based on the timing of an event.
+end_timing() {
+  local start_time="$1"
+  local event_name="$2"
+
+  local end_time="$(get_timestamp)"
+  local elapsed_time="$((end_time - start_time))"
+
+  keyval "${event_name}_start=${start_time}"
+  keyval "${event_name}_end=${end_time}"
+  keyval "${event_name}_elapsed=${elapsed_time}"
+}
+
+time_cmd() {
+  local event_name="$1"
+  shift
+  local start_time="$(get_timestamp)"
+  "$@"
+  end_timing "${start_time}" "${event_name}"
+}
+
 # Attempt to post a status update for the provision process.
 # Requires status_url FLAGS to be set.
 post_status() {
@@ -116,8 +142,8 @@
 
   # TODO(davidriley): Enable blkdiscard when moving to verifying zero blocks
   # before writing them.
-  # info blkdiscard ${part}
-  # blkdiscard ${part}
+  # info blkdiscard "${part}"
+  # blkdiscard "${part}"
 
   info Updating "${part}" with "${url}"
   get_url_to_stdout "${url}" | gzip -d | write_partition "${part}"
@@ -178,12 +204,14 @@
 }
 
 main() {
-  if [[ $# -ne 2 ]]; then
+  if [[ "$#" -ne 2 ]]; then
     usage "ERROR: Incorrect number of arguments."
   fi
   local build="$1"
   local static_url="$2"
 
+  local script_start_time="$(get_timestamp)"
+
   info "Provisioning ${build} from ${static_url}"
   keyval "BOOT_ID=$(</proc/sys/kernel/random/boot_id)"
   keyval "$(grep CHROMEOS_RELEASE_BUILDER_PATH /etc/lsb-release | \
@@ -228,24 +256,30 @@
   # Kernel.
   info "Update kernel ${NEXT_KERN}"
   post_status "DUT: Updating kernel ${NEXT_KERN}"
-  update_partition "${static_url}/${build}/${KERN_IMAGE}" ${NEXT_KERN}
+  time_cmd UPDATE_KERNEL \
+    update_partition "${static_url}/${build}/${KERN_IMAGE}" ${NEXT_KERN}
 
   # Rootfs.
   info "Update rootfs ${NEXT_ROOT}"
   post_status "DUT: Updating rootfs ${NEXT_ROOT}"
-  update_partition "${static_url}/${build}/${ROOT_IMAGE}" ${NEXT_ROOT}
+  time_cmd UPDATE_ROOTFS \
+    update_partition "${static_url}/${build}/${ROOT_IMAGE}" ${NEXT_ROOT}
 
   # Stateful.
-  stateful_update "${static_url}/${build}/${STATEFUL_TGZ}"
+  time_cmd UPDATE_STATEFUL \
+    stateful_update "${static_url}/${build}/${STATEFUL_TGZ}"
 
   # Boot the next kernel.
-  set_next_kernel "${NEXT_KERN_PART}"
+  time_cmd SET_NEXT_KERNEL \
+    set_next_kernel "${NEXT_KERN_PART}"
 
   # Reboot in the background, giving time for the ssh invocation to
   # cleanly terminate.
   info "Reboot (into ${build})"
   post_status "DUT: Reboot"
   (sleep 2; reboot) &
+
+  end_timing "${script_start_time}" QUICK_PROVISION
 }
 
 main "$@" |& tee -a "${FLAGS_logfile}"