Re: 100% CPU Utilization when we run queries.

From: bakkiya <bakkiya(at)gmail(dot)com>
To: pgsql-performance(at)postgresql(dot)org
Subject: Re: 100% CPU Utilization when we run queries.
Date: 2011-06-16 04:35:00
Message-ID: 1308198900426-4493567.post@n5.nabble.com
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: pgsql-performance

Hi,
Sorry. I am posting the query details below.
Query:
SELECT DISTINCT events_rpt_v3.init_service_comp FROM public.events_rpt_v3
events_rpt_v3;
events_rpt_v3 is a view based on partition tables.
Number of rows in events_rpt_v3: 57878

vmstat o/p:
procs -----------memory---------- ---swap-- -----io---- -system--
-----cpu------
r b swpd free buff cache si so bi bo in cs us sy id
wa st
1 0 632108 377948 132928 1392996 1 1 10 33 2 2 1 0 99
0 0
1 0 632108 371476 132928 1399016 0 0 3072 36 834 788 49 1 50
0 0
1 0 632108 364408 132928 1405112 0 0 3072 0 795 707 49 1 50
0 0
1 0 632108 357596 132928 1411944 0 0 3584 0 797 712 50 1 50
0 0
1 0 632108 351148 132928 1418540 0 0 3072 0 827 768 49 1 50
0 0
1 0 632108 344700 132928 1425028 0 0 3072 0 811 725 66 1 34
0 0
1 0 632108 337688 132928 1431976 0 0 3584 16 829 802 49 1 50
0 0
1 0 632108 330860 132928 1438808 0 0 3072 0 804 755 50 1 50
0 0
1 0 632108 323916 132928 1446032 0 0 3584 0 810 738 49 1 50
0 0
1 0 632108 317344 132928 1452544 0 0 3072 0 806 736 50 1 50
0 0
1 0 632108 310648 132928 1459120 0 0 3584 0 793 703 49 1 50
0 0
1 0 632108 304464 132928 1465488 0 0 3072 0 811 745 49 2 50
0 0
1 0 632108 297396 132936 1472068 0 0 3072 12 808 715 49 1 50
0 0
1 0 632108 290468 132936 1478876 0 0 3584 0 797 714 50 1 50
0 0
1 0 632108 284764 132944 1484132 0 0 3072 47284 996 776 50 2 43
6 0
2 0 632108 278564 132944 1490484 0 0 3072 0 813 720 58 1 41
0 0
1 0 632108 272480 132944 1496684 0 0 3072 32 822 742 56 2 43
0 0
1 0 632108 265800 132944 1503420 0 0 3584 0 826 743 50 1 50
0 0
1 0 632108 259592 132944 1509836 0 0 3072 0 798 742 49 1 50
0 0
1 0 632108 252772 132944 1516204 0 0 3072 0 771 716 58 2 40
0 0
1 0 632108 245952 132944 1523052 0 0 3584 4 785 699 50 1 50
0 0
procs -----------memory---------- ---swap-- -----io---- -system--
-----cpu------
r b swpd free buff cache si so bi bo in cs us sy id
wa st
1 0 632108 239380 132944 1529576 0 0 3072 21796 832 649 49 2 49
0 0
1 0 632108 233072 132944 1535908 0 0 3072 0 773 718 50 0 50
0 0
1 0 632108 226128 132944 1542780 0 0 3584 0 834 769 49 1 49
0 0
2 0 632108 219556 132944 1549556 0 0 3072 0 817 757 57 1 43
0 0
1 0 632108 213248 132944 1555864 0 0 3072 0 798 710 57 2 40
0 0
1 0 632108 206480 132944 1562492 0 0 3584 0 841 836 50 1 49
0 0
1 0 632108 200000 132944 1569012 0 0 3072 0 842 809 50 1 50
0 0
1 0 632108 193684 132944 1575320 0 0 3072 0 841 749 49 1 50
0 0
1 0 632108 188104 132956 1580916 0 0 3584 25540 923 772 49 3 46
3 0

