Optimize verbosity

Author: dmius

nancy_run.sh

@@ -5,6 +5,7 @@ CURRENT_TS=$(date +%Y%m%d_%H%M%S%N_%Z)
 DOCKER_MACHINE="nancy-$CURRENT_TS"
 DOCKER_MACHINE="${DOCKER_MACHINE//_/-}"
 DEBUG_TIMEOUT=0
+OUTPUT_REDIRECT=" > /dev/null"
 EBS_SIZE_MULTIPLIER=15
 
 ## Get command line params
@@ -180,7 +181,10 @@ while true; do
 
     " | less -RFX
     exit ;;
-    -d | --debug ) DEBUG=1; shift ;;
+    -d | --debug )
+      DEBUG=1;
+      OUTPUT_REDIRECT='';
+      shift ;;
     --run-on )
       RUN_ON="$2"; shift 2 ;;
     --container-id )
@@ -538,7 +542,7 @@ checkParams;
 # Determine dump file size
 if ([ "$RUN_ON" == "aws" ] && [ ! ${AWS_EC2_TYPE:0:2} == "i3" ] && \
    [ -z ${EBS_VOLUME_SIZE+x} ] && [ ! -z ${DB_DUMP_PATH+x} ]); then
-    echo "Calculate EBS volume size."
+    echo "$(date "+%Y-%m-%d %H:%M:%S"): Calculate EBS volume size."
     dumpFileSize=0
     if [[ $DB_DUMP_PATH =~ "s3://" ]]; then
       dumpFileSize=$(s3cmd info $DB_DUMP_PATH | grep "File size:" )
