Received: from maia.hub.org (maia-3.hub.org [200.46.204.243]) by mail.postgresql.org (Postfix) with ESMTP id B4F4B632F66 for ; Fri, 2 Jul 2010 16:08:44 -0300 (ADT) Received: from mail.postgresql.org ([200.46.204.86]) by maia.hub.org (mx1.hub.org [200.46.204.243]) (amavisd-maia, port 10024) with ESMTP id 19968-07 for ; Fri, 2 Jul 2010 19:08:32 +0000 (UTC) X-Greylist: from auto-whitelisted by SQLgrey-1.7.6 Received: from exchange.eldocomp.com (winex2.eldocomp.com [205.159.99.53]) by mail.postgresql.org (Postfix) with ESMTP id 04FD6632F04 for ; Fri, 2 Jul 2010 16:08:32 -0300 (ADT) Received: from WINEX1.eldocomp.com ([fe80::4020:f5e6:ce9:1af]) by winex2.eldocomp.com ([::1]) with mapi; Fri, 2 Jul 2010 12:08:00 -0700 From: Deborah Fuentes To: Rajesh Kumar Mallah CC: "pgsql-performance@postgresql.org" Subject: Re: Extremely high CPU usage when building tables Thread-Topic: [PERFORM] Extremely high CPU usage when building tables Thread-Index: AQHLGQLRGTrTZy2kS06hwn0kFlKdupKeAQNw Date: Fri, 2 Jul 2010 19:07:58 +0000 Message-ID: <306A7ABFF569E847BC99BA08C183EFF3013645@WINEX1.eldocomp.com> References: <306A7ABFF569E847BC99BA08C183EFF3ED95@WINEX1.eldocomp.com> In-Reply-To: Accept-Language: en-US Content-Language: en-US X-MS-Has-Attach: X-MS-TNEF-Correlator: Content-Type: multipart/alternative; boundary="_000_306A7ABFF569E847BC99BA08C183EFF3013645WINEX1eldocompcom_" MIME-Version: 1.0 X-Virus-Scanned: Maia Mailguard 1.0.1 X-Spam-Status: No, hits=0.791 tagged_above=-10 required=5 tests=BAYES_50=0.8, HTML_MESSAGE=0.001, T_RP_MATCHES_RCVD=-0.01 X-Spam-Level: X-Archive-Number: 201007/46 X-Sequence-Number: 39435 --_000_306A7ABFF569E847BC99BA08C183EFF3013645WINEX1eldocompcom_ Content-Type: text/plain; charset="us-ascii" Content-Transfer-Encoding: quoted-printable We did see a small spike in disk I/O, but only had wait I/O for less than 1= 0 seconds total. The low CPU idle event goes on for several minutes, wait I= /O or heavier I/O does not correlate to the extended period. System time does jump up at the same time as the user time. System times of= 15% when CPU us at 60% (25% idle) is around the average for this test. We = believe that jump is related to showing time spent getting processes on and= off CPU to execute. No general system wait I/O is observed during this tim= e. Five second samples of the Fiber disk SAN volumes. Wait I/O is listed in re= d. Note it's ten seconds or less. extended device statistics r/s w/s Mr/s Mw/s wait actv wsvc_t asvc_t %w %b device 1.0 296.9 0.0 136.5 0.0 62.3 0.0 209.0 0 168 c3 0.0 11.4 0.0 0.1 0.0 0.5 0.0 41.6 0 30 c3t60A98000572= D4275684A563761586D71d0 0.4 28.0 0.0 0.9 0.0 3.0 0.0 104.4 0 41 c3t60A98000572= D4275684A5638364D644Ed0 0.6 257.5 0.0 135.6 0.0 58.8 0.0 227.9 0 98 c3t60A98000572= D4275684A56385468434Fd0 extended device statistics r/s w/s Mr/s Mw/s wait actv wsvc_t asvc_t %w %b device 13.8 721.2 0.1 133.9 0.0 75.0 0.0 102.0 0 200 c3 0.0 88.8 0.0 6.0 0.0 19.0 0.0 213.7 0 65 c3t60A98000572= D4275684A563761586D71d0 2.4 86.6 0.0 1.2 0.0 1.6 0.0 18.0 0 39 c3t60A98000572= D4275684A5638364D644Ed0 11.4 545.8 0.1 126.7 0.0 54.4 0.0 97.7 0 97 c3t60A98000572= D4275684A56385468434Fd0 extended device statistics r/s w/s Mr/s Mw/s wait actv wsvc_t asvc_t %w %b device 3.6 769.0 0.0 123.2 29.4 182.9 38.1 236.7 5 220 c3 0.0 104.2 0.0 1.4 0.0 34.3 0.0 329.0 0 46 c3t60A98000572= D4275684A563761586D71d0 1.0 77.0 0.0 13.1 0.0 8.1 0.0 103.2 0 77 c3t60A98000572= D4275684A5638364D644Ed0 2.6 587.8 0.0 108.8 29.4 140.5 49.9 238.0 41 98 c3t60A9800057= 2D4275684A56385468434Fd0 extended device statistics r/s w/s Mr/s Mw/s wait actv wsvc_t asvc_t %w %b device 9.4 761.2 0.1 133.1 3.3 122.6 4.3 159.1 1 196 c3 0.0 33.8 0.0 0.3 0.0 2.1 0.0 63.5 0 30 c3t60A98000572= D4275684A563761586D71d0 7.4 94.8 0.1 1.8 0.0 16.2 0.0 158.6 0 66 c3t60A98000572= D4275684A5638364D644Ed0 2.0 632.6 0.0 131.0 3.3 104.3 5.2 164.3 10 99 c3t60A9800057= 2D4275684A56385468434Fd0 extended device statistics r/s w/s Mr/s Mw/s wait actv wsvc_t asvc_t %w %b device 2.8 588.2 0.0 126.0 0.0 112.6 0.0 190.5 0 239 c3 0.0 25.0 0.0 0.2 0.0 1.8 0.0 72.3 0 52 c3t60A98000572= D4275684A563761586D71d0 0.0 157.4 0.0 12.0 0.0 10.7 0.2 68.0 0 87 c3t60A98000572= D4275684A5638364D644Ed0 2.8 405.8 0.0 113.8 0.0 100.1 0.0 244.9 0 100 c3t60A9800057= 2D4275684A56385468434Fd0 Thanks! Deb From: Rajesh Kumar Mallah [mailto:mallah.rajesh@gmail.com] Sent: Thursday, July 01, 2010 2:50 AM To: Deborah Fuentes Cc: pgsql-performance@postgresql.org Subject: Re: [PERFORM] Extremely high CPU usage when building tables Hi, 1. Did you also check vmstat output , from sar output the i/o wait is not c= lear. 2. i gues you must be populating the database between creating tables and = creating indexes. creating indexes require sorting of data that may be cpu inte= nsive, loading/populating the data may saturate the i/o bandwidth . I think you should check whe= n the max cpu utilisation is taking place exactly. regds Rajesh Kumar Mallah. On Sat, Jun 26, 2010 at 3:55 AM, Deborah Fuentes > wrote: Hello, When I run an SQL to create new tables and indexes is when Postgres consume= s all CPU and impacts other users on the server. We are running Postgres 8.3.7 on a Sun M5000 with 2 x quad core CPUs (16 th= reads) running Solaris 10. I've attached the sar data at the time of the run- here's a snip-it below. Any ideas would be greatly appreciated. Thanks! Deb **************************************************** Here, note the run queue, the left column. That is the number of processes = waiting to run. 97 processes waiting to run at any time with only eight CPU= cores looks very busy. root@core2 # sar -q 5 500 SunOS core2 5.10 Generic_142900-11 sun4u 06/17/2010 12:01:50 runq-sz %runocc swpq-sz %swpocc 12:01:55 1.8 80 0.0 0 12:02:00 1.0 20 0.0 0 12:02:05 1.0 20 0.0 0 12:02:10 0.0 0 0.0 0 12:02:15 0.0 0 0.0 0 12:02:21 3.3 50 0.0 0 12:02:26 1.0 20 0.0 0 12:02:31 1.0 60 0.0 0 12:02:36 1.0 20 0.0 0 12:02:42 27.0 50 0.0 0 12:02:49 32.8 83 0.0 0 12:02:55 76.0 100 0.0 0 12:03:01 66.1 100 0.0 0 12:03:07 43.8 100 0.0 0 12:03:13 52.0 100 0.0 0 12:03:19 91.2 100 0.0 0 12:03:26 97.8 83 0.0 0 12:03:33 63.7 100 0.0 0 12:03:39 67.4 100 0.0 0 12:03:47 41.5 100 0.0 0 12:03:53 82.0 83 0.0 0 12:03:59 88.7 100 0.0 0 12:04:06 87.7 50 0.0 0 12:04:12 41.3 100 0.0 0 12:04:17 94.3 50 0.0 0 12:04:22 1.0 20 0.0 0 12:04:27 3.3 60 0.0 0 12:04:32 1.0 20 0.0 0 12:04:38 0.0 0 0.0 0 -- Sent via pgsql-performance mailing list (pgsql-performance@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-performance --_000_306A7ABFF569E847BC99BA08C183EFF3013645WINEX1eldocompcom_ Content-Type: text/html; charset="us-ascii" Content-Transfer-Encoding: quoted-printable

