Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtp (Exim 4.80) (envelope-from ) id 1VXxGt-0000Da-LT for pgsql-performance@arkaria.postgresql.org; Sun, 20 Oct 2013 17:58:35 +0000 Received: from localhost ([127.0.0.1] helo=postgresql.org) by malur.postgresql.org with smtp (Exim 4.80) (envelope-from ) id 1VXxGs-0000XG-9i for pgsql-performance@arkaria.postgresql.org; Sun, 20 Oct 2013 17:58:34 +0000 Received: from magus.postgresql.org ([2a02:c0:301:0:ffff::29]) by malur.postgresql.org with esmtp (Exim 4.80) (envelope-from ) id 1VXxGq-0000X6-38 for pgsql-performance@postgresql.org; Sun, 20 Oct 2013 17:58:32 +0000 Received: from sam.nabble.com ([216.139.236.26]) by magus.postgresql.org with esmtp (Exim 4.80) (envelope-from ) id 1VXxGi-0003Y2-Vw for pgsql-performance@postgresql.org; Sun, 20 Oct 2013 17:58:30 +0000 Received: from [192.168.236.26] (helo=sam.nabble.com) by sam.nabble.com with esmtp (Exim 4.72) (envelope-from ) id 1VXxGf-0000jF-Ha for pgsql-performance@postgresql.org; Sun, 20 Oct 2013 10:58:21 -0700 Date: Sun, 20 Oct 2013 10:58:21 -0700 (PDT) From: sparikh To: pgsql-performance@postgresql.org Message-ID: <1382291901534-5775181.post@n5.nabble.com> In-Reply-To: <1381869626548-5774673.post@n5.nabble.com> References: <1381869626548-5774673.post@n5.nabble.com> Subject: Re: Hot Standby performance issue MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Transfer-Encoding: quoted-printable X-Pg-Spam-Score: -0.8 (/) 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 Thanks so much Tomas and Kevin for your valuable inputs. I am getting very good response from this forum and learning so many new stuffs. I will try all those options and will let you update . standby_performance_issue.rar =20=20 On further digging I found from the new relic report that as soon as I execute query IO spikes immediately (100%). But the same query on primary executes very fast. I am not sure if postgres has some utility like what oracle's tkprof or AWR where I can exactly pin point where exactly the query spends time. I will try Tomas' suggestions perf and strace. Below is the query. I also tried to attached rar file one more time, hopefully it gets through this time. SELECT xfer_id, transaction_type, evse_time, transmit_time, error_code, detail, reported_card_account_number as reported_card_account_number, event_id, event_code,evse_id, batch_id, port, charge_event_id as charge_event_id FROM (SELECT t.transaction_id::text AS xfer_id, t.transaction_type, e.event_time AS evse_time, t.create_date AS transmit_time, t.error_code::text, '' AS detail, COALESCE(e.reported_rfid,'N/A') AS reported_card_account_number, e.event_id::text, e.event_code::text, t.evse_id::text, t.batch_id, e.port, COALESCE(e.evse_charge_id,'N/A') AS charge_event_id=20 FROM evse_transaction t, evse_event e , evse_unit u=20 WHERE e.transaction_id =3D t.transaction_id AND t.evse_id =3D u.evse_id=20= =20 AND e.event_code IN ('1','2','3','4','5','6','7','8','9','10','11','12','13','14','15','16','17= ','18','19','20','21','22','23','24','25','26','27','28','29','30','31','32= ','33','34','35','36','37','38','39','40','41','42','43','44','45','46','47= ','48','49'))=20=20 AND u.evse_id =3D 1 AND t.create_date BETWEEN '2013-10-01'::date AND '2013-10-15'::date + INTERVAL '1 day' UNION SELECT t.transaction_id::text AS xfer_id, t.transaction_type, t.log_time AS evse_time, t.create_date AS transmit_time, t.error_code::text, '' AS detail, COALESCE(t.reported_card_account_number,'N/A') AS reported_card_account_number, '' AS event_id, '' AS event_code, t.evse_id::text,t.batch_id, '' AS port, 'N/A' AS charge_event_id=20 FROM evse_transaction t, evse_unit u=20 WHERE t.evse_id =3D u.evse_id AND t.api_error IS NULL=20 AND t.transaction_type NOT IN ('DCFCTransactionService','L2TransactionService','EVSEUploadTransactionServ= ice','EVSEUploadTransactionService','UploadTransactionService')=20=20 AND t.transaction_type IN ('DCFCDownloadConfigService','L2DownloadConfigService','EVSEDownloadConfigS= ervice','DownloadConfigService','ConfigDownloadService','DCFCUploadConfigSe= rvice','L2UploadConfigService','EVSEUploadConfigService','UploadConfigServi= ce','ConfigUploadService','L2GetAdPackageListService','AdPackageListService= ','L2GPSService','EVSEGPSService','GPSService','ReportErrorService','EVSEDo= wnloadRevisionService','DCFCCommandService','L2CommandService','CommandServ= ice','DCFCErrorService','L2ErrorService','EVSEReportErrorService','ErrorSer= vice','DCFCHeartbeatService','L2HeartbeatService','HeartbeatService','DCFCA= uthorizeService','L2AuthorizeService','AuthorizeService','DCFCGetAccessList= Service','L2GetAccessListService','GetAccessListService','DCFCSetAccessServ= ice','L2SetAccessService','SetAccessService','DCFCPackageDownloadService','= L2PackageDownloadService','PackageDownloadService','DCFCReportInventoryServ= ice','L2ReportInventoryService','ReportInventoryService','DCFCTargetVersion= Service','L2TargetVersionService','TargetVersionService','DCFCPackageListSe= rvice','L2PackageInfoService','PackageListService','DCFCPackageInfoService'= ,'L2PackageInfoService','PackageInfoService','DCFCRegisterService','L2Autho= rizeCodeService', 'AuthorizeCodeService')=20 AND u.evse_id =3D 1 AND t.create_date BETWEEN '2013-10-01'::date AND '2013-10-15'::date + INTERVAL '1 day'=20 UNION SELECT ef.fee_id::text AS xfer_id, 'FEE' as transaction_type, ef.event_time AS evse_time, ef.create_time AS transmit_time,=20 '' AS error_code, 'Fee Event' AS detail, COALESCE(ef.card_account_number, 'N/A') AS reported_card_account_number, '' AS event_id, '' AS event_code, ef.evse_id::text, '' AS batch_id,=20 ef.port::text AS port, COALESCE(ef.client_charge_id, 'N/A') AS charge_event_id=20 FROM evse_fee ef LEFT OUTER JOIN evse_unit eu ON eu.evse_id =3D ef.evse_id= =20 WHERE ef.evse_id =3D 1 AND ef.create_time BETWEEN '2013-10-01'::date AND '2013-10-15'::date + INTERVAL '1 day' ) x=20 ORDER BY transmit_time DESC LIMIT 500 =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D= =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D Query plan: Limit (cost=3D101950.33..101950.40 rows=3D30 width=3D368) (actual time=3D18.421..18.421 rows=3D0 loops=3D1) Output: ((t.transaction_id)::text), t.transaction_type, e.event_time, t.create_date, t.error_code, (''::text), (COALESCE(e.reported_rfid, 'N/A'::text)), ((e.event_id)::text), ((e.event_code)::text), ((t.evse_id)::text), t.batch_id, e.port, (COALESCE(e.evse_charge_id, 'N/A'::text)) Buffers: shared hit=3D5 read=3D7 -> Sort (cost=3D101950.33..101950.40 rows=3D30 width=3D368) (actual time=3D18.421..18.421 rows=3D0 loops=3D1) Output: ((t.transaction_id)::text), t.transaction_type, e.event_time, t.create_date, t.error_code, (''::text), (COALESCE(e.reported_rfid, 'N/A'::text)), ((e.event_id)::text), ((e.event_code)::text), ((t.evse_id)::text), t.batch_id, e.port, (COALESCE(e.evse_charge_id, 'N/A'::text)) Sort Key: t.create_date Sort Method: quicksort Memory: 25kB Buffers: shared hit=3D5 read=3D7 -> HashAggregate (cost=3D101948.99..101949.29 rows=3D30 width=3D9= 5) (actual time=3D4.414..4.414 rows=3D0 loops=3D1) Output: ((t.transaction_id)::text), t.transaction_type, e.event_time, t.create_date, t.error_code, (''::text), (COALESCE(e.reported_rfid, 'N/A'::text)), ((e.event_id)::text), ((e.event_code)::text), ((t.evse_id)::text), t.batch_id, e.port, (COALESCE(e.evse_charge_id, 'N/A'::text)) Buffers: shared hit=3D5 read=3D5 -> Append (cost=3D0.00..101948.01 rows=3D30 width=3D95) (ac= tual time=3D4.412..4.412 rows=3D0 loops=3D1) Buffers: shared hit=3D5 read=3D5 -> Nested Loop (cost=3D0.00..101163.24 rows=3D10 width=3D112) (actual time=3D4.397..4.397 rows=3D0 loops=3D1) Output: (t.transaction_id)::text, t.transaction_type, e.event_time, t.create_date, t.error_code, ''::text, COALESCE(e.reported_rfid, 'N/A'::text), (e.event_id)::text, (e.event_code)::text, (t.evse_id)::text, t.batch_id, e.port, COALESCE(e.evse_charge_id, 'N/A'::text) Buffers: shared read=3D4 -> Index Scan using evse_unit_pkey on public.evse_unit u (cost=3D0.00..8.72 rows=3D1 width=3D4) (actual time=3D4.395..4.395 rows=3D0 loops=3D1) Output: u.evse_id Index Cond: (u.evse_id =3D 123) Buffers: shared read=3D4 -> Nested Loop (cost=3D0.00..101154.22 rows=3D10 width=3D112) (never executed) Output: t.transaction_id, t.transaction_type, t.create_date, t.error_code, t.evse_id, t.batch_id, e.event_time, e.reported_rfid, e.event_id, e.event_code, e.port, e.evse_charge_id -> Index Scan using evse_transaction_evse_id_create_date_idx on public.evse_transaction t=20 (cost=3D0.00..380.04 rows=3D89 width=3D65) (never executed) Output: t.transaction_id, t.transaction_type, t.create_date, t.error_code, t.evse_id, t.batch_id Index Cond: ((t.evse_id =3D 123) AND (t.create_date >=3D '2013-10-07'::date) AND (t.create_date <=3D '2013-10-10 00:00:00'::timestamp without time zone)) -> Index Scan using evse_event_transaction_idx on public.evse_event e (cost=3D0.00..1131.07 rows=3D98 width=3D51) (never executed) Output: e.event_id, e.transaction_id, e.event_code, e.event_name, e.event_row, e.event_time, e.status, e.status_detail, e.plug_event_id, e.charge_event_id, e.power_id, e.flow_id, e.port, e.event_source, e.evse_id, e.reported_rfid, e.evse_charge_id Index Cond: (e.transaction_id =3D t.transaction_id) Filter: (e.event_code =3D ANY ('{1,2,3,4,5,6,7,8,9,10,11,12,13,14,15,16,17,18,19,20,21,22,23,24,25,26,27,= 28,29,30,31,32,33,34,35,36,37,38,39,40,41,42,43,44,45,46,47,48,49}'::intege= r[])) -> Nested Loop (cost=3D0.00..395.68 rows=3D18 width= =3D88) (actual time=3D0.011..0.011 rows=3D0 loops=3D1) Output: (t.transaction_id)::text, t.transaction_type, t.log_time, t.create_date, t.error_code, ''::text, COALESCE(t.reported_card_account_number, 'N/A'::text), ''::text, ''::text, (t.evse_id)::text, t.batch_id, ''::text, 'N/A'::text Buffers: shared hit=3D2 read=3D1 -> Index Scan using evse_unit_pkey on public.evse_unit u (cost=3D0.00..8.72 rows=3D1 width=3D4) (actual time=3D0.010..0.010 rows=3D0 loops=3D1) Output: u.evse_id Index Cond: (u.evse_id =3D 1234) Buffers: shared hit=3D2 read=3D1 -> Index Scan using evse_transaction_evse_id_create_date_idx on public.evse_transaction t=20 (cost=3D0.00..386.60 rows=3D18 width=3D88) (never executed) Output: t.transaction_id, t.transaction_type, t.log_time, t.create_date, t.error_code, t.reported_card_account_number, t.evse_id, t.batch_id Index Cond: ((t.evse_id =3D 1234) AND (t.create_date >=3D '2013-10-07'::date) AND (t.create_date <=3D '2013-10-10 00:00:00'::timestamp without time zone)) Filter: ((t.api_error IS NULL) AND (t.transaction_type <> ALL ('{DCFCTransactionService,L2TransactionService,EVSEUploadTransactionService= ,EVSEUploadTransactionService,UploadTransactionService}'::text[])) AND (t.transaction_type =3D ANY ('{DCFCDownloadConfigService,L2DownloadConfigService,EVSEDownloadConfigServ= ice,DownloadConfigService,ConfigDownloadService,DCFCUploadConfigService,L2U= ploadConfigService,EVSEUploadConfigService,UploadConfigService,ConfigUpload= Service,L2GetAdPackageListService,AdPackageListService,L2GPSService,EVSEGPS= Service,GPSService,ReportErrorService,EVSEDownloadRevisionService,DCFCComma= ndService,L2CommandService,CommandService,DCFCErrorService,L2ErrorService,E= VSEReportErrorService,ErrorService,DCFCHeartbeatService,L2HeartbeatService,= HeartbeatService,DCFCAuthorizeService,L2AuthorizeService,AuthorizeService,D= CFCGetAccessListService,L2GetAccessListService,GetAccessListService,DCFCSet= AccessService,L2SetAccessService,SetAccessService,DCFCPackageDownloadServic= e,L2PackageDownloadService,PackageDownloadService,DCFCReportInventoryServic= e,L2ReportInventoryService,ReportInventoryService,DCFCTargetVersionService,= L2TargetVersionService,TargetVersionService,DCFCPackageListService,L2Packag= eInfoService,PackageListService,DCFCPackageInfoService,L2PackageInfoService= ,PackageInfoService,DCFCRegisterService,L2AuthorizeCodeService,AuthorizeCod= eService}'::text[]))) -> Nested Loop (cost=3D0.00..388.80 rows=3D2 width=3D= 80) (actual time=3D0.002..0.002 rows=3D0 loops=3D1) Output: (t.transaction_id)::text, 'ERROR'::text, t.create_date, t.create_date, t.error_code, t.transaction_type, COALESCE(t.reported_card_account_number, 'N/A'::text), ''::text, ''::text, (t.evse_id)::text, t.batch_id, ''::text, 'N/A'::text Buffers: shared hit=3D3 -> Index Scan using evse_unit_pkey on public.evse_unit u (cost=3D0.00..8.72 rows=3D1 width=3D4) (actual time=3D0.002..0.002 rows=3D0 loops=3D1) Output: u.evse_id Index Cond: (u.evse_id =3D 1234) Buffers: shared hit=3D3 -> Index Scan using evse_transaction_evse_id_create_date_idx on public.evse_transaction t=20 (cost=3D0.00..380.04 rows=3D2 width=3D80) (never executed) Output: t.transaction_id, t.create_date, t.error_code, t.transaction_type, t.reported_card_account_number, t.evse_id, t.batch_id Index Cond: ((t.evse_id =3D 1234) AND (t.create_date >=3D '2013-10-07'::date) AND (t.create_date <=3D '2013-10-10 00:00:00'::timestamp without time zone)) Filter: (t.api_error IS NOT NULL) Total runtime: 18.611 ms -- View this message in context: http://postgresql.1045698.n5.nabble.com/Hot-S= tandby-performance-issue-tp5774673p5775181.html Sent from the PostgreSQL - performance mailing list archive at Nabble.com. --=20 Sent via pgsql-performance mailing list (pgsql-performance@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-performance