novell(at)wdhsen01:~> vmstat 1 30
procs -----------memory---------- ---swap-- -----io---- -system--
-----cpu------
r b swpd free buff cache si so bi bo in cs us sy id
wa st
1 0 632108 45496 132808 1721868 1 1 10 33 2 2 1 0 99
0 0
2 0 632108 39420 132808 1728308 0 0 3072 0 817 747 58 1 42
0 0
1 0 632108 33344 132808 1734528 0 0 3072 0 760 670 56 1 43
0 0
1 0 632108 82200 132280 1685904 0 0 3584 12 751 679 49 2 49
1 0
1 0 632108 76496 132280 1692268 0 0 3072 0 739 672 48 2 50
0 0
1 0 632108 70172 132280 1698524 0 0 3072 28 767 691 50 1 50
0 0
1 0 632108 63152 132280 1705572 0 0 3584 0 785 727 49 1 50
0 0
1 0 632108 57208 132280 1711568 0 0 3072 0 784 722 49 2 49
0 0
2 0 632108 50884 132280 1717956 0 0 3072 0 804 711 50 1 50
0 0
1 0 632108 43956 132280 1724708 0 0 3584 0 815 779 49 1 50
0 0
2 0 632108 37772 132280 1731088 0 0 3072 32 814 724 56 1 43
0 0
1 0 632108 30456 132280 1738260 0 0 3584 0 790 700 60 1 40
0 0
1 0 632108 80056 131640 1689212 0 0 3072 0 795 716 49 2 50
0 0
1 0 632108 73740 131640 1695520 0 0 3072 0 832 803 50 1 50
0 0
1 0 632108 68664 131648 1700552 0 0 3072 47356 975 713 49 2 43
6 0
1 0 632108 61968 131652 1707292 0 0 3584 28 817 763 49 2 50
0 0
1 0 632108 56016 131652 1713424 0 0 3072 156 795 707 49 2 50
0 0
1 0 632108 49692 131652 1719764 0 0 3072 0 814 755 49 1 50
0 0
1 0 632108 42864 131652 1726720 0 0 3584 0 794 691 49 1 50
0 0
2 0 632108 36912 131652 1732716 0 0 3072 0 794 732 58 1 41
0 0
1 0 632108 91224 130992 1678484 0 0 3584 0 822 730 57 2 42
0 0
procs -----------memory---------- ---swap-- -----io---- -system--
-----cpu------
r b swpd free buff cache si so bi bo in cs us sy id
wa st
1 0 632108 84900 130992 1685028 0 0 3072 22412 924 761 49 1 50
0 0
1 0 632108 78576 130992 1691260 0 0 3072 0 843 776 49 1 50
0 0
1 0 632108 71756 130992 1698284 0 0 3584 0 865 792 50 0 50
0 0
1 0 632108 65308 130992 1704828 0 0 3072 0 861 770 49 2 50
0 0
1 0 632108 58324 130992 1711600 0 0 3584 0 866 905 49 1 50
0 0
1 0 632108 51852 130992 1718008 0 0 3072 0 813 754 49 1 50
0 0
1 0 632108 45496 130992 1724524 0 0 3072 0 812 737 49 1 50
0 0
4 0 632108 38560 130992 1731312 0 0 3584 0 816 737 49 2 50
0 0
2 0 632108 33228 131004 1736472 0 0 3072 26356 904 727 61 3 34
3 0

For small tables, it is not using 100% of CPU, but the same query with limit
1 is also taking 100% of CPU.
Explain Analyze o/p is very big. I am pasting here:

Unique (cost=133906741.63..133916648.38 rows=200 width=516) (actual
time=486765.451..487236.949 rows=35 loops=1)
-> Sort (cost=133906741.63..133911695.00 rows=1981350 width=516) (actual
time=486765.450..487053.139 rows=1979735 loops=1)
Sort Key: events_rpt_v3.init_service_comp
Sort Method: external merge Disk: 46416kB
-> Subquery Scan events_rpt_v3 (cost=131752986.71..133238999.21
rows=1981350 width=516) (actual time=452529.136..472555.577 rows=1979735
loops=1)
-> Unique (cost=131752986.71..133219185.71 rows=1981350
width=73436) (actual time=452529.128..471365.258 rows=1979735 loops=1)
-> Sort (cost=131752986.71..131757940.09 rows=1981350
width=73436) (actual time=452529.126..460179.820 rows=1979735 loops=1)

