8177770: Need more precise control on build system logging

Reviewed-by: ihse, erikj

common/autoconf/basics.m4

@@ -1098,6 +1098,7 @@ AC_DEFUN_ONCE([BASIC_SETUP_COMPLEX_TOOLS],
   BASIC_PATH_PROGS(HG, hg)
   BASIC_PATH_PROGS(STAT, stat)
   BASIC_PATH_PROGS(TIME, time)
+  BASIC_PATH_PROGS(FLOCK, flock)
   # Dtrace is usually found in /usr/sbin on Solaris, but that directory may not
   # be in the user path.
   BASIC_PATH_PROGS(DTRACE, dtrace, $PATH:/usr/sbin)

common/autoconf/generated-configure.sh

@@ -932,6 +932,7 @@ DSYMUTIL
 IS_GNU_TIME
 PATCH
 DTRACE
+FLOCK
 TIME
 STAT
 HG
@@ -1292,6 +1293,7 @@ READELF
 HG
 STAT
 TIME
+FLOCK
 DTRACE
 PATCH
 DSYMUTIL
@@ -2256,6 +2258,7 @@ Some influential environment variables:
   HG          Override default value for HG
   STAT        Override default value for STAT
   TIME        Override default value for TIME
+  FLOCK       Override default value for FLOCK
   DTRACE      Override default value for DTRACE
   PATCH       Override default value for PATCH
   DSYMUTIL    Override default value for DSYMUTIL
@@ -5173,7 +5176,7 @@ VS_SDK_PLATFORM_NAME_2013=
 #CUSTOM_AUTOCONF_INCLUDE
 
 # Do not change or remove the following line, it is needed for consistency checks:
-DATE_WHEN_GENERATED=1489410066
+DATE_WHEN_GENERATED=1490900744
 
 ###############################################################################
 #
@@ -23056,6 +23059,203 @@ $as_echo "$tool_specified" >&6; }
   fi
 
 
