Category Archives: PostgreSQL

Logging information on long running transactions in PostgreSQL

Leave a reply

PostgreSQL has some runtime parameters we can use to monitor long running queries; we can set log_min_duration_statement to log any statements that take longer than the value in milliseconds we set. But what can we do if we have an application that keeps a long running transaction open but is mainly just ‘<IDLE> in transaction’? Perhaps it’s pinning that transaction open whilst it performs some long running action elsewhere? We can use a monitoring tool like Nagios to show long running transactions, but the activity they actually do won’t be logged by postgres unless they’re blocking somewhere. What comes to mind here, is distributed transaction managers playing up.

For example here if we set log_min_duration_statement to 0 postgres will log every query we issue, and we’ll see a message like this in the log:

[postgres]
LOG: duration: 3.475 ms statement: SELECT * FROM pg_stat_database where datname=’TEST’
[/postgres]

We can set statement_timeout to forcefully prevent applications running queries that take longer than we would like them to, so any statement that exceeds statement_timeout in milliseconds will be cancelled, for example:

[postgres]
TEST=# set statement_timeout = ‘2ms’;
SET
TEST=# SELECT * FROM pg_stat_database where datname=’TEST’;
ERROR: canceling statement due to statement timeout
[/postgres]

Obviously setting such a low value is not much use, but a typical use case for this would be in a busy web application where a user is likely to have gone away after 10 seconds anyway, in which case we could alter the applications user to have a statement_timeout somewhere around 10 seconds.

To log blocking queries we can set log_lock_waits to on, in which case postgres will log details of blocking queries when it checks for deadlock after the deadlock_timeout interval (default 1 second). We’ll see a message something like this in the log depending on the type of lock:

[postgres]
LOG: process 16532 still waiting for ShareLock on transaction 311823400 after 1000.147 ms
STATEMENT: UPDATE balls SET description = ‘TEST’ WHERE id = 5;
[/postgres]

The above tells us that after 1 second our statement was still waiting on a lock, this is not to be confused with deadlock; the deadlock_timeout parameter factors into this only because postgres may as well output this information whilst it is doing the work to check for deadlock anyway. Actual deadlock would look something like this:

[postgres]
LOG: process 4465 detected deadlock while waiting for ShareLock on transaction 311824216 after 1000.158 ms
STATEMENT: UPDATE balls SET description = ‘TEST’ WHERE id = 5;
ERROR: deadlock detected
DETAIL: Process 4465 waits for ShareLock on transaction 311824216; blocked by process 16532.
Process 16532 waits for ShareLock on transaction 311824207; blocked by process 4465.
Process 4465: UPDATE balls SET name = ‘TEST’ WHERE id = 5;
Process 16532: UPDATE balls SET name = ‘TEST2’ WHERE id = 6;
[/postgres]

Whilst all of the above is useful for tracking down problems, the one thing that we can’t do do with runtime parameters is timeout or log long running transactions, and perhaps even log the statements that may only persist for short periods within the transaction. In most cases we’d be using some sort of monitoring platfom like nagios, cacti or munin to monitor transaction times along with everything else (including query times and locks mentioned above), but sometimes it’d be nice to see that information in the postgres logs too.

Generally if some application is keeping long running or idle transactions open, then it’s the application that needs to be fixed. But when that’s out of your hands you can just feel a bit stuck whilst you wait for that to happen, I’ve a pl/pgsql function that can be scheduled to log some information, and even cancel/terminate sessions. The function can be downloaded here or here

For example if we want to log information on long running transactions, we could run the following:

[postgres]
TEST=# SELECT public.pg_log_long_xact(‘1s’);
NOTICE: long_xact pid: 4465 duration: 431.325747 ms user: glyn application: psql client: [local] statement: <IDLE> in transaction
NOTICE: long_xact pid: 16532 duration: 327.438302 ms user: glyn application: psql client: [local] statement: UPDATE balls SET description = ‘TEST’ WHERE id = 5;
pg_log_long_xact
—————
(0 rows)
[/postgres]

If we want to see if either of these is waiting on the other:

