Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtp (Exim 4.80) (envelope-from ) id 1YYC2H-0000sb-GR for pgsql-performance@arkaria.postgresql.org; Wed, 18 Mar 2015 11:21:17 +0000 Received: from localhost ([127.0.0.1] helo=postgresql.org) by malur.postgresql.org with smtp (Exim 4.80) (envelope-from ) id 1YYC2G-0008NR-9k for pgsql-performance@arkaria.postgresql.org; Wed, 18 Mar 2015 11:21:16 +0000 Received: from makus.postgresql.org ([2001:4800:1501:1::229]) by malur.postgresql.org with esmtps (TLS1.2:DHE_RSA_AES_256_CBC_SHA256:256) (Exim 4.80) (envelope-from ) id 1YYC2F-0008NJ-1U for pgsql-performance@postgresql.org; Wed, 18 Mar 2015 11:21:15 +0000 Received: from col004-omc4s6.hotmail.com ([65.55.34.208]) by makus.postgresql.org with esmtp (Exim 4.80) (envelope-from ) id 1YYC2A-00077G-WF for pgsql-performance@postgresql.org; Wed, 18 Mar 2015 11:21:13 +0000 Received: from COL129-W88 ([65.55.34.201]) by COL004-OMC4S6.hotmail.com over TLS secured channel with Microsoft SMTPSVC(7.5.7601.22751); Wed, 18 Mar 2015 04:21:09 -0700 X-TMN: [GE70S/XNuB3qwc2FAe/s9w619/kOH6uyiYsKMqbX6Ww=] X-Originating-Email: [steven.jones1201@outlook.com] Message-ID: Content-Type: multipart/alternative; boundary="_b70c9808-e000-418b-a99d-ad0588422abd_" From: Steven Jones To: "pgsql-performance@postgresql.org" Subject: Very slow checkpoints Date: Wed, 18 Mar 2015 11:21:08 +0000 Importance: Normal MIME-Version: 1.0 X-OriginalArrivalTime: 18 Mar 2015 11:21:09.0182 (UTC) FILETIME=[A20CC5E0:01D0616D] X-Pg-Spam-Score: -1.6 (-) List-Archive: List-Help: List-ID: List-Owner: List-Post: List-Subscribe: List-Unsubscribe: X-Mailing-List: pgsql-performance Precedence: bulk Sender: pgsql-performance-owner@postgresql.org --_b70c9808-e000-418b-a99d-ad0588422abd_ Content-Type: text/plain; charset="iso-8859-1" Content-Transfer-Encoding: quoted-printable Hi=2C We have a so far (to us) unexplainable issue on our production systems afte= r we roughly doubled the amount of data we import daily. We should be ok on= pure theoretical hardware performance=2C but we are seeing some weird IO c= ounters when the actual throughput of the writes is very low. The use case = is as follows: - typical DW - relatively constant periodic data loads - i.= e. heavy write - we receive large CSV files ~ 5-10Gb every 15 minutes spre= ad out across 5-7 minutes - Custom ETL scripts process and filter files wi= thin < 30 seconds down to about 5Gb CSV ready to load - 2 loader queues lo= ad the files=2C picking off a file one-by-one - tables are partitioned dai= ly=2C indexed on a primary key + timestamp - system is HP blade=3B 128Gb = RAM=2C 2x 8-core=2C 12x 10k RPM RAID1+0 (database) on first controller=2C 2= x 15k RAID1 (xlog) on a different controller - DB size is ~2.5Tb=3B rotati= ng load of 30 days keeps the database stable - filesystem: zfs with lz4 co= mpression - raw throughput of the database disk is > 700Mbytes/sec sequent= ial and >150Mbytes random for read and roughly half for write in various be= nchmarks - CPU load is minimal when copy loads are taking place (i.e. afte= r ETL has finished) The issue is that the system is constantly checkpointing regardless of vari= ous kernel and postgres settings. Having read through most of the history o= f this list and most of the recommendations on various blogs=2C we have bee= n unable to find an answer why the checkpoints are being written so slowly.= Even when we disable all import processes or if index is dropped=2C the ch= eckpoint is still taking > 1hour. Stats are pointing to checkpoint sizes of= roughly 7Gb which should take < 1min even with full random reads=3B so eve= n when imports are fully disabled=2C what is not making sense is why would = the checkpointing be taking well over an hour? One other thing that's noticed=2C but not measured=2C i.e. mostly anecdotal= is that for a period of <1hr when postgres is restarted=2C the system perf= orms mostly fine and checkpoints are completing in <5min=3B so it may be th= at after a while some (OS/postgres) buffers are filling up and causing this= issue? Full iostat/iotop=2C configuration=2C checkpoint stats=2C etc. are pasted b= elow for completeness. Highlights are:checkpoint_segments=3D512shared_buffe= rs=3D16GBcheckpoint_timeout=3D15mincheckpoint_completion_target=3D0.1 Regards=2CSteve ---Checkpoint stats: db=3D# select * from pg_stat_bgwriter=3B checkpoints_timed 6 checkpoints_req 3 checkpoint_write_time 26346184 = checkpoint_sync_time 142 buffers_checkpoint 4227065 buffers_clean 4139= 841 maxwritten_clean 8261 buffers_backend 9128583 buffers_backend_fsync = 0 buffers_alloc 9311478 stats_reset 2015-03-17 11:14:21.5649 ---postgres log file - checkpoint log entries: 2015-03-17 11:25:25 LOG: checkpoint complete: wrote 855754 buffers (40.8%)= =3B 0 transaction log file(s) added=2C 0 removed=2C 500 recycled=3B write= =3D2988.185 s=2C sync=3D0.044 s=2C total=3D2988.331 s=3B sync files=3D110= =2C longest=3D0.003 s=2C average=3D0.000 s2015-03-17 11:25:25 LOG: checkpo= int starting: xlog time2015-03-17 11:59:54 LOG: parameter "checkpoint_comp= letion_target" changed to "0.9"2015-03-17 13:30:20 LOG: checkpoint complet= e: wrote 1012112 buffers (48.3%)=3B 0 transaction log file(s) added=2C 0 re= moved=2C 512 recycled=3B write=3D7494.228 s=2C sync=3D0.021 s=2C total=3D74= 94.371 s=3B sync files=3D119=2C longest=3D0.001 s=2C average=3D0.000 s2015-= 03-17 13:30:20 LOG: checkpoint starting: xlog time2015-03-17 14:21:53 LOG:= parameter "checkpoint_completion_target" changed to "0.1"2015-03-17 16:00= :58 LOG: checkpoint complete: wrote 1411979 buffers (67.3%)=3B 0 transacti= on log file(s) added=2C 696 removed=2C 900 recycled=3B write=3D9036.898 s= =2C sync=3D0.020 s=2C total=3D9038.538 s=3B sync files=3D109=2C longest=3D0= .000 s=2C average=3D0.000 s2015-03-17 16:00:58 LOG: checkpoint starting: t= ime2015-03-17 16:28:40 LOG: checkpoint complete: wrote 345183 buffers (16.= 5%)=3B 0 transaction log file(s) added=2C 2001 removed=2C 0 recycled=3B wri= te=3D1660.333 s=2C sync=3D0.018 s=2C total=3D1661.816 s=3B sync files=3D93= =2C longest=3D0.002 s=2C average=3D0.000 s2015-03-17 17:28:40 LOG: checkpo= int starting: time2015-03-17 18:54:47 LOG: checkpoint complete: wrote 6020= 37 buffers (28.7%)=3B 0 transaction log file(s) added=2C 0 removed=2C 500 r= ecycled=3B write=3D5166.540 s=2C sync=3D0.039 s=2C total=3D5166.657 s=3B sy= nc files=3D122=2C longest=3D0.003 s=2C average=3D0.000 s2015-03-17 18:54:47= LOG: checkpoint starting: xlog time ---iostat -x snapshot: avg-cpu: %user %nice %system %iowait %steal %idle 0.50 0= .00 2.35 15.09 0.00 82.05 Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s avgrq-sz = avgqu-sz await r_await w_await svctm %utilsda 0.00 0.= 00 0.00 5.00 0.00 2056.00 822.40 0.00 0.00 0.00 0= .00 0.00 0.00sdb 0.00 0.00 1055.00 549.00 41166.50 2= 2840.00 79.81 5.28 3.28 4.94 0.10 0.62 100.00 ---vmstat 60 output # vmstat 60procs -----------memory---------- ---swap-- -----io---- -system-= - ----cpu---- r b swpd free buff cache si so bi bo in = cs us sy id wa 5 3 877508 1251152 74476 98853728 0 0 87 1891 = 0 0 1 5 92 2 6 5 877508 915044 74940 99237840 0 0 46588 418= 57 6993 41784 8 4 76 12 2 4 877508 1676008 75292 98577936 0 0 468= 47 34540 4778 17175 9 3 75 13 ---sysctl settings for dirty pages vm.dirty_background_bytes =3D 0vm.dirty_background_ratio =3D 5vm.dirty_byte= s =3D 0vm.dirty_expire_centisecs =3D 3000vm.dirty_ratio =3D 10vm.dirty_writ= eback_centisecs =3D 500 ---# free -m total used free shared buffers = cachedMem: 128905 126654 2250 0 70 = 95035-/+ buffers/cache: 31549 97355Swap: 15255 8= 56 14399 ---postgres settings:=20 # cat postgresql.conf |grep checkcheckpoint_segments =3D 512 # in log= file segments=2C min 1=2C 16MB eachcheckpoint_timeout =3D 15min = # range 30s-1hcheckpoint_completion_target =3D 0.1 # checkpoint targ= et duration=2C 0.0 - 1.0checkpoint_warning =3D 10min # 0 disab= leslog_checkpoints =3D on # cat postgresql.conf |egrep -e 'wal|arch|hot|lru|shared'shared_buffers =3D= 16384MBbgwriter_lru_maxpages =3D 500#bgwriter_lru_multiplier =3D 2.0 = # 0-10.0 multipler on buffers scanned/roundwal_level =3D 'archive'archi= ve_mode =3D onarchive_command =3D 'cd .' # we can also use exit 0=2C anyt= hing thatmax_wal_senders =3D 0wal_keep_segments =3D 500 hot_standby =3D o= ff ---iotop snapshot:Total DISK READ: 41.63 M/s | Total DISK WRITE: = 31.43 M/s TID PRIO USER DISK READ DISK WRITE SWAPIN IO> COM= MAND32101 be/4 postgres 10.25 M/s 1085.86 K/s 0.00 % 96.80 % postgres: c= heckpointer process56661 be/4 postgres 6.84 M/s 591.61 K/s 0.00 % 90.9= 1 % postgres: dbauser db [local] COPY56751 be/4 postgres 6.97 M/s 838.7= 3 K/s 0.00 % 88.00 % postgres: dbauser db [local] COPY56744 be/4 postgres = 6.13 M/s 958.55 K/s 0.00 % 85.48 % postgres: dbauser db [local] COPY56= 621 be/4 postgres 6.77 M/s 1288.05 K/s 0.00 % 83.96 % postgres: dbauser= db [local] COPY32102 be/4 postgres 8.05 M/s 1340.47 K/s 0.00 % 82.47 %= postgres: writer process 1005 be/0 root 0.00 B/s 0.00 B/s 0.00 = % 5.81 % [txg_sync]32103 be/4 postgres 0.00 B/s 10.41 M/s 0.00 % 0.= 52 % postgres: wal writer process --- = --_b70c9808-e000-418b-a99d-ad0588422abd_ Content-Type: text/html; charset="iso-8859-1" Content-Transfer-Encoding: quoted-printable
Hi=2C