+
+
+  # Publish this variable in the help.
+
+
+  if [ -z "${FLOCK+x}" ]; then
+    # The variable is not set by user, try to locate tool using the code snippet
+    for ac_prog in flock
+do
+  # Extract the first word of "$ac_prog", so it can be a program name with args.
+set dummy $ac_prog; ac_word=$2
+{ $as_echo "$as_me:${as_lineno-$LINENO}: checking for $ac_word" >&5
+$as_echo_n "checking for $ac_word... " >&6; }
+if ${ac_cv_path_FLOCK+:} false; then :
+  $as_echo_n "(cached) " >&6
+else
+  case $FLOCK in
+  [\\/]* | ?:[\\/]*)
+  ac_cv_path_FLOCK="$FLOCK" # Let the user override the test with a path.
+  ;;
+  *)
+  as_save_IFS=$IFS; IFS=$PATH_SEPARATOR
+for as_dir in $PATH
+do
+  IFS=$as_save_IFS
+  test -z "$as_dir" && as_dir=.
+    for ac_exec_ext in '' $ac_executable_extensions; do
+  if as_fn_executable_p "$as_dir/$ac_word$ac_exec_ext"; then
+    ac_cv_path_FLOCK="$as_dir/$ac_word$ac_exec_ext"
+    $as_echo "$as_me:${as_lineno-$LINENO}: found $as_dir/$ac_word$ac_exec_ext" >&5
+    break 2
+  fi
+done
+  done
+IFS=$as_save_IFS
+
+  ;;
+esac
+fi
+FLOCK=$ac_cv_path_FLOCK
+if test -n "$FLOCK"; then
+  { $as_echo "$as_me:${as_lineno-$LINENO}: result: $FLOCK" >&5
+$as_echo "$FLOCK" >&6; }
+else
+  { $as_echo "$as_me:${as_lineno-$LINENO}: result: no" >&5
+$as_echo "no" >&6; }
+fi
+
+
+  test -n "$FLOCK" && break
+done
+
+  else
+    # The variable is set, but is it from the command line or the environment?
+
+    # Try to remove the string !FLOCK! from our list.
+    try_remove_var=${CONFIGURE_OVERRIDDEN_VARIABLES//!FLOCK!/}
+    if test "x$try_remove_var" = "x$CONFIGURE_OVERRIDDEN_VARIABLES"; then
+      # If it failed, the variable was not from the command line. Ignore it,
+      # but warn the user (except for BASH, which is always set by the calling BASH).
+      if test "xFLOCK" != xBASH; then
+        { $as_echo "$as_me:${as_lineno-$LINENO}: WARNING: Ignoring value of FLOCK from the environment. Use command line variables instead." >&5
+$as_echo "$as_me: WARNING: Ignoring value of FLOCK from the environment. Use command line variables instead." >&2;}
+      fi
+      # Try to locate tool using the code snippet
+      for ac_prog in flock
+do
+  # Extract the first word of "$ac_prog", so it can be a program name with args.
+set dummy $ac_prog; ac_word=$2
+{ $as_echo "$as_me:${as_lineno-$LINENO}: checking for $ac_word" >&5
+$as_echo_n "checking for $ac_word... " >&6; }
+if ${ac_cv_path_FLOCK+:} false; then :
+  $as_echo_n "(cached) " >&6
+else
+  case $FLOCK in
+  [\\/]* | ?:[\\/]*)
+  ac_cv_path_FLOCK="$FLOCK" # Let the user override the test with a path.
+  ;;
+  *)
+  as_save_IFS=$IFS; IFS=$PATH_SEPARATOR
+for as_dir in $PATH
+do
+  IFS=$as_save_IFS
+  test -z "$as_dir" && as_dir=.
+    for ac_exec_ext in '' $ac_executable_extensions; do
+  if as_fn_executable_p "$as_dir/$ac_word$ac_exec_ext"; then
+    ac_cv_path_FLOCK="$as_dir/$ac_word$ac_exec_ext"
+    $as_echo "$as_me:${as_lineno-$LINENO}: found $as_dir/$ac_word$ac_exec_ext" >&5
+    break 2
+  fi
+done
+  done
+IFS=$as_save_IFS
+
+  ;;
+esac
+fi
+FLOCK=$ac_cv_path_FLOCK
+if test -n "$FLOCK"; then
+  { $as_echo "$as_me:${as_lineno-$LINENO}: result: $FLOCK" >&5
+$as_echo "$FLOCK" >&6; }
+else
+  { $as_echo "$as_me:${as_lineno-$LINENO}: result: no" >&5
+$as_echo "no" >&6; }
+fi
+
+
+  test -n "$FLOCK" && break
+done
+
+    else
+      # If it succeeded, then it was overridden by the user. We will use it
+      # for the tool.
+
+      # First remove it from the list of overridden variables, so we can test
+      # for unknown variables in the end.
+      CONFIGURE_OVERRIDDEN_VARIABLES="$try_remove_var"
+
+      # Check if we try to supply an empty value
+      if test "x$FLOCK" = x; then
+        { $as_echo "$as_me:${as_lineno-$LINENO}: Setting user supplied tool FLOCK= (no value)" >&5
+$as_echo "$as_me: Setting user supplied tool FLOCK= (no value)" >&6;}
+        { $as_echo "$as_me:${as_lineno-$LINENO}: checking for FLOCK" >&5
+$as_echo_n "checking for FLOCK... " >&6; }
+        { $as_echo "$as_me:${as_lineno-$LINENO}: result: disabled" >&5
+$as_echo "disabled" >&6; }
+      else
+        # Check if the provided tool contains a complete path.
+        tool_specified="$FLOCK"
+        tool_basename="${tool_specified##*/}"
+        if test "x$tool_basename" = "x$tool_specified"; then
+          # A command without a complete path is provided, search $PATH.
+          { $as_echo "$as_me:${as_lineno-$LINENO}: Will search for user supplied tool FLOCK=$tool_basename" >&5
+$as_echo "$as_me: Will search for user supplied tool FLOCK=$tool_basename" >&6;}
+          # Extract the first word of "$tool_basename", so it can be a program name with args.
+set dummy $tool_basename; ac_word=$2
+{ $as_echo "$as_me:${as_lineno-$LINENO}: checking for $ac_word" >&5
+$as_echo_n "checking for $ac_word... " >&6; }
+if ${ac_cv_path_FLOCK+:} false; then :
+  $as_echo_n "(cached) " >&6
+else
+  case $FLOCK in
+  [\\/]* | ?:[\\/]*)
+  ac_cv_path_FLOCK="$FLOCK" # Let the user override the test with a path.
+  ;;
+  *)
+  as_save_IFS=$IFS; IFS=$PATH_SEPARATOR
+for as_dir in $PATH
+do
+  IFS=$as_save_IFS
+  test -z "$as_dir" && as_dir=.
+    for ac_exec_ext in '' $ac_executable_extensions; do
+  if as_fn_executable_p "$as_dir/$ac_word$ac_exec_ext"; then
+    ac_cv_path_FLOCK="$as_dir/$ac_word$ac_exec_ext"
+    $as_echo "$as_me:${as_lineno-$LINENO}: found $as_dir/$ac_word$ac_exec_ext" >&5
+    break 2
+  fi
+done
+  done
+IFS=$as_save_IFS
+
+  ;;
+esac
+fi
+FLOCK=$ac_cv_path_FLOCK
+if test -n "$FLOCK"; then
+  { $as_echo "$as_me:${as_lineno-$LINENO}: result: $FLOCK" >&5
+$as_echo "$FLOCK" >&6; }
+else
+  { $as_echo "$as_me:${as_lineno-$LINENO}: result: no" >&5
+$as_echo "no" >&6; }
+fi
+
+
+          if test "x$FLOCK" = x; then
+            as_fn_error $? "User supplied tool $tool_basename could not be found" "$LINENO" 5
+          fi
+        else
+          # Otherwise we believe it is a complete path. Use it as it is.
+          { $as_echo "$as_me:${as_lineno-$LINENO}: Will use user supplied tool FLOCK=$tool_specified" >&5
+$as_echo "$as_me: Will use user supplied tool FLOCK=$tool_specified" >&6;}
+          { $as_echo "$as_me:${as_lineno-$LINENO}: checking for FLOCK" >&5
+$as_echo_n "checking for FLOCK... " >&6; }
+          if test ! -x "$tool_specified"; then
+            { $as_echo "$as_me:${as_lineno-$LINENO}: result: not found" >&5
+$as_echo "not found" >&6; }
+            as_fn_error $? "User supplied tool FLOCK=$tool_specified does not exist or is not executable" "$LINENO" 5
+          fi
+          { $as_echo "$as_me:${as_lineno-$LINENO}: result: $tool_specified" >&5
+$as_echo "$tool_specified" >&6; }
+        fi
+      fi
+    fi
+
+  fi
+
+
   # Dtrace is usually found in /usr/sbin on Solaris, but that directory may not
   # be in the user path.
 

