experimental debug output for debugging performance issues

clowder_init.sh

@@ -1,23 +1,41 @@
 #!/bin/sh
 
+logtime "start clowder_init..."
+echo "start clowder_init.sh"  | tee -a $LOGPATH
+
 if [[ -z "${ACG_CONFIG}" ]]; then
+  logtime "export PG_BOUNCER_LISTEN_PORT..."
   export PG_BOUNCER_LISTEN_PORT="5432"
 else
+  logtime "export DB_NAME..."
   export DB_NAME="`cat $ACG_CONFIG | jq -r '.database.name // empty'`"
+  logtime "export DB_HOST..."
   export DB_HOST="`cat $ACG_CONFIG | jq -r '.database.hostname // empty'`"
+  logtime "export DB_PORT..."
   export DB_PORT="`cat $ACG_CONFIG | jq -r '.database.port // empty'`"
+  logtime "export DB_USER..."
   export DB_USER="`cat $ACG_CONFIG | jq -r '.database.username // empty'`"
+  logtime "export DB_PASSWORD..."
   export DB_PASSWORD="`cat $ACG_CONFIG | jq -r '.database.password // empty'`"
+  logtime "export DB_SSLMODE..."
   export DB_SSLMODE="`cat $ACG_CONFIG | jq -r '.database.sslMode // empty'`"
+  logtime "export DB_CAFILE..."
   export DB_CAFILE="/etc/pgbouncer/rdsca.cert"
+  logtime "export PG_BOUNCER_LISTEN_PORT..."
   export PG_BOUNCER_LISTEN_PORT="`cat $ACG_CONFIG | jq -r '.webPort'`"
 
+  logtime "db_cert=..."
   db_cert="`cat $ACG_CONFIG | jq -r '.database.rdsCa // empty'`"
   >${DB_CAFILE}
   if [[ -n "${db_cert}" ]]; then
+    logtime "echo db_cert to DB_CAFILE..."
     echo "${db_cert}" > ${DB_CAFILE}
+    logtime "unset db_cert..."
     unset db_cert
   fi
 
   [[ -z "${DB_PORT}" ]] && DB_PORT="5432"
 fi
+
+logtime "exit clowder_init..."
+echo "exit clowder_init.sh" | tee -a $LOGPATH

entrypoint.sh

@@ -1,50 +1,66 @@
 #!/bin/sh
 
+PID="$$"
+LOGPATH=/tmp/log-entrypoint-"$PID"
+
+function logtime() {
+  echo "$(date --iso-8601=ns)" | tee -a $LOGPATH
+}
+
+logtime
 source /clowder_init.sh