We did see a small spike= in disk I/O, but only had wait I/O for less than 10 seconds total. The low CPU idle event goes on for several minutes, wait I/O or heavier I/O does not correla= te to the extended period.

 =

System time does jump up= at the same time as the user time. System times of 15% when CPU us at 60% (25% idl= e) is around the average for this test. We believe that jump is related to sho= wing time spent getting processes on and off CPU to execute. No general system w= ait I/O is observed during this time.

 =

Five second samples of t= he Fiber disk SAN volumes. Wait I/O is listed in red. Note it’s ten seconds or= less.

 =

&nb= sp;            =        extended device statistics           = ;  

&nb= sp;   r/s    w/s   Mr/s   Mw/s wait actv wsvc_= t asvc_t  %w  %b device

&nb= sp;   1.0  296.9    0.0  136.5  0.0 62.3    0.0  209.0   0 168 c3

&nb= sp;   0.0   11.4    0.0    0.1  0.0  0.5    0.0   41.6   0  30= c3t60A98000572D4275684A563761586D71d0

&nb= sp;   0.4   28.0    0.0    0.9  0.0  3.0    0.0  104.4   0  41 c3t60A98000572D4275684A5638364D644Ed0

&nb= sp;   0.6  257.5    0.0  135.6  0.0 58.8    0.0  227.9   0  98 c3t60A98000572D4275684A56385468434Fd0