Sort Key: public.events.evt_id, public.events.res,
public.events.sres, public.events.sev, public.events.evt_time,
public.events.evt_time, public.events.device_evt_time,
public.events.sentinel_process_time, public.events.begin_time,
public.events.end_time, public.events.repeat_cnt, public.events.dp_int,
public.events.sp_int, public.events.msg, public.events.evt,
public.events.et, public.events.cust_id, public.events.src_asset_id,
public.events.dest_asset_id, public.events.agent_id, public.events.prtcl_id,
public.events.arch_id, public.events.sip, (to_ip_char(public.events.sip)),
public.events.shn, public.events.sp, public.events.dip,
(to_ip_char(public.events.dip)), public.events.dhn, public.events.dp,
public.events.sun, public.events.dun, public.events.fn, public.events.ei,
public.events.init_usr_sys_id, public.events.init_usr_identity_guid,
public.events.trgt_usr_sys_id, public.events.trgt_usr_identity_guid,

Sort Method: external merge Disk: 1504224kB
-> Append (cost=0.00..7167670.80 rows=1981350
width=73436) (actual time=188.427..432870.506 rows=1979735 loops=1)
-> Result (cost=0.00..7117927.97
rows=1972965 width=73436) (actual time=188.427..431513.274 rows=1971352
loops=1)
-> Append (cost=0.00..212550.47
rows=1972965 width=73436) (actual time=4.445..19200.613 rows=1971352
loops=1)
-> Seq Scan on events
(cost=0.00..10.00 rows=1 width=73436) (actual time=0.000..0.000 rows=0
loops=1)
-> Seq Scan on events_p_max
events (cost=0.00..10.00 rows=1 width=73436) (actual time=0.000..0.000
rows=0 loops=1)
-> Seq Scan on
events_p_20110617110000 events (cost=0.00..10.00 rows=1 width=73436)
(actual time=0.000..0.000 rows=0 loops=1)
-> Result (cost=0.00..29929.33 rows=8385
width=73436) (actual time=11.691..928.277 rows=8383 loops=1)
-> Append (cost=0.00..581.83
rows=8385 width=73436) (actual time=11.194..94.103 rows=8383 loops=1)
-> Seq Scan on hist_events
(cost=0.00..10.00 rows=1 width=73436) (actual time=0.001..0.001 rows=0
loops=1)
-> Seq Scan on
hist_events_p_max hist_events (cost=0.00..10.00 rows=1 width=73436) (actual
time=0.000..0.000 rows=0 loops=1)

-> Seq Scan on
hist_events_p_20101105112519 hist_events (cost=0.00..212.18 rows=2918
width=62004) (actual time=11.192..31.355 rows=2918 loops=1)
-> Seq Scan on
hist_events_p_20101107112519 hist_events (cost=0.00..169.64 rows=2764
width=65510) (actual time=7.605..24.603 rows=2764 loops=1)
-> Seq Scan on
hist_events_p_20101104112519 hist_events (cost=0.00..180.01 rows=2701
width=61827) (actual time=19.064..37.047 rows=2701 loops=1)
Total runtime: 487423.797 ms

I have started vaccuum analyzing all the partitions, I will run the query
and post the results once it is done.

--
View this message in context: http://postgresql.1045698.n5.nabble.com/100-CPU-Utilization-when-we-run-queries-tp4465765p4493567.html
Sent from the PostgreSQL - performance mailing list archive at Nabble.com.

In response to

Responses

Browse pgsql-performance by date

  From Date Subject
Next Message Svetlin Manavski 2011-06-16 13:55:30 seq scan in the case of max() on the primary key column
Previous Message Svetlin Manavski 2011-06-15 08:55:07 Re: need to repeat the same condition on joined tables in order to choose the proper plan