<= div>We have a so far (to us) unexplainable issue on our production systems = after we roughly doubled the amount of data we import daily. We should be o= k on pure theoretical hardware performance=2C but we are seeing some weird = IO counters when the actual throughput of the writes is very low. The use c= ase is as follows:
 =3B - typical DW - relatively constant pe= riodic data loads - i.e. heavy write
 =3B - we receive large = CSV files ~ 5-10Gb every 15 minutes spread out across 5-7 minutes
 =3B - Custom ETL scripts process and filter files within <=3B 30 se= conds down to about 5Gb CSV ready to load
 =3B - 2 loader que= ues load the files=2C picking off a file one-by-one
 =3B - ta= bles are partitioned daily=2C indexed on a primary key + timestamp =3B<= /div>
 =3B - system is HP blade=3B 128Gb RAM=2C 2x 8-core=2C 12x 10= k RPM RAID1+0 (database) on first controller=2C 2x 15k RAID1 (xlog) on a di= fferent controller
 =3B - DB size is ~2.5Tb=3B rotating load = of 30 days keeps the database stable
 =3B - filesystem: zfs w= ith lz4 compression
 =3B - raw throughput of the database dis= k is >=3B 700Mbytes/sec sequential and >=3B150Mbytes random for read an= d roughly half for write in various benchmarks
 =3B - CPU loa= d is minimal when copy loads are taking place (i.e. after ETL has finished)=