[postgres]
TEST=# SELECT public.pg_log_long_xact(‘1s’, true);
NOTICE: long_xact pid: 4465 duration: 471.885373 ms user: glyn application: psql client: [local] statement: <IDLE> in transaction
NOTICE: long_xact pid: 16532 duration: 367.997928 ms user: glyn application: psql client: [local] statement: UPDATE balls SET description = ‘TEST’ WHERE id = 5;
NOTICE: long_xact waiter pid: 16532 blocker detail is; pid: 4465 duration: 471.885373 ms relation: any (public.balls (RowExclusiveLock)) lock type: transaction id 311824482 user: glyn application: psql client: [local] statement: <IDLE> in transaction
pg_log_long_xact
—————
(0 rows)
[/postgres]

We can set the level of raise it uses (in hindsight the default should probably have been LOG), or have it output the details as text:

[postgres]
TEST=# \t off
Showing only tuples.
TEST=# SELECT public.pg_log_long_xact(‘1s’, true, ‘text’);
long_xact pid: 4465 duration: 574.477076 ms user: glyn application: psql client: [local] statement: <IDLE>; in transaction
long_xact pid: 16532 duration: 470.589631 ms user: glyn application: psql client: [local] statement: UPDATE balls SET description = ‘TEST’ WHERE id = 5;
long_xact waiter pid: 16532 blocker detail is; pid: 4465 duration: 574.477076 ms relation: any (public.balls (RowExclusiveLock)) lock type: transaction id 311824482 user: glyn application: psql client: [local] statement: <IDLE> in transaction
[/postgres]

If we’re really having issues, we can make it start cancelling statements on each run, starting with those that have been blocking for the longest else those that have been running for the longest duration. As of pg 9.3 there’s now a lock_timeout parameter that will abort any statement waiting longer than the specified number of milliseconds, which is much better, but even post 9.3 the above function can be useful (Note that the difference here is that the above function will attempt to abort the blocking transaction rather than the waiting statement, or if there is no locking just the longest transaction. Obviously not to be used in haste.):

[postgres]
TEST=# SELECT public.pg_log_long_xact(‘1s’, true, ‘text’, ’10 minutes’);
long_xact pid: 4465 duration: 895.57988 ms user: glyn application: psql client: [local] statement: <IDLE> in transaction
long_xact unable to cancel backend with pid: 4465
long_xact pid: 16532 duration: 791.692435 ms user: glyn application: psql client: [local] statement: UPDATE balls SET description = ‘TEST’ WHERE id = 5;
long_xact waiter pid: 16532 blocker detail is; pid: 4465 duration: 895.57988 ms relation: any (public.balls (RowExclusiveLock)) lock type: transaction id 31182
4482 user: glyn application: psql client: [local] statement: <IDLE> in transaction
[/postgres]

In this case it can’t cancel the blocking statement as it is idle in trasaction, so there’s nothing to cancel, but we can pass another timeout to start terminating backends after:

[postgres]
TEST=# SELECT public.pg_log_long_xact(‘1s’, true, ‘text’, ’10 minutes’, ’15 minutes’);
long_xact pid: 4465 duration: 1026.90736 ms user: glyn application: psql client: [local] statement: <IDLE> in transaction
long_xact terminated backend with pid: 4465
long_xact pid: 16532 duration: 923.019915 ms user: glyn application: psql client: [local] statement: UPDATE balls SET description = ‘TEST’ WHERE id = 5;
[/postgres]

On out next run it has “resolved” the issue, I say “resolved” because it’s removed the blocking session:

[postgres]
TEST=#\t on
TEST=# SELECT public.pg_log_long_xact(‘1s’, true, ‘text’, ’10 minutes’, ’15 minutes’);
pg_log_long_xact
—————
(0 rows)
[/postgres]

By default the function only cancels/terminates the longest running blocker, or longest running transaction, we can be more forceful than that by passing an extra parameter to tell it to cancel statements/terminate backends of all long running transactions it finds (I’ve lowerd the timeouts purely because I had to restart the transactions/statements):