&nb= sp;            =        extended device statistics           = ;  

&nb= sp;   r/s    w/s   Mr/s   Mw/s wait actv wsvc_= t asvc_t  %w  %b device

&nb= sp;  13.8  721.2    0.1  133.9  0.0 75.0    0.0  102.0   0 200 c3

&nb= sp;   0.0   88.8    0.0    6.0  0.0 19.0    0.0  213.7   0  65 c3t60A98000572D4275684A563761586D71d0

&nb= sp;   2.4   86.6    0.0    1.2  0.0  1.6    0.0   18.0   0  39 c3t60A98000572D4275684A5638364D644Ed0

&nb= sp;  11.4  545.8    0.1  126.7  0.0 54.4    0.0   97.7   0  97 c3t60A98000572D4275684A56385468434Fd0

&nb= sp;            =        extended device statistics        &= nbsp;    

&nb= sp;   r/s    w/s   Mr/s   Mw/s wait actv wsvc_= t asvc_t  %w  %b device

&nb= sp;   3.6  769.0    0.0  123.2 29.4 182.9   38.1  236.7   5 220 c3

&nb= sp;   0.0  104.2    0.0    1.4  0.0 34.3    0.0  329.0   0  46 c3t60A98000572D4275684A563761586D71d0

&nb= sp;   1.0   77.0    0.0   13.1  0.0  8.1    0.0  103.2   0  77 c3t60A98000572D4275684A5638364D644Ed0

&nb= sp;   2.6  587.8    0.0  108.8 29.4 140.5   49.9  238.0  41  98 c3t60A98000572D4275684A56385468434Fd0

&nb= sp;            =        extended device statistics           = ;  

&nb= sp;   r/s    w/s   Mr/s   Mw/s wait actv wsvc_= t asvc_t  %w  %b device

&nb= sp;   9.4  761.2    0.1  133.1  3.3 122.6    4.3  159.1   1 196 c3

&nb= sp;   0.0   33.8    0.0    0.3  0.0  2.1    0.0   63.5   0  30 c3t60A98000572D4275684A563761586D71d0

&nb= sp;   7.4   94.8    0.1    1.8  0.0 16.2    0.0  158.6   0  66 c3t60A98000572D4275684A5638364D644Ed0

