Re: BUG #9635: Wal sender process is using 100% CPU

I was able to recreate the issue.
Basically, we have a job that inserts 30+ million records into a table.
During the loading of this table, the wal_sender cpu spikes to 100% and appears to stay at 100% until the replication is completed on the slave.
I was able to test inserting this much data on another master/slave configuration with streaming replication and saw the same results.

Other than offloading this job, is there anything we can do to decrease the replication lag?
Also, is this expected behavior due to the volume of data that got inserted and needs to get replicated?

Thanks!

-----Original Message-----
From: Heikki Linnakangas [mailto:hlinnakangas(at)vmware(dot)com]
Sent: Tuesday, May 06, 2014 10:33 AM
To: Jamie Koceniak
Cc: pgsql-bugs(at)postgresql(dot)org
Subject: Re: [BUGS] BUG #9635: Wal sender process is using 100% CPU

On 05/06/2014 07:44 PM, Jamie Koceniak wrote:
> Hi Heikki,
>
> Attached is a trace route for one of the pids that was running at 100% cpu.
> Note: when the wal_senders hit 100% cpu, our slave servers tend to lag the master for up to around 3-4 minutes until the wal_sender cpu utilization drops. This is very problematic for us since we are trying to use the slaves for reads in our application.
>
> Here is perf top results:
> 39.49% libz.so.1.2.7 [.] 0x000000000000301e
> 32.97% postgres [.] 0x00000000000cf150
> 6.50% postgres [.] nocachegetattr
> 2.63% postgres [.] btint4cmp
> 1.64% postgres [.] _start
> 1.40% [unknown] [.] 0x00007f9dfca6a34b
> 1.06% libc-2.13.so [.] 0x000000000012934b
> 0.94% postgres [.] slot_getattr
> 0.85% libcrypto.so.1.0.0 [.] 0x000000000009f48f
> 0.69% postgres [.] ExecProject
> 0.67% libz.so.1.2.7 [.] adler32
> 0.66% postgres [.] GetMemoryChunkSpace
> 0.58% [kernel] [k] copy_user_generic_string
> 0.45% postgres [.] heap_fill_tuple
> 0.38% postgres [.] execTuplesMatch
> 0.27% postgres [.] FunctionCall2Coll
> 0.27% postgres [.] ExecProcNode
> 0.25% postgres [.] heap_tuple_untoast_attr
> 0.22% postgres [.] MemoryContextAlloc
> 0.21% postgres [.] heap_form_minimal_tuple
> 0.21% postgres [.] pfree
> 0.19% postgres [.] heap_compute_data_size

Hmm, these results seem to include all processes, not just the WAL sender

> Here is some data using perf record and perf report:
>
> + 33.93% 193019 postgres postgres [.] 0x0000000000369e27
> + 30.06% 173825 postgres libz.so.1.2.7 [.] 0x00000000000036c0
> + 10.21% 60618 postgres [unknown] [.] 0x00007f9dfc2fd529
> + 4.81% 27275 postgres postgres [.] nocachegetattr
> + 2.55% 14443 postgres postgres [.] btint4cmp
> + 1.22% 6916 postgres postgres [.] ExecProject
> + 1.20% 6837 postgres postgres [.] _start
> + 1.10% 6495 postgres libc-2.13.so [.] 0x000000000012b8e9
> + 0.84% 4760 postgres postgres [.] heap_fill_tuple
> + 0.74% 4265 postgres [kernel.kallsyms] [k] copy_user_generic_string
> + 0.71% 4001 postgres postgres [.] GetMemoryChunkSpace
> + 0.66% 3881 postgres libcrypto.so.1.0.0 [.] 0x0000000000081ec7
> + 0.63% 3673 postgres libz.so.1.2.7 [.] adler32
> + 0.43% 2448 postgres postgres [.] slot_getattr
> + 0.40% 2277 postgres postgres [.] ExecProcNode
> + 0.40% 2250 postgres postgres [.] heap_form_minimal_tuple
> + 0.37% 2078 postgres postgres [.] heap_compute_data_size
> + 0.31% 1739 postgres postgres [.] ExecScan
> + 0.27% 1779 postgres [kernel.kallsyms] [k] page_fault
> + 0.24% 1374 postgres postgres [.] LogicalTapeWrite
> + 0.24% 4206 swapper [kernel.kallsyms] [k] intel_idle
> + 0.21% 1206 postgres postgres [.] slot_getsomeattrs

Same here.

> Also, here are our wal settings on the master.
> Do these settings appear ok?
>
> wal_block_size | 8192 |
> wal_buffers | 16MB |
> wal_keep_segments | 5000 |
> wal_level | hot_standby |
> wal_receiver_status_interval | 10s |
> wal_segment_size | 16MB |
> wal_sender_delay | 1s |
> wal_sync_method | fdatasync |
> wal_writer_delay | 200ms |

Looks reasonable to me.

So, the strace output repeats this, with small variations in the number of bytes written in each sendto() call:

recvfrom(10, 0x7f9dfec1f753, 5, 0, 0, 0) = -1 EAGAIN (Resource temporarily unavailable) read(7, ..., 131072) = 131072 sendto(10, ..., 3690, 0, NULL, 0) = 3690 sendto(10, ..., 3605, 0, NULL, 0) = 3605 sendto(10, ..., 3669, 0, NULL, 0) = 3669 sendto(10, ..., 3653, 0, NULL, 0) = 3653 sendto(10, ..., 3637, 0, NULL, 0) = 3637 sendto(10, ..., 3621, 0, NULL, 0) = 3621 sendto(10, ..., 3669, 0, NULL, 0) = 3669 sendto(10, ..., 3605, 0, NULL, 0) = 3605 sendto(10, ..., 53, 0, NULL, 0) = 53
getppid() = 5474

The read() reads 128kB of WAL from the file in pg_xlog, and it is then sent to the client. Now, it's pretty surprising that the number of bytes written with sendto() doesn't match the number of bytes read from the file. Unless, you're using SSL with compression. That would also explain the high amount of CPU time spent in libz in the perf output.

Try disabling SSL compression, with sslcompression=0 option in primary_conninfo, or disable SSL altogether if the network is trustworthy enough for that.

- Heikki