Re: BUG #14635: Query is executed slower on hot standby slave database then on master database

Hello,

I didn't found a way how to write a response for your message on Postgresql
support web site, I didn't find ant button like "Response" or "New comment"
or so. Can you please share this info, maybe there is present an
instruction?

Will write my response by mail.

Yes, it happens always.

There is an execution plan from master:
texting=# explain (analyze, verbose, buffers) SELECT "om".* FROM "Table" AS
"om" WHERE (om."UserID" = 11111) AND (NOT om."Deleted") AND (om."Status" =
0) ORDER BY "StampToSend" asc LIMIT 11;

QUERY PLAN

-------------------------------------------------------------------------------------------------------------------------------------------
-------------------------------------------------------------------------------------------------------------------------------------------
----------------------------------------------
Limit (cost=3819.29..3819.30 rows=6 width=207) (actual
time=139.847..139.847 rows=0 loops=1)
Output: "ID", "MessageTypeID", "ServerID", "UserID", "RecipientsCount",
"Credits", "Subject", "Message", "StampToSend", "StampProcessed"
, "SendToNewRecipients", "StampNewRecipientsChecked",
"InsufficientCreditsEmailSent", "Deleted", "Status", "CreatedAt",
"UpdatedAt", "Code"
, "Source", "MultiplePartsNumber"
Buffers: shared hit=70256
-> Sort (cost=3819.29..3819.30 rows=6 width=207) (actual
time=139.845..139.845 rows=0 loops=1)
Output: "ID", "MessageTypeID", "ServerID", "UserID",
"RecipientsCount", "Credits", "Subject", "Message", "StampToSend",
"StampProc
essed", "SendToNewRecipients", "StampNewRecipientsChecked",
"InsufficientCreditsEmailSent", "Deleted", "Status", "CreatedAt",
"UpdatedAt",
"Code", "Source", "MultiplePartsNumber"
Sort Key: om."StampToSend"
Sort Method: quicksort Memory: 25kB
Buffers: shared hit=70256
-> Bitmap Heap Scan on public."Table" om (cost=3795.14..3819.21
rows=6 width=207) (actual time=139.836..139.836 rows=
0 loops=1)
Output: "ID", "MessageTypeID", "ServerID", "UserID",
"RecipientsCount", "Credits", "Subject", "Message", "StampToSend", "Sta
mpProcessed", "SendToNewRecipients", "StampNewRecipientsChecked",
"InsufficientCreditsEmailSent", "Deleted", "Status", "CreatedAt", "Update
dAt", "Code", "Source", "MultiplePartsNumber"
Recheck Cond: ((om."UserID" = 11111) AND (om."Status" = 0))
Filter: (NOT om."Deleted")
Buffers: shared hit=70256
-> BitmapAnd (cost=3795.14..3795.14 rows=6 width=0)
(actual time=139.832..139.832 rows=0 loops=1)
Buffers: shared hit=70256
-> Bitmap Index Scan on "OutgoingMessages_UserID"
(cost=0.00..237.99 rows=6872 width=0) (actual time=0.032..0.032 ro
ws=12 loops=1)
Index Cond: (om."UserID" = 11111)
Buffers: shared hit=4
-> Bitmap Index Scan on
"OutgoingMessages_Status_StampToSend_Deleted" (cost=0.00..3556.90
rows=80249 width=0) (actua
l time=139.761..139.761 rows=9158 loops=1)
Index Cond: ((om."Status" = 0) AND (om."Deleted"
= false))
Buffers: shared hit=70252
Total runtime: 139.900 ms
(22 rows)

There is an execution plan from slave:
texting=# explain (analyze, verbose, buffers) SELECT "om".* FROM "Table" AS
"om" WHERE (om."UserID" = 11111) AND (NOT om."Deleted") AND (om."Status" =
0) ORDER BY "StampToSend" asc LIMIT 11;

QUERY PLAN