[postgres]
TEST=#\t off
TEST=# SELECT public.pg_log_long_xact(‘1s’, true, ‘text’, ‘2 minutes’, ‘3 minutes’, true);
long_xact pid: 19065 duration: 187.279089 ms user: glyn application: psql client: [local] statement: <IDLE> in transaction
long_xact terminated backend with pid: 19065
long_xact pid: 16532 duration: 184.251569 ms user: glyn application: psql client: [local] statement: UPDATE balls SET description = ‘TEST’ WHERE id = 5;
long_xact cancelled backend with pid: 16532
(4 rows)
[/postgres]

What would be nice to see in addition to the lock_timeout parameter would be a blocker_timeout parameter that would function just like the lock_timeout but abort the blocking session. Obviously such a parameter could just cause more havoc if the offending application just keeps retrying the blocking operation, or worse you have it set and it aborts the restructure you’ve been waiting hours for. But I think in some instances it could be useful, set to a large enough value we could kill the offending blocking transaction and let all the others complete.

Update 30/09/2016 – Postgres 9.6 adds idle_in_transaction_session_timeout which allows us to automatically terminate any transactions that sit idle for longer than the value in milliseconds we set.

Unit testing in PostgreSQL with pgTap

2 Replies

The applications I work with use procedural functions and RDBMS features quite heavily, and although we have unit tests for application code, we currently have no unit testing directly in the database. I’ll be the first to admit that I can be fairly highly strung when making large changes to our systems, and having a suite of unit tests to run is a great way to extinguish any histrionics.

I’ve been looking at pgTap today which provides an excellent way to perform unit testing in PostgreSQL covering pretty much every aspect of the schema.

To install pgTap we just download, make and install just like any other extension:

$ cd /usr/pgsql_src
$ wget http://api.pgxn.org/dist/pgtap/0.94.0/pgtap-0.94.0.zip
$ unzip pgtap-0.94.0.zip && cd pgtap*
$ make
$ make installcheck PGUSER=glyn
$ sudo make install

The system I’m testing on is still running Postgres 9.0, so to install the extension I have to revert to running the sql script rather than “CREATE EXTENSION”, and for some reason the pgtap.sql script didn’t end up in my contrib directory along with the sql for the extension based versions, so I just copied it there manually before running it:

$ cp sql/pgtap.sql `pg_config --sharedir`/contrib
$ psql -d TEST -f `pg_config --sharedir`/contrib/pgtap.sql

If this were 9.1+ that would just be just be:

$ psql -d TEST -c "CREATE EXTENSION pgtap"

Now pgTap is installed I can run a test that checks nothing. We perform all tests within a transaction which is rolled back at the end to ensure our tests do not make any persistent changes.

[postgres highlight=”1,3,8,13,17″]
TEST=# BEGIN;
BEGIN
TEST=# SELECT plan(1);
plan
——
1..1
(1 row)
TEST=# SELECT pass( ‘Testing nothing’ );
pass
————————
ok 1 – Testing nothing
(1 row)
TEST=# SELECT * FROM finish();
finish
——–
(0 rows)
TEST=# ROLLBACK;
ROLLBACK
[/postgres]

The output basically means; 1..1 we ran 1 of 1 tests and ok 1 – Testing nothing test number 1, with description “Testing nothing” returned “ok”. The above looks a bit messy and the docs recommend setting the following in psql to make the behaviour and output a little easier to handle:

[postgres]
\set ECHO
\set QUIET 1
\pset format unaligned
\pset tuples_only true
\pset pager
\set ON_ERROR_ROLLBACK 1
\set ON_ERROR_STOP true
\set QUIET 1
[/postgres]

Now lets create a function and perform an actual test on the results:

[postgres]
TEST=# CREATE OR REPLACE FUNCTION public.test1(text) RETURNS text AS ‘SELECT upper($1) || length($1)::text’ language ‘SQL’;

