5

We have 2 dedicated DB Servers. One is master and other is its streaming slave.
Postgres version 9.0.17.

We have similar hardware on both servers and using 15krpm SAS drive in Raid 10 for Database cluster. The only difference is that on server we have 128 GB ram and on slave we have 64 GB ram.

The issue which we are facing is that our streaming slave is lagging behind.

On the streaming slave we have

postgres=# select pg_last_xlog_receive_location();
 pg_last_xlog_receive_location
-------------------------------
 1F7D/DD3BA000


postgres=# select pg_last_xlog_replay_location();
 pg_last_xlog_replay_location
------------------------------
 1F75/5BE08980

This difference between wal received and replay is increasing constantly.

Please let me know that how this issue can be resolved.

Output of perf top -u postgres is

98.30%  postgres          (.) DropRelFileNodeBuffers
0.20%  postgres          (.) 0x000000000008b05b
0.14%  (kernel)          (k) copy_user_generic_string
0.13%  postgres          (.) hash_seq_search
0.07%  postgres          (.) hash_search_with_hash_value
0.05%  (kernel)          (k) _spin_lock
0.05%  (kernel)          (k) apic_timer_interrupt
0.03%  (kernel)          (k) do_timer
0.03%  postgres          (.) RememberFsyncRequest
0.03%  (kernel)          (k) __sb_start_write
0.02%  (jbd2)            (k) do_get_write_access
0.02%  (kernel)          (k) unroll_tree_refs
0.02%  (cciss)           (k) do_cciss_request
0.02%  (ext4)            (k) ext4_check_dir_entry
0.02%  (kernel)          (k) path_walk
0.02%  (kernel)          (k) scheduler_tick
0.02%  postgres          (.) LWLockAcquire
0.02%  (kernel)          (k) dyntick_save_progress_counter
0.02%  (kernel)          (k) _spin_lock_irqsave
0.02%  (kernel)          (k) audit_syscall_entry
0.02%  (ext4)            (k) ext4_journal_start_sb
0.02%  (kernel)          (k) radix_tree_range_tag_if_tagged
0.01%  (kernel)          (k) sys_getppid
0.01%  (kernel)          (k) native_read_tsc
0.01%  libc-2.12.so      (.) _IO_str_init_static_internal
0.01%  (kernel)          (k) __getblk
0.01%  (kernel)          (k) run_timer_softirq
0.01%  (kernel)          (k) system_call
0.01%  postgres          (.) __errno_location@plt
0.01%  libc-2.12.so      (.) __GI___libc_lseek64
0.01%  postgres          (.) XLogReadBufferExtended
0.01%  (kernel)          (k) memcpy
0.01%  (kernel)          (k) irq_work_run
0.01%  postgres          (.) fsm_set_avail
0.01%  (kernel)          (k) kmem_cache_free
0.01%  (kernel)          (k) do_unlinkat
0.01%  libc-2.12.so      (.) vfprintf
0.01%  postgres          (.) hash_any
0.01%  (kernel)          (k) sysret_check
0.01%  (kernel)          (k) mutex_lock
0.01%  (kernel)          (k) printk_tick
0.01%  postgres          (.) elog_start
0.01%  (kernel)          (k) __percpu_counter_add
0.01%  (kernel)          (k) file_update_time
0.01%  (kernel)          (k) enqueue_task_fair
0.01%  (kernel)          (k) blk_recount_segments
0.01%  (kernel)          (k) rcu_check_callbacks
0.01%  (kernel)          (k) put_pid
0.01%  postgres          (.) mdunlink
0.01%  postgres          (.) LWLockRelease
0.01%  (kernel)          (k) current_kernel_time
0.01%  (kernel)          (k) perf_event_task_tick
0.01%  (kernel)          (k) native_apic_mem_write

output of gdb for postgres startup process

(gdb) thread apply all backtrace Thread 1 (Thread 0x7fd06d28f7c0 (LWP 26949)):
#0  0x00000000005ec320 in DropRelFileNodeBuffers ()
#1  0x0000000000603115 in smgrdounlink ()
#2  0x000000000047d992 in ?? ()
#3  0x000000000048eca9 in StartupXLOG ()
#4  0x0000000000490c58 in StartupProcessMain ()
#5  0x00000000004a6faf in AuxiliaryProcessMain ()
#6  0x00000000005d31c3 in ?? ()
#7  0x00000000005d7372 in PostmasterMain ()
#8  0x000000000057e320 in main ()

migrated from stackoverflow.com Apr 9 '14 at 13:07