+logtime
 
 set -e
 
 function check_svc_status() {
   local SVC_NAME=$1 SVC_PORT=$2
 
-  [[ $# -lt 2 ]] && echo "Error: Usage: check_svc_status svc_name svc_port" && exit 1
+  [[ $# -lt 2 ]] && echo "Error: Usage: check_svc_status svc_name svc_port" | tee -a $LOGPATH && exit 1
 
   while true; do
-    echo "${LOGPREFIX} Checking ${SVC_NAME}:$SVC_PORT status ..."
+    logtime
+    echo "${LOGPREFIX} Checking ${SVC_NAME}:$SVC_PORT status ..." | tee -a $LOGPATH
     ncat ${SVC_NAME} ${SVC_PORT} < /dev/null && break
-    sleep 5
+    logtime
+    echo "not ready yet" | tee -a $LOGPATH
+    sleep 1
   done
+  logtime
   echo "${LOGPREFIX} ${SVC_NAME}:${SVC_PORT} - accepting connections"
 }
 
+
 if [[ -n "${ACG_CONFIG}" ]]; then
   export LOGPREFIX="Clowder Init:"
-  echo "${LOGPREFIX} Running in a clowder environment"
+  echo "${LOGPREFIX} Running in a clowder environment" | tee -a $LOGPATH
 
-  echo "${LOGPREFIX} Database name:     ${DB_NAME}"
-  echo "${LOGPREFIX} Database host:     ${DB_HOST}"
-  echo "${LOGPREFIX} Database port:     ${DB_PORT}"
-  echo "${LOGPREFIX} PG Bouncer port:   ${PG_BOUNCER_LISTEN_PORT}"
+  echo "${LOGPREFIX} Database name:     ${DB_NAME}" | tee -a $LOGPATH
+  echo "${LOGPREFIX} Database host:     ${DB_HOST}" | tee -a $LOGPATH
+  echo "${LOGPREFIX} Database port:     ${DB_PORT}" | tee -a $LOGPATH
+  echo "${LOGPREFIX} PG Bouncer port:   ${PG_BOUNCER_LISTEN_PORT}" | tee -a $LOGPATH
   if [[ -n "${DB_SSLMODE}" ]]; then
-    echo "${LOGPREFIX} Database SSL Mode: ${DB_SSLMODE}"
+    echo "${LOGPREFIX} Database SSL Mode: ${DB_SSLMODE}" | tee -a $LOGPATH
   fi
   if [[ -s "${DB_CAFILE}" ]]; then
-    echo "${LOGPREFIX} Database CA File:  ${DB_CAFILE}"
+    echo "${LOGPREFIX} Database CA File:  ${DB_CAFILE}" | tee -a $LOGPATH
   fi
 
-  [[ -z "${DB_HOST}" ]] && echo "${LOGPREFIX} Error: Missing Database configuration" && exit 1
+  [[ -z "${DB_HOST}" ]] && echo "${LOGPREFIX} Error: Missing Database configuration"  | tee -a $LOGPATH && exit 1
 
   # Wait for the database to be ready
-  echo "${LOGPREFIX} Waiting for database readiness ..."
+  echo "${LOGPREFIX} Waiting for database readiness ..." | tee -a $LOGPATH
   check_svc_status $DB_HOST $DB_PORT
 fi
 
 PG_CONFIG_DIR=/etc/pgbouncer
 
+logtime
 # md5 and write the password
 pass="md5$(echo -n "$DB_PASSWORD$DB_USER" | md5sum | cut -f 1 -d ' ')"
 echo "\"$DB_USER\" \"$pass\"" >> ${PG_CONFIG_DIR}/userlist.txt
-echo "Wrote authentication credentials to ${PG_CONFIG_DIR}/userlist.txt"
+logtime
+echo "Wrote authentication credentials to ${PG_CONFIG_DIR}/userlist.txt" | tee -a $LOGPATH
 
 # pgbouncer config
 printf "\
@@ -72,7 +88,8 @@ if [[ -s "${DB_CAFILE}" ]]; then
   echo "server_tls_ca_file=${DB_CAFILE}" >> ${PG_CONFIG_DIR}/pgbouncer.ini
 fi
 
-echo "Wrote pgbouncer config to ${PG_CONFIG_DIR}/pgbouncer.ini"
+logtime
+echo "Wrote pgbouncer config to ${PG_CONFIG_DIR}/pgbouncer.ini" | tee -a $LOGPATH
 
-echo "Starting $*..."
+echo "Starting $*..." | tee -a $LOGPATH
 exec "$@"

probe-liveness.sh

@@ -1,7 +1,24 @@
 #!/bin/bash
 
+PID="$$"
+LOGPATH=/tmp/log-liveness-"$PID"
+
+function logtime() {
+  echo "$(date --iso-8601=ns) $1" | tee -a $LOGPATH
+}
+
+
+exec {BASH_XTRACEFD}>>$LOGPATH
+#set -x
+
+
+logtime "before clowder init"
 source /clowder_init.sh
 
-/usr/pgsql-14/bin/pg_isready -h localhost -p ${PG_BOUNCER_LISTEN_PORT} -U "${DB_USER}" | grep "accepting connections"
-exit $?
+logtime "before pg_isready"
+/usr/pgsql-14/bin/pg_isready -h localhost -p ${PG_BOUNCER_LISTEN_PORT} -U "${DB_USER}" | grep "accepting connections"  | tee -a $LOGPATH
+RESULT=$?
+logtime "after pg_isready"
+echo "result was $RESULT" | tee -a $LOGPATH
+exit $RESULT
 

probe-readiness.sh

@@ -1,14 +1,29 @@
 #!/bin/bash
 
+function logtime() {
+  echo "$(date --iso-8601=ns) $1" | tee -a $LOGPATH
+}
+
+
+PID="$$"
+LOGPATH=/tmp/log-readiness-"$PID"
+
+exec {BASH_XTRACEFD}>>$LOGPATH
+#set -x
+
 # Note: host and port should remain localhost and ${PG_BOUNCER_LISTEN_PORT}
 # because that represents the location of pgbouncer itself, not the
 # remote psql server that would have $DB_HOST:$DB_PORT.
-
 source /clowder_init.sh
 
+logtime "before psql select"
 PGPASSWORD="$DB_PASSWORD" /usr/pgsql-14/bin/psql \
   -h localhost -p ${PG_BOUNCER_LISTEN_PORT} -U "${DB_USER}" -d "${DB_NAME}" \
   -c "select 1 as psql_is_ready" 2>/dev/null \
-  | grep "psql_is_ready"
-exit $?
+  | grep "psql_is_ready" | tee -a $LOGPATH
+RESULT=$?
+
+logtime "psql finished"
+echo "result was $RESULT" | tee -a $LOGPATH
+exit $RESULT