TEST=# BEGIN;
TEST=# SELECT plan(1);
1..1
TEST=# SELECT results_eq(E’SELECT * FROM public.test1(\’glyn\’)’, E’SELECT upper(\’glyn\’) || length(\’glyn\’)::text’,’public.test1() should return text in uppercase suffixed with length’);
ok 1 – public.test1() should return text in uppercase suffixed with length
TEST=# SELECT * FROM finish();
TEST=# ROLLBACK;
[/postgres]

We can also simply test if some operation like an insert succeeds:

[postgres]
TEST=# CREATE TABLE public.table1 (a text, b integer);

TEST=# BEGIN;
TEST=# SELECT plan(1);
1..1
TEST=# SELECT lives_ok(E’INSERT INTO public.table1 VALUES (\’TEST\’, 1)’);
ok 1
TEST=# SELECT * FROM finish();
TEST=# ROLLBACK;
[/postgres]

…and we can check that performing some operation fails with a particular exception:

[postgres]
TEST=# BEGIN;
TEST=# SELECT plan(1);
1..1
TEST=# SELECT throws_ok(E’INSERT INTO public.table1 VALUES (\’test\’, \’not an integer\’)’,’22P02′,NULL,’Column b is an integer, inserting text should fail’);
ok 1 – Column b is an integer, inserting text should fail
TEST=# SELECT * FROM finish();
TEST=# ROLLBACK;
[/postgres]

We can test if an operation created the expected data too, if I create a trigger on my test table to uppercase any text inserted, we can check if it worked as expected:

[postgres]
TEST=# CREATE FUNCTION public.table1_upper_func() RETURNS trigger AS $$ BEGIN NEW.a := upper(NEW.a); RETURN NEW; END; $$ LANGUAGE plpgsql VOLATILE;
TEST=# CREATE TRIGGER table1_upper_trig BEFORE INSERT OR UPDATE ON public.table1 FOR EACH ROW EXECUTE PROCEDURE public.table1_upper_func();

TEST=# BEGIN;
TEST=# SELECT plan(1);
1..1
TEST=# INSERT INTO public.table1 VALUES (‘test’,1);
TEST=# SELECT is(a, ‘TEST’, ‘Inserted values into column "a" should be uppercased’ ) FROM public.table1 WHERE b = 1;
ok 1 – Inserted values into column "a" should be uppercased
TEST=# SELECT * FROM finish();
TEST=# ROLLBACK;
[/postgres]

We can also test the existence and structure of a table:

[postgres]
TEST=# CREATE INDEX ON public.table1 USING btree(b);
TEST=#
TEST=# BEGIN;
TEST=# SELECT plan(6);
1..6
TEST=# SELECT has_table(‘public’, ‘table1’, ‘table public.table1 exists’ );
ok 1 – table public.table1 exists
TEST=# SELECT has_column(‘public’, ‘table1’, ‘a’, ‘column public.table1.a exists’);
ok 2 – column public.table1.a exists
TEST=# SELECT col_type_is(‘public’, ‘table1’, ‘a’, ‘text’, ‘Type of column public.table1.a is text’);
ok 3 – Type of column public.table1.a is text
TEST=# SELECT has_column(‘public’, ‘table1’, ‘b’, ‘column public.table1.b exists’);
ok 4 – column public.table1.b exists
TEST=# SELECT col_type_is(‘public’, ‘table1’, ‘b’, ‘integer’, ‘Type of column public.table1.b is integer’);
ok 5 – Type of column public.table1.b is integer
TEST=# SELECT has_index(‘public’, ‘table1′,’table1_b_idx’, ‘Table public.table1 has an index table1_b_idx’);
ok 6 – Table public.table1 has an index table1_b_idx
TEST=# SELECT * FROM finish();
TEST=# ROLLBACK;
[/postgres]

To wrap all of this up pgTap provides a runtests() function that will run predefined test functions without us having to define the number of tests with plan(n) or run finish(), and we can write these functions just like any other function incorporating the tests demonstrated above. By default the function looks for function names starting with test, it’s probably a good idea to put the tests in a specific schema or give them a more unique name than that.

