Received: from maia.hub.org (maia-2.hub.org [200.46.204.251]) by mail.postgresql.org (Postfix) with ESMTP id 70F5DB5DBC5 for ; Tue, 12 Jul 2011 16:02:01 -0300 (ADT) Received: from mail.postgresql.org ([200.46.204.86]) by maia.hub.org (mx1.hub.org [200.46.204.251]) (amavisd-maia, port 10024) with ESMTP id 08300-07 for ; Tue, 12 Jul 2011 19:01:55 +0000 (UTC) X-Greylist: domain auto-whitelisted by SQLgrey-1.7.6 Received: from nm16.bullet.mail.sp2.yahoo.com (nm16.bullet.mail.sp2.yahoo.com [98.139.91.86]) by mail.postgresql.org (Postfix) with SMTP id BCA61B5DBC4 for ; Tue, 12 Jul 2011 16:01:54 -0300 (ADT) Received: from [98.139.91.64] by nm16.bullet.mail.sp2.yahoo.com with NNFMP; 12 Jul 2011 19:01:54 -0000 Received: from [98.136.185.28] by tm4.bullet.mail.sp2.yahoo.com with NNFMP; 12 Jul 2011 19:01:53 -0000 Received: from [127.0.0.1] by smtp109.mail.gq1.yahoo.com with NNFMP; 12 Jul 2011 19:01:53 -0000 DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=yahoo.com; s=s1024; t=1310497313; bh=BsjvmMM50Ae/eSs41dGeioUxNNocfmNlTiK7obauj5E=; h=X-Yahoo-Newman-Id:Received:X-Yahoo-SMTP:X-YMail-OSG:X-Yahoo-Newman-Property:Message-ID:Date:From:User-Agent:MIME-Version:To:CC:Subject:References:In-Reply-To:Content-Type:Content-Transfer-Encoding; b=zE0AaN6JeyWljbXuW9SvPb7Z7+WSBEpLnNzeii7y9OL7cmKGaR7UFTcNG7ntNtWjjtz5Yy+DSdmfWlQdeZRVc4mEdCJSj5V66njrbtAnM6cI6Rpy97Nur/EfFelWnu9gCvEaNWJTOPhPsHJlkRF2MbNMepX/ZLmUJGV7SiPaxKg= X-Yahoo-Newman-Id: 766855.95420.bm@smtp109.mail.gq1.yahoo.com Received: from [192.168.206.5] (lhofhansl@67.170.234.149 with plain) by smtp109.mail.gq1.yahoo.com with SMTP; 12 Jul 2011 12:01:53 -0700 PDT X-Yahoo-SMTP: YmezqLWswBDx0ai534H100MJuqGzDQ-- X-YMail-OSG: voOna3UVM1lTn30epIlsggZAK__s8vtFaq8e7maT_XgYHtF UbnlNQvdbn.FZkg2XSAuAHq6n_appqqMqrPuQDBTzF3mS1eeFAwDEMlPtmT8 U8cEyaq2xCNKIuXItHLnh.6jjGF1jtxhLSJHhMOq0OcuBWOyC9JXHaZeAith .zKauWrcOyKN4kPjZQQZnD2ix9ioLUXWTTy0nJZG8Qj7LlSgfihyaqaCP9Ck 3IOErBcqKNsIi20fxMs_nHN3G17_weuxbi4Er44GidNDeMLplr9Ot9WTuemt ts6pjfddu.kQnbsMcHAy3Rz.x361CbsDpfqrRm7DAEnIerTm7qLiCDFhI9JP uQcCKdB1lPd2Q9J6U5uY12VLW5_0AZitDoH0Dpfyx X-Yahoo-Newman-Property: ymail-3 Message-ID: <4E1C9A05.7060005@yahoo.com> Date: Tue, 12 Jul 2011 12:01:25 -0700 From: lars User-Agent: Mozilla/5.0 (X11; U; Linux x86_64; en-US; rv:1.9.2.18) Gecko/20110621 Fedora/3.1.11-1.fc14 Thunderbird/3.1.11 MIME-Version: 1.0 To: Ivan Voras CC: pgsql-performance@postgresql.org Subject: Re: UPDATEDs slowing SELECTs in a fully cached database References: <4E16479D.3050605@yahoo.com> <4E1A0CBC.6090009@yahoo.com> <4E1A31AB.9010201@postnewspapers.com.au> <1310359653.80687.YahooMailRC@web121705.mail.ne1.yahoo.com> <4E1AEDAB020000250003F1C3@gw.wicourts.gov> <4E1B41EA.90104@yahoo.com> <4E1B05CC020000250003F1E6@gw.wicourts.gov> <4E1B810D.4070404@yahoo.com> <4E1B90AF.1020408@yahoo.com> In-Reply-To: Content-Type: text/plain; charset=UTF-8; format=flowed Content-Transfer-Encoding: 7bit X-Virus-Scanned: Maia Mailguard 1.0.1 X-Spam-Status: No, hits=-0.009 tagged_above=-10 required=5 tests=BAYES_20=-0.001, FREEMAIL_FROM=0.001, LOTS_OF_MONEY=0.001, RCVD_IN_DNSWL_NONE=-0.0001, T_RP_MATCHES_RCVD=-0.01 X-Spam-Level: X-Archive-Number: 201107/115 X-Sequence-Number: 44327 On 07/12/2011 08:13 AM, Ivan Voras wrote: > On 12/07/2011 02:09, lars wrote: > >> Oh, and iowait hovers around 20% when SELECTs are slow: >> >> avg-cpu: %user %nice %system %iowait %steal %idle >> 1.54 0.00 0.98 18.49 0.07 78.92 >> >> When SELECTs are fast it looks like this: >> avg-cpu: %user %nice %system %iowait %steal %idle >> 8.72 0.00 0.26 0.00 0.00 91.01 >> >> Note that this is a 12 core VM. So one core at 100% would show as 8.33% >> CPU. > > Now only if you could do an "iostat -x" and show the output in both > cases... > > Sure (sorry for missing details): iostat -x during selects when all's fine: avg-cpu: %user %nice %system %iowait %steal %idle 8.25 0.00 0.00 0.00 0.00 91.75 Device: rrqm/s wrqm/s r/s w/s rsec/s wsec/s avgrq-sz avgqu-sz await svctm %util xvdap1 0.00 1.00 0.00 2.00 0.00 24.00 12.00 0.00 0.00 0.00 0.00 xvdf 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 xvdg 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 xvdap1 is OS volumn. xvdf holds the database files xvdg holds the WAL No IO on database/WAL volumes, one core is pegged close to 100% CPU. ------------------------------------ iostat -x during update: avg-cpu: %user %nice %system %iowait %steal %idle 1.05 0.00 0.58 4.00 0.00 94.37 Device: rrqm/s wrqm/s r/s w/s rsec/s wsec/s avgrq-sz avgqu-sz await svctm %util xvdap1 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 xvdf 0.00 0.00 7.00 0.00 128.00 0.00 18.29 0.00 0.00 0.00 0.00 xvdg 0.00 7352.00 0.00 804.00 0.00 62368.00 77.57 66.07 68.83 0.86 69.20 Just updating the WAL. ----------------------------------- and while it's checkpointing: avg-cpu: %user %nice %system %iowait %steal %idle 0.64 0.00 0.32 8.88 0.00 90.16 Device: rrqm/s wrqm/s r/s w/s rsec/s wsec/s avgrq-sz avgqu-sz await svctm %util xvdap1 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 xvdf 0.00 2548.00 2.00 1658.00 32.00 33408.00 20.14 144.18 86.69 0.60 100.00 xvdg 0.00 5428.00 0.00 778.00 0.00 58480.00 75.17 77.44 100.22 1.21 94.00 Updating the WAL, and database volume due to checkpointing. ---------------------------------- iostat -x after I stopped the update process and checkpointing is done: avg-cpu: %user %nice %system %iowait %steal %idle 0.00 0.00 0.00 0.00 0.00 100.00 Device: rrqm/s wrqm/s r/s w/s rsec/s wsec/s avgrq-sz avgqu-sz await svctm %util xvdap1 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 xvdf 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 xvdg 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 No activity at all. --------------------------------- iostat -x after I started the select queries after the updates: avg-cpu: %user %nice %system %iowait %steal %idle 2.09 0.00 1.49 12.15 0.00 84.26 Device: rrqm/s wrqm/s r/s w/s rsec/s wsec/s avgrq-sz avgqu-sz await svctm %util xvdap1 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 xvdf 0.00 8.00 0.00 2.00 0.00 80.00 40.00 0.00 2.00 2.00 0.40 xvdg 0.00 7844.00 1.00 1098.00 8.00 82336.00 74.93 58.27 59.39 0.70 77.20 Heavy writes to the WAL volume. select * from pg_stat_activity; datid | datname | procpid | usesysid | usename | application_name | client_addr | client_hostname | client_port | backend_start | xact_start | qu ery_start | waiting | current_query -------+---------+---------+----------+----------+------------------+-------------+-----------------+-------------+-------------------------------+-------------------------------+------------ -------------------+---------+--------------------------------------------------------------- 16385 | lars | 2654 | 16384 | lars | | 127.0.0.1 | | 44972 | 2011-07-12 18:44:09.479581+00 | 2011-07-12 18:50:32.629412+00 | 2011-07-12 18:50:32.629473+00 | f | select count(*) from test where tenant = $1 and created_date = $2 16385 | lars | 2658 | 10 | postgres | psql | | | -1 | 2011-07-12 18:49:02.675436+00 | 2011-07-12 18:50:32.631013+00 | 2011-07-12 18:50:32.631013+00 | f | select * from pg_stat_activity; 16385 | lars | 2660 | 16384 | lars | psql | | | -1 | 2011-07-12 18:49:45.711643+00 | | | f | (3 rows)