Re: Hot Standby performance issue

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
<http://postgresql.1045698.n5.nabble.com/file/n5775181/standby_performance_issue.rar>

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
FROM evse_transaction t, evse_event e , evse_unit u
WHERE e.transaction_id = t.transaction_id AND t.evse_id = u.evse_id
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'))
AND u.evse_id = 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
FROM evse_transaction t, evse_unit u
WHERE t.evse_id = u.evse_id AND t.api_error IS NULL
AND t.transaction_type NOT IN
('DCFCTransactionService','L2TransactionService','EVSEUploadTransactionService','EVSEUploadTransactionService','UploadTransactionService')
AND t.transaction_type IN
('DCFCDownloadConfigService','L2DownloadConfigService','EVSEDownloadConfigService','DownloadConfigService','ConfigDownloadService','DCFCUploadConfigService','L2UploadConfigService','EVSEUploadConfigService','UploadConfigService','ConfigUploadService','L2GetAdPackageListService','AdPackageListService','L2GPSService','EVSEGPSService','GPSService','ReportErrorService','EVSEDownloadRevisionService','DCFCCommandService','L2CommandService','CommandService','DCFCErrorService','L2ErrorService','EVSEReportErrorService','ErrorService','DCFCHeartbeatService','L2HeartbeatService','HeartbeatService','DCFCAuthorizeService','L2AuthorizeService','AuthorizeService','DCFCGetAccessListService','L2GetAccessListService','GetAccessListService','DCFCSetAccessService','L2SetAccessService','SetAccessService','DCFCPackageDownloadService','L2PackageDownloadService','PackageDownloadService','DCFCReportInventoryService','L2ReportInventoryService','ReportInventoryService','DCFCTargetVersionService','L2TargetVersionService','TargetVersionService','DCFCPackageListService','L2PackageInfoService','PackageListService','DCFCPackageInfoService','L2PackageInfoService','PackageInfoService','DCFCRegisterService','L2AuthorizeCodeService',
'AuthorizeCodeService')
AND u.evse_id = 1 AND t.create_date BETWEEN '2013-10-01'::date AND
'2013-10-15'::date + INTERVAL '1 day'
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,
'' 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,
ef.port::text AS port, COALESCE(ef.client_charge_id, 'N/A') AS
charge_event_id
FROM evse_fee ef LEFT OUTER JOIN evse_unit eu ON eu.evse_id = ef.evse_id
WHERE ef.evse_id = 1 AND ef.create_time BETWEEN '2013-10-01'::date AND
'2013-10-15'::date + INTERVAL '1 day'
) x
ORDER BY transmit_time DESC LIMIT 500

==========================================

Query plan:

Limit (cost=101950.33..101950.40 rows=30 width=368) (actual
time=18.421..18.421 rows=0 loops=1)
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=5 read=7
-> Sort (cost=101950.33..101950.40 rows=30 width=368) (actual
time=18.421..18.421 rows=0 loops=1)
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=5 read=7
-> HashAggregate (cost=101948.99..101949.29 rows=30 width=95)
(actual time=4.414..4.414 rows=0 loops=1)
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=5 read=5
-> Append (cost=0.00..101948.01 rows=30 width=95) (actual
time=4.412..4.412 rows=0 loops=1)
Buffers: shared hit=5 read=5
-> Nested Loop (cost=0.00..101163.24 rows=10
width=112) (actual time=4.397..4.397 rows=0 loops=1)
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=4
-> Index Scan using evse_unit_pkey on
public.evse_unit u (cost=0.00..8.72 rows=1 width=4) (actual
time=4.395..4.395 rows=0 loops=1)
Output: u.evse_id
Index Cond: (u.evse_id = 123)
Buffers: shared read=4
-> Nested Loop (cost=0.00..101154.22 rows=10
width=112) (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
(cost=0.00..380.04 rows=89 width=65) (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 = 123) AND
(t.create_date >= '2013-10-07'::date) AND (t.create_date <= '2013-10-10
00:00:00'::timestamp without time zone))
-> Index Scan using
evse_event_transaction_idx on public.evse_event e (cost=0.00..1131.07
rows=98 width=51) (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 =
t.transaction_id)
Filter: (e.event_code = 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}'::integer[]))
-> Nested Loop (cost=0.00..395.68 rows=18 width=88)
(actual time=0.011..0.011 rows=0 loops=1)
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=2 read=1
-> Index Scan using evse_unit_pkey on
public.evse_unit u (cost=0.00..8.72 rows=1 width=4) (actual
time=0.010..0.010 rows=0 loops=1)
Output: u.evse_id
Index Cond: (u.evse_id = 1234)
Buffers: shared hit=2 read=1
-> Index Scan using
evse_transaction_evse_id_create_date_idx on public.evse_transaction t
(cost=0.00..386.60 rows=18 width=88) (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 = 1234) AND
(t.create_date >= '2013-10-07'::date) AND (t.create_date <= '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 = ANY
('{DCFCDownloadConfigService,L2DownloadConfigService,EVSEDownloadConfigService,DownloadConfigService,ConfigDownloadService,DCFCUploadConfigService,L2UploadConfigService,EVSEUploadConfigService,UploadConfigService,ConfigUploadService,L2GetAdPackageListService,AdPackageListService,L2GPSService,EVSEGPSService,GPSService,ReportErrorService,EVSEDownloadRevisionService,DCFCCommandService,L2CommandService,CommandService,DCFCErrorService,L2ErrorService,EVSEReportErrorService,ErrorService,DCFCHeartbeatService,L2HeartbeatService,HeartbeatService,DCFCAuthorizeService,L2AuthorizeService,AuthorizeService,DCFCGetAccessListService,L2GetAccessListService,GetAccessListService,DCFCSetAccessService,L2SetAccessService,SetAccessService,DCFCPackageDownloadService,L2PackageDownloadService,PackageDownloadService,DCFCReportInventoryService,L2ReportInventoryService,ReportInventoryService,DCFCTargetVersionService,L2TargetVersionService,TargetVersionService,DCFCPackageListService,L2PackageInfoService,PackageListService,DCFCPackageInfoService,L2PackageInfoService,PackageInfoService,DCFCRegisterService,L2AuthorizeCodeService,AuthorizeCodeService}'::text[])))
-> Nested Loop (cost=0.00..388.80 rows=2 width=80)
(actual time=0.002..0.002 rows=0 loops=1)
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=3
-> Index Scan using evse_unit_pkey on
public.evse_unit u (cost=0.00..8.72 rows=1 width=4) (actual
time=0.002..0.002 rows=0 loops=1)
Output: u.evse_id
Index Cond: (u.evse_id = 1234)
Buffers: shared hit=3
-> Index Scan using
evse_transaction_evse_id_create_date_idx on public.evse_transaction t
(cost=0.00..380.04 rows=2 width=80) (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 = 1234) AND
(t.create_date >= '2013-10-07'::date) AND (t.create_date <= '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-Standby-performance-issue-tp5774673p5775181.html
Sent from the PostgreSQL - performance mailing list archive at Nabble.com.