common/autoconf/spec.gmk.in

@@ -48,7 +48,7 @@ MAKE := @MAKE@
 
 # The default make arguments
 MAKE_ARGS = $(MAKE_LOG_FLAGS) -r -R -I $(TOPDIR)/make/common SPEC=$(SPEC) \
-    MAKE_LOG_FLAGS="$(MAKE_LOG_FLAGS)" LOG_LEVEL=$(LOG_LEVEL)
+    MAKE_LOG_FLAGS="$(MAKE_LOG_FLAGS)" $(MAKE_LOG_VARS)
 
 OUTPUT_SYNC_SUPPORTED:=@OUTPUT_SYNC_SUPPORTED@
 OUTPUT_SYNC:=@OUTPUT_SYNC@
@@ -636,6 +636,7 @@ DIRNAME:=@DIRNAME@
 DSYMUTIL:=@DSYMUTIL@
 FIND:=@FIND@
 FIND_DELETE:=@FIND_DELETE@
+FLOCK:=@FLOCK@
 ECHO:=@ECHO@
 EGREP:=@EGREP@
 FGREP:=@FGREP@

common/bin/shell-profiler.sh

@@ -22,26 +22,48 @@
 # questions.
 #
 
-# Usage: sh shell-tracer.sh <TIME_CMD> <OUTPUT_FILE> <OLD_SHELL> <shell command line>
+# Usage: sh shell-tracer.sh <TIME_CMD_TYPE> <TIME_CMD> <OUTPUT_FILE> <shell command line>
 #
 # This shell script is supposed to be set as a replacement for SHELL in make,
 # causing it to be called whenever make wants to execute shell commands.
 # The <shell command line> is suitable for passing on to the old shell,
 # typically beginning with -c.
 #
