Intro

Most web applications make use of databases. When deploying your app in production, you will need, among other things, monitoring and analysis/reports of log data generated by your application.

This comes in handy when troubleshooting problems, in situations involving bottlenecks in large applications, where we need to find low-performing SQL queries.

Overview

This is a simplified diagram that shows the interactions between the main components of a typical web application production environment.

The users make requests to the web application. In order to serve the requests, the web application needs information from a database, in this case, the databased being used is PostgreSQL, so it makes queries to it.

The PostgreSQL database server computes the queries, returns back data, but at the same time, it also writes to log files on disk.

The log files are being rotated on a daily basis. We employ rotating logs to avoid running into low disk-space situations on productive systems. And generally, the rotated logs are sufficient to troubleshoot a problem signaled by a monitoring system.

Each day has its own log file. Log lines are accumulated in the log file according to the day of the week when the logged operation was executed (the most common operation would be a query). The entire cycle continues for each day, and after one week, on the same day, the log file is truncated, and then it's written to again.

User 1
User 2
User 3
PostgreSQL database server
Web application
PostgreSQL
rotating logs
  • Monday
  • Tuesday
  • Wednesday
  • Thursday
  • Friday
  • Saturday
  • Sunday

PostgreSQL logging and log rotation

Most of the settings described here are documented in the 18.8 Error reporting and logging section of the PostgreSQL manual.

We're turning on the logging collector, we ensure that we have %w in the configuration for the daily log filename (this is the 0-based weekday represented as a decimal number, with 0 being sunday, 1 is monday and so on).

Once the logging collector is enabled, the logs are no longer stored in /var/log/postgresql/ , but instead, they will be located at /var/lib/postgresql/9.4/main/pg_log/ .

We're also aiming to truncate the file on rotation.

logging_collector = on
log_filename = 'postgresql-%w.log'
log_file_mode = 0640
log_truncate_on_rotation = on
log_rotation_age = 1d
log_min_duration_statement = 0
log_checkpoints = on
log_connections = on
log_disconnections = on
log_duration = on
log_lock_waits = on
log_line_prefix = '%t [%p]: [%l-1] db=%d,user=%u,app=%a,client=%h '

Running pgBadger on a schedule

In order to run pgbadger periodically, we need to schedule it in cron.

After running, pgBadger 8.1 seems to leave its pidfile behind, but we can easily clean up the pidfile for it.

We only process/analyze log files that were recently modified (at the latest, 180 minutes ago).

The -R 5 parameter tells pgBadger to only retain the last 5 weeks of binary data and reports.

And finally, we delete PostgreSQL log files older than 2 days. In combination with the Pg 7-day rotating logs, this means we only keep 2 PostgreSQL log files (since there's one Pg log file per day, given the way we've set up PostgreSQL logging).

We may have multiple applications using the same database. Since we've set up PostgreSQL to log the application name as well, we can build separate pgbadger reports for each application.

For example, if you're running the queries in a Bash script, you may use the PGAPPNAME environment variable, which can be passed on by psql when it makes queries to the PostgreSQL server and therefore, the queries will be logged with the application name.

The application name is usually passed in the connection string at application level. For example, if you're using a language like Python and the psycopg2 PostgreSQL driver, you can pass application_name in the connection string. The Java Pg driver pgjdbc-ng allows you to pass the applicationName parameter in the jdbc connection string.

#!/bin/bash
PG_LOG_PATH=/var/lib/postgresql/9.4/main/pg_log/
PGBADGER="/home/user/bin/pgbadger --anonymize -q -R 5 "
ROOT=/home/user/pgbadger

check_pgbadger_pid() {
    if [[ -e '/tmp/pgbadger.pid' ]]; then
        PAST_PID=$(cat /tmp/pgbadger.pid)
        CURRENT_PIDS=$(pgrep -f pgbadger)
        if [[ $CURRENT_PIDS =~ $PAST_PID ]]; then
            echo "[ERROR] pgbadger still running"
            exit -1
        else
            rm '/tmp/pgbadger.pid'
        fi
    fi
}

RECENTLY_MODIFIED_LOGS=$(find $PG_LOG_PATH -mmin -180 -name "postgresql*")

mkdir -p "$ROOT" "$ROOT/bot" "$ROOT/metrics" "$ROOT/collector" "$ROOT/web"

$PGBADGER -l "$ROOT/.pgbadger_last_state_file"           -d test1 -X -I                                -O "$ROOT"           $RECENTLY_MODIFIED_LOGS
check_pgbadger_pid
$PGBADGER -l "$ROOT/bot/.pgbadger_last_state_file"       -d test1 -X -I --appname "upstats-bot"        -O "$ROOT/bot"       $RECENTLY_MODIFIED_LOGS
check_pgbadger_pid
$PGBADGER -l "$ROOT/metrics/.pgbadger_last_state_file"   -d test1 -X -I --appname "upstats-metrics"    -O "$ROOT/metrics"   $RECENTLY_MODIFIED_LOGS
check_pgbadger_pid
$PGBADGER -l "$ROOT/collector/.pgbadger_last_state_file" -d test1 -X -I --appname "upstats-collector"  -O "$ROOT/collector" $RECENTLY_MODIFIED_LOGS
check_pgbadger_pid
$PGBADGER -l "$ROOT/web/.pgbadger_last_state_file"       -d test1 -X -I --appname "upstats-web"        -O "$ROOT/web"       $RECENTLY_MODIFIED_LOGS
check_pgbadger_pid

OLD_LOGS=$(find $PG_LOG_PATH -type f -mtime +2)
if [ ! -z "$OLD_LOGS" ]; then
    rm $OLD_LOGS;
fi

After analyzing the logs, pgBadger will create a number of reports including:

  • Queries that took up the most time
  • Histogram of query times
  • Overall statistics
  • The most frequent waiting queries
  • Queries per user and total duration per user
  • Distribution of queries type per database/application
  • Queries by type (select/insert/update/delete)
  • SQL queries statistics

Conclusion

We've covered the usage of a log analysis tool called pgBadger in a PostgreSQL setup configured with rotating logs.