&nb= sp;   2.0  632.6    0.0  131.0  3.3 104.3    5.2  164.3  10  99 c3t60A98000572D4275684A56385468434Fd0

&nb= sp;            =        extended device statistics           = ;  

&nb= sp;   r/s    w/s   Mr/s   Mw/s wait actv wsvc_= t asvc_t  %w  %b device

&nb= sp;   2.8  588.2    0.0  126.0  0.0 112.6    0.0  190.5   0 239 c3

&nb= sp;   0.0   25.0    0.0    0.2  0.0  1.8    0.0   72.3   0  52 c3t60A98000572D4275684A563761586D71d0

&nb= sp;   0.0  157.4    0.0   12.0  0.0 10.7    0.2   68.0   0  87 c3t60A98000572D4275684A5638364D644Ed0

&nb= sp;   2.8  405.8    0.0  113.8  0.0 100.1    0.0  244.9   0 100 c3t60A98000572D4275684A56385468434Fd0

 

 

Thanks!

Deb

 

From: Rajesh Kumar = Mallah [mailto:mallah.rajesh@gmail.com]
Sent: Thursday, July 01, 2010 2:50 AM
To: Deborah Fuentes
Cc: pgsql-performance@postgresql.org
Subject: Re: [PERFORM] Extremely high CPU usage when building tables=

 

Hi,

1. Did you also check vmstat output , from sar output the i/o wait is not clear.
2.  i gues you must be populating the database between creating tables= and creating
     indexes. creating indexes require sorting of data = that may be cpu intensive, loading/populating
     the data may saturate the i/o bandwidth . I think = you should check when the max cpu utilisation
     is taking place exactly.

regds
Rajesh Kumar Mallah.

On Sat, Jun 26, 2010 at 3:55 AM, Deborah Fuentes <<= a href=3D"mailto:dfuentes@eldocomp.com">dfuentes@eldocomp.com> wrote:<= o:p>

Hello,

When I run an SQL to create new tables and indexes is when Postgres consume= s all CPU and impacts other users on the server.

We are running Postgres 8.3.7 on a Sun M5000 with 2 x quad core CPUs (16 threads) running Solaris 10.

I've attached the sar data at the time of the run- here's a snip-it below.<= br>
Any ideas would be greatly appreciated.

Thanks!
Deb

****************************************************

Here, note the run queue, the left column. That is the number of processes waiting to run. 97 processes waiting to run at any time with only eight CPU cores looks very busy.

root@core2 # sar -q 5 500

SunOS core2 5.10 Generic_142900-11 sun4u    06/17/2010

12:01:50 runq-sz %runocc swpq-sz %swpocc
12:01:55     1.8      80     0.0       0
12:02:00     1.0      20     0.0       0
12:02:05     1.0      20     0.0       0
12:02:10     0.0       0     0.0       0
12:02:15     0.0       0     0.0       0
12:02:21     3.3      50     0.0       0
12:02:26     1.0      20     0.0       0
12:02:31     1.0      60     0.0       0
12:02:36     1.0      20     0.0       0
12:02:42    27.0      50     0.0       0
12:02:49    32.8      83     0.0       0
12:02:55    76.0     100     0.0    = ;   0
12:03:01    66.1     100     0.0    = ;   0
12:03:07    43.8     100     0.0    = ;   0
12:03:13    52.0     100     0.0    = ;   0
12:03:19    91.2     100     0.0    = ;   0
12:03:26    97.8      83     0.0       0
12:03:33    63.7     100     0.0    = ;   0
12:03:39    67.4     100     0.0    = ;   0
12:03:47    41.5     100     0.0    = ;   0
12:03:53    82.0      83     0.0       0
12:03:59    88.7     100     0.0    = ;   0
12:04:06    87.7      50     0.0       0
12:04:12    41.3     100     0.0    = ;   0
12:04:17    94.3      50     0.0       0
12:04:22     1.0      20     0.0       0
12:04:27     3.3      60     0.0       0
12:04:32     1.0      20     0.0       0
12:04:38     0.0       0     0.0       0


--
Sent via pgsql-performance mailing list (pgsql-performance@postgres= ql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-performance

 

--_000_306A7ABFF569E847BC99BA08C183EFF3013645WINEX1eldocompcom_--