The issue is that the system is constantly checkp= ointing regardless of various kernel and postgres settings. Having read thr= ough most of the history of this list and most of the recommendations on va= rious blogs=2C we have been unable to find an answer why the checkpoints ar= e being written so slowly. Even when we disable all import processes or if = index is dropped=2C the checkpoint is still taking >=3B 1hour. Stats are = pointing to checkpoint sizes of roughly 7Gb which should take <=3B 1min e= ven with full random reads=3B so even when imports are fully disabled=2C wh= at is not making sense is why would the checkpointing be taking well over a= n hour?

One other thing that's noticed=2C but not = measured=2C i.e. mostly anecdotal is that for a period of <=3B1hr when po= stgres is restarted=2C the system performs mostly fine and checkpoints are = completing in <=3B5min=3B so it may be that after a while some (OS/postgr= es) buffers are filling up and causing this issue?

Full iostat/iotop=2C configuration=2C checkpoint stats=2C etc. are pasted = below for completeness. Highlights are:
checkpoint_segments=3D512
shared_buffers=3D16GB
checkpoint_timeout=3D15min
= checkpoint_completion_target=3D0.1=

Regards=2C
Steve

<= /div>
---
Checkpoint stats:

db=3D# select * from pg_stat_bgwriter=3B<= /div>

 =3B checkpoints_timed  =3B = 6
 =3Bcheckpo= ints_req  =3B3
 =3Bcheckpoint_sync_time  =3B 142
 =3Bbuffers_ch= eckpoint  =3B 4227065
 =3Bbuffers_clean  =3B4139841
 =3Bmaxwritten_clean  =3B 8261
 =3Bbuffers_backen= d  =3B9128583
 =3Bbuffers_backend_fsync  =3B0
 =3Bbuffers_alloc  =3B9311478