When runtests() is run it also first looks for functions starting with “startup” or “shutdown” and these are run in alphabetical order before and after a whole set of test functions respectively. In addition functions starting with “setup” or “teardown” are, again, run in alphabetical order before and after each test function respectively. Typically these would be used to check, perform and undo any data changes required by each and or all tests, for example if we’ve called a sequence that doesn’t belong to a table during our tests, it’s value won’t be rolled back so we might want to reset it’s value.

One thing to clarify though (which came to my attention when running pg_prove blelow), is that where the “setup” and “teardown” functions are automatically rolled back at the end of each test, the “startup” and “shutdown” functions are not automatically rolled back at the end of the tests. If you want that functionality then you need to wrap your call to runtests in a transaction and roll it back at the end just as before.

E.g. we can create our test schema and functions:

[postgres]
CREATE SCHEMA unit_testing;

TEST=# CREATE OR REPLACE FUNCTION unit_testing.setup_tap_test_example()
RETURNS SETOF TEXT AS $$
BEGIN
INSERT INTO public.table1 VALUES (‘test’,1);
RETURN NEXT is(a, ‘TEST’, ‘Should have initial row in table1’) FROM public.table1 WHERE b = 1;
END;
$$ LANGUAGE plpgsql;

TEST=# CREATE OR REPLACE FUNCTION unit_testing.tap_test_example()
RETURNS SETOF TEXT AS $$
BEGIN
RETURN NEXT has_table(‘public’, ‘table1’, ‘table public.table1 exists’ );
RETURN NEXT has_column(‘public’, ‘table1’, ‘a’, ‘column public.table1.a exists’);
RETURN NEXT col_type_is(‘public’, ‘table1’, ‘a’, ‘text’, ‘Type of column public.table1.a is text’);
RETURN NEXT has_column(‘public’, ‘table1’, ‘b’, ‘column public.table1.b exists’);
RETURN NEXT col_type_is(‘public’, ‘table1’, ‘b’, ‘integer’, ‘Type of column public.table1.b is integer’);
RETURN NEXT has_index(‘public’, ‘table1′,’table1_b_idx’, ‘Table public.table1 has an index table1_b_idx’);
END;
$$ LANGUAGE plpgsql;

TEST=# CREATE OR REPLACE FUNCTION unit_testing.teardown_tap_test_example()
RETURNS SETOF TEXT AS $$
BEGIN
RETURN NEXT lives_ok(‘DELETE FROM public.table1 WHERE b = 1’);
END;
$$ LANGUAGE plpgsql;
[/postgres]

Now we can run them:
[postgres]
TEST=# BEGIN;
TEST=# SELECT * FROM runtests(‘unit_testing’,’^tap_test_example’);
ok 1 – Should have initial row in table1
# unit_testing.tap_test_example()
ok 2 – table public.table1 exists
ok 3 – column public.table1.a exists
ok 4 – Type of column public.table1.a is text
ok 5 – column public.table1.b exists
ok 6 – Type of column public.table1.b is integer
ok 7 – Table public.table1 has an index table1_b_idx
ok 8
1..8
TEST=# ROLLBACK;
[/postgres]

Gravy. We can, if we want, also install the pg_prove module from cpan to finish wrapping it all together with TAP::Harness and provide a summary of our tests:

$ sudo cpan TAP::Parser::SourceHandler::pgTAP
$ pg_prove -d TEST -R -s unit_testing -x '^tap_test_example'
runtests('unit_testing'::name, '^tap_test_example'::text); ..
# unit_testing.tap_test_example()
runtests('unit_testing'::name, '^tap_test_example'::text); .. ok
All tests successful.
Files=1, Tests=9,  0 wallclock secs ( 0.05 usr  0.02 sys +  0.00 cusr  0.01 csys =  0.08 CPU)
Result: PASS

This is just a small example of some of the tests we can do with pgTap, the suite provides a very extensive set of tests. See the documentation here.

Updating Royal Mail PAF data and ignorance about PostgreSQL deferred foreign keys

Leave a reply

A few months ago I bashed together a pl/pgsql function for importing Royal Mail PAF
data into PostgreSQL and at the same time I also put together another function to perform an update from their “changes” files.