This question came from our site for professional and enthusiast programmers.

  • 1
    So what is the network and disk I/O on both? There's no way we can tell what your machines are doing, is there? – Richard Huxton Apr 9 '14 at 11:33
  • There is no issue with network speed as I can see that all the wal files are transferred from master to slave. There is not much IO wait on slave. System load average is around 1. If I look into the details of postgres startup process, it is consuming from 99.1% to 99.9% of CPU and wait% is just 0.0% to 0.1%. I am wondering what this postgres startup process is doing as it is recovering wal files at really slow rate. On Master, the load average is staying around 1 to 3. We are not having any issue with master. It is the backup which is not catching up. – user3514462 Apr 9 '14 at 12:12
  • perf top -u postgres might tell you more about what it's doing. Is iotop showing much activity on the replica? Is there anything informative in dmesg? – Craig Ringer Apr 9 '14 at 12:18
  • OK, that's an interesting one. What's your shared_buffers set to? And how many tables do you have, vaguely? Do you CREATE and DROP, CLUSTER or TRUNCATE lots of tables/sequences/etc in normal production operation? Do lots of REINDEXes? – Craig Ringer Apr 10 '14 at 9:28
6

Current (true at least in PostgreSQL 9.4 and older) PostgreSQL releases have single-threaded WAL recovery.

This means that replay of the write-ahead log occurs in only one recovery worker, and is thus able to benefit less from I/O concurrency than a normal running master. This can result in WAL replay lagging behind in cases where the replica and master have similar hardware, even when you'd expect the master (which is generally also under more load) to be the slower server.

(It'd be great to improve this, but wanted it enough to do the work yet, and nobody seems keen to fund it at the moment).

That said, your case with very high CPU use doesn't seem to fit with issues of low I/O concurrency. In your situation I'd be attaching gdb and seeing what the replay proess was doing, or using perf top to examine what the system as a whole is up to, then dig deeper with perf once I had some clues. I'd also be looking closely at iotop, vmstat, iostat, the PostgreSQL logs, dmesg, etc.

After investigation

Profiles revealed that most time was being spent in DropRelFileNodeBuffers.

That does a linear scan through shared_buffers whenever a relfilenode is deleted - caused by truncate, drop table, cluster, drop index, etc. This must be done during WAL replay, as well as on the main node.

So this suggests that:

  • Your shared_buffers is probably very big; and
  • You're probably doing lots of operations that delete relfilenodes

Reducing shared_buffers on the replica may well help.

  • There are no errors in dmesg as well as postgres logs. In iotop the writing of postgress is staying between 200Kb/s to 600Kb/s (combined of postgress startup and wal writer process). The disk is however capable of very high writing speed. Even if I will do a bonnie++ run with the runing slave, bonnie++ is writing at speed of around 450Mb/s. I am unable to figure out any thing from perf top. Its output is attached for you reference. – user3514462 Apr 9 '14 at 12:38
  • 98.46% postgres [.] DropRelFileNodeBuffers 0.20% postgres [.] 0x000000000008b05b 0.09% postgres [.] hash_seq_search 0.08% postgres [.] hash_search_with_hash_value 0.04% [kernel] [k] do_timer 0.03% [kernel] [k] apic_timer_interrupt 0.02% postgres [.] LWLockAcquire 0.02% postgres [.] hash_any 0.02% [kernel] [k] native_write_msr_safe – user3514462 Apr 9 '14 at 12:40
  • 450MB/s sequential I/O doesn't mean 450MB/s random I/O - on RAID 5 systems I've seen incredibly awful random I/O results. But this is RAID 10 so it should be OK. You'll need to look at what it's doing while it hammers away at the CPU - gdb, perf, etc. – Craig Ringer Apr 9 '14 at 12:40
  • Ugh, things like that are unreadable in comments. Edit question, comment when edited. (include command as well as results). – Craig Ringer Apr 9 '14 at 12:41
  • Are there any postgres configuration settings which can affect the restoration speed? – user3514462 Apr 9 '14 at 12:43
0

The issue is resolved. Someone pointed out that reducing the shared buffer can help. It was set to 12 GB. I changed it to 1 GB. After that I can see the postgres startup is utilizing alot of resources in iotop. Previously it was writing in few hundred KB/s but now it is varying from 2 MB/s to 30 MB/s. Postgres startup process cpu utilization which was around 99.9% has dropped as well.

The lag which was increasing by 50 wals per hour is now reducing by 200 per hour. So our backup will soon catch up with master.

  • Yeah, that's why I asked you what shared_buffers was set to, once I saw the profiles... – Craig Ringer Apr 10 '14 at 13:03
  • Thank you for your help. The backup has now catch up with master and is working fine. – haroon_aut Apr 10 '14 at 17:25

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.