Thread: [BUGS] BUG #14635: Query is executed slower on hot standby slave databasethen on master database

The following bug has been logged on the website:

Bug reference:      14635
Logged by:          Vitaliy Gomenyuk
Email address:      vgomenyuk@callfire.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?

Vitaliy Gomenyuk <vgomenyuk@callfire.com> writes:
> [ same query slower on slave ]

Hmm, the discrepancy is evidently in the larger bitmap index scan:

> There is an execution plan from master:
>                      ->  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)
>                            Index Cond: ((om."Status" = 0) AND (om."Deleted" = false))
>                            Buffers: shared hit=70252

> There is an execution plan from slave:
>                      ->  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)
>                            Index Cond: ((om."Status" = 0) AND (om."Deleted" = false))
>                            Buffers: shared hit=70252

The contents of the indexes should be the same, so why is the slave
returning so many more rows?  It has to be because the index entries are
not marked as killed (known-dead-to-everybody), or not being treated as
killed, in the slave.  I vaguely recall that there's a difference in the
rules for index entry visibility on slaves, but it's not clear to me why
that should be.

On Thu, May  4, 2017 at 10:26:17AM +1000, Haribabu Kommi wrote:
>     The contents of the indexes should be the same, so why is the slave
>     returning so many more rows?  It has to be because the index entries are
>     not marked as killed (known-dead-to-everybody), or not being treated as
>     killed, in the slave.  I vaguely recall that there's a difference in the
>     rules for index entry visibility on slaves, but it's not clear to me why
>     that should be.
>
>
> The index cleanup by the full vacuum and vacuum one page are WAL logged,
> so when they gets replayed on the slave, both the indexes must be same.
>
> May be the WAL didn't replayed on the slave because of conflict transaction?
> Or Any other scenarios it may be different?

We don't WAL-log hint bits.  Could that affect queries running on the
standbys?

On Mon, May 15, 2017 at 10:44 PM, Haribabu Kommi
<kommi.haribabu@gmail.com> wrote:
>
>
> On Sat, May 13, 2017 at 3:30 AM, Bruce Momjian <bruce@momjian.us> wrote:
>>
>> On Thu, May  4, 2017 at 10:26:17AM +1000, Haribabu Kommi wrote:
>> >     The contents of the indexes should be the same, so why is the slave
>> >     returning so many more rows?  It has to be because the index entries
>> > are
>> >     not marked as killed (known-dead-to-everybody), or not being treated
>> > as
>> >     killed, in the slave.  I vaguely recall that there's a difference in
>> > the
>> >     rules for index entry visibility on slaves, but it's not clear to me
>> > why
>> >     that should be.
>> >
>> >
>> > The index cleanup by the full vacuum and vacuum one page are WAL logged,
>> > so when they gets replayed on the slave, both the indexes must be same.
>> >
>> > May be the WAL didn't replayed on the slave because of conflict
>> > transaction?
>> > Or Any other scenarios it may be different?
>>
>> We don't WAL-log hint bits.  Could that affect queries running on the
>> standbys?
>
>
> Yes, this may be a reason for extra number of records that are present in
> the
> index.
>
> Hi Vitaly,
>
> Hint bits are used to mark tuples as created and/or deleted by transactions
> that are known committed or aborted. The changes to the hint bits are not
> WAL logged. These are WAL logged when the data checksums are enabled
> or wal_log_hintbits GUC is set, but these two options are not available in
> PostgreSQL version 9.2
>
> Is it possible for you test the query when you execute the reindex of the
> index?
>
> or
>
> Try to add pgstattuple and pageinspect extensions and verify whether the
> index
> is same in both master and standby.
>
> If there exists more number of records in standby compared to master, this
> may
> be because of some cleanup that is happening in master and not done in the
> standby.
>

Because hint bit affects to only heap tuple I think that it's not
relevant. But because marking index entry as dead is not WAL-logged
it's possible that unnecessary index entries are marked as dead on
master server while these are not marked on standby server. This would
make index scan on standby server return entry much more than master
server.

