Re: Postgres Replaying WAL slowly

On Jun 30, 2014, at 11:39 AM, Andres Freund <andres@2ndquadrant.com> wrote:

> On 2014-06-30 11:34:52 -0700, Jeff Frost wrote:
>> On Jun 30, 2014, at 10:29 AM, Soni M <diptatapa@gmail.com> wrote:
>
>>> It is
>>> 96.62%  postgres             [.] StandbyReleaseLocks
>>> as Jeff said. It runs quite long time, more than 5 minutes i think
>>>
>>> i also use hot standby. we have 4 streaming replica, some of them has active connection some has not. this issue
haslast more than 4 days. On one of the standby, above postgres process is the only process that consume high cpu load. 
>>
>> compiled with -fno-omit-frame-pointer doesn't yield much more info:
>
> You'd need to do perf record -ga instead of perf record -a to see
> additional information.
>

Ah! That's right.

Here's how that looks:

Samples: 473K of event 'cpu-clock', Event count (approx.): 473738
+  68.42%          init  [kernel.kallsyms]                         [k] native_safe_halt
+  26.07%      postgres  postgres                                  [.] StandbyReleaseLocks
+   2.82%       swapper  [kernel.kallsyms]                         [k] native_safe_halt
+   0.19%           ssh  libcrypto.so.1.0.1e                       [.] md5_block_asm_data_order
+   0.19%      postgres  postgres                                  [.] RecordIsValid
+   0.16%           ssh  libcrypto.so.1.0.1e                       [.] RC4
+   0.10%      postgres  postgres                                  [.] hash_search_with_hash_value
+   0.06%      postgres  [kernel.kallsyms]                         [k] _spin_unlock_irqrestore
+   0.05%          init  [vmxnet3]                                 [k] vmxnet3_poll_rx_only
+   0.04%      postgres  [kernel.kallsyms]                         [k] copy_user_generic_unrolled
+   0.04%          init  [kernel.kallsyms]                         [k] finish_task_switch
+   0.04%          init  [kernel.kallsyms]                         [k] __do_softirq
+   0.04%           ssh  [kernel.kallsyms]                         [k] _spin_unlock_irqrestore
+   0.04%           ssh  [vmxnet3]                                 [k] vmxnet3_xmit_frame
+   0.03%      postgres  postgres                                  [.] PinBuffer
+   0.03%          init  [vmxnet3]                                 [k] vmxnet3_xmit_frame
+   0.03%           ssh  [kernel.kallsyms]                         [k] copy_user_generic_unrolled
+   0.03%      postgres  postgres                                  [.] XLogReadBufferExtended
+   0.03%           ssh  ssh                                       [.] 0x000000000002aa07
+   0.03%          init  [kernel.kallsyms]                         [k] _spin_unlock_irqrestore
+   0.03%           ssh  [vmxnet3]                                 [k] vmxnet3_poll_rx_only
+   0.02%           ssh  [kernel.kallsyms]                         [k] __do_softirq
+   0.02%      postgres  libc-2.12.so                              [.] _wordcopy_bwd_dest_aligned
+   0.02%      postgres  postgres                                  [.] mdnblocks
+   0.02%           ssh  libcrypto.so.1.0.1e                       [.] 0x00000000000e25a1
+   0.02%           scp  [kernel.kallsyms]                         [k] copy_user_generic_unrolled
+   0.02%           ssh  libc-2.12.so                              [.] memcpy
+   0.02%      postgres  libc-2.12.so                              [.] memcpy


> But:
>
>> 76.24%  postgres                               [.] StandbyReleaseLocks
>
> already is quite helpful.
>
> What are you doing on that system? Is there anything requiring large
> amounts of access exclusive locks on the primary? Possibly large amounts
> of temporary relations?


The last time we did a 100% logging run, the peak temp table creation was something like 120k/hr, but the replicas
seemedable to keep up with that just fine. 

Hopefully Soni can answer whether that has increased significantly since May.