pg_xlog becomes extremely large during CREATE INDEX

[Jeffrey W. Baker]

Greetings,

I have a 23GB data table upon which I am building a primary key of three
columns. The data is mounted in a 137GB device and pg_xlog is mounted
on a separate 3.5GB device. I have configured 24 checkpoint segments,
which I expect gives me a worst-case usage in pg_xlog of 384MB.
Unfortunately, during the CREATE INDEX, pg_xlog becomes full!

[There's an ls(1) listing at the end of this mail, if you care to see]

The operation created 222 files in pg_xlog before it filled the device,
and there's no indication that it was planning to stop there. Is there
some factor, other than checkpoint segments, which controls the size of
pg_xlog, or is there some other operation that also writes files in
pg_xlog, or, is the server just running away?

I have reset the xlogs and I'm trying again.

Regards,
Jeffrey

mistral:/pg_xlog_full# ls -l
total 3641692
-rw------- 1 postgres postgres 16777216 May 12 15:51 000000060000009 2
-rw------- 1 postgres postgres 16777216 May 12 15:51 000000060000009 3
-rw------- 1 postgres postgres 16777216 May 12 15:51 000000060000009 4
-rw------- 1 postgres postgres 16777216 May 12 15:51 000000060000009 5
-rw------- 1 postgres postgres 16777216 May 12 15:52 000000060000009 6
-rw------- 1 postgres postgres 16777216 May 12 15:52 000000060000009 7
-rw------- 1 postgres postgres 16777216 May 12 15:52 000000060000009 8
-rw------- 1 postgres postgres 16777216 May 12 15:52 000000060000009 9
-rw------- 1 postgres postgres 16777216 May 12 15:52 000000060000009 A
-rw------- 1 postgres postgres 16777216 May 12 15:52 000000060000009 B
-rw------- 1 postgres postgres 16777216 May 12 15:53 000000060000009 C
-rw------- 1 postgres postgres 16777216 May 12 15:53 000000060000009 D
-rw------- 1 postgres postgres 16777216 May 12 15:53 000000060000009 E
-rw------- 1 postgres postgres 16777216 May 12 15:53 000000060000009 F
-rw------- 1 postgres postgres 16777216 May 12 15:53 00000006000000A 0
-rw------- 1 postgres postgres 16777216 May 12 15:53 00000006000000A 1
-rw------- 1 postgres postgres 16777216 May 12 15:54 00000006000000A 2
-rw------- 1 postgres postgres 16777216 May 12 15:54 00000006000000A 3
-rw------- 1 postgres postgres 16777216 May 12 15:54 00000006000000A 4
-rw------- 1 postgres postgres 16777216 May 12 15:54 00000006000000A 5
-rw------- 1 postgres postgres 16777216 May 12 15:54 00000006000000A 6
-rw------- 1 postgres postgres 16777216 May 12 15:54 00000006000000A 7
-rw------- 1 postgres postgres 16777216 May 12 15:54 00000006000000A 8
-rw------- 1 postgres postgres 16777216 May 12 15:55 00000006000000A 9
-rw------- 1 postgres postgres 16777216 May 12 15:55 00000006000000A A
-rw------- 1 postgres postgres 16777216 May 12 15:55 00000006000000A B
-rw------- 1 postgres postgres 16777216 May 12 15:55 00000006000000A C
-rw------- 1 postgres postgres 16777216 May 12 15:55 00000006000000A D
-rw------- 1 postgres postgres 16777216 May 12 15:55 00000006000000A E
-rw------- 1 postgres postgres 16777216 May 12 15:56 00000006000000A F
-rw------- 1 postgres postgres 16777216 May 12 15:56 00000006000000B 0
-rw------- 1 postgres postgres 16777216 May 12 15:56 00000006000000B 1
-rw------- 1 postgres postgres 16777216 May 12 15:56 00000006000000B 2
-rw------- 1 postgres postgres 16777216 May 12 15:56 00000006000000B 3
-rw------- 1 postgres postgres 16777216 May 12 15:56 00000006000000B 4
-rw------- 1 postgres postgres 16777216 May 12 15:57 00000006000000B 5
-rw------- 1 postgres postgres 16777216 May 12 15:57 00000006000000B 6
-rw------- 1 postgres postgres 16777216 May 12 15:57 00000006000000B 7
-rw------- 1 postgres postgres 16777216 May 12 15:57 00000006000000B 8
-rw------- 1 postgres postgres 16777216 May 12 15:57 00000006000000B 9
-rw------- 1 postgres postgres 16777216 May 12 15:57 00000006000000B A
-rw------- 1 postgres postgres 16777216 May 12 15:58 00000006000000B B
-rw------- 1 postgres postgres 16777216 May 12 15:58 00000006000000B C
-rw------- 1 postgres postgres 16777216 May 12 15:58 00000006000000B D
-rw------- 1 postgres postgres 16777216 May 12 15:58 00000006000000B E
-rw------- 1 postgres postgres 16777216 May 12 15:58 00000006000000B F
-rw------- 1 postgres postgres 16777216 May 12 15:58 00000006000000C 0
-rw------- 1 postgres postgres 16777216 May 12 15:58 00000006000000C 1
-rw------- 1 postgres postgres 16777216 May 12 15:59 00000006000000C 2
-rw------- 1 postgres postgres 16777216 May 12 15:59 00000006000000C 3
-rw------- 1 postgres postgres 16777216 May 12 15:59 00000006000000C 4
-rw------- 1 postgres postgres 16777216 May 12 15:59 00000006000000C 5
-rw------- 1 postgres postgres 16777216 May 12 15:59 00000006000000C 6
-rw------- 1 postgres postgres 16777216 May 12 15:59 00000006000000C 7
-rw------- 1 postgres postgres 16777216 May 12 16:00 00000006000000C 8
-rw------- 1 postgres postgres 16777216 May 12 16:00 00000006000000C 9
-rw------- 1 postgres postgres 16777216 May 12 16:00 00000006000000C A
-rw------- 1 postgres postgres 16777216 May 12 16:00 00000006000000C B
-rw------- 1 postgres postgres 16777216 May 12 16:00 00000006000000C C
-rw------- 1 postgres postgres 16777216 May 12 16:01 00000006000000C D
-rw------- 1 postgres postgres 16777216 May 12 16:01 00000006000000C E
-rw------- 1 postgres postgres 16777216 May 12 16:01 00000006000000C F
-rw------- 1 postgres postgres 16777216 May 12 16:01 00000006000000D 0
-rw------- 1 postgres postgres 16777216 May 12 16:01 00000006000000D 1
-rw------- 1 postgres postgres 16777216 May 12 16:01 00000006000000D 2
-rw------- 1 postgres postgres 16777216 May 12 16:02 00000006000000D 3
-rw------- 1 postgres postgres 16777216 May 12 16:02 00000006000000D 4
-rw------- 1 postgres postgres 16777216 May 12 16:02 00000006000000D 5
-rw------- 1 postgres postgres 16777216 May 12 16:02 00000006000000D 6
-rw------- 1 postgres postgres 16777216 May 12 16:02 00000006000000D 7
-rw------- 1 postgres postgres 16777216 May 12 16:03 00000006000000D 8
-rw------- 1 postgres postgres 16777216 May 12 16:03 00000006000000D 9
-rw------- 1 postgres postgres 16777216 May 12 16:03 00000006000000D A
-rw------- 1 postgres postgres 16777216 May 12 16:03 00000006000000D B
-rw------- 1 postgres postgres 16777216 May 12 16:03 00000006000000D C
-rw------- 1 postgres postgres 16777216 May 12 16:03 00000006000000D D
-rw------- 1 postgres postgres 16777216 May 12 16:04 00000006000000D E
-rw------- 1 postgres postgres 16777216 May 12 16:04 00000006000000D F
-rw------- 1 postgres postgres 16777216 May 12 16:04 00000006000000E 0
-rw------- 1 postgres postgres 16777216 May 12 16:04 00000006000000E 1
-rw------- 1 postgres postgres 16777216 May 12 16:04 00000006000000E 2
-rw------- 1 postgres postgres 16777216 May 12 16:04 00000006000000E 3
-rw------- 1 postgres postgres 16777216 May 12 16:05 00000006000000E 4
-rw------- 1 postgres postgres 16777216 May 12 16:05 00000006000000E 5
-rw------- 1 postgres postgres 16777216 May 12 16:05 00000006000000E 6
-rw------- 1 postgres postgres 16777216 May 12 16:05 00000006000000E 7
-rw------- 1 postgres postgres 16777216 May 12 16:05 00000006000000E 8
-rw------- 1 postgres postgres 16777216 May 12 16:06 00000006000000E 9
-rw------- 1 postgres postgres 16777216 May 12 16:06 00000006000000E A
-rw------- 1 postgres postgres 16777216 May 12 16:06 00000006000000E B
-rw------- 1 postgres postgres 16777216 May 12 16:06 00000006000000E C
-rw------- 1 postgres postgres 16777216 May 12 16:07 00000006000000E D
-rw------- 1 postgres postgres 16777216 May 12 16:07 00000006000000E E
-rw------- 1 postgres postgres 16777216 May 12 16:07 00000006000000E F
-rw------- 1 postgres postgres 16777216 May 12 16:07 00000006000000F 0
-rw------- 1 postgres postgres 16777216 May 12 16:07 00000006000000F 1
-rw------- 1 postgres postgres 16777216 May 12 16:08 00000006000000F 2
-rw------- 1 postgres postgres 16777216 May 12 16:08 00000006000000F 3
-rw------- 1 postgres postgres 16777216 May 12 16:08 00000006000000F 4
-rw------- 1 postgres postgres 16777216 May 12 16:08 00000006000000F 5
-rw------- 1 postgres postgres 16777216 May 12 16:08 00000006000000F 6
-rw------- 1 postgres postgres 16777216 May 12 16:09 00000006000000F 7
-rw------- 1 postgres postgres 16777216 May 12 16:09 00000006000000F 8
-rw------- 1 postgres postgres 16777216 May 12 16:09 00000006000000F 9
-rw------- 1 postgres postgres 16777216 May 12 16:09 00000006000000F A
-rw------- 1 postgres postgres 16777216 May 12 16:09 00000006000000F B
-rw------- 1 postgres postgres 16777216 May 12 16:09 00000006000000F C
-rw------- 1 postgres postgres 16777216 May 12 16:10 00000006000000F D
-rw------- 1 postgres postgres 16777216 May 12 16:10 00000006000000F E
-rw------- 1 postgres postgres 16777216 May 12 16:10 000000070000000 0
-rw------- 1 postgres postgres 16777216 May 12 16:10 000000070000000 1
-rw------- 1 postgres postgres 16777216 May 12 16:10 000000070000000 2
-rw------- 1 postgres postgres 16777216 May 12 16:11 000000070000000 3
-rw------- 1 postgres postgres 16777216 May 12 16:11 000000070000000 4
-rw------- 1 postgres postgres 16777216 May 12 16:11 000000070000000 5
-rw------- 1 postgres postgres 16777216 May 12 16:11 000000070000000 6
-rw------- 1 postgres postgres 16777216 May 12 16:12 000000070000000 7
-rw------- 1 postgres postgres 16777216 May 12 16:12 000000070000000 8
-rw------- 1 postgres postgres 16777216 May 12 16:12 000000070000000 9
-rw------- 1 postgres postgres 16777216 May 12 16:12 000000070000000 A
-rw------- 1 postgres postgres 16777216 May 12 16:12 000000070000000 B
-rw------- 1 postgres postgres 16777216 May 12 16:13 000000070000000 C
-rw------- 1 postgres postgres 16777216 May 12 16:13 000000070000000 D
-rw------- 1 postgres postgres 16777216 May 12 16:13 000000070000000 E
-rw------- 1 postgres postgres 16777216 May 12 16:13 000000070000000 F
-rw------- 1 postgres postgres 16777216 May 12 16:13 000000070000001 0
-rw------- 1 postgres postgres 16777216 May 12 16:14 000000070000001 1
-rw------- 1 postgres postgres 16777216 May 12 16:14 000000070000001 2
-rw------- 1 postgres postgres 16777216 May 12 16:14 000000070000001 3
-rw------- 1 postgres postgres 16777216 May 12 16:14 000000070000001 4
-rw------- 1 postgres postgres 16777216 May 12 16:15 000000070000001 5
-rw------- 1 postgres postgres 16777216 May 12 16:15 000000070000001 6
-rw------- 1 postgres postgres 16777216 May 12 16:15 000000070000001 7
-rw------- 1 postgres postgres 16777216 May 12 16:15 000000070000001 8
-rw------- 1 postgres postgres 16777216 May 12 16:15 000000070000001 9
-rw------- 1 postgres postgres 16777216 May 12 16:16 000000070000001 A
-rw------- 1 postgres postgres 16777216 May 12 16:16 000000070000001 B
-rw------- 1 postgres postgres 16777216 May 12 16:16 000000070000001 C
-rw------- 1 postgres postgres 16777216 May 12 16:16 000000070000001 D
-rw------- 1 postgres postgres 16777216 May 12 16:17 000000070000001 E
-rw------- 1 postgres postgres 16777216 May 12 16:17 000000070000001 F
-rw------- 1 postgres postgres 16777216 May 12 16:17 000000070000002 0
-rw------- 1 postgres postgres 16777216 May 12 16:17 000000070000002 1
-rw------- 1 postgres postgres 16777216 May 12 16:18 000000070000002 2
-rw------- 1 postgres postgres 16777216 May 12 16:18 000000070000002 3
-rw------- 1 postgres postgres 16777216 May 12 16:18 000000070000002 4
-rw------- 1 postgres postgres 16777216 May 12 16:18 000000070000002 5
-rw------- 1 postgres postgres 16777216 May 12 16:19 000000070000002 6
-rw------- 1 postgres postgres 16777216 May 12 16:19 000000070000002 7
-rw------- 1 postgres postgres 16777216 May 12 16:19 000000070000002 8
-rw------- 1 postgres postgres 16777216 May 12 16:19 000000070000002 9
-rw------- 1 postgres postgres 16777216 May 12 16:20 000000070000002 A
-rw------- 1 postgres postgres 16777216 May 12 16:20 000000070000002 B
-rw------- 1 postgres postgres 16777216 May 12 16:20 000000070000002 C
-rw------- 1 postgres postgres 16777216 May 12 16:20 000000070000002 D
-rw------- 1 postgres postgres 16777216 May 12 16:20 000000070000002 E
-rw------- 1 postgres postgres 16777216 May 12 16:21 000000070000002 F
-rw------- 1 postgres postgres 16777216 May 12 16:21 000000070000003 0
-rw------- 1 postgres postgres 16777216 May 12 16:21 000000070000003 1
-rw------- 1 postgres postgres 16777216 May 12 16:21 000000070000003 2
-rw------- 1 postgres postgres 16777216 May 12 16:22 000000070000003 3
-rw------- 1 postgres postgres 16777216 May 12 16:22 000000070000003 4
-rw------- 1 postgres postgres 16777216 May 12 16:22 000000070000003 5
-rw------- 1 postgres postgres 16777216 May 12 16:22 000000070000003 6
-rw------- 1 postgres postgres 16777216 May 12 16:23 000000070000003 7
-rw------- 1 postgres postgres 16777216 May 12 16:23 000000070000003 8
-rw------- 1 postgres postgres 16777216 May 12 16:23 000000070000003 9
-rw------- 1 postgres postgres 16777216 May 12 16:23 000000070000003 A
-rw------- 1 postgres postgres 16777216 May 12 16:24 000000070000003 B
-rw------- 1 postgres postgres 16777216 May 12 16:24 000000070000003 C
-rw------- 1 postgres postgres 16777216 May 12 16:24 000000070000003 D
-rw------- 1 postgres postgres 16777216 May 12 16:24 000000070000003 E
-rw------- 1 postgres postgres 16777216 May 12 16:25 000000070000003 F
-rw------- 1 postgres postgres 16777216 May 12 16:25 000000070000004 0
-rw------- 1 postgres postgres 16777216 May 12 16:25 000000070000004 1
-rw------- 1 postgres postgres 16777216 May 12 16:25 000000070000004 2
-rw------- 1 postgres postgres 16777216 May 12 16:26 000000070000004 3
-rw------- 1 postgres postgres 16777216 May 12 16:26 000000070000004 4
-rw------- 1 postgres postgres 16777216 May 12 16:26 000000070000004 5
-rw------- 1 postgres postgres 16777216 May 12 16:26 000000070000004 6
-rw------- 1 postgres postgres 16777216 May 12 16:26 000000070000004 7
-rw------- 1 postgres postgres 16777216 May 12 16:27 000000070000004 8
-rw------- 1 postgres postgres 16777216 May 12 16:27 000000070000004 9
-rw------- 1 postgres postgres 16777216 May 12 16:27 000000070000004 A
-rw------- 1 postgres postgres 16777216 May 12 16:27 000000070000004 B
-rw------- 1 postgres postgres 16777216 May 12 16:28 000000070000004 C
-rw------- 1 postgres postgres 16777216 May 12 16:28 000000070000004 D
-rw------- 1 postgres postgres 16777216 May 12 16:28 000000070000004 E
-rw------- 1 postgres postgres 16777216 May 12 16:28 000000070000004 F
-rw------- 1 postgres postgres 16777216 May 12 16:29 000000070000005 0
-rw------- 1 postgres postgres 16777216 May 12 16:29 000000070000005 1
-rw------- 1 postgres postgres 16777216 May 12 16:29 000000070000005 2
-rw------- 1 postgres postgres 16777216 May 12 16:29 000000070000005 3
-rw------- 1 postgres postgres 16777216 May 12 16:30 000000070000005 4
-rw------- 1 postgres postgres 16777216 May 12 16:30 000000070000005 5
-rw------- 1 postgres postgres 16777216 May 12 16:30 000000070000005 6
-rw------- 1 postgres postgres 16777216 May 12 16:30 000000070000005 7
-rw------- 1 postgres postgres 16777216 May 12 16:31 000000070000005 8
-rw------- 1 postgres postgres 16777216 May 12 16:31 000000070000005 9
-rw------- 1 postgres postgres 16777216 May 12 16:31 000000070000005 A
-rw------- 1 postgres postgres 16777216 May 12 16:32 000000070000005 B
-rw------- 1 postgres postgres 16777216 May 12 16:32 000000070000005 C
-rw------- 1 postgres postgres 16777216 May 12 16:32 000000070000005 D
-rw------- 1 postgres postgres 16777216 May 12 16:32 000000070000005 E
-rw------- 1 postgres postgres 16777216 May 12 16:33 000000070000005 F
-rw------- 1 postgres postgres 16777216 May 12 16:33 000000070000006 0
-rw------- 1 postgres postgres 16777216 May 12 16:33 000000070000006 1
-rw------- 1 postgres postgres 16777216 May 12 16:33 000000070000006 2
-rw------- 1 postgres postgres 16777216 May 12 16:34 000000070000006 3
-rw------- 1 postgres postgres 16777216 May 12 16:34 000000070000006 4
-rw------- 1 postgres postgres 16777216 May 12 16:34 000000070000006 5
-rw------- 1 postgres postgres 16777216 May 12 16:34 000000070000006 6
-rw------- 1 postgres postgres 16777216 May 12 16:34 000000070000006 7
-rw------- 1 postgres postgres 16777216 May 12 16:35 000000070000006 8
-rw------- 1 postgres postgres 16777216 May 12 16:35 000000070000006 9
-rw------- 1 postgres postgres 16777216 May 12 16:35 000000070000006 A
-rw------- 1 postgres postgres 16777216 May 12 16:35 000000070000006 B
-rw------- 1 postgres postgres 16777216 May 12 16:36 000000070000006 C
-rw------- 1 postgres postgres 16777216 May 12 16:36 000000070000006 D
-rw------- 1 postgres postgres 16777216 May 12 16:36 000000070000006 E
-rw------- 1 postgres postgres 16777216 May 12 16:36 000000070000006 F
-rw------- 1 postgres postgres 16777216 May 12 16:45 000000070000007 0

---------------------------(end of broadcast)---------------------------
TIP 3: if posting/reading through Usenet, please send an appropriate
subscribe-nomail command to ma*******@postg resql.org so that your
message can get through to the mailing list cleanly

[Tom Lane]

"Jeffrey W. Baker" <jw*****@acm.or g> writes:

I have configured 24 checkpoint segments,
which I expect gives me a worst-case usage in pg_xlog of 384MB.
Unfortunately, during the CREATE INDEX, pg_xlog becomes full!

Postgres version? AFAIR 7.1.2 or thereabouts would act that way,
because it wouldn't discard log segments containing work of open
transactions.

The only reason I can think of for such behavior in a current version
is if the checkpoint isn't completing for some reason. Have you looked
in the postmaster log to see if checkpoint is bleating about anything?

Note that your calculation is off anyway: per documentation, recent
versions will allow up to 2*checkpoint_se gments+1 WAL files to exist.
This is because we save the last two checkpoints worth of data.

regards, tom lane

---------------------------(end of broadcast)---------------------------
TIP 1: subscribe and unsubscribe commands go to ma*******@postg resql.org

[Jeffrey W. Baker]

On Wed, 2004-05-12 at 20:18, Tom Lane wrote:

"Jeffrey W. Baker" <jw*****@acm.or g> writes:

I have configured 24 checkpoint segments,
which I expect gives me a worst-case usage in pg_xlog of 384MB.
Unfortunately, during the CREATE INDEX, pg_xlog becomes full!
Postgres version? AFAIR 7.1.2 or thereabouts would act that way,
because it wouldn't discard log segments containing work of open
transactions.

This is 7.4.1.
The only reason I can think of for such behavior in a current version
is if the checkpoint isn't completing for some reason. Have you looked
in the postmaster log to see if checkpoint is bleating about anything?
Oh sure, it's bleating. Apparently my computer is too fast:

syslog:May 12 21:20:32 mistral postgres[17458]: [214-1] LOG: checkpoints are occurring too frequently (12 seconds apart)
syslog:May 12 21:20:32 mistral postgres[17458]: [214-2] HINT: Consider increasing the configuration parameter "checkpoint_seg ments".

That's also what preceeded the most recent crash:

May 12 16:36:53 mistral postgres[506]: [173-1] LOG: checkpoints are occurring too frequently (16 seconds apart)
May 12 16:36:53 mistral postgres[506]: [173-2] HINT: Consider increasing the configuration parameter "checkpoint_seg ments".
May 12 16:37:08 mistral postgres[506]: [174-1] LOG: server process (PID 16403) was terminated by signal 6
May 12 16:37:08 mistral postgres[506]: [175-1] LOG: terminating any other active server processes
May 12 16:37:08 mistral postgres[26212]: [3-1] WARNING: terminating connection because of crash of another server process
May 12 16:37:08 mistral postgres[26212]: [3-2] DETAIL: The postmaster has commanded this server process to roll back the current transaction and exit, because another server
May 12 16:37:08 mistral postgres[26212]: [3-3] process exited abnormally and possibly corrupted shared memory.
May 12 16:37:08 mistral postgres[26212]: [3-4] HINT: In a moment you should be able to reconnect to the database and repeat your command.
May 12 16:37:08 mistral postgres[14396]: [1-1] WARNING: terminating connection because of crash of another server process
May 12 16:37:08 mistral postgres[14396]: [1-2] DETAIL: The postmaster has commanded this server process to roll back the current transaction and exit, because another server
May 12 16:37:08 mistral postgres[14396]: [1-3] process exited abnormally and possibly corrupted shared memory.
May 12 16:37:08 mistral postgres[14396]: [1-4] HINT: In a moment you should be able to reconnect to the database and repeat your command.
May 12 16:37:08 mistral postgres[14396]: [1-5] CONTEXT: writing block 56889 of relation 17142/289600495
May 12 16:37:08 mistral postgres[506]: [176-1] LOG: all server processes terminated; reinitializing
May 12 16:37:08 mistral postgres[17086]: [177-1] LOG: database system was interrupted at 2004-05-12 16:36:53 PDT
May 12 16:37:08 mistral postgres[17086]: [178-1] LOG: checkpoint record is at 6/92B32D48
May 12 16:37:08 mistral postgres[17086]: [179-1] LOG: redo record is at 6/92B32D48; undo record is at 0/0; shutdown FALSE
May 12 16:37:08 mistral postgres[17086]: [180-1] LOG: next transaction ID: 10232; next OID: 289600632
May 12 16:37:08 mistral postgres[17086]: [181-1] LOG: database system was not properly shut down; automatic recovery in progress
May 12 16:37:08 mistral postgres[17086]: [182-1] LOG: redo starts at 6/92B32D88
May 12 16:45:29 mistral postgres[17086]: [183-1] LOG: could not open file "/var/lib/postgres/data/pg_xlog/000000070000007 1" (log file 7, segment 113): No such file or directory
May 12 16:45:29 mistral postgres[17086]: [184-1] LOG: redo done at 7/70FFC400
May 12 16:45:50 mistral postgres[506]: [177-1] LOG: startup process (PID 17086) was terminated by signal 6
May 12 16:45:50 mistral postgres[506]: [178-1] LOG: aborting startup due to startup process failure

I also have many "recycled" messages:

May 12 13:10:01 mistral postgres[16373]: [20-1] LOG: recycled transaction log file "00000006000000 78"
May 12 13:10:01 mistral postgres[16373]: [21-1] LOG: recycled transaction log file "00000006000000 79"
May 12 13:10:01 mistral postgres[16373]: [22-1] LOG: recycled transaction log file "00000006000000 7A"
May 12 13:10:01 mistral postgres[16373]: [23-1] LOG: recycled transaction log file "00000006000000 7B"
May 12 13:10:01 mistral postgres[16373]: [24-1] LOG: recycled transaction log file "00000006000000 7C"
May 12 13:20:03 mistral postgres[16408]: [1-1] LOG: removing transaction log file "00000006000000 90"
May 12 13:20:03 mistral postgres[16408]: [2-1] LOG: removing transaction log file "00000006000000 91"
Note that your calculation is off anyway: per documentation, recent
versions will allow up to 2*checkpoint_se gments+1 WAL files to exist.
This is because we save the last two checkpoints worth of data.

That's why I gave it an order of magnitude leeway. Such calculations
are always off by a factor or two.

It's doing it again at this very moment, I get the feeling that pg_xlog
is converging on the same size as $PGDATA/base/$OID/pgsql_tmp:

mistral:/backup_temp# du -hs pg_xlog /var/lib/postgres/data/base/17142/pgsql_tmp/
4.8G pg_xlog
5.4G /var/lib/postgres/data/base/17142/pgsql_tmp

-jwb

---------------------------(end of broadcast)---------------------------
TIP 2: you can get off all lists at once with the unregister command
(send "unregister YourEmailAddres sHere" to ma*******@postg resql.org)

[Jeffrey W. Baker]

On Wed, 2004-05-12 at 21:31, Jeffrey W. Baker wrote:

On Wed, 2004-05-12 at 20:18, Tom Lane wrote:

"Jeffrey W. Baker" <jw*****@acm.or g> writes:

I have configured 24 checkpoint segments,
which I expect gives me a worst-case usage in pg_xlog of 384MB.
Unfortunately, during the CREATE INDEX, pg_xlog becomes full!

Postgres version? AFAIR 7.1.2 or thereabouts would act that way,
because it wouldn't discard log segments containing work of open
transactions.

The CREATE INDEX finally returned, and none of the xlog space was
reclaimed. The terminal size is 6.1GB. Interestingly, there is a
continuous group of xlogs that haven't been touched since data started
being copied from pgsql_tmp to ../. (what do you call this stage of the
index build?) In reverse order of modification time:

May 12 21:55 00000008000000F 7
May 12 21:49 00000008000000F 6
May 12 21:49 00000008000000F 5
[... decreasing by 1 until ...]
May 12 20:40 000000070000008 C
May 12 20:40 000000070000008 B
May 12 20:40 000000070000008 A
[the ones below have higher numbers, but aren't being written to!]
May 12 20:40 000000090000001 0
May 12 20:40 000000090000000 F
May 12 20:39 000000090000000 E
May 12 20:39 000000090000000 D
May 12 20:39 000000090000000 C
May 12 20:39 000000090000000 B
May 12 20:39 000000090000000 A
May 12 20:39 000000090000000 9
May 12 20:39 000000090000000 8
May 12 20:39 000000090000000 7
May 12 20:39 000000090000000 6
May 12 20:39 000000090000000 5
May 12 20:39 000000090000000 4
May 12 20:38 000000090000000 3
May 12 20:38 000000090000000 2
May 12 20:38 000000090000000 1
May 12 20:38 000000090000000 0
May 12 20:38 00000008000000F E
May 12 20:38 00000008000000F D
May 12 20:38 00000008000000F C
May 12 20:38 00000008000000F B
May 12 20:38 00000008000000F A
May 12 20:38 00000008000000F 9
May 12 20:37 00000008000000F 8

Not coincidentally, there are 24 of these oddballs and 24 is also the
number of checkpoint segments I have configured.

-jwb

---------------------------(end of broadcast)---------------------------
TIP 8: explain analyze is your friend

[Tom Lane]

"Jeffrey W. Baker" <jw*****@acm.or g> writes:

Oh sure, it's bleating. Apparently my computer is too fast:
I don't think the checkpoint process is completing.
May 12 16:37:08 mistral postgres[506]: [174-1] LOG: server process (PID 16403) was terminated by signal 6

You need to find out why these aborts (presumably Assert failures) are
occurring. Having just looked at the source code, I see that Assert
messages are never sent to syslog only to stderr. So you'll want to
set things up to capture the postmaster's stderr instead of discarding it.

regards, tom lane

---------------------------(end of broadcast)---------------------------
TIP 9: the planner will ignore your desire to choose an index scan if your
joining column's datatypes do not match

[Jeffrey W. Baker]

On Thu, 2004-05-13 at 06:10, Tom Lane wrote:

"Jeffrey W. Baker" <jw*****@acm.or g> writes:

Oh sure, it's bleating. Apparently my computer is too fast:

I don't think the checkpoint process is completing.

May 12 16:37:08 mistral postgres[506]: [174-1] LOG: server process (PID 16403) was terminated by signal 6

You need to find out why these aborts (presumably Assert failures) are
occurring. Having just looked at the source code, I see that Assert
messages are never sent to syslog only to stderr. So you'll want to
set things up to capture the postmaster's stderr instead of discarding it.

The server process aborted when the device filled up.

-jwb

---------------------------(end of broadcast)---------------------------
TIP 3: if posting/reading through Usenet, please send an appropriate
subscribe-nomail command to ma*******@postg resql.org so that your
message can get through to the mailing list cleanly

[Jeffrey W. Baker]

On Thu, 2004-05-13 at 09:28, Tom Lane wrote:

"Jeffrey W. Baker" <jw*****@acm.or g> writes:

Sorry, my last mail got cut off. The server aborted because it couldn't
write the xlog. Looks like I omitted this from my last mail:

Selective quoting of the log output? Naughty naughty.

However, that still doesn't explain how you got into the current state.
Had you once had checkpoint_segm ents set much higher than the current
value of 24? On looking at the code I see that it doesn't make any
attempt to prune future log segments after a decrease in
checkpoint_segm ents, so if a previous misconfiguratio n had allowed the
number of future segments to get really large, that could be the root of
the issue.

The database where this happened was freshly initialized and this was
one of its first operations. I think I will write a small example
script so you can reproduce it locally. Give me a few hours or so.

-jwb

---------------------------(end of broadcast)---------------------------
TIP 3: if posting/reading through Usenet, please send an appropriate
subscribe-nomail command to ma*******@postg resql.org so that your
message can get through to the mailing list cleanly

[Tom Lane]

"Jeffrey W. Baker" <jw*****@acm.or g> writes:

Sorry, my last mail got cut off. The server aborted because it couldn't
write the xlog. Looks like I omitted this from my last mail:

Selective quoting of the log output? Naughty naughty.

However, that still doesn't explain how you got into the current state.
Had you once had checkpoint_segm ents set much higher than the current
value of 24? On looking at the code I see that it doesn't make any
attempt to prune future log segments after a decrease in
checkpoint_segm ents, so if a previous misconfiguratio n had allowed the
number of future segments to get really large, that could be the root of
the issue.

regards, tom lane

---------------------------(end of broadcast)---------------------------
TIP 8: explain analyze is your friend

[Jeffrey W. Baker]

[For whatever reason this got delayed in delivery. Sending again from another route. -jwb]

On Thu, 2004-05-13 at 09:28, Tom Lane wrote:

"Jeffrey W. Baker" <jw*****@acm.or g> writes:

Sorry, my last mail got cut off. The server aborted because it couldn't
write the xlog. Looks like I omitted this from my last mail:

Selective quoting of the log output? Naughty naughty.

However, that still doesn't explain how you got into the current state.
Had you once had checkpoint_segm ents set much higher than the current
value of 24? On looking at the code I see that it doesn't make any
attempt to prune future log segments after a decrease in
checkpoint_segm ents, so if a previous misconfiguratio n had allowed the
number of future segments to get really large, that could be the root of
the issue.

Okay, I installed a fresh, completely stock 7.4.2 and did the following:

#!/bin/sh

createdb growxlog
echo "create table data (a int, b int, c int, d int, e int)" | psql growxlog
perl -e 'use POSIX qw(floor); print "COPY data FROM STDIN;\n"; for ($i = 0; $i < 100000000; $i++) {print(join("\t ", $i, floor(rand()*10 00000), floor(rand()*10 00000), floor(rand()*10 00000), floor(rand()*10 00000)), "\n")}' | psql growxlog
echo "create unique index data_pkey on data(a,b,c)" | psql growxlog

The result was a table with 100 million rows, a 5.3GB data table, a
2.7GB index, and 2.6GB in pg_xlog. Reproducable every time.

For the less patient, the problem is also reproduceable at only 10
million rows (xlog = 337MB), but not at 1 million rows (presumably the
whole mess fits inside the usual # of segments).

You'll need approximately rows*125 bytes of free space to run the test.

-jwb
---------------------------(end of broadcast)---------------------------
TIP 7: don't forget to increase your free space map settings

[Tom Lane]

"Jeffrey W. Baker" <jw*****@acm.or g> writes:

Okay, I installed a fresh, completely stock 7.4.2 and did the following: createdb growxlog
echo "create table data (a int, b int, c int, d int, e int)" | psql growxlog
perl -e 'use POSIX qw(floor); print "COPY data FROM STDIN;\n"; for ($i = 0; $i < 100000000; $i++) {print(join("\t ", $i, floor(rand()*10 00000), floor(rand()*10 00000), floor(rand()*10 00000), floor(rand()*10 00000)), "\n")}' | psql growxlog
echo "create unique index data_pkey on data(a,b,c)" | psql growxlog

I tried this locally, and what I see happening is that a checkpoint
process starts shortly after the CREATE INDEX begins whomping out the
index data --- but it doesn't finish until after the CREATE INDEX does.
AFAICS there is not any sort of locking problem, it's just that the
CREATE INDEX is chewing all the I/O bandwidth. If we could get some
more checkpoints pushed through then the xlog would get truncated, but
it's not happening.

I'm running this on a development machine with an ok CPU and junk
consumer-grade-IDE disk drive, so lack of I/O bandwidth is hardly
surprising; can anyone confirm the observation on better hardware?

I think one reason for the problem is that btree CREATE INDEX is as bad
as VACUUM, if not worse, with respect to chewing all available shared
buffers. It will fill shared buffers with newly-created dirty pages ---
and I'll bet the CHECKPOINT process is getting stuck with dumping the
majority of those pages to disk. It might be worth tweaking CREATE
INDEX so it pushes out the newly created pages for itself, thus limiting
the number of dirtied buffers it creates.

regards, tom lane

---------------------------(end of broadcast)---------------------------
TIP 4: Don't 'kill -9' the postmaster