Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtp (Exim 4.80) (envelope-from ) id 1YYC6T-00012m-LN for pgsql-performance@arkaria.postgresql.org; Wed, 18 Mar 2015 11:25:37 +0000 Received: from localhost ([127.0.0.1] helo=postgresql.org) by malur.postgresql.org with smtp (Exim 4.80) (envelope-from ) id 1YYC6T-0002bY-3X for pgsql-performance@arkaria.postgresql.org; Wed, 18 Mar 2015 11:25:37 +0000 Received: from magus.postgresql.org ([2a02:c0:301:0:ffff::29]) by malur.postgresql.org with esmtps (TLS1.2:DHE_RSA_AES_256_CBC_SHA256:256) (Exim 4.80) (envelope-from ) id 1YYC6R-0002ZJ-4a for pgsql-performance@postgresql.org; Wed, 18 Mar 2015 11:25:35 +0000 Received: from col004-omc4s15.hotmail.com ([65.55.34.217]) by magus.postgresql.org with esmtp (Exim 4.80) (envelope-from ) id 1YYC6M-0007ky-Sh for pgsql-performance@postgresql.org; Wed, 18 Mar 2015 11:25:34 +0000 Received: from COL129-W91 ([65.55.34.199]) by COL004-OMC4S15.hotmail.com over TLS secured channel with Microsoft SMTPSVC(7.5.7601.22751); Wed, 18 Mar 2015 04:25:28 -0700 X-TMN: [0KnmKMc9d+ERB8dVDiSJRJxS4446WwfH2DzPhU2Y01g=] X-Originating-Email: [steven.jones1201@outlook.com] Message-ID: Content-Type: multipart/alternative; boundary="_276bef44-9517-4ea1-902c-0e9b0b91add6_" From: Steven Jones To: "pgsql-performance@postgresql.org" Subject: Re: Very slow checkpoints Date: Wed, 18 Mar 2015 11:25:27 +0000 Importance: Normal In-Reply-To: References: MIME-Version: 1.0 X-OriginalArrivalTime: 18 Mar 2015 11:25:28.0079 (UTC) FILETIME=[3C5D51F0:01D0616E] X-Pg-Spam-Score: -1.7 (-) 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 --_276bef44-9517-4ea1-902c-0e9b0b91add6_ Content-Type: text/plain; charset="iso-8859-1" Content-Transfer-Encoding: quoted-printable Apologies about the formatting=3B resending again as plain-text.=0A= =0A= Regards=2C=0A= Steve=0A= =0A= =0A= From: steven.jones1201@outlook.com=0A= To: pgsql-performance@postgresql.org=0A= Subject: [PERFORM] Very slow checkpoints=0A= Date: Wed=2C 18 Mar 2015 11:21:08 +0000=0A= =0A= Hi=2C=0A= =0A= 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:=0A= =0A= - typical DW - relatively constant periodic data loads - i.e. heavy write= =0A= - we receive large CSV files ~ 5-10Gb every 15 minutes spread out across = 5-7 minutes=0A= - Custom ETL scripts process and filter files within < 30 seconds down to= about 5Gb CSV ready to load=0A= - 2 loader queues load the files=2C picking off a file one-by-one=0A= - tables are partitioned daily=2C indexed on a primary key + timestamp = =0A= - system is HP blade=3B 128Gb RAM=2C 2x 8-core=2C 12x 10k RPM RAID1+0 (da= tabase) on first controller=2C 2x 15k RAID1 (xlog) on a different controlle= r=0A= - DB size is ~2.5Tb=3B rotating load of 30 days keeps the database stable= =0A= - filesystem: zfs with lz4 compression=0A= - raw throughput of the database disk is> 700Mbytes/sec sequential and>15= 0Mbytes random for read and roughly half for write in various benchmarks=0A= - CPU load is minimal when copy loads are taking place (i.e. after ETL ha= s finished)=0A= =0A= 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 even= when imports are fully disabled=2C what is not making sense is why would t= he checkpointing be taking well over an hour?=0A= =0A= One other thing that's noticed=2C but not measured=2C i.e. mostly anecdotal= is that for a period of COMMAND=0A= 32101 be/4 postgres 10.25 M/s 1085.86 K/s 0.00 % 96.80 % postgres: check= pointer process=0A= 56661 be/4 postgres 6.84 M/s 591.61 K/s 0.00 % 90.91 % postgres: dbaus= er db [local] COPY=0A= 56751 be/4 postgres 6.97 M/s 838.73 K/s 0.00 % 88.00 % postgres: dbaus= er db [local] COPY=0A= 56744 be/4 postgres 6.13 M/s 958.55 K/s 0.00 % 85.48 % postgres: dbaus= er db [local] COPY=0A= 56621 be/4 postgres 6.77 M/s 1288.05 K/s 0.00 % 83.96 % postgres: dbaus= er db [local] COPY=0A= 32102 be/4 postgres 8.05 M/s 1340.47 K/s 0.00 % 82.47 % postgres: write= r process=0A= 1005 be/0 root 0.00 B/s 0.00 B/s 0.00 % 5.81 % [txg_sync]=0A= 32103 be/4 postgres 0.00 B/s 10.41 M/s 0.00 % 0.52 % postgres: wal w= riter process=0A= =0A= =0A= --- = --_276bef44-9517-4ea1-902c-0e9b0b91add6_ Content-Type: text/html; charset="iso-8859-1" Content-Transfer-Encoding: quoted-printable
Apologies about the formatting= =3B resending again as plain-text.=0A= =0A= Regards=2C=0A= Steve=0A= =0A= =0A= From: steven.jones1201@outlook.com=0A= To: pgsql-performance@postgresql.org=0A= Subject: [PERFORM] Very slow checkpoints=0A= Date: Wed=2C 18 Mar 2015 11:21:08 +0000=0A= =0A= Hi=2C=0A= =0A= 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:=0A= =0A= =A0 - typical DW - relatively constant periodic data loads - i.e. heavy wri= te=0A= =A0 - we receive large CSV files ~ 5-10Gb every 15 minutes spread out acros= s 5-7 minutes=0A= =A0 - Custom ETL scripts process and filter files within < 30 seconds down = to about 5Gb CSV ready to load=0A= =A0 - 2 loader queues load the files=2C picking off a file one-by-one=0A= =A0 - tables are partitioned daily=2C indexed on a primary key + timestamp= =A0=0A= =A0 - system is HP blade=3B 128Gb RAM=2C 2x 8-core=2C 12x 10k RPM RAID1+0 (= database) on first controller=2C 2x 15k RAID1 (xlog) on a different control= ler=0A= =A0 - DB size is ~2.5Tb=3B rotating load of 30 days keeps the database stab= le=0A= =A0 - filesystem: zfs with lz4 compression=0A= =A0 - raw throughput of the database disk is> 700Mbytes/sec sequential and>= 150Mbytes random for read and roughly half for write in various benchmarks= =0A= =A0 - CPU load is minimal when copy loads are taking place (i.e. after ETL = has finished)=0A= =0A= 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 even= when imports are fully disabled=2C what is not making sense is why would t= he checkpointing be taking well over an hour?=0A= =0A= 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?=0A= =0A= Full iostat/iotop=2C configuration=2C checkpoint stats=2C etc. are pasted b= elow for completeness. Highlights are:=0A= checkpoint_segments=3D512=0A= shared_buffers=3D16GB=0A= checkpoint_timeout=3D15min=0A= checkpoint_completion_target=3D0.1=0A= =0A= Regards=2C=0A= Steve=0A= =0A= ---=0A= Checkpoint stats:=0A= =0A= db=3D# select * from pg_stat_bgwriter=3B=0A= =0A= =A0 checkpoints_timed =A0 6=0A= =A0checkpoints_req =A03=0A= =A0checkpoint_write_time =A026346184=0A= =A0checkpoint_sync_time =A0 142=0A= =A0buffers_checkpoint =A0 4227065=0A= =A0buffers_clean =A04139841=0A= =A0maxwritten_clean =A0 8261=0A= =A0buffers_backend =A09128583=0A= =A0buffers_backend_fsync =A00=0A= =A0buffers_alloc =A09311478=0A= =A0stats_reset =A0 2015-03-17 11:14:21.5649=0A= =0A= ---=0A= postgres log file - checkpoint log entries:=0A= =0A= 2015-03-17 11:25:25 LOG: =A0checkpoint 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 s=0A= 2015-03-17 11:25:25 LOG: =A0checkpoint starting: xlog time=0A= 2015-03-17 11:59:54 LOG: =A0parameter "checkpoint_completion_target" change= d to "0.9"=0A= 2015-03-17 13:30:20 LOG: =A0checkpoint complete: wrote 1012112 buffers (48.= 3%)=3B 0 transaction log file(s) added=2C 0 removed=2C 512 recycled=3B writ= e=3D7494.228 s=2C sync=3D0.021 s=2C total=3D7494.371 s=3B sync files=3D119= =2C longest=3D0.001 s=2C average=3D0.000 s=0A= 2015-03-17 13:30:20 LOG: =A0checkpoint starting: xlog time=0A= 2015-03-17 14:21:53 LOG: =A0parameter "checkpoint_completion_target" change= d to "0.1"=0A= 2015-03-17 16:00:58 LOG: =A0checkpoint complete: wrote 1411979 buffers (67.= 3%)=3B 0 transaction log file(s) added=2C 696 removed=2C 900 recycled=3B wr= ite=3D9036.898 s=2C sync=3D0.020 s=2C total=3D9038.538 s=3B sync files=3D10= 9=2C longest=3D0.000 s=2C average=3D0.000 s=0A= 2015-03-17 16:00:58 LOG: =A0checkpoint starting: time=0A= 2015-03-17 16:28:40 LOG: =A0checkpoint complete: wrote 345183 buffers (16.5= %)=3B 0 transaction log file(s) added=2C 2001 removed=2C 0 recycled=3B writ= e=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 s=0A= 2015-03-17 17:28:40 LOG: =A0checkpoint starting: time=0A= 2015-03-17 18:54:47 LOG: =A0checkpoint 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=0A= 2015-03-17 18:54:47 LOG: =A0checkpoint starting: xlog time=0A= =0A= ---=0A= iostat -x snapshot:=0A= =0A= avg-cpu: =A0%user =A0 %nice %system %iowait =A0%steal =A0 %idle=0A= =A0 =A0 =A0 =A0 =A0 =A00.50 =A0 =A00.00 =A0 =A02.35 =A0 15.09 =A0 =A00.00 = =A0 82.05=0A= =0A= Device: =A0 =A0 =A0 =A0 rrqm/s =A0 wrqm/s =A0 =A0 r/s =A0 =A0 w/s =A0 =A0rk= B/s =A0 =A0wkB/s avgrq-sz avgqu-sz =A0 await r_await w_await =A0svctm =A0%u= til=0A= sda =A0 =A0 =A0 =A0 =A0 =A0 =A0 0.00 =A0 =A0 0.00 =A0 =A00.00 =A0 =A05.00 = =A0 =A0 0.00 =A02056.00 =A0 822.40 =A0 =A0 0.00 =A0 =A00.00 =A0 =A00.00 =A0= =A00.00 =A0 0.00 =A0 0.00=0A= sdb =A0 =A0 =A0 =A0 =A0 =A0 =A0 0.00 =A0 =A0 0.00 1055.00 =A0549.00 41166.5= 0 22840.00 =A0 =A079.81 =A0 =A0 5.28 =A0 =A03.28 =A0 =A04.94 =A0 =A00.10 = =A0 0.62 100.00=0A= =0A= ---=0A= vmstat 60 output=0A= =0A= # vmstat 60=0A= procs -----------memory---------- ---swap-- -----io---- -system-- ----cpu--= --=0A= =A0r =A0b =A0 swpd =A0 free =A0 buff =A0cache =A0 si =A0 so =A0 =A0bi =A0 = =A0bo =A0 in =A0 cs us sy id wa=0A= =A05 =A03 877508 1251152 =A074476 98853728 =A0 =A00 =A0 =A00 =A0 =A087 =A01= 891 =A0 =A00 =A0 =A00 =A01 =A05 92 =A02=0A= =A06 =A05 877508 915044 =A074940 99237840 =A0 =A00 =A0 =A00 46588 41857 699= 3 41784 =A08 =A04 76 12=0A= =A02 =A04 877508 1676008 =A075292 98577936 =A0 =A00 =A0 =A00 46847 34540 47= 78 17175 =A09 =A03 75 13=0A= =0A= ---=0A= sysctl settings for dirty pages=0A= =0A= vm.dirty_background_bytes =3D 0=0A= vm.dirty_background_ratio =3D 5=0A= vm.dirty_bytes =3D 0=0A= vm.dirty_expire_centisecs =3D 3000=0A= vm.dirty_ratio =3D 10=0A= vm.dirty_writeback_centisecs =3D 500=0A= =0A= ---=0A= # free -m=0A= =A0 =A0 =A0 =A0 =A0 =A0 =A0total =A0 =A0 =A0 used =A0 =A0 =A0 free =A0 =A0 = shared =A0 =A0buffers =A0 =A0 cached=0A= Mem: =A0 =A0 =A0 =A0128905 =A0 =A0 126654 =A0 =A0 =A0 2250 =A0 =A0 =A0 =A0 = =A00 =A0 =A0 =A0 =A0 70 =A0 =A0 =A095035=0A= -/+ buffers/cache: =A0 =A0 =A031549 =A0 =A0 =A097355=0A= Swap: =A0 =A0 =A0 =A015255 =A0 =A0 =A0 =A0856 =A0 =A0 =A014399=0A= =0A= =0A= ---=0A= postgres settings:=A0=0A= =0A= # cat postgresql.conf |grep check=0A= checkpoint_segments =3D 512 =A0 =A0 =A0 # in logfile segments=2C min 1=2C 1= 6MB each=0A= checkpoint_timeout =3D 15min =A0 =A0 =A0 =A0 =A0 =A0 =A0# range 30s-1h=0A= checkpoint_completion_target =3D 0.1 =A0 =A0 =A0# checkpoint target duratio= n=2C 0.0 - 1.0=0A= checkpoint_warning =3D 10min =A0 =A0 =A0 =A0 =A0 =A0 =A0# 0 disables=0A= log_checkpoints =3D on=0A= =0A= # cat postgresql.conf |egrep -e 'wal|arch|hot|lru|shared'=0A= shared_buffers =3D 16384MB=0A= bgwriter_lru_maxpages =3D 500=0A= #bgwriter_lru_multiplier =3D 2.0 =A0 =A0 =A0 =A0 =A0# 0-10.0 multipler on b= uffers scanned/round=0A= wal_level =3D 'archive'=0A= archive_mode =3D on=0A= archive_command =3D 'cd .' =A0 # we can also use exit 0=2C anything that=0A= max_wal_senders =3D 0=0A= wal_keep_segments =3D 500 =A0=A0=0A= hot_standby =3D off=0A= =0A= =0A= ---=0A= iotop snapshot:=0A= Total DISK READ: =A0 =A0 =A041.63 M/s | Total DISK WRITE: =A0 =A0 =A031.43 = M/s=0A= =A0 TID =A0PRIO =A0USER =A0 =A0 DISK READ =A0DISK WRITE =A0SWAPIN =A0 =A0 I= O> =A0 =A0COMMAND=0A= 32101 be/4 postgres =A0 10.25 M/s 1085.86 K/s =A00.00 % 96.80 % postgres: c= heckpointer process=0A= 56661 be/4 postgres =A0 =A06.84 M/s =A0591.61 K/s =A00.00 % 90.91 % postgre= s: dbauser db [local] COPY=0A= 56751 be/4 postgres =A0 =A06.97 M/s =A0838.73 K/s =A00.00 % 88.00 % postgre= s: dbauser db [local] COPY=0A= 56744 be/4 postgres =A0 =A06.13 M/s =A0958.55 K/s =A00.00 % 85.48 % postgre= s: dbauser db [local] COPY=0A= 56621 be/4 postgres =A0 =A06.77 M/s 1288.05 K/s =A00.00 % 83.96 % postgres:= dbauser db [local] COPY=0A= 32102 be/4 postgres =A0 =A08.05 M/s 1340.47 K/s =A00.00 % 82.47 % postgres:= writer process=0A= =A01005 be/0 root =A0 =A0 =A0 =A00.00 B/s =A0 =A00.00 B/s =A00.00 % =A05.81= % [txg_sync]=0A= 32103 be/4 postgres =A0 =A00.00 B/s =A0 10.41 M/s =A00.00 % =A00.52 % postg= res: wal writer process=0A= =0A= =0A= ---
= --_276bef44-9517-4ea1-902c-0e9b0b91add6_--