<= div> =3Bstats_reset  =3B 2= 015-03-17 11:14:21.5649

---
postgres log file = - checkpoint log entries:

201= 5-03-17 11:25:25 LOG:  =3Bcheckpoint complete: wrote 855754 buffers (40= .8%)=3B 0 transaction log file(s) added=2C 0 removed=2C 500 recycled=3B wri= te=3D2988.185 s=2C sync=3D0.044 s=2C total=3D2988.331 s=3B sync files=3D110= =2C longest=3D0.003 s=2C average=3D0.000 s
2015-03-17 11:25:25 LOG:  =3Bcheckpoint start= ing: xlog time
20= 15-03-17 11:59:54 LOG:  =3Bparameter "checkpoint_completion_target" cha= nged to "0.9"
201= 5-03-17 13:30:20 LOG:  =3Bcheckpoint complete: wrote 1012112 buffers (4= 8.3%)=3B 0 transaction log file(s) added=2C 0 removed=2C 512 recycled=3B wr= ite=3D7494.228 s=2C sync=3D0.021 s=2C total=3D7494.371 s=3B sync files=3D11= 9=2C longest=3D0.001 s=2C average=3D0.000 s
2015-03-17 13:30:20 LOG:  =3Bcheckpoint star= ting: xlog time
2= 015-03-17 14:21:53 LOG:  =3Bparameter "checkpoint_completion_target" ch= anged to "0.1"
20= 15-03-17 16:00:58 LOG:  =3Bcheckpoint complete: wrote 1411979 buffers (= 67.3%)=3B 0 transaction log file(s) added=2C 696 removed=2C 900 recycled=3B= write=3D9036.898 s=2C sync=3D0.020 s=2C total=3D9038.538 s=3B sync files= =3D109=2C longest=3D0.000 s=2C average=3D0.000 s
2015-03-17 16:00:58 LOG:  =3Bcheckpoint= starting: time
2= 015-03-17 16:28:40 LOG:  =3Bcheckpoint complete: wrote 345183 buffers (= 16.5%)=3B 0 transaction log file(s) added=2C 2001 removed=2C 0 recycled=3B = write=3D1660.333 s=2C sync=3D0.018 s=2C total=3D1661.816 s=3B sync files=3D= 93=2C longest=3D0.002 s=2C average=3D0.000 s
2015-03-17 17:28:40 LOG:  =3Bcheckpoint sta= rting: time
2015-= 03-17 18:54:47 LOG:  =3Bcheckpoint complete: wrote 602037 buffers (28.7= %)=3B 0 transaction log file(s) added=2C 0 removed=2C 500 recycled=3B write= =3D5166.540 s=2C sync=3D0.039 s=2C total=3D5166.657 s=3B sync files=3D122= =2C longest=3D0.003 s=2C average=3D0.000 s
2015-03-17 18:54:47 LOG:  =3Bcheckpoint start= ing: xlog time
---
iostat -x snapshot:<= /div>

