Thread: Replaying 48 WAL files takes 80 minutes
I am configuring streaming replication with hot standby
with PostgreSQL 9.1.3 on RHEL 6 (kernel 2.6.32-220.el6.x86_64).
PostgreSQL was compiled from source.
It works fine, except that starting the standby took for ever:
it took the system more than 80 minutes to replay 48 WAL files
and connect to the primary.
Can anybody think of an explanation why it takes that long?
This is decent hardware: 24 cores of AMD Opteron 6174, 128 GB RAM,
NetApp SAN attached with 8 GBit Fibrechannel (ext4 file system).
An identical system performed fine in performance tests.
Here is the log; I have edited it for readability:
2012-10-29 09:22:22.945 database system was interrupted; last known up
at 2012-10-26 01:11:59 CEST
2012-10-29 09:22:22.945 creating missing WAL directory
"pg_xlog/archive_status"
2012-10-29 09:22:22.947 entering standby mode
2012-10-29 09:22:23.434 restored log file "00000001000001D1000000C4"
from archive
2012-10-29 09:22:23.453 redo starts at 1D1/C4000020
2012-10-29 09:22:25.847 restored log file "00000001000001D1000000C5"
from archive
2012-10-29 09:22:27.457 restored log file "00000001000001D1000000C6"
from archive
2012-10-29 09:22:28.946 restored log file "00000001000001D1000000C7"
from archive
2012-10-29 09:22:30.421 restored log file "00000001000001D1000000C8"
from archive
2012-10-29 09:22:31.243 restored log file "00000001000001D1000000C9"
from archive
2012-10-29 09:22:32.194 restored log file "00000001000001D1000000CA"
from archive
2012-10-29 09:22:33.169 restored log file "00000001000001D1000000CB"
from archive
2012-10-29 09:22:33.565 restored log file "00000001000001D1000000CC"
from archive
2012-10-29 09:23:35.451 restored log file "00000001000001D1000000CD"
from archive
Everything is nice until here.
Replaying this WAL file suddenly takes 1.5 minutes instead
of mere seconds as before.
2012-10-29 09:24:54.761 restored log file "00000001000001D1000000CE"
from archive
2012-10-29 09:27:23.013 restartpoint starting: time
2012-10-29 09:28:12.200 restartpoint complete: wrote 242 buffers
(0.0%);
0 transaction log file(s) added, 0 removed, 0
recycled;
write=48.987 s, sync=0.185 s, total=49.184 s;
sync files=1096, longest=0.016 s, average=0.000
s
2012-10-29 09:28:12.206 recovery restart point at 1D1/CC618278
2012-10-29 09:28:31.226 restored log file "00000001000001D1000000CF"
from archive
Again there is a difference of 2.5 minutes
between these WAL files, only 50 seconds of
which were spent in the restartpoint.
From here on it continues in quite the same vein.
Some WAL files are restored in seconds, but some take
more than 4 minutes.
I'll skip to the end of the log:
2012-10-29 10:37:53.809 restored log file "00000001000001D1000000EF"
from archive
2012-10-29 10:38:53.194 restartpoint starting: time
2012-10-29 10:39:25.929 restartpoint complete: wrote 161 buffers
(0.0%);
0 transaction log file(s) added, 0 removed, 0
recycled;
write=32.661 s, sync=0.066 s, total=32.734 s;
sync files=251, longest=0.003 s, average=0.000
s
2012-10-29 10:39:25.929 recovery restart point at 1D1/ED95C728
2012-10-29 10:42:56.153 restored log file "00000001000001D1000000F0"
from archive
2012-10-29 10:43:53.062 restartpoint starting: time
2012-10-29 10:45:36.871 restored log file "00000001000001D1000000F1"
from archive
2012-10-29 10:45:39.832 restartpoint complete: wrote 594 buffers
(0.0%);
0 transaction log file(s) added, 0 removed, 0
recycled;
write=106.666 s, sync=0.093 s, total=106.769 s;
sync files=729, longest=0.004 s, average=0.000
s
2012-10-29 10:45:39.832 recovery restart point at 1D1/EF5D4340
2012-10-29 10:46:13.602 restored log file "00000001000001D1000000F2"
from archive
2012-10-29 10:47:38.396 restored log file "00000001000001D1000000F3"
from archive
2012-10-29 10:47:38.962 streaming replication successfully connected to
primary
I'd be happy if somebody could shed light on this.
Yours,
Laurenz Albe
PS: Here is the configuration:
name | current_setting
------------------------------+---------------------------
version | PostgreSQL 9.1.3 on
x86_64-unknown-linux-gnu, compiled by gcc (GCC) 4.4.6 20110731 (Red Hat
4.4.6-3), 64-bit
archive_command | gzip -1 <"%p" | tee
/POSTGRES/data/exchange/"%f".gz >/POSTGRES/data/backups/ELAK/"%f".gz
archive_mode | on
checkpoint_completion_target | 0.9
checkpoint_segments | 30
client_encoding | UTF8
constraint_exclusion | off
cursor_tuple_fraction | 1
custom_variable_classes | pg_stat_statements
default_statistics_target | 1000
effective_cache_size | 64GB
hot_standby | on
lc_collate | de_DE.UTF8
lc_ctype | de_DE.UTF8
listen_addresses | *
log_checkpoints | on
log_connections | on
log_destination | csvlog
log_directory | /POSTGRES/data/logs/ELAK
log_disconnections | on
log_filename | ELAK-%Y-%m-%d.log
log_lock_waits | on
log_min_duration_statement | 3s
log_min_error_statement | log
log_min_messages | log
log_rotation_size | 0
log_statement | ddl
log_temp_files | 0
logging_collector | on
maintenance_work_mem | 1GB
max_connections | 800
max_prepared_transactions | 800
max_stack_depth | 9MB
max_standby_archive_delay | 0
max_standby_streaming_delay | 0
max_wal_senders | 2
pg_stat_statements.max | 5000
pg_stat_statements.track | all
port | 55503
server_encoding | UTF8
shared_buffers | 16GB
shared_preload_libraries | pg_stat_statements,passwordcheck
ssl | on
tcp_keepalives_count | 0
tcp_keepalives_idle | 0
TimeZone | Europe/Vienna
wal_buffers | 16MB
wal_level | hot_standby
work_mem | 8MB
(49 rows)
On Mon, Oct 29, 2012 at 02:05:24PM +0100, Albe Laurenz wrote: > I am configuring streaming replication with hot standby > with PostgreSQL 9.1.3 on RHEL 6 (kernel 2.6.32-220.el6.x86_64). > PostgreSQL was compiled from source. > > It works fine, except that starting the standby took for ever: > it took the system more than 80 minutes to replay 48 WAL files > and connect to the primary. > > Can anybody think of an explanation why it takes that long? > > This is decent hardware: 24 cores of AMD Opteron 6174, 128 GB RAM, > NetApp SAN attached with 8 GBit Fibrechannel (ext4 file system). > An identical system performed fine in performance tests. > > Here is the log; I have edited it for readability: > > 2012-10-29 09:22:22.945 database system was interrupted; last known up > at 2012-10-26 01:11:59 CEST > 2012-10-29 09:22:22.945 creating missing WAL directory > "pg_xlog/archive_status" > 2012-10-29 09:22:22.947 entering standby mode > 2012-10-29 09:22:23.434 restored log file "00000001000001D1000000C4" > from archive > 2012-10-29 09:22:23.453 redo starts at 1D1/C4000020 > 2012-10-29 09:22:25.847 restored log file "00000001000001D1000000C5" > from archive > 2012-10-29 09:22:27.457 restored log file "00000001000001D1000000C6" > from archive > 2012-10-29 09:22:28.946 restored log file "00000001000001D1000000C7" > from archive > 2012-10-29 09:22:30.421 restored log file "00000001000001D1000000C8" > from archive > 2012-10-29 09:22:31.243 restored log file "00000001000001D1000000C9" > from archive > 2012-10-29 09:22:32.194 restored log file "00000001000001D1000000CA" > from archive > 2012-10-29 09:22:33.169 restored log file "00000001000001D1000000CB" > from archive > 2012-10-29 09:22:33.565 restored log file "00000001000001D1000000CC" > from archive > 2012-10-29 09:23:35.451 restored log file "00000001000001D1000000CD" > from archive > > Everything is nice until here. > Replaying this WAL file suddenly takes 1.5 minutes instead > of mere seconds as before. > > 2012-10-29 09:24:54.761 restored log file "00000001000001D1000000CE" > from archive > 2012-10-29 09:27:23.013 restartpoint starting: time > 2012-10-29 09:28:12.200 restartpoint complete: wrote 242 buffers > (0.0%); > 0 transaction log file(s) added, 0 removed, 0 > recycled; > write=48.987 s, sync=0.185 s, total=49.184 s; > sync files=1096, longest=0.016 s, average=0.000 > s > 2012-10-29 09:28:12.206 recovery restart point at 1D1/CC618278 > 2012-10-29 09:28:31.226 restored log file "00000001000001D1000000CF" > from archive > > Again there is a difference of 2.5 minutes > between these WAL files, only 50 seconds of > which were spent in the restartpoint. > > From here on it continues in quite the same vein. > Some WAL files are restored in seconds, but some take > more than 4 minutes. > > I'll skip to the end of the log: > > 2012-10-29 10:37:53.809 restored log file "00000001000001D1000000EF" > from archive > 2012-10-29 10:38:53.194 restartpoint starting: time > 2012-10-29 10:39:25.929 restartpoint complete: wrote 161 buffers > (0.0%); > 0 transaction log file(s) added, 0 removed, 0 > recycled; > write=32.661 s, sync=0.066 s, total=32.734 s; > sync files=251, longest=0.003 s, average=0.000 > s > 2012-10-29 10:39:25.929 recovery restart point at 1D1/ED95C728 > 2012-10-29 10:42:56.153 restored log file "00000001000001D1000000F0" > from archive > 2012-10-29 10:43:53.062 restartpoint starting: time > 2012-10-29 10:45:36.871 restored log file "00000001000001D1000000F1" > from archive > 2012-10-29 10:45:39.832 restartpoint complete: wrote 594 buffers > (0.0%); > 0 transaction log file(s) added, 0 removed, 0 > recycled; > write=106.666 s, sync=0.093 s, total=106.769 s; > sync files=729, longest=0.004 s, average=0.000 > s > 2012-10-29 10:45:39.832 recovery restart point at 1D1/EF5D4340 > 2012-10-29 10:46:13.602 restored log file "00000001000001D1000000F2" > from archive > 2012-10-29 10:47:38.396 restored log file "00000001000001D1000000F3" > from archive > 2012-10-29 10:47:38.962 streaming replication successfully connected to > primary > > I'd be happy if somebody could shed light on this. > > Yours, > Laurenz Albe > > PS: Here is the configuration: > > name | current_setting > ------------------------------+--------------------------- > version | PostgreSQL 9.1.3 on > x86_64-unknown-linux-gnu, compiled by gcc (GCC) 4.4.6 20110731 (Red Hat > 4.4.6-3), 64-bit > archive_command | gzip -1 <"%p" | tee > /POSTGRES/data/exchange/"%f".gz >/POSTGRES/data/backups/ELAK/"%f".gz > archive_mode | on > checkpoint_completion_target | 0.9 > checkpoint_segments | 30 > client_encoding | UTF8 > constraint_exclusion | off > cursor_tuple_fraction | 1 > custom_variable_classes | pg_stat_statements > default_statistics_target | 1000 > effective_cache_size | 64GB > hot_standby | on > lc_collate | de_DE.UTF8 > lc_ctype | de_DE.UTF8 > listen_addresses | * > log_checkpoints | on > log_connections | on > log_destination | csvlog > log_directory | /POSTGRES/data/logs/ELAK > log_disconnections | on > log_filename | ELAK-%Y-%m-%d.log > log_lock_waits | on > log_min_duration_statement | 3s > log_min_error_statement | log > log_min_messages | log > log_rotation_size | 0 > log_statement | ddl > log_temp_files | 0 > logging_collector | on > maintenance_work_mem | 1GB > max_connections | 800 > max_prepared_transactions | 800 > max_stack_depth | 9MB > max_standby_archive_delay | 0 > max_standby_streaming_delay | 0 > max_wal_senders | 2 > pg_stat_statements.max | 5000 > pg_stat_statements.track | all > port | 55503 > server_encoding | UTF8 > shared_buffers | 16GB > shared_preload_libraries | pg_stat_statements,passwordcheck > ssl | on > tcp_keepalives_count | 0 > tcp_keepalives_idle | 0 > TimeZone | Europe/Vienna > wal_buffers | 16MB > wal_level | hot_standby > work_mem | 8MB > (49 rows) > > Hi Albe, My first guess would be that there was something using I/O resources on your NetApp. That is the behavior you would expect once the I/O cache on the NetApp has been filled and you actually have to perform writes to the underlying disks. Is this a dedicated box? Can you get I/O stats from the box during the recovery? Regards, Ken > -- > Sent via pgsql-performance mailing list (pgsql-performance@postgresql.org) > To make changes to your subscription: > http://www.postgresql.org/mailpref/pgsql-performance >
Albe Laurenz wrote: > I am configuring streaming replication with hot standby > with PostgreSQL 9.1.3 on RHEL 6 (kernel 2.6.32-220.el6.x86_64). > PostgreSQL was compiled from source. > > It works fine, except that starting the standby took for ever: > it took the system more than 80 minutes to replay 48 WAL files > and connect to the primary. > > Can anybody think of an explanation why it takes that long? Can you do a quick xlogdump of those files? Maybe there is something unusual (say particular types of GIN/GiST index updates) on the files that take longer. -- Álvaro Herrera http://www.2ndQuadrant.com/ PostgreSQL Development, 24x7 Support, Training & Services
Alvaro Herrera wrote:
>> I am configuring streaming replication with hot standby
>> with PostgreSQL 9.1.3 on RHEL 6 (kernel 2.6.32-220.el6.x86_64).
>> PostgreSQL was compiled from source.
>>
>> It works fine, except that starting the standby took for ever:
>> it took the system more than 80 minutes to replay 48 WAL files
>> and connect to the primary.
>>
>> Can anybody think of an explanation why it takes that long?
>
> Can you do a quick xlogdump of those files? Maybe there is something
> unusual (say particular types of GIN/GiST index updates) on the files
> that take longer.
There are no GIN and GiST indexes in this cluster.
Here's the output of "xlogdump -S" on one of the WAL files
that took over 4 minutes:
00000001000001D1000000EF:
Unable to read continuation page?
** maybe continues to next segment **
---------------------------------------------------------------
TimeLineId: 1, LogId: 465, LogSegment: 239
Resource manager stats:
[0]XLOG : 2 records, 112 bytes (avg 56.0 bytes)
checkpoint: 2, switch: 0, backup end: 0
[1]Transaction: 427 records, 96512 bytes (avg 226.0 bytes)
commit: 427, abort: 0
[2]Storage : 0 record, 0 byte (avg 0.0 byte)
[3]CLOG : 0 record, 0 byte (avg 0.0 byte)
[4]Database : 0 record, 0 byte (avg 0.0 byte)
[5]Tablespace: 0 record, 0 byte (avg 0.0 byte)
[6]MultiXact : 0 record, 0 byte (avg 0.0 byte)
[7]RelMap : 0 record, 0 byte (avg 0.0 byte)
[8]Standby : 84 records, 1352 bytes (avg 16.1 bytes)
[9]Heap2 : 325 records, 9340 bytes (avg 28.7 bytes)
[10]Heap : 7611 records, 4118483 bytes (avg 541.1 bytes)
ins: 2498, upd/hot_upd: 409/2178, del: 2494
[11]Btree : 3648 records, 120814 bytes (avg 33.1 bytes)
[12]Hash : 0 record, 0 byte (avg 0.0 byte)
[13]Gin : 0 record, 0 byte (avg 0.0 byte)
[14]Gist : 0 record, 0 byte (avg 0.0 byte)
[15]Sequence : 0 record, 0 byte (avg 0.0 byte)
Backup block stats: 2600 blocks, 11885880 bytes (avg 4571.5 bytes)
Yours,
Laurenz Albe
On Mon, Oct 29, 2012 at 6:05 AM, Albe Laurenz <laurenz.albe@wien.gv.at> wrote: > I am configuring streaming replication with hot standby > with PostgreSQL 9.1.3 on RHEL 6 (kernel 2.6.32-220.el6.x86_64). > PostgreSQL was compiled from source. > > It works fine, except that starting the standby took for ever: > it took the system more than 80 minutes to replay 48 WAL files > and connect to the primary. > > Can anybody think of an explanation why it takes that long? Could the slow log files be replaying into randomly scattered pages which are not yet in RAM? Do you have sar or vmstat reports? Cheers, Jeff
>> On Mon, Oct 29, 2012 at 6:05 AM, Albe Laurenz <laurenz.albe@wien.gv.at> wrote: >>> I am configuring streaming replication with hot standby >>> with PostgreSQL 9.1.3 on RHEL 6 (kernel 2.6.32-220.el6.x86_64). >>> PostgreSQL was compiled from source. >>> >>> It works fine, except that starting the standby took for ever: >>> it took the system more than 80 minutes to replay 48 WAL files >>> and connect to the primary. >>> >>> Can anybody think of an explanation why it takes that long? Jeff Janes wrote: >> Could the slow log files be replaying into randomly scattered pages >> which are not yet in RAM? >> >> Do you have sar or vmstat reports? The sar reports from the time in question tell me that I read about 350 MB/s and wrote less than 0.2 MB/s. The disks were fairly busy (around 90%). Jeff Trout wrote: > If you do not have good random io performance log replay is nearly unbearable. > > also, what io scheduler are you using? if it is cfq change that to deadline or noop. > that can make a huge difference. We use the noop scheduler. As I said, an identical system performed well in load tests. The sar reports give credit to Jeff Janes' theory. Why does WAL replay read much more than it writes? I thought that pretty much every block read during WAL replay would also get dirtied and hence written out. I wonder why the performance is good in the first few seconds. Why should exactly the pages that I need in the beginning happen to be in cache? And finally: are the numbers I observe (replay 48 files in 80 minutes) ok or is this terribly slow as it seems to me? Yours, Laurenz Albe
On 30.10.2012 10:50, Albe Laurenz wrote: > Why does WAL replay read much more than it writes? > I thought that pretty much every block read during WAL > replay would also get dirtied and hence written out. Not necessarily. If a block is modified and written out of the buffer cache before next checkpoint, the latest version of the block is already on disk. On replay, the redo routine reads the block, sees that the change was applied, and does nothing. > I wonder why the performance is good in the first few seconds. > Why should exactly the pages that I need in the beginning > happen to be in cache? This is probably because of full_page_writes=on. When replay has a full page image of a block, it doesn't need to read the old contents from disk. It can just blindly write the image to disk. Writing a block to disk also puts that block in the OS cache, so this also efficiently warms the cache from the WAL. Hence in the beginning of replay, you just write a lot of full page images to the OS cache, which is fast, and you only start reading from disk after you've filled up the OS cache. If this theory is true, you should see a pattern in the I/O stats, where in the first seconds there is no I/O, but the CPU is 100% busy while it reads from WAL and writes out the pages to the OS cache. After the OS cache fills up with the dirty pages (up to dirty_ratio, on Linux), you will start to see a lot of writes. As the replay progresses, you will see more and more reads, as you start to get cache misses. - Heikki
On Tue, Oct 30, 2012 at 09:50:44AM +0100, Albe Laurenz wrote: > >> On Mon, Oct 29, 2012 at 6:05 AM, Albe Laurenz > <laurenz.albe@wien.gv.at> wrote: > >>> I am configuring streaming replication with hot standby > >>> with PostgreSQL 9.1.3 on RHEL 6 (kernel 2.6.32-220.el6.x86_64). > >>> PostgreSQL was compiled from source. > >>> > >>> It works fine, except that starting the standby took for ever: > >>> it took the system more than 80 minutes to replay 48 WAL files > >>> and connect to the primary. > >>> > >>> Can anybody think of an explanation why it takes that long? > > Jeff Janes wrote: > >> Could the slow log files be replaying into randomly scattered pages > >> which are not yet in RAM? > >> > >> Do you have sar or vmstat reports? > > The sar reports from the time in question tell me that I read > about 350 MB/s and wrote less than 0.2 MB/s. The disks were > fairly busy (around 90%). > > Jeff Trout wrote: > > If you do not have good random io performance log replay is nearly > unbearable. > > > > also, what io scheduler are you using? if it is cfq change that to > deadline or noop. > > that can make a huge difference. > > We use the noop scheduler. > As I said, an identical system performed well in load tests. > > The sar reports give credit to Jeff Janes' theory. > Why does WAL replay read much more than it writes? > I thought that pretty much every block read during WAL > replay would also get dirtied and hence written out. > > I wonder why the performance is good in the first few seconds. > Why should exactly the pages that I need in the beginning > happen to be in cache? > > And finally: are the numbers I observe (replay 48 files in 80 > minutes) ok or is this terribly slow as it seems to me? > > Yours, > Laurenz Albe > Hi, The load tests probably had the "important" data already cached. Processing a WAL file would involve bringing all the data back into memory using a random I/O pattern. Perhaps priming the file cache using some sequential reads would allow the random I/O to hit memory instead of disk. I may be misremembering, but wasn't there an associated project/program that would parse the WAL files and generate cache priming reads? Regards, Ken
Heikki Linnakangas wrote: >> Why does WAL replay read much more than it writes? >> I thought that pretty much every block read during WAL >> replay would also get dirtied and hence written out. > > Not necessarily. If a block is modified and written out of the buffer > cache before next checkpoint, the latest version of the block is already > on disk. On replay, the redo routine reads the block, sees that the > change was applied, and does nothing. True. Could that account for 1000 times more reads than writes? >> I wonder why the performance is good in the first few seconds. >> Why should exactly the pages that I need in the beginning >> happen to be in cache? > > This is probably because of full_page_writes=on. When replay has a full > page image of a block, it doesn't need to read the old contents from > disk. It can just blindly write the image to disk. Writing a block to > disk also puts that block in the OS cache, so this also efficiently > warms the cache from the WAL. Hence in the beginning of replay, you just > write a lot of full page images to the OS cache, which is fast, and you > only start reading from disk after you've filled up the OS cache. If > this theory is true, you should see a pattern in the I/O stats, where in > the first seconds there is no I/O, but the CPU is 100% busy while it > reads from WAL and writes out the pages to the OS cache. After the OS > cache fills up with the dirty pages (up to dirty_ratio, on Linux), you > will start to see a lot of writes. As the replay progresses, you will > see more and more reads, as you start to get cache misses. That makes sense to me. Unfortunately I don't have statistics in the required resolution to verify that. Thanks for the explanations. Yours, Laurenz Albe
ktm@rice.edu wrote: >>> If you do not have good random io performance log replay is nearly >>> unbearable. >>> >>> also, what io scheduler are you using? if it is cfq change that to >>> deadline or noop. >>> that can make a huge difference. >> >> We use the noop scheduler. >> As I said, an identical system performed well in load tests. > The load tests probably had the "important" data already cached. Processing > a WAL file would involve bringing all the data back into memory using a > random I/O pattern. The database is way too big (1 TB) to fit into cache. What are "all the data" that have to be brought back? Surely only the database blocks that are modified by the WAL, right? Yours, Laurenz Albe
On Tue, Oct 30, 2012 at 02:16:57PM +0100, Albe Laurenz wrote: > ktm@rice.edu wrote: > >>> If you do not have good random io performance log replay is nearly > >>> unbearable. > >>> > >>> also, what io scheduler are you using? if it is cfq change that to > >>> deadline or noop. > >>> that can make a huge difference. > >> > >> We use the noop scheduler. > >> As I said, an identical system performed well in load tests. > > > The load tests probably had the "important" data already cached. > Processing > > a WAL file would involve bringing all the data back into memory using > a > > random I/O pattern. > > The database is way too big (1 TB) to fit into cache. > > What are "all the data" that have to be brought back? > Surely only the database blocks that are modified by the WAL, > right? > > Yours, > Laurenz Albe > Right, it would only read the blocks that are modified. Regards, Ken
On Oct 29, 2012, at 12:42 PM, Jeff Janes wrote: > On Mon, Oct 29, 2012 at 6:05 AM, Albe Laurenz <laurenz.albe@wien.gv.at> wrote: >> I am configuring streaming replication with hot standby >> with PostgreSQL 9.1.3 on RHEL 6 (kernel 2.6.32-220.el6.x86_64). >> PostgreSQL was compiled from source. >> >> It works fine, except that starting the standby took for ever: >> it took the system more than 80 minutes to replay 48 WAL files >> and connect to the primary. >> >> Can anybody think of an explanation why it takes that long? > > Could the slow log files be replaying into randomly scattered pages > which are not yet in RAM? > > Do you have sar or vmstat reports? > > Cheers, If you do not have good random io performance log replay is nearly unbearable. also, what io scheduler are you using? if it is cfq change that to deadline or noop. that can make a huge difference. -- Jeff Trout <jeff@jefftrout.com>
On Oct 29, 2012, at 12:42 PM, Jeff Janes wrote: > On Mon, Oct 29, 2012 at 6:05 AM, Albe Laurenz <laurenz.albe@wien.gv.at> wrote: >> I am configuring streaming replication with hot standby >> with PostgreSQL 9.1.3 on RHEL 6 (kernel 2.6.32-220.el6.x86_64). >> PostgreSQL was compiled from source. >> >> It works fine, except that starting the standby took for ever: >> it took the system more than 80 minutes to replay 48 WAL files >> and connect to the primary. >> >> Can anybody think of an explanation why it takes that long? > > Could the slow log files be replaying into randomly scattered pages > which are not yet in RAM? > > Do you have sar or vmstat reports? > If you do not have good random io performance log replay is nearly unbearable. (I've run into this before many times) Also, what io scheduler are you using? if it is cfq change that to deadline or noop. that can make a huge difference. -- Jeff Trout <jeff@jefftrout.com