-# This script will make sure the shell command line is executed with
+# This script will run the shell command line and it will also store a simple
-# OLD_SHELL -x, and it will also store a simple log of the the time it takes to
+# log of the the time it takes to execute the command in the OUTPUT_FILE, using
-# execute the command in the OUTPUT_FILE, using the "time" utility as pointed
+# utility for time measure specified with TIME_CMD option.
-# to by TIME_CMD. If TIME_CMD is "-", no timestamp will be stored.
+#
+# Type of time measure utility is specified with TIME_CMD_TYPE option.
+# Recognized options values of TIME_CMD_TYPE option: "gnutime", "flock".
 
-TIME_CMD="$1"
+TIME_CMD_TYPE="$1"
-OUTPUT_FILE="$2"
+TIME_CMD="$2"
-OLD_SHELL="$3"
+OUTPUT_FILE="$3"
 shift
 shift
 shift
-if [ "$TIME_CMD" != "-" ]; then
+if [ "$TIME_CMD_TYPE" = "gnutime" ]; then
-"$TIME_CMD" -f "[TIME:%E] $*" -a -o "$OUTPUT_FILE" "$OLD_SHELL" -x "$@"
+  # Escape backslashes (\) and percent chars (%). See man for GNU 'time'.
+  msg=${@//\\/\\\\}
+  msg=${msg//%/%%}
+  "$TIME_CMD" -f "[TIME:%E] $msg" -a -o "$OUTPUT_FILE" "$@"
+elif [ "$TIME_CMD_TYPE" = "flock" ]; then
+  # Emulated GNU 'time' with 'flock' and 'date'.
+  ts=`date +%s%3N`
+  "$@"
+  status=$?
+  ts2=`date +%s%3N`
+  millis=$((ts2 - ts))
+  ms=$(($millis % 1000))
+  seconds=$((millis / 1000))
+  ss=$(($seconds % 60))
+  minutes=$(($seconds / 60))
+  mm=$(($minutes % 60))
+  hh=$(($minutes / 60)):
+  [ $hh != "0:" ] || hh=
+  # Synchronize on this script.
+  flock -w 10 "$0" printf "[TIME:${hh}${mm}:${ss}.%.2s] %s\n" $ms "$*" >> "$OUTPUT_FILE" || true
+  exit $status
 else
-"$OLD_SHELL" -x "$@"
+  "$@"
 fi

make/Init.gmk

@@ -117,7 +117,7 @@ ifeq ($(HAS_SPEC),)
     # Check that CONF_CHECK is valid.
     $(eval $(call ParseConfCheckOption))
 
-    # Check that the LOG given is valid, and set LOG_LEVEL, LOG_NOFILE and MAKE_LOG_FLAGS.
+    # Check that the LOG given is valid, and set LOG_LEVEL, LOG_NOFILE, MAKE_LOG_VARS and MAKE_LOG_FLAGS.
     $(eval $(call ParseLogLevel))
 
     # After this SPECS contain 1..N spec files (otherwise ParseConfAndSpec fails).
@@ -171,7 +171,7 @@ ifeq ($(HAS_SPEC),)
 
     MAKE_INIT_WITH_SPEC_ARGUMENTS := ACTUAL_TOPDIR=$(topdir) \
         USER_MAKE_VARS="$(USER_MAKE_VARS)" MAKE_LOG_FLAGS=$(MAKE_LOG_FLAGS) \
-        LOG_LEVEL=$(LOG_LEVEL) LOG_NOFILE=$(LOG_NOFILE) LOG_CMDLINES=$(LOG_CMDLINES) \
+        $(MAKE_LOG_VARS) \
         INIT_TARGETS="$(INIT_TARGETS)" \
         SEQUENTIAL_TARGETS="$(SEQUENTIAL_TARGETS)" \
         PARALLEL_TARGETS="$(PARALLEL_TARGETS)"
@@ -319,6 +319,7 @@ else # HAS_SPEC=true
 	    exit 1 ; \
 	  fi
 	  $(PRINTF) "Finished building $(TARGET_DESCRIPTION)\n" $(BUILD_LOG_PIPE)
+	  $(call ReportProfileTimes)
         endif
 
     on-failure:
@@ -327,6 +328,7 @@ else # HAS_SPEC=true
 	$(call ReportBuildTimes)
 	$(call PrintFailureReports)
 	$(call PrintBuildLogFailures)
+	$(call ReportProfileTimes)
 	$(PRINTF) "Hint: If caused by a warning, try configure --disable-warnings-as-errors.\n\n"
         ifneq ($(COMPARE_BUILD), )
 	  $(call CleanupCompareBuild)

make/InitSupport.gmk

@@ -158,6 +158,18 @@ ifeq ($(HAS_SPEC),)
     # If the "cmdline" argument is given, act on it and strip it away
     $$(eval $$(call ParseLogOption, cmdlines, LOG_CMDLINES))
 
+    # If the "profile-to-log" argument is given, write shell times in build log
+    $$(eval $$(call ParseLogOption, profile-to-log, LOG_PROFILE_TIMES_LOG))
+
+    # If the "profile" argument is given, write shell times in separate log file
+    # IMPORTANT: $(ParseLogOption profile-to-log) should go first. Otherwise
+    # parsing of 'LOG=debug,profile-to-log,nofile' ends up in the following error:
+    # Error: LOG contains unknown option or log level: debug-to-log.
+    $$(eval $$(call ParseLogOption, profile, LOG_PROFILE_TIMES_FILE))
+
+    # Treat LOG=profile-to-log as if it were LOG=profile,profile-to-log
+    LOG_PROFILE_TIMES_FILE := $$(firstword $$(LOG_PROFILE_TIMES_FILE) $$(LOG_PROFILE_TIMES_LOG))
+
     LOG_LEVEL := $$(LOG)
 
     ifeq ($$(LOG_LEVEL),)
@@ -175,7 +187,7 @@ ifeq ($(HAS_SPEC),)
       MAKE_LOG_FLAGS :=
     else
       $$(info Error: LOG contains unknown option or log level: $$(LOG).)
-      $$(info LOG can be <level>[,<opt>[...]] where <opt> is nofile | cmdlines)
+      $$(info LOG can be <level>[,<opt>[...]] where <opt> is nofile | cmdlines | profile | profile-to-log)
       $$(info and <level> is warn | info | debug | trace)
       $$(error Cannot continue)
     endif
@@ -309,7 +321,7 @@ ifeq ($(HAS_SPEC),)
 	@( cd $$(topdir) && \
 	$$(MAKE) $$(MAKE_LOG_FLAGS) -r -R -f $$(topdir)/make/Main.gmk \
 	    -I $$(topdir)/make/common SPEC=$(strip $2) NO_RECIPES=true \
-	    LOG_LEVEL=$$(LOG_LEVEL) \
+	    $$(MAKE_LOG_VARS) \
 	    create-main-targets-include )
 
     # Now include main-targets.gmk. This will define ALL_MAIN_TARGETS.
@@ -334,7 +346,7 @@ else # $(HAS_SPEC)=true
 
   # Define basic logging setup
   BUILD_LOG := $(OUTPUT_ROOT)/build.log
-  BUILD_TRACE_LOG := $(OUTPUT_ROOT)/build-trace-time.log
+  BUILD_PROFILE_LOG := $(OUTPUT_ROOT)/build-profile.log
 
   BUILD_LOG_PIPE := > >($(TEE) -a $(BUILD_LOG)) 2> >($(TEE) -a $(BUILD_LOG) >&2) && wait
 
@@ -494,9 +506,9 @@ else # $(HAS_SPEC)=true
   define RotateLogFiles
 	$(RM) $(BUILD_LOG).old 2> /dev/null && \
 	$(MV) $(BUILD_LOG) $(BUILD_LOG).old 2> /dev/null || true
-	$(if $(findstring trace, $(LOG_LEVEL)), \
+	$(if $(findstring true, $(LOG_PROFILE_TIMES_FILE)), \
-	  $(RM) $(BUILD_TRACE_LOG).old 2> /dev/null && \
+	  $(RM) $(BUILD_PROFILE_LOG).old 2> /dev/null && \
-	  $(MV) $(BUILD_TRACE_LOG) $(BUILD_TRACE_LOG).old 2> /dev/null || true \
+	  $(MV) $(BUILD_PROFILE_LOG) $(BUILD_PROFILE_LOG).old 2> /dev/null || true \
 	)
   endef
 
@@ -558,6 +570,22 @@ else # $(HAS_SPEC)=true
 	    $(BUILD_LOG_PIPE)
   endef
 
+  define ReportProfileTimes
+    $(if $(findstring true, $(LOG_PROFILE_TIMES_LOG)), \
+      [ ! -f $(BUILD_PROFILE_LOG) ] || \
+      { $(ECHO) Begin $(notdir $(BUILD_PROFILE_LOG)) && \
+        $(CAT) $(BUILD_PROFILE_LOG) && \
+        $(ECHO) End $(notdir $(BUILD_PROFILE_LOG)); \
+      } \
+      $(BUILD_LOG_PIPE)
+    )
+  endef
+
 endif # HAS_SPEC
 
+MAKE_LOG_VARS = $(foreach v, \
+    LOG_LEVEL LOG_NOFILE LOG_CMDLINES LOG_PROFILE_TIMES_LOG LOG_PROFILE_TIMES_FILE, \
+    $v=$($v) \
+)
+
 endif # _INITSUPPORT_GMK

make/common/MakeBase.gmk

@@ -355,17 +355,28 @@ FindAllReposRel = \
 ################################################################################
 
 define SetupLogging
+  ifeq ($$(LOG_PROFILE_TIMES_FILE), true)
+    ifeq ($$(IS_GNU_TIME), yes)
+      SHELL :=  $$(BASH) $$(SRC_ROOT)/common/bin/shell-profiler.sh \
+                gnutime $$(TIME) \
+                $$(OUTPUT_ROOT)/build-profile.log $$(SHELL)
+    else ifneq ($$(FLOCK), )
+      SHELL :=  $$(BASH) $$(SRC_ROOT)/common/bin/shell-profiler.sh \
+                flock $$(FLOCK) \
+                $$(OUTPUT_ROOT)/build-profile.log $$(SHELL)
+    endif
+  endif
+
   ifeq ($$(LOG_LEVEL), trace)
+    SHELL_NO_RECURSE := $$(SHELL)
     # Shell redefinition trick inspired by http://www.cmcrossroads.com/ask-mr-make/6535-tracing-rule-execution-in-gnu-make
     # For each target executed, will print
     # Building <TARGET> (from <FIRST PREREQUISITE>) (<ALL NEWER PREREQUISITES> newer)
     # but with a limit of 20 on <ALL NEWER PREREQUISITES>, to avoid cluttering logs too much
     # (and causing a crash on Cygwin).
-    # Default shell seems to always be /bin/sh. Must override with bash to get this to work on Solaris.
+    SHELL = $$(warning $$(if $$@,Building $$@,Running shell command) $$(if $$<, (from $$<))$$(if $$?, ($$(wordlist 1, 20, $$?) $$(if $$(wordlist 21, 22, $$?), ... [in total $$(words $$?) files]) newer)))$$(SHELL_NO_RECURSE) -x
-    # Only use time if it's GNU time which supports format and output file.
-    WRAPPER_SHELL := $$(BASH) $$(SRC_ROOT)/common/bin/shell-tracer.sh $$(if $$(findstring yes,$$(IS_GNU_TIME)),$$(TIME),-) $$(OUTPUT_ROOT)/build-trace-time.log $$(SHELL)
-    SHELL = $$(warning $$(if $$@,Building $$@,Running shell command) $$(if $$<, (from $$<))$$(if $$?, ($$(wordlist 1, 20, $$?) $$(if $$(wordlist 21, 22, $$?), ... [in total $$(words $$?) files]) newer)))$$(WRAPPER_SHELL)
   endif
+
   # The warn level can never be turned off
   LogWarn = $$(info $$(strip $$1))
   LOG_WARN :=