avg-cpu:  =3B%user  =3B %nic= e %system %iowait  =3B%steal  =3B %idle
 =3B  =3B  =3B  =3B  =3B=  =3B0.50  =3B  =3B0.00  =3B  =3B2.35  =3B 15.09 &n= bsp=3B  =3B0.00  =3B 82.05

Device:  =3B  =3B  =3B  =3B rrqm/s  =3B wrqm/s &n= bsp=3B  =3B r/s  =3B  =3B w/s  =3B  =3BrkB/s  =3B &= nbsp=3BwkB/s avgrq-sz avgqu-sz  =3B await r_await w_await  =3Bsvctm=  =3B%util
sd= a  =3B  =3B  =3B  =3B  =3B  =3B  =3B 0.00  = =3B  =3B 0.00  =3B  =3B0.00  =3B  =3B5.00  =3B &nbs= p=3B 0.00  =3B2056.00  =3B 822.40  =3B  =3B 0.00  =3B &= nbsp=3B0.00  =3B  =3B0.00  =3B  =3B0.00  =3B 0.00  = =3B 0.00
sdb &nbs= p=3B  =3B  =3B  =3B  =3B  =3B  =3B 0.00  =3B &n= bsp=3B 0.00 1055.00  =3B549.00 41166.50 22840.00  =3B  =3B79.81=  =3B  =3B 5.28  =3B  =3B3.28  =3B  =3B4.94  = =3B  =3B0.10  =3B 0.62 100.00

---
vmst= at 60 output

=
# vmstat 60
procs -----------memo= ry---------- ---swap-- -----io---- -system-- ----cpu----
<= font face=3D"Courier New=2C sans-serif"> =3Br  =3Bb  =3B swpd &= nbsp=3B free  =3B buff  =3Bcache  =3B si  =3B so  =3B &= nbsp=3Bbi  =3B  =3Bbo  =3B in  =3B cs us sy id wa
 =3B5  =3B3 877508= 1251152  =3B74476 98853728  =3B  =3B0  =3B  =3B0  = =3B  =3B87  =3B1891  =3B  =3B0  =3B  =3B0  =3B1=  =3B5 92  =3B2
 =3B6  =3B5 877508 915044  =3B74940 99237840  =3B &n= bsp=3B0  =3B  =3B0 46588 41857 6993 41784  =3B8  =3B4 76 12=
 =3B2  = =3B4 877508 1676008  =3B75292 98577936  =3B  =3B0  =3B &nbs= p=3B0 46847 34540 4778 17175  =3B9  =3B3 75 13

---
sysctl settings for dirty pages

