Excessive (and slow) fsync() within single transaction - Mailing list 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