Excessive (and slow) fsync() within single transaction

From: Stephen Tyler <stephen(at)stephen-tyler(dot)com>
To: pgsql-general(at)postgresql(dot)org
Subject: Excessive (and slow) fsync() within single transaction
Date: 2009-12-09 00:28:52
Message-ID: 51549ea20912081628u2b5450beo59fb4f549ac85d09@mail.gmail.com
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: pgsql-general

I've been trying to track down a performance issue I have. In simple terms,
my select performance is very good (generally either CPU limited, or disk
limited, depending upon the query), and small updates seem OK.

But a huge UPDATE is incredibly slow. CPU is on average below 1%, and disk
IO is generally below 0.1% of what I would expect. It seems to be doing
tiny bursts of activity, interspersed with long periods of inactivity. I've
observed the same behaviour in many other cases where the amount of writing
is large.

My system:

Mac Pro 2009 Quad 2.93 with 16G of ECC RAM
Snow Leopard 10.6.2 in 64bit mode, fully patched
Database on RAID 0 array of Intel X-25M SSDs
Postgres 8.4.1, 64 bit, compiled from source

From outside of postgres, I can sustain over 400MB/s read, and 140MB/s write
indefinitely. And around 10K random read I/Os/sec, and 4K random write
I/Os. With no hint of pauses. I have never witnessed anything other than
speedy performance from the SSDs except from within postgresql.

An example of a problematic SQL command is:
update link_relurl as u set sid = m.sid from link_meta as m where u.link =
m.link;

Both tables are around 20Gbytes, and 200M rows, with link as the primary
integer key. So in this example, I am joining 2 tables or 200M rows and
writing a new value to a column of one of those tables.

The command is issued via psql. There are no other connections to the
database.

My expectation would be that postgresql would issue an fsync() (or perhaps a
few such calls) at the end of the transaction. But this does not seem to be
the case:

Using the DTrace utility dtruss to time all calls to fsync being made by
postgres:
$> sudo dtruss -n postgres -t fsync -e
107/0x2dd: 7 fsync(0x3, 0xD, 0x100805400) = 0 0
107/0x2dd: 5 fsync(0x5, 0x8, 0x100805400) = 0 0
107/0x2dd: 4 fsync(0x21, 0x1A, 0x100805400) = 0 0
107/0x2dd: 5 fsync(0x1A, 0x8, 0x100805400) = 0 0
107/0x2dd: 4 fsync(0x19, 0x12, 0x100805400) = 0 0
107/0x2dd: 4 fsync(0x4, 0x2, 0x100805400) = 0 0
107/0x2dd: 5 fsync(0x7, 0x12, 0x100805400) = 0 0
107/0x2dd: 4 fsync(0x1C, 0xB, 0x100805400) = 0 0
107/0x2dd: 4 fsync(0x1E, 0xB, 0x100805400) = 0 0
107/0x2dd: 174 fsync(0x24, 0x103102AD8, 0x0) = 0 0
107/0x2dd: 2018 fsync(0x20, 0x1B, 0x100805400) = 0 0
107/0x2dd: 7 fsync(0x12, 0xC, 0x100805400) = 0 0
107/0x2dd: 987 fsync(0x23, 0x1B, 0x100805400) = 0 0
.....

With thousands of such lines. The columns are PID, elapsed time in
microseconds, and the system call with arguments. In the lines above, the
longest fsync is only 2 milliseconds. Most of the lines are similar to the
above.

So firstly, why are there so many calls to fsync()?

Unfortunately, some of the calls to fsync are incredibly slow:
107/0x2dd: 22526373 fsync(0x19, 0x1, 0x100805400) = 0 0
107/0x2dd: 22637723 fsync(0x10, 0x9, 0x100805400) = 0 0
107/0x2dd: 61745976 fsync(0xA, 0xF, 0x100805400) = 0 0

So in this triplet of consecutive calls we have elapsed times of 22, 22 and
61 seconds!

I'm no expert on DTrace, nor the inner workings of postgresql, but if
anybody has any ideas on what might be causing this behaviour, how to track
it down, or how to fix or avoid it, I would be very grateful.

Stephen

Responses

Browse pgsql-general by date

  From Date Subject
Next Message George Silva 2009-12-09 00:52:03 Rules and conditions
Previous Message jackassplus 2009-12-09 00:19:10 Re: Counts and percentages and such