Regards,

--
Masahiko Sawada
NIPPON TELEGRAPH AND TELEPHONE CORPORATION
NTT Open Source Software Center

2. I'm not sure that the problem is with not WAL-logged hint bits, because due to my next investigation:

  2.0. We have two equal servers for master and slave database (CPU, RAM, HDD).

  2.1. On master database I'm running a query, it executes in 138.116 ms

  2.2. On a hot-standby slave database with working replication process I'm running the same query, it executes in 1623.496 ms (much slower)

  2.3. Then on that hot-standby slave database I've created a trigger file, which stops a replication process immediately and right after that, I'm running the same query, it executes in 132.354 ms (fast like on master). 

  2.4. During the time when I'm creating a trigger file (less then 1 second), indexes in that table can't be changed. Even more, that slave hot-standby database was created from the full master copy just before I started test. So master and slave databases are equal. One difference is turned on replication process in a hot-standby mode. So only a replication process can cause this behaviour.

But why and how to improve the situation?

Hello, 

So we have two reasons of current problem:

1. Changes to hint bits are not WAL logged => can be fixed by upgrading PostgreSQL at least to 9.4 version and turning on parameter "wal_log_hints";

2. Slave DB does not use the index hint bits while it is in hot standby mode => how this can be fixed?

On Fri, May 26, 2017 at 9:42 PM, Vitaliy Gomenyuk <vgomenyuk@callfire.com> wrote:

Hello, 

So we have two reasons of current problem:

1. Changes to hint bits are not WAL logged => can be fixed by upgrading PostgreSQL at least to 9.4 version and turning on parameter "wal_log_hints";

2. Slave DB does not use the index hint bits while it is in hot standby mode => how this can be fixed?

The main reason for slave DB not use the index hint bits because of difference

in between xmin value of both master and standby, This is required for proper

MVCC behavior for the queries that are running on the standby.

Following is the comment from the code that explains more.

/*

* During recovery we ignore killed tuples and don't bother to kill them

* either. We do this because the xmin on the primary node could easily be

* later than the xmin on the standby node, so that what the primary

* thinks is killed is supposed to be visible on standby. So for correct

* MVCC for queries during recovery we must ignore these hints and check

* all tuples. Do *not* set ignore_killed_tuples to true when running in a

* transaction that was started during recovery. xactStartedInRecovery

* should not be altered by index AMs.

*/

Even if the hint bits are WAL logged, it doesn't solve the problem of multiple

rows selection in standby. I feel the only way to reduce the number of dead tuples

visibility in standby, do a frequent VACUUM or Increase the AUTOVACUUM

interval or changing the default values of AUTOVACUUM parameters of the

tables that are frequently updated/deleted as these operations generates dead

tuples.

 

Regards,

Hari Babu

Fujitsu Australia

On Fri, May 26, 2017 at 9:42 PM, Vitaliy Gomenyuk <vgomenyuk@callfire.com> wrote:

Hello, 

So we have two reasons of current problem:

1. Changes to hint bits are not WAL logged => can be fixed by upgrading PostgreSQL at least to 9.4 version and turning on parameter "wal_log_hints";

2. Slave DB does not use the index hint bits while it is in hot standby mode => how this can be fixed?

The main reason for slave DB not use the index hint bits because of difference

in between xmin value of both master and standby, This is required for proper

MVCC behavior for the queries that are running on the standby.

Following is the comment from the code that explains more.

/*

* During recovery we ignore killed tuples and don't bother to kill them

* either. We do this because the xmin on the primary node could easily be

* later than the xmin on the standby node, so that what the primary

* thinks is killed is supposed to be visible on standby. So for correct

* MVCC for queries during recovery we must ignore these hints and check

* all tuples. Do *not* set ignore_killed_tuples to true when running in a

* transaction that was started during recovery. xactStartedInRecovery

* should not be altered by index AMs.

*/