-------------------------------------------------------------------------------------------------------------------------------------------
-------------------------------------------------------------------------------------------------------------------------------------------
----------------------------------------------
Limit (cost=3819.29..3819.30 rows=6 width=207) (actual
time=1472.199..1472.199 rows=0 loops=1)
Output: "ID", "MessageTypeID", "ServerID", "UserID", "RecipientsCount",
"Credits", "Subject", "Message", "StampToSend", "StampProcessed"
, "SendToNewRecipients", "StampNewRecipientsChecked",
"InsufficientCreditsEmailSent", "Deleted", "Status", "CreatedAt",
"UpdatedAt", "Code"
, "Source", "MultiplePartsNumber"
Buffers: shared hit=70256
-> Sort (cost=3819.29..3819.30 rows=6 width=207) (actual
time=1472.197..1472.197 rows=0 loops=1)
Output: "ID", "MessageTypeID", "ServerID", "UserID",
"RecipientsCount", "Credits", "Subject", "Message", "StampToSend",
"StampProc
essed", "SendToNewRecipients", "StampNewRecipientsChecked",
"InsufficientCreditsEmailSent", "Deleted", "Status", "CreatedAt",
"UpdatedAt",
"Code", "Source", "MultiplePartsNumber"
Sort Key: om."StampToSend"
Sort Method: quicksort Memory: 25kB
Buffers: shared hit=70256
-> Bitmap Heap Scan on public."Table" om (cost=3795.14..3819.21
rows=6 width=207) (actual time=1472.191..1472.191 row
s=0 loops=1)
Output: "ID", "MessageTypeID", "ServerID", "UserID",
"RecipientsCount", "Credits", "Subject", "Message", "StampToSend", "Sta
mpProcessed", "SendToNewRecipients", "StampNewRecipientsChecked",
"InsufficientCreditsEmailSent", "Deleted", "Status", "CreatedAt", "Update
dAt", "Code", "Source", "MultiplePartsNumber"
Recheck Cond: ((om."UserID" = 11111) AND (om."Status" = 0))
Filter: (NOT om."Deleted")
Buffers: shared hit=70256
-> BitmapAnd (cost=3795.14..3795.14 rows=6 width=0)
(actual time=1472.186..1472.186 rows=0 loops=1)
Buffers: shared hit=70256
-> Bitmap Index Scan on "OutgoingMessages_UserID"
(cost=0.00..237.99 rows=6872 width=0) (actual time=0.025..0.025 ro
ws=12 loops=1)
Index Cond: (om."UserID" = 11111)
Buffers: shared hit=4
-> Bitmap Index Scan on
"OutgoingMessages_Status_StampToSend_Deleted" (cost=0.00..3556.90
rows=80249 width=0) (actua
l time=1470.853..1470.853 rows=8671249 loops=1)
Index Cond: ((om."Status" = 0) AND (om."Deleted"
= false))
Buffers: shared hit=70252
Total runtime: 1472.253 ms
(22 rows)

The difference is:
-> Bitmap Index Scan on "OutgoingMessages_Status_StampToSend_Deleted"
(cost=0.00..3556.90 rows=80249 width=0) (actual time=139.761..139.761
rows=9158 loops=1)

-> Bitmap Index Scan on "OutgoingMessages_Status_StampToSend_Deleted"
(cost=0.00..3556.90 rows=80249 width=0) (actual time=1470.853..1470.853
rows=8671249 loops=1)

On Tue, May 2, 2017 at 4:20 PM, Haribabu Kommi <kommi(dot)haribabu(at)gmail(dot)com>
wrote:

>
>
> On Fri, Apr 28, 2017 at 11:38 PM, <vgomenyuk(at)callfire(dot)com> wrote:
>
>> The following bug has been logged on the website:
>>
>> Bug reference: 14635
>> Logged by: Vitaliy Gomenyuk
>> Email address: vgomenyuk(at)callfire(dot)com
>> PostgreSQL version: 9.2.14
>> Operating system: CentOS 6
>> Description:
>>
>> Hello,
>>
>> We have two equal servers (CPU, RAM, HDD).
>> We are using Postgresql 9.2.14 currently.
>> Have setup master-slave streaming replication.
>>
>> Running next query at master and slave databases:
>> explain analyze SELECT "om".* FROM "Table" AS "om" WHERE (om."UserID" =
>> 11111) AND (NOT om."Deleted") AND (om."Status" = 0) ORDER BY "StampToSend"
>> asc LIMIT 11;
>> An execution plans are the same on master and slave databases.
>>
>> An execution time on master database: 138.116 ms
>> An execution time on hot standby slave database with working replication:
>> 1623.496 ms
>> An execution time on slave database with turned off replication (after
>> creating trigger file): 132.354 ms (equal to an execution time on master
>> database).
>>
>> Why there is so huge difference in execution time between Postgresql with
>> and without working streaming replication?
>> How to improve the situation: to make an execution time on Hot standby
>> slave
>> dtabase with working replication equeal to master database?
>>
>
> Is the issue happening always or only sometimes?
> can you please check explain plan output on both the machines with verbose
> and buffers options.
>
> explain (analyze, verbose, buffers) /*query*/
>
> The explain output may help in identifying the plan of the query where it
> is taking
> more time compared to master.
>
> Regards,
> Hari Babu
> Fujitsu Australia
>

--

Best regards,
*Vitaliy Gomenyuk* Senior DBA
vgomenyuk(at)callfire(dot)com | +380 67 220 5903
email <vgomenyuk(at)callfire(dot)com> | website <https://www.callfire.com/> |
Facebook <https://www.facebook.com/callfire> | Twitter
<https://www.twitter.com/callfire>