vm.dirty_background_bytes =3D 0
vm.dirty_background_ratio =3D 5
=
vm.dirty_bytes =3D 0
vm.dirty_expire_centisecs= =3D 3000
vm.dirt= y_ratio =3D 10
vm= .dirty_writeback_centisecs =3D 500

---
# free = -m
 =3B  = =3B  =3B  =3B  =3B  =3B  =3Btotal  =3B  =3B &nb= sp=3B used  =3B  =3B  =3B free  =3B  =3B shared  = =3B  =3Bbuffers  =3B  =3B cached
Mem:  =3B  =3B  =3B  =3B128905 =  =3B  =3B 126654  =3B  =3B  =3B 2250  =3B  =3B =  =3B  =3B  =3B0  =3B  =3B  =3B  =3B 70  =3B=  =3B  =3B95035
-/+ buffers/cache:  =3B  =3B  =3B31549  =3B  =3B=  =3B97355
Sw= ap:  =3B  =3B  =3B  =3B15255  =3B  =3B  =3B &nb= sp=3B856  =3B  =3B  =3B14399


= ---
postgres sett= ings: =3B
# cat postgresq= l.conf |grep check
checkpoint_timeout =3D 15min  =3B  =3B  =3B  =3B &= nbsp=3B  =3B  =3B# range 30s-1h
checkpoint_completion_target =3D 0.1  =3B  = =3B  =3B# checkpoint target duration=2C 0.0 - 1.0
checkpoint_warning =3D 10min  =3B =  =3B  =3B  =3B  =3B  =3B  =3B# 0 disables
log_checkpoints =3D on

# cat postgresql.conf |egrep -e = 'wal|arch|hot|lru|shared'
shared_buffers =3D 16384MB
bgwriter_lru_maxpages =3D 500
#bgwriter_lru_multiplier =3D 2.0  =3B &= nbsp=3B  =3B  =3B  =3B# 0-10.0 multipler on buffers scanned/rou= nd
wal_level =3D = 'archive'
archive= _mode =3D on
arch= ive_command =3D 'cd .'  =3B # we can also use exit 0=2C anything that
max_wal_senders = =3D 0
wal_keep_se= gments =3D 500  =3B =3B
hot_standby =3D off


---
iotop snapshot:
Total DISK READ: &n= bsp=3B  =3B  =3B41.63 M/s | Total DISK WRITE:  =3B  =3B &nb= sp=3B31.43 M/s
&n= bsp=3B TID  =3BPRIO  =3BUSER  =3B  =3B DISK READ  =3BDI= SK WRITE  =3BSWAPIN  =3B  =3B IO>=3B  =3B  =3BCOMMAND=
32101 be/4 postg= res  =3B 10.25 M/s 1085.86 K/s  =3B0.00 % 96.80 % postgres: checkpo= inter process
566= 61 be/4 postgres  =3B  =3B6.84 M/s  =3B591.61 K/s  =3B0.00 = % 90.91 % postgres: dbauser db [local] COPY
56751 be/4 postgres  =3B  =3B6.97 M/s &n= bsp=3B838.73 K/s  =3B0.00 % 88.00 % postgres: dbauser db [local] COPY
56744 be/4 postgre= s  =3B  =3B6.13 M/s  =3B958.55 K/s  =3B0.00 % 85.48 % postg= res: dbauser db [local] COPY
56621 be/4 postgres  =3B  =3B6.77 M/s 1288.05 K/s  = =3B0.00 % 83.96 % postgres: dbauser db [local] COPY
32102 be/4 postgres  =3B  =3B8.0= 5 M/s 1340.47 K/s  =3B0.00 % 82.47 % postgres: writer process
 =3B1005 be/0 root &nb= sp=3B  =3B  =3B  =3B0.00 B/s  =3B  =3B0.00 B/s  =3B= 0.00 %  =3B5.81 % [txg_sync]
32103 be/4 postgres  =3B  =3B0.00 B/s  =3B 10.4= 1 M/s  =3B0.00 %  =3B0.52 % postgres: wal writer process


---
= --_b70c9808-e000-418b-a99d-ad0588422abd_--