@@ -557,9 +561,9 @@ if ([ "$RUN_ON" == "aws" ] && [ ! ${AWS_EC2_TYPE:0:2} == "i3" ] && \
         let ebsSize=$dumpFileSize
         ebsSize=$(numfmt --to-unit=G $ebsSize)
         EBS_VOLUME_SIZE=$ebsSize
-        [ $DEBUG -eq 1 ] && echo "EBS volume size: $EBS_VOLUME_SIZE Gb"
+        [ $DEBUG -eq 1 ] && echo "$(date "+%Y-%m-%d %H:%M:%S"): EBS volume size: $EBS_VOLUME_SIZE Gb"
     else
-      echo "EBS volume is not require."
+      echo "$(date "+%Y-%m-%d %H:%M:%S"): EBS volume is not require."
     fi
 fi
 
@@ -601,15 +605,15 @@ function waitEC2Ready() {
 #  5) key pair name
 #  6) key path
 function createDockerMachine() {
-  echo "Attempt to create a docker machine..."
+  echo "$(date "+%Y-%m-%d %H:%M:%S"): Attempt to create a docker machine..."
   docker-machine create --driver=amazonec2 \
     --amazonec2-request-spot-instance \
     --amazonec2-keypair-name="$5" \
     --amazonec2-ssh-keypath="$6" \
-    --amazonec2-block-duration-minutes=$4 \
     --amazonec2-instance-type=$2 \
     --amazonec2-spot-price=$3 \
     $1 2> >(grep -v "failed waiting for successful resource state" >&2) &
+#    --amazonec2-block-duration-minutes=$4 \
 }
 
 function destroyDockerMachine() {
@@ -622,11 +626,17 @@ function destroyDockerMachine() {
   # when we have "price-too-low" attempts, such errors come in few minutes
   # after an attempt and are generally unexpected by user.
   cmdout=$(docker-machine rm --force $1 2> >(grep -v "unknown instance" >&2) )
-  echo "Termination requested for machine '$1', current status: $cmdout"
+  echo "$(date "+%Y-%m-%d %H:%M:%S"): Termination requested for machine, current status: $cmdout"
 }
 
 function cleanupAndExit {
-  echo "Remove temp files..." # if exists
+  if  [ "$DEBUG_TIMEOUT" -gt "0" ]; then
+    echo "$(date "+%Y-%m-%d %H:%M:%S"): Debug timeout is $DEBUG_TIMEOUT seconds - started."
+    echo "  To connect docker machine use:"
+    echo "    docker \`docker-machine config $DOCKER_MACHINE\` exec -it pg_nancy_${CURRENT_TS} bash"
+    sleep $DEBUG_TIMEOUT
+  fi
+  echo "$(date "+%Y-%m-%d %H:%M:%S"): Remove temp files..." # if exists
   docker $dockerConfig exec -i ${containerHash} sh -c "sudo rm -rf $MACHINE_HOME"
   rm -f "$TMP_PATH/after_db_init_code_tmp.sql"
   rm -f "$TMP_PATH/before_db_init_code_tmp.sql"
@@ -636,16 +646,16 @@ function cleanupAndExit {
   rm -f "$TMP_PATH/target_config_tmp.conf"
   rm -f "$TMP_PATH/pg_config_tmp.conf"
   if [ "$RUN_ON" = "localhost" ]; then
-    echo "Remove docker container"
+    echo "$(date "+%Y-%m-%d %H:%M:%S"): Remove docker container"
     docker container rm -f $containerHash
   elif [ "$RUN_ON" = "aws" ]; then
     destroyDockerMachine $DOCKER_MACHINE
     if [ ! -z ${VOLUME_ID+x} ]; then
-        echo "Wait and delete volume $VOLUME_ID"
+        echo "$(date "+%Y-%m-%d %H:%M:%S"): Wait and delete volume $VOLUME_ID"
         sleep 60 # wait to machine removed
         delvolout=$(aws ec2 delete-volume --volume-id $VOLUME_ID)
-        echo "Volume $VOLUME_ID deleted"
-    fi    
+        echo "$(date "+%Y-%m-%d %H:%M:%S"): Volume $VOLUME_ID deleted"
+    fi
   else
     >&2 echo "ASSERT: must not reach this point"
     exit 1
@@ -675,18 +685,18 @@ elif [[ "$RUN_ON" = "aws" ]]; then
   maxprice=$(echo $prices | jq 'max_by(.price) | .price')
   maxprice="${maxprice/\"/}"
   maxprice="${maxprice/\"/}"
-  echo "Max price from history: $maxprice"
+  echo "$(date "+%Y-%m-%d %H:%M:%S"): Max price from history: $maxprice"
   multiplier="1.1"
   price=$(echo "$maxprice * $multiplier" | bc -l)
-  echo "Increased price: $price"
+  echo "$(date "+%Y-%m-%d %H:%M:%S"): Increased price: $price"
   EC2_PRICE=$price
 
   createDockerMachine $DOCKER_MACHINE $AWS_EC2_TYPE $EC2_PRICE \
     60 $AWS_KEY_PAIR $AWS_KEY_PATH;
   status=$(waitEC2Ready "docker-machine create" "$DOCKER_MACHINE" 1)
   if [ "$status" == "price-too-low" ]
   then
-    echo "Price $price is too low for $AWS_EC2_TYPE instance. Getting the up-to-date value from the error message..."
+    echo "$(date "+%Y-%m-%d %H:%M:%S"): Price $price is too low for $AWS_EC2_TYPE instance. Getting the up-to-date value from the error message..."
 
     #destroyDockerMachine $DOCKER_MACHINE
     # "docker-machine rm" doesn't work for "price-too-low" spot requests,
@@ -710,31 +720,31 @@ elif [[ "$RUN_ON" = "aws" ]]; then
       DOCKER_MACHINE="nancy-$CURRENT_TS"
       DOCKER_MACHINE="${DOCKER_MACHINE//_/-}"
       #try start docker machine name with new price
-      echo "Attempt to create a new docker machine: $DOCKER_MACHINE with price: $EC2_PRICE."
+      echo "$(date "+%Y-%m-%d %H:%M:%S"): Attempt to create a new docker machine: $DOCKER_MACHINE with price: $EC2_PRICE."
       createDockerMachine $DOCKER_MACHINE $AWS_EC2_TYPE $EC2_PRICE \
         60 $AWS_KEY_PAIR $AWS_KEY_PATH;
       waitEC2Ready "docker-machine create" "$DOCKER_MACHINE" 0;
     else
-      >&2 echo "ERROR: Cannot determine actual price for the instance $AWS_EC2_TYPE."
+      >&2 echo "$(date "+%Y-%m-%d %H:%M:%S") ERROR: Cannot determine actual price for the instance $AWS_EC2_TYPE."
       exit 1;
     fi
   fi
 
-  echo "Check a docker machine status."
+  echo "$(date "+%Y-%m-%d %H:%M:%S"): Check a docker machine status."
   res=$(docker-machine status $DOCKER_MACHINE 2>&1 &)
   if [ "$res" != "Running" ]
   then
-    >&2 echo "Failed: Docker $DOCKER_MACHINE is NOT running."
+    >&2 echo "$(date "+%Y-%m-%d %H:%M:%S"): Failed: Docker $DOCKER_MACHINE is NOT running."
     exit 1;
   fi
-  echo "Docker $DOCKER_MACHINE is running."
+  echo "$(date "+%Y-%m-%d %H:%M:%S"): Docker $DOCKER_MACHINE is running."
 
   docker-machine ssh $DOCKER_MACHINE "sudo sh -c \"mkdir /home/storage\""
   if [ ${AWS_EC2_TYPE:0:2} == 'i3' ]
   then
-    echo "Attempt use high speed disk"
+    echo "$(date "+%Y-%m-%d %H:%M:%S"): Attempt use high speed disk"
     # Init i3 storage, just mount existing volume
-    echo "Attach i3 nvme volume"
+    echo "$(date "+%Y-%m-%d %H:%M:%S"): Attach i3 nvme volume"
     docker-machine ssh $DOCKER_MACHINE sudo add-apt-repository -y ppa:sbates
     docker-machine ssh $DOCKER_MACHINE sudo apt-get update || :
     docker-machine ssh $DOCKER_MACHINE sudo apt-get install -y nvme-cli
@@ -750,11 +760,11 @@ elif [[ "$RUN_ON" = "aws" ]]; then
     docker-machine ssh $DOCKER_MACHINE sudo mkfs -t ext4 /dev/nvme0n1p1
     docker-machine ssh $DOCKER_MACHINE sudo mount /dev/nvme0n1p1 /home/storage
   else
-    echo "Attempt use external disk"
+    echo "$(date "+%Y-%m-%d %H:%M:%S"): Attempt use external disk"
     # Create new volume and attach them for non i3 instances if needed
     if [ ! -z ${EBS_VOLUME_SIZE+x} ]; then
-      echo "Create and attach EBS volume"
-      [ $DEBUG -eq 1 ] && echo "Create volume with size: $EBS_VOLUME_SIZE Gb"
+      echo "$(date "+%Y-%m-%d %H:%M:%S"): Create and attach EBS volume"
+      [ $DEBUG -eq 1 ] && echo "$(date "+%Y-%m-%d %H:%M:%S"): Create volume with size: $EBS_VOLUME_SIZE Gb"
       VOLUME_ID=$(aws ec2 create-volume --size $EBS_VOLUME_SIZE --region us-east-1 --availability-zone us-east-1a --volume-type gp2 | jq -r .VolumeId)
       INSTANCE_ID=$(docker-machine ssh $DOCKER_MACHINE curl -s http://169.254.169.254/latest/meta-data/instance-id)
       sleep 10 # wait to volume will ready
@@ -786,7 +796,7 @@ if [[ "$RUN_ON" = "aws" ]]; then
   MACHINE_HOME="$MACHINE_HOME/storage"
   docker_exec sh -c "chmod a+w /storage"
 
-  echo "Move posgresql to separated disk"
+  echo "$(date "+%Y-%m-%d %H:%M:%S"): Move posgresql to separated disk"
   docker_exec bash -c "sudo /etc/init.d/postgresql stop"
   sleep 2 # wait for postgres stopped
   docker_exec bash -c "sudo mv /var/lib/postgresql /storage/"
@@ -828,41 +838,42 @@ function copyFile() {
 # Dump
 sleep 2 # wait for postgres up&running
 
-echo "Apply sql code before db init"
+echo "$(date "+%Y-%m-%d %H:%M:%S"): Apply sql code before db init"
 if ([ ! -z ${BEFORE_DB_INIT_CODE+x} ] && [ "$BEFORE_DB_INIT_CODE" != "" ])
 then
   BEFORE_DB_INIT_CODE_FILENAME=$(basename $BEFORE_DB_INIT_CODE)
   copyFile $BEFORE_DB_INIT_CODE
-  docker_exec bash -c "psql --set ON_ERROR_STOP=on -U postgres test -b -f $MACHINE_HOME/$BEFORE_DB_INIT_CODE_FILENAME"
+  # --set ON_ERROR_STOP=on
+  docker_exec bash -c "psql --set ON_ERROR_STOP=on -U postgres test -b -f $MACHINE_HOME/$BEFORE_DB_INIT_CODE_FILENAME $OUTPUT_REDIRECT"
 fi
-echo "Restore database dump"
+echo "$(date "+%Y-%m-%d %H:%M:%S"): Restore database dump"
 case "$DB_DUMP_EXT" in
   sql)
-    docker_exec bash -c "cat $MACHINE_HOME/$DB_DUMP_FILENAME | psql --set ON_ERROR_STOP=on -U postgres test"
+    docker_exec bash -c "cat $MACHINE_HOME/$DB_DUMP_FILENAME | psql --set ON_ERROR_STOP=on -U postgres test $OUTPUT_REDIRECT"
     ;;
   bz2)
-    docker_exec bash -c "bzcat $MACHINE_HOME/$DB_DUMP_FILENAME | psql --set ON_ERROR_STOP=on -U postgres test"
+    docker_exec bash -c "bzcat $MACHINE_HOME/$DB_DUMP_FILENAME | psql --set ON_ERROR_STOP=on -U postgres test $OUTPUT_REDIRECT"
     ;;
   gz)
-    docker_exec bash -c "zcat $MACHINE_HOME/$DB_DUMP_FILENAME | psql --set ON_ERROR_STOP=on -U postgres test"
+    docker_exec bash -c "zcat $MACHINE_HOME/$DB_DUMP_FILENAME | psql --set ON_ERROR_STOP=on -U postgres test $OUTPUT_REDIRECT"
     ;;
 esac
 # After init database sql code apply
-echo "Apply sql code after db init"
+echo "$(date "+%Y-%m-%d %H:%M:%S"): Apply sql code after db init"
 if ([ ! -z ${AFTER_DB_INIT_CODE+x} ] && [ "$AFTER_DB_INIT_CODE" != "" ])
 then
   AFTER_DB_INIT_CODE_FILENAME=$(basename $AFTER_DB_INIT_CODE)
   copyFile $AFTER_DB_INIT_CODE
-  docker_exec bash -c "psql -U postgres test -b -f $MACHINE_HOME/$AFTER_DB_INIT_CODE_FILENAME"
+  docker_exec bash -c "psql --set ON_ERROR_STOP=on -U postgres test -b -f $MACHINE_HOME/$AFTER_DB_INIT_CODE_FILENAME $OUTPUT_REDIRECT"
 fi
 # Apply DDL code
-echo "Apply DDL SQL code"
+echo "$(date "+%Y-%m-%d %H:%M:%S"): Apply DDL SQL code"
 if ([ ! -z ${TARGET_DDL_DO+x} ] && [ "$TARGET_DDL_DO" != "" ]); then
   TARGET_DDL_DO_FILENAME=$(basename $TARGET_DDL_DO)
-  docker_exec bash -c "psql -U postgres test -b -f $MACHINE_HOME/$TARGET_DDL_DO_FILENAME"
+  docker_exec bash -c "psql --set ON_ERROR_STOP=on -U postgres test -b -f $MACHINE_HOME/$TARGET_DDL_DO_FILENAME $OUTPUT_REDIRECT"
 fi
 # Apply initial postgres configuration
-echo "Apply initial postgres configuration"
+echo "$(date "+%Y-%m-%d %H:%M:%S"): Apply initial postgres configuration"
 if ([ ! -z ${PG_CONFIG+x} ] && [ "$PG_CONFIG" != "" ]); then
   PG_CONFIG_FILENAME=$(basename $PG_CONFIG)
   docker_exec bash -c "cat $MACHINE_HOME/$PG_CONFIG_FILENAME >> /etc/postgresql/$PG_VERSION/main/postgresql.conf"
@@ -872,46 +883,62 @@ if ([ ! -z ${PG_CONFIG+x} ] && [ "$PG_CONFIG" != "" ]); then
   fi
 fi
 # Apply postgres configuration
-echo "Apply postgres configuration"
+echo "$(date "+%Y-%m-%d %H:%M:%S"): Apply postgres configuration"
 if ([ ! -z ${TARGET_CONFIG+x} ] && [ "$TARGET_CONFIG" != "" ]); then
   TARGET_CONFIG_FILENAME=$(basename $TARGET_CONFIG)
   docker_exec bash -c "cat $MACHINE_HOME/$TARGET_CONFIG_FILENAME >> /etc/postgresql/$PG_VERSION/main/postgresql.conf"
   docker_exec bash -c "sudo /etc/init.d/postgresql restart"
 fi
+#Save before workload log
+echo "$(date "+%Y-%m-%d %H:%M:%S"): Save prepaparation log"
+logpath=$( \
+  docker_exec bash -c "psql -XtU postgres \
+    -c \"select string_agg(setting, '/' order by name) from pg_settings where name in ('log_directory', 'log_filename');\" \
+    | grep / | sed -e 's/^[ \t]*//'"
+)
+docker_exec bash -c "gzip -c $logpath > $MACHINE_HOME/$ARTIFACTS_FILENAME.prepare.log.gz"
+if [[ $ARTIFACTS_DESTINATION =~ "s3://" ]]; then
+    docker_exec s3cmd put /$MACHINE_HOME/$ARTIFACTS_FILENAME.prepare.log.gz $ARTIFACTS_DESTINATION/
+else
+    if [ "$RUN_ON" = "localhost" ]; then
+      docker cp $containerHash:$MACHINE_HOME/$ARTIFACTS_FILENAME.prepare.log.gz $ARTIFACTS_DESTINATION/
+    elif [ "$RUN_ON" = "aws" ]; then
+      docker-machine scp $DOCKER_MACHINE:/home/storage/$ARTIFACTS_FILENAME.prepare.log.gz $ARTIFACTS_DESTINATION/
+    else
+      >&2 echo "ASSERT: must not reach this point"
+      exit 1
+    fi
+fi
+
 # Clear statistics and log
-echo "Execute vacuumdb..."
+echo "$(date "+%Y-%m-%d %H:%M:%S"): Execute vacuumdb..."
 docker_exec vacuumdb -U postgres test -j $(cat /proc/cpuinfo | grep processor | wc -l) --analyze
 docker_exec bash -c "echo '' > /var/log/postgresql/postgresql-$PG_VERSION-main.log"
 # Execute workload
-echo "Execute workload..."
+echo "$(date "+%Y-%m-%d %H:%M:%S"): Execute workload..."
 if [ ! -z ${WORKLOAD_REAL+x} ] && [ "$WORKLOAD_REAL" != '' ];then
-  echo "Execute pgreplay queries..."
+  echo "$(date "+%Y-%m-%d %H:%M:%S"): Execute pgreplay queries..."
   docker_exec psql -U postgres test -c 'create role testuser superuser login;'
   WORKLOAD_FILE_NAME=$(basename $WORKLOAD_REAL)
   docker_exec bash -c "pgreplay -r -j $MACHINE_HOME/$WORKLOAD_FILE_NAME"
 else
   if ([ ! -z ${WORKLOAD_CUSTOM_SQL+x} ] && [ "$WORKLOAD_CUSTOM_SQL" != "" ]); then
     WORKLOAD_CUSTOM_FILENAME=$(basename $WORKLOAD_CUSTOM_SQL)
-    echo "Execute custom sql queries..."
-    docker_exec bash -c "psql -U postgres test -E -f $MACHINE_HOME/$WORKLOAD_CUSTOM_FILENAME"
+    echo "$(date "+%Y-%m-%d %H:%M:%S"): Execute custom sql queries..."
+    docker_exec bash -c "psql -U postgres test -E -f $MACHINE_HOME/$WORKLOAD_CUSTOM_FILENAME $OUTPUT_REDIRECT"
   fi
 fi
 
 ## Get statistics
-echo "Prepare JSON log..."
+echo "$(date "+%Y-%m-%d %H:%M:%S"): Prepare JSON log..."
 docker_exec bash -c "/root/pgbadger/pgbadger \
   -j $(cat /proc/cpuinfo | grep processor | wc -l) \
   --prefix '%t [%p]: [%l-1] db=%d,user=%u (%a,%h)' /var/log/postgresql/* -f stderr \
   -o $MACHINE_HOME/$ARTIFACTS_FILENAME.json"
   #2> >(grep -v "install the Text::CSV_XS" >&2)
 
-logpath=$( \
-  docker_exec bash -c "psql -XtU postgres \
-    -c \"select string_agg(setting, '/' order by name) from pg_settings where name in ('log_directory', 'log_filename');\" \
-    | grep / | sed -e 's/^[ \t]*//'"
-)
 docker_exec bash -c "gzip -c $logpath > $MACHINE_HOME/$ARTIFACTS_FILENAME.log.gz"
-echo "Save artifcats..."
+echo "$(date "+%Y-%m-%d %H:%M:%S"): Save artifcats..."
 if [[ $ARTIFACTS_DESTINATION =~ "s3://" ]]; then
     docker_exec s3cmd put /$MACHINE_HOME/$ARTIFACTS_FILENAME.json $ARTIFACTS_DESTINATION/
     docker_exec s3cmd put /$MACHINE_HOME/$ARTIFACTS_FILENAME.log.gz $ARTIFACTS_DESTINATION/
@@ -931,23 +958,19 @@ else
     fi
 fi
 
-echo "Apply DDL undo SQL code"
+echo "$(date "+%Y-%m-%d %H:%M:%S"): Apply DDL undo SQL code"
 if ([ ! -z ${TARGET_DDL_UNDO+x} ] && [ "$TARGET_DDL_UNDO" != "" ]); then
     TARGET_DDL_UNDO_FILENAME=$(basename $TARGET_DDL_UNDO)
-    docker_exec bash -c "psql -U postgres test -b -f $MACHINE_HOME/$TARGET_DDL_UNDO_FILENAME"
+    docker_exec bash -c "psql --set ON_ERROR_STOP=on -U postgres test -b -f $MACHINE_HOME/$TARGET_DDL_UNDO_FILENAME $OUTPUT_REDIRECT"
 fi
 
-echo -e "Run done!"
-echo -e "Report: $ARTIFACTS_DESTINATION/$ARTIFACTS_FILENAME.json"
-echo -e "Query log: $ARTIFACTS_DESTINATION/$ARTIFACTS_FILENAME.log.gz"
+echo -e "$(date "+%Y-%m-%d %H:%M:%S"): Run done!"
+echo -e "  Report: $ARTIFACTS_DESTINATION/$ARTIFACTS_FILENAME.json"
+echo -e "  Query log: $ARTIFACTS_DESTINATION/$ARTIFACTS_FILENAME.log.gz"
+echo -e "  -------------------------------------------"
+echo -e "  Summary:"
+echo -e "    Queries duration:\t\t" $(docker_exec cat /$MACHINE_HOME/$ARTIFACTS_FILENAME.json | jq '.overall_stat.queries_duration') " ms"
+echo -e "    Queries count:\t\t" $( docker_exec cat /$MACHINE_HOME/$ARTIFACTS_FILENAME.json | jq '.overall_stat.queries_number')
+echo -e "    Normalized queries count:\t" $(docker_exec cat /$MACHINE_HOME/$ARTIFACTS_FILENAME.json | jq '.normalyzed_info| length')
+echo -e "    Errors count:\t\t\t" $(docker_exec cat /$MACHINE_HOME/$ARTIFACTS_FILENAME.json | jq '.overall_stat.errors_number')
 echo -e "-------------------------------------------"
-echo -e "Summary:"
-echo -e "  Queries duration:\t\t" $(docker_exec cat /$MACHINE_HOME/$ARTIFACTS_FILENAME.json | jq '.overall_stat.queries_duration') " ms"
-echo -e "  Queries count:\t\t" $( docker_exec cat /$MACHINE_HOME/$ARTIFACTS_FILENAME.json | jq '.overall_stat.queries_number')
-echo -e "  Normalized queries count:\t" $(docker_exec cat /$MACHINE_HOME/$ARTIFACTS_FILENAME.json | jq '.normalyzed_info| length')
-echo -e "  Errors count:\t\t\t" $(docker_exec cat /$MACHINE_HOME/$ARTIFACTS_FILENAME.json | jq '.overall_stat.errors_number')
-echo -e "-------------------------------------------"
-
-sleep $DEBUG_TIMEOUT
-
-echo Bye!