A while back, I wrote about ‘Helpful Postgres logging and defaults‘.  The real question is, how helpful are these, really?  So, let’s take a quick look at how we can use the increased logging in order to do something useful.  If the previous post is TL;DR, here’s the quick list:

logging_collector = on 
log_filename = 'postgresql-%a.log' 
log_truncate_on_rotation=on 
log_line_prefix = '%t [%p]: [%l-1] user=%u,db=%d,app=%a,client=%h '
log_checkpoints = on
log_autovacuum_min_duration=0
log_temp_files = 0
log_lock_waits = on

Essentially, these cover the basics when it comes to monitoring, without adding a whole lot of stuff to your logs.  These settings are default in the BigSQL sandboxes so that you’re running out of the gate.  If you’ve installed PostgreSQL another way, you can simply modify your postgresql.conf file to include these items.

Follow along

Quick Install

If you’d like to follow along, you can quickly setup a test pg96 environment by using the ‘standalone’ installer for postgres that BigSQL provides.  If you already have PostgreSQL, you can skip this section.

Grab BigSQL

scottm: ~ $ python -c "$(curl -fsSL http://s3.amazonaws.com/pgcentral/install.py)"
Downloading BigSQL PGC 3.0.0 ...
Unpacking ...
Cleaning up
Setting REPO to http://s3.amazonaws.com/pgcentral
Updating Metadata
 BigSQL PGC installed. Try 'bigsql/pgc help' to get started.

Install PostgreSQL 9.6.current

scottm: ~ $ cd bigsql/
 scottm: bigsql $ ./pgc install pg96
 ['pg96']
 Get:1 http://s3.amazonaws.com/pgcentral pg96-9.6.0-1b-osx64
 Unpacking pg96-9.6.0-1b-osx64.tar.bz2

Init pg96

scottm: bigsql $ ./pgc init pg96
## Initializing pg96 #######################
Superuser Password [password]:
 Giving current user permission to data dir
Initializing Postgres DB at:
 -D "/Users/scottm/bigsql/data/pg96"
Using PostgreSQL Port 5432
Password securely remembered in the file: /Users/scottm/.pgpass
to load this postgres into your environment, source the env file:
 /Users/scottm/bigsql/pg96/pg96.env

Start pg96

scottm: bigsql $ ./pgc start pg96
 pg96 starting on port 5432

Since the BigSQL package automatically sets the appropriate logging defaults, we’re set to go!

Modify Existing PG

That’s if you’re using bigSQL.  You can use pgBadger with any postgresql, you just need to make sure that it’s logging enough to be useful.

Basically, we’re going to add the logging settings required to up-the-ante on logging:

logging_collector = on 
log_filename = 'postgresql-%a.log' 
log_truncate_on_rotation=on 
log_line_prefix = '%t [%p]: [%l-1] user=%u,db=%d,app=%a,client=%h '
log_checkpoints = on
log_autovacuum_min_duration=0
log_temp_files = 0
log_lock_waits = on
  1. open up your postgresql.conf file
  2. paste the above values in to the bottom of the file
  3. save & close postgresql.conf
  4. restart postgres (if you already had ‘logging_collector=on’, you can just reload).

Workload

Now that you’re logging, it’s time to generate some workload.  My database isn’t actually serving clients at this point, so, I’m going to use the included pgbench tool to generate some data and traffic. (NB: If you run this step, you’ll use up about 2.5 GB of disk space).

pgbench -i -s 100 -U postgres

This initializes a new pgbench database with a ‘scaling factor’ (i.e. sizing factor) of 100 bank branches (pgbench simulates debit/credit).  You’ll see a bunch of output fly-by as you initialize 10,000,000 rows (tuples) of data.  Don’t worry, this only translates to about 2.5 GB of space.

pgBadger-ing

Great!  Now we’re logging at a verbosity that lets us see what’s going on in PostgreSQL, how do I take advantage?  Enter pgBadger; this tool is essentially a high-performance log parser for the postgresql information logs.  If you’re following along with my BigSQL install from above, you can grab pgBadger with:

scottm: bigsql $ ./pgc install pgbadger
 ['pgbadger']
Get:1 http://s3.amazonaws.com/pgcentral pgbadger-9.0
 Unpacking pgbadger-9.0.tar.bz2

If you’re not using the BigSQL package, you can:

git clone https://github.com/dalibo/pgbadger.git

Now, let’s run pgBadger against the logs.

If you’re following along:

scottm: bigsql $ perl pgbadger/pgbadger data/logs/pg96/postgresql-*.log
[========================>] Parsed 8993 bytes of 8993 (100.00%), queries: 0, events: 2
LOG: Ok, generating html report...
scottm: bigsql $

By default, pgBadger puts its output in a file called ‘out.html’ (see perl pgbadger/pgbadger –help for the flag to change this).

I’m going to open up the ‘out.html’ file in my web browser and view my report (I’ve attached the out.html report I generated for this blog so you can download it and play if you’d like).

 

pgBadger empty overview

Hmmm, looks like I have an empty report?  Strange?  Well, keep in mind, we’ve told postgres to log certain things:

  •  checkpoints
  • Vacuum
  • temp files
  • lock waits

We never told postgres to log queries (we’ll come back to this in a minute).  For now, let’s take a look at the ‘checkpoints’ and see what’s there.

Choose Checkpoints

 

Once we choose the ‘Checkpoints’ item from the top menu, we’ll see that our data-load created some activity for us (your data will most likely look somewhat different).

Screen Shot 2016-10-21 at 4.45.47 PM

Now I’m starting to see data about my checkpoint buffer utilization!  Cool!  I can actually see how memory is being used in the server.  This is coming out of the ‘log_checkpoints’ parameter that we set earlier.

To get richer data, we need to push more activity against our DB server.  With pgBench:

scottm: bigsql $ pg96/bin/pgbench -T 300 -c 10

This will run a 5 minute (300 second) test with 10 concurrent client sessions.

Once that’s complete, re-run pgBadger:

scottm: bigsql $ perl pgbadger/pgbadger data/logs/pg96/postgresql-*.log
[========================>] Parsed 38636 bytes of 38636 (100.00%), queries: 0, events: 2
[========================>] Parsed 3024 bytes of 3024 (100.00%), queries: 0, events: 2
[========================>] Parsed 24694 bytes of 24694 (100.00%), queries: 0, events: 2
LOG: Ok, generating html report...

(Your output may appear slightly different based on the number of log files that you have)

Now, your ‘out.html’ will have data based on your workload.

Badger with WorkloadWe also have some interesting data surrounding VACUUM behavior:Vacuum DataIt should be noted, these are just quick screen grabs, take a look at the attached ‘out.html’ for more.

 

The point is, using some wise logging defaults gets you some awesome pgBadger joy, without paying a TON in logging overhead.  Stay tuned for part 2 where I’ll crank up logging even more and show you how to get per-statement data.