experimental debug output for debugging performance issues

Author: infinitewarp

clowder_init.sh

@@ -1,5 +1,8 @@
 #!/bin/sh
 
+echo "$(date --iso-8601=ns)" | tee -a $LOGPATH
+echo "start clowder_init.sh"  | tee -a $LOGPATH
+
 if [[ -z "${ACG_CONFIG}" ]]; then
   export PG_BOUNCER_LISTEN_PORT="5432"
 else
@@ -21,3 +24,6 @@ else
 
   [[ -z "${DB_PORT}" ]] && DB_PORT="5432"
 fi
+
+echo "$(date --iso-8601=ns)" | tee -a $LOGPATH
+echo "exit clowder_init.sh" | tee -a $LOGPATH

entrypoint.sh

@@ -1,16 +1,19 @@
 #!/bin/sh
 
+PID="$$"
+LOGPATH=/tmp/log-entrypoint-"$PID"
+
 source /clowder_init.sh
 
 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 ..."
+    echo "${LOGPREFIX} Checking ${SVC_NAME}:$SVC_PORT status ..." | tee -a $LOGPATH
     ncat ${SVC_NAME} ${SVC_PORT} < /dev/null && break
     sleep 5
   done
@@ -19,23 +22,23 @@ function check_svc_status() {
 
 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
 
@@ -44,7 +47,7 @@ PG_CONFIG_DIR=/etc/pgbouncer
 # 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"
+echo "Wrote authentication credentials to ${PG_CONFIG_DIR}/userlist.txt" | tee -a $LOGPATH
 
 # pgbouncer config
 printf "\
@@ -72,7 +75,7 @@ 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"
+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,19 @@
 #!/bin/bash
 
+PID="$$"
+LOGPATH=/tmp/log-liveness-"$PID"
+
+exec {BASH_XTRACEFD}>>$LOGPATH
+#set -x
+
+
+echo "$(date --iso-8601=ns)" | tee -a $LOGPATH
 source /clowder_init.sh
 
-/usr/pgsql-14/bin/pg_isready -h localhost -p ${PG_BOUNCER_LISTEN_PORT} -U "${DB_USER}" | grep "accepting connections"
-exit $?
+echo "$(date --iso-8601=ns)" | tee -a $LOGPATH
+/usr/pgsql-14/bin/pg_isready -h localhost -p ${PG_BOUNCER_LISTEN_PORT} -U "${DB_USER}" | grep "accepting connections"  | tee -a $LOGPATH
+RESULT=$?
+echo "$(date --iso-8601=ns)" | tee -a $LOGPATH
+echo "result was $RESULT" | tee -a $LOGPATH
+exit $RESULT
 

probe-readiness.sh

@@ -1,14 +1,23 @@
 #!/bin/bash
 
+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
 
+echo "$(date --iso-8601=ns)" | tee -a $LOGPATH
 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=$?
+echo "$(date --iso-8601=ns)" | tee -a $LOGPATH
+echo "result was $RESULT" | tee -a $LOGPATH
+exit $RESULT