Monitor subcommand memory usage (#566)

* Add utility to monitor memory usage of subcommands

.travis.yml

@@ -7,6 +7,7 @@ env:
   - TEST=heroku-16 STACK=heroku-16
   - TEST=cedar-14 STACK=cedar-14
   - TEST=hatchet
+  - TEST=unit
 install:
   - if [[ -n $STACK ]]; then
       docker pull "heroku/${STACK/-/:}";

bin/compile

@@ -24,6 +24,7 @@ STDLIB_FILE=$(mktemp -t stdlib.XXXXX)
 curl --silent --retry 5 --retry-max-time 15 'https://lang-common.s3.amazonaws.com/buildpack-stdlib/v7/stdlib.sh' > "$STDLIB_FILE"
 source "$STDLIB_FILE"
 source $BP_DIR/lib/output.sh
+source $BP_DIR/lib/monitor.sh
 source $BP_DIR/lib/json.sh
 source $BP_DIR/lib/failure.sh
 source $BP_DIR/lib/environment.sh

lib/dependencies.sh

@@ -21,10 +21,10 @@ run_if_present() {
   if [ -n "$has_script" ]; then
     if $YARN; then
       echo "Running $script_name (yarn)"
-      yarn run "$script_name"
+      monitor "$script_name" yarn run "$script_name"
     else
       echo "Running $script_name"
-      npm run "$script_name" --if-present
+      monitor "$script_name" npm run "$script_name" --if-present
     fi
   fi
 }
@@ -91,7 +91,7 @@ yarn_node_modules() {
 
   echo "Installing node modules (yarn.lock)"
   cd "$build_dir"
-  yarn install --production=$production --frozen-lockfile --ignore-engines 2>&1
+  monitor "yarn-install" yarn install --production=$production --frozen-lockfile --ignore-engines 2>&1
 }
 
 yarn_prune_devdependencies() {
@@ -107,10 +107,8 @@ yarn_prune_devdependencies() {
     echo "Skipping because YARN_PRODUCTION is '$YARN_PRODUCTION'"
     return 0
   else 
-    local start=$(nowms)
     cd "$build_dir" 
-    yarn install --frozen-lockfile --ignore-engines --ignore-scripts --prefer-offline 2>&1
-    mtime "prune.yarn.time" "${start}"
+    monitor "yarn-prune" yarn install --frozen-lockfile --ignore-engines --ignore-scripts --prefer-offline 2>&1
   fi
 }
 
@@ -128,7 +126,7 @@ npm_node_modules() {
     else
       echo "Installing node modules (package.json)"
     fi
-    npm install --production=$production --unsafe-perm --userconfig $build_dir/.npmrc 2>&1
+    monitor "npm-install" npm install --production=$production --unsafe-perm --userconfig $build_dir/.npmrc 2>&1
   else
     echo "Skipping (no package.json)"
   fi
@@ -147,7 +145,7 @@ npm_rebuild() {
     else
       echo "Installing any new modules (package.json)"
     fi
-    npm install --production=$production --unsafe-perm --userconfig $build_dir/.npmrc 2>&1
+    monitor "npm-rebuild" npm install --production=$production --unsafe-perm --userconfig $build_dir/.npmrc 2>&1
   else
     echo "Skipping (no package.json)"
   fi
@@ -189,9 +187,7 @@ npm_prune_devdependencies() {
     echo "https://devcenter.heroku.com/articles/nodejs-support#specifying-an-npm-version"
     return 0
   else
-    local start=$(nowms)
     cd "$build_dir" 
-    npm prune --userconfig $build_dir/.npmrc 2>&1
-    mtime "prune.npm.time" "${start}"
+    monitor "npm-prune" npm prune --userconfig $build_dir/.npmrc 2>&1
   fi
 }

lib/monitor.sh

+
+monitor_memory_usage() {
+  local output_file="$1"
+
+  # drop the first argument, and leave other arguments in place
+  shift
+
+  # Run the command in the background
+  "${@:-}" &
+
+  # save the PID of the running command
+  pid=$!
+
+  # if this build process is SIGTERM'd
+  trap "kill -TERM $pid" TERM
+
+  # set the peak memory usage to 0 to start
+  peak="0"
+
+  while true; do
+    sleep .1
+
+    # check the memory usage
+    sample="$(ps -o rss= $pid 2> /dev/null)" || break
+
+    if [[ $sample -gt $peak ]]; then
+      peak=$sample
+    fi
+  done
+
+  # ps gives us kb, let's convert to mb for convenience
+  echo "$(($peak / 1024))" > $output_file
+
+  # After wait returns we can get the exit code of $command
+  wait $pid
+
+  # wait a second time in case the trap was executed
+  # http://veithen.github.io/2014/11/16/sigterm-propagation.html
+  wait $pid
+
+  # return the exit code of $command
+  return $?
+}
+
+monitor() {
+  local command_name=$1
+  shift
+  local command="${@:-}"
+  local peak_mem_output=$(mktemp)
+  local start=$(nowms)
+
+  # execute the subcommand and save the peak memory usage
+  monitor_memory_usage $peak_mem_output $command
+
+  mtime "exec.$command_name.time" "${start}"
+  mmeasure "exec.$command_name.memory" "$(cat $peak_mem_output)"
+}

makefile

@@ -27,6 +27,11 @@ nodebin-test:
 	@bash etc/hatchet.sh spec/nodebin/
 	@echo ""
 
+unit:
+	@echo "Running unit tests in docker (heroku-18)..."
+	@docker run -v $(shell pwd):/buildpack:ro --rm -it -e "STACK=heroku-18" heroku/heroku:18 bash -c 'cp -r /buildpack /buildpack_test; cd /buildpack_test/; test/unit;'
+	@echo ""
+
 shell:
 	@echo "Opening heroku-16 shell..."
 	@docker run -v $(shell pwd):/buildpack:ro --rm -it heroku/heroku:16 bash -c 'cp -r /buildpack /buildpack_test; cd /buildpack_test/; bash'

test/run

@@ -965,6 +965,31 @@ testPluginInstallationUnsupportedNodeRunTime() {
   cleanupStartup
 }
 
+testMemoryMetrics() {
+  env_dir=$(mktmpdir)
+  local metrics_log=$(mktemp)
+  echo "$metrics_log" > $env_dir/BUILDPACK_LOG_FILE
+
+  compile "pre-post-build-scripts" "$(mktmpdir)" $env_dir
+  assertFileContains "measure#buildpack.nodejs.exec.heroku-prebuild.time=" $metrics_log
+  assertFileContains "measure#buildpack.nodejs.exec.heroku-prebuild.memory=" $metrics_log
+  assertFileContains "measure#buildpack.nodejs.exec.npm-install.time=" $metrics_log
+  assertFileContains "measure#buildpack.nodejs.exec.npm-install.memory=" $metrics_log
+  assertFileContains "measure#buildpack.nodejs.exec.heroku-postbuild.time=" $metrics_log
+  assertFileContains "measure#buildpack.nodejs.exec.heroku-postbuild.memory=" $metrics_log
+
+  # erase the metrics log
+  echo "" > $metrics_log
+  compile "yarn" "$(mktmpdir)" $env_dir
+  assertFileContains "measure#buildpack.nodejs.exec.yarn-install.memory=" "$metrics_log"
+  assertFileContains "measure#buildpack.nodejs.exec.yarn-install.time=" "$metrics_log"
+  # this fixture does not have pre or post-build scripts
+  assertFileNotContains "measure#buildpack.nodejs.exec.heroku-prebuild.time=" $metrics_log
+  assertFileNotContains "measure#buildpack.nodejs.exec.heroku-prebuild.memory=" $metrics_log
+  assertFileNotContains "measure#buildpack.nodejs.exec.heroku-postbuild.time=" $metrics_log
+  assertFileNotContains "measure#buildpack.nodejs.exec.heroku-postbuild.memory=" $metrics_log
+}
+
 # Utils
 
 pushd "$(dirname 0)" >/dev/null

test/unit

+#!/usr/bin/env bash
+
+# testing monitor_memory_usage
+
+# allocate ~14 mb of memory and wait a bit
+use_memory() {
+  for index in $(seq 10); do
+    value=$(seq -w -s '' $index $(($index + 100000)))
+    eval array$index=$value
+  done
+  sleep 0.5
+}
+
+# print each argument to a separate line on stdout
+print_args() {
+  while (( "$#" )); do 
+    echo $1 
+    shift 
+  done
+}
+
+testMonitorMemory() {
+  local mem_output=$(mktemp)
+  local stdout_capture=$(mktemp)
+
+  monitor_memory_usage $mem_output echo "this is a test" > /dev/null
+  assertTrue "should use less than 2mb" "[[ $(cat $mem_output) -lt 2 ]]"
+
+  monitor_memory_usage $mem_output use_memory
+  assertTrue "should use more than 10mb" "[[ $(cat $mem_output) -gt 10 ]]"
+
+  monitor_memory_usage $mem_output print_args --foo --bar="baz lol hi" > $stdout_capture
+  assertTrue "should use less than 2mb" "[[ $(cat $mem_output) -lt 2 ]]"
+  assertTrue "should output 2 lines" "[[ $(wc -l < $stdout_capture) -eq 2 ]]"
+  assertEquals "first line" "$(head -n 1 $stdout_capture)" "--foo"
+  assertEquals "second line" "$(tail -n 1 $stdout_capture)" "--bar=baz lol hi"
+}
+
+# the modules to be tested
+source "$(pwd)"/lib/monitor.sh
+
+# import the testing framework
+source "$(pwd)"/test/shunit2
\ No newline at end of file