Today I came to actually try and use that function, and it’s not much of a surprise that it needed a little more work; at the time I was working off a fresh import and a small set of changes, whilst looking (with squinty eyes) at the fairly long winded docs. The changes files from RM are supplied as a journal of changes, which I can only assume were intended to be read and applied sequentially; this means we have to rely on some of the smarts SQL provides us with to apply them in bulk. The docs even try to dissuade the use of the changes files by saying “Applying Changes files regularly is ‘high maintenance’, because applying thousands of changes is a very long & involved process compared to buying full refreshes”, however I don’t want to do full refreshes as that’s likely to cause more interruption, and besides it just seems a bit of a cop out to me.

So after another quick skim over the docs, I made a couple of corrections to the update function where I’d complicated things by replacing blank key columns with nulls, and added in an update procedure for the Alias and Postzon files (which are only supplied as a full refresh), this time using postgis to generate the latitude and longitude and save running my horrible perl script.

Then I had a go at running the update:

[postgres]
TEST=# BEGIN;
TEST=# SELECT update_pc_paf(‘Y14M04’, ‘/tmp’);
NOTICE: 2014-05-22 19:40:00.161582+01: Import starting for edition Y14M04 with data root /tmp/Y14M04_CHANGES/
NOTICE: 2014-05-22 19:40:00.165233+01: Begin staging Changes1 file
NOTICE: 2014-05-22 19:40:00.439189+01: Done staging Changes1 file
NOTICE: 2014-05-22 19:40:00.439379+01: Preparing to update localities
NOTICE: 2014-05-22 19:40:00.487656+01: Prepared 15 records for update on localities
NOTICE: 2014-05-22 19:40:00.489481+01: Removed 0 records from localities
NOTICE: 2014-05-22 19:40:00.504522+01: Created 15 records in localities
NOTICE: 2014-05-22 19:40:00.504651+01: Preparing to update thoroughfares
NOTICE: 2014-05-22 19:40:00.54741+01: Prepared 377 records for update on thoroughfares
NOTICE: 2014-05-22 19:40:00.548924+01: Removed 0 records from thoroughfares
NOTICE: 2014-05-22 19:40:00.589353+01: Created 377 records in thoroughfares
NOTICE: 2014-05-22 19:40:00.589477+01: Preparing to update thoroughfare_descriptor
NOTICE: 2014-05-22 19:40:00.631469+01: Prepared 0 records for update on thoroughfare_descriptor
NOTICE: 2014-05-22 19:40:00.632967+01: Removed 0 records from thoroughfare_descriptor
NOTICE: 2014-05-22 19:40:00.633275+01: Created 0 records in thoroughfare_descriptor
NOTICE: 2014-05-22 19:40:00.633444+01: Preparing to update building_names
NOTICE: 2014-05-22 19:40:00.700856+01: Prepared 7947 records for update on building_names
NOTICE: 2014-05-22 19:40:00.704261+01: Removed 0 records from building_names
NOTICE: 2014-05-22 19:40:01.155068+01: Created 7947 records in building_names
NOTICE: 2014-05-22 19:40:01.155178+01: Preparing to update sub_building_names
NOTICE: 2014-05-22 19:40:01.223108+01: Prepared 7798 records for update on sub_building_names
NOTICE: 2014-05-22 19:40:01.226335+01: Removed 0 records from sub_building_names
NOTICE: 2014-05-22 19:40:01.669071+01: Created 7798 records in sub_building_names
NOTICE: 2014-05-22 19:40:01.675826+01: Begin staging Changes2 file
NOTICE: 2014-05-22 19:40:02.59217+01: Done staging Changes2 file
NOTICE: 2014-05-22 19:40:02.592303+01: Preparing to update mainfile
NOTICE: 2014-05-22 19:40:05.07166+01: Prepared 216438 records for update on mainfile
NOTICE: 2014-05-22 19:41:41.439761+01: Removed 87291 records from mainfile
NOTICE: 2014-05-22 19:42:54.976222+01: Created 129147 records in mainfile
NOTICE: 2014-05-22 19:42:54.97639+01: Preparing to update organisations
NOTICE: 2014-05-22 19:42:55.609607+01: Prepared 65158 records for update on organisations
NOTICE: 2014-05-22 19:43:07.778516+01: Removed 32840 records from organisations
NOTICE: 2014-05-22 19:43:10.141383+01: Created 32318 records in organisations
NOTICE: 2014-05-22 19:43:10.18821+01: Begin staging WChanges file
NOTICE: 2014-05-22 19:43:10.218245+01: Done staging WChanges file
NOTICE: 2014-05-22 19:43:10.218346+01: Preparing to update welsh mainfile
NOTICE: 2014-05-22 19:43:10.311915+01: Prepared 8395 records for update on welsh mainfile
NOTICE: 2014-05-22 19:43:20.631738+01: Removed 3098 records from welsh mainfile
NOTICE: 2014-05-22 19:43:23.616801+01: Created 5149 records in welsh mainfile
NOTICE: 2014-05-22 19:43:23.61696+01: Preparing to update welsh organisations
NOTICE: 2014-05-22 19:43:23.624131+01: Prepared 0 records for update on welsh organisations
NOTICE: 2014-05-22 19:43:23.624836+01: Removed 0 records from welsh organisations
NOTICE: 2014-05-22 19:43:23.625512+01: Created 0 records in welsh organisations
NOTICE: 2014-05-22 19:43:23.634001+01: Begin staging postzon
NOTICE: 2014-05-22 19:43:29.097317+01: Done staging postzon file, now staging with lat long data
NOTICE: 2014-05-22 19:44:41.996743+01: Done staging postzon with lat long data, updating
NOTICE: 2014-05-22 19:44:57.195802+01: Inserted 3594 new records for update on postzon_100m
NOTICE: 2014-05-22 19:46:13.242174+01: Updated 212398 records for update on postzon_100m
NOTICE: 2014-05-22 19:46:24.038271+01: Deleted 3991 records for update on postzon_100m
NOTICE: 2014-05-22 19:46:24.808325+01: Begin staging alias file
NOTICE: 2014-05-22 19:46:32.810242+01: Done staging alias file
NOTICE: 2014-05-22 19:46:34.021948+01: Done staging counties , updating
NOTICE: 2014-05-22 19:46:34.023405+01: Inserted 0 new records for update on counties
NOTICE: 2014-05-22 19:46:34.024632+01: Updated 0 records for update on counties
NOTICE: 2014-05-22 19:46:34.025273+01: Deleted 0 records for update on counties
NOTICE: 2014-05-22 19:46:38.25488+01: Done staging county_alias , updating
NOTICE: 2014-05-22 19:46:41.711214+01: Inserted 3594 new records for update on county_alias
NOTICE: 2014-05-22 19:46:46.227681+01: Updated 12 records for update on county_alias
NOTICE: 2014-05-22 19:46:53.812323+01: Deleted 3991 records for update on county_alias
NOTICE: 2014-05-22 19:46:53.812483+01: Completed
update_pc_paf
—————
t
(1 row)
[/postgres]

My schema for the PAF data has deferrable foreign keys, and in order to apply the updates in chunks I’ve set them as deferred in the above function; I only find out if I’ve violated them when they’re checked on commit:

[postgres]
TEST=# COMMIT;
[/postgres]

…. And it just sits there forever! I go and do something else, but when I come back it’s still sitting there; what did I forget?

Well we can make a pretty good guess that we’re waiting whilst the deferred constraints are checked, but the constraint checks don’t take that long when they’re not deferred so why is it taking so long?

Well it turns out I’ve got indexes on the satellite tables that are referenced by the foreign keys on my main address table, but no indexes for those keys on the actual main address table. It’s apparent that when the deferred constraint is checked it needs to look up the row first; something that wouldn’t have been required if the constraint were immediate. I add some indexes, and try again:

[postgres]
TEST=# COMMIT;
Time: 281979.437 ms
[/postgres]

It worked, and we didn’t violate any constraints!

The new script (named paf_postgresql_import_postgis.plpgsql) is in the git repository at postgresql/geographic_data (mirrored also on github glynastill/geographic_data).