surprising behavior or nothing to see here? - Mailing list pgsql-general

From Ben Chobot
Subject surprising behavior or nothing to see here?
Date
Msg-id 2C8C4B2D-7815-42AA-8079-6067B398DD17@silentmedia.com
Whole thread Raw
Responses Re: surprising behavior or nothing to see here?  (Tom Lane <tgl@sss.pgh.pa.us>)
List pgsql-general
Today we saw a couple behaviors in postgres we weren't expecting, and I'm not sure if there's something odd going on,
orthis is all business as usual and we never noticed before. 

In steady-state, we have a 32-core box with a fair amount of ram acting as a job queue. It's constantly busy inserting,
updating,and deleting a table that rarely has more than 100k rows. All access is done via indices, and query times are
usuallyjust a few ms. So that's all good. This server version is: 

PostgreSQL 9.1.5 on x86_64-unknown-linux-gnu, compiled by gcc (Ubuntu/Linaro 4.6.3-1ubuntu5) 4.6.3, 64-bit

This morning, one of the two servers that this streams wal files to for hot standby got locked up xlog replay pause
mode.Nobody noticed this for several hours. The other server kept replicating just fine. 

Within an hour, we had a query idle in transaction that was blocking other queries. This happens with our application
sometimes,so we killed it and all the locks cleared out immediately. We didn't think much of it at the time. 

However, soon after that, all other queries started taking longer. Even though there wasn't apparently any locking
goingon, queries were now taking almost 2 seconds each, and the CPUs were pegged. Eventually, we noticed that if we
rebuiltthe index that was being used by that query, things would speed right back up again.... until autovacuum analyze
kickedoff, at which point things would immediately start taking 2 seconds again. Manually analyzing would not
immediatelycause things to get bad, but they would eventually revert back to being too slow. To be clear, even with the
2squery times, the proper index was still being used - it was just taking hundreds of ms, instead of a few ms. We tried
increasingcolumn stats to try to tease out any change in value distribution but this had no effect. So this was our
firstmystery. 

Then we noticed that autovacuum wasn't clearing out tuples. Even odder, it appeared that when autovacuum started
running,all the dead tuples would be listed as live tuples in pg_stat_user_tables, and after the vacuum completed,
wouldgo back to being dead tuples. Vacuum verbose showed that these tuples were not yet removable, even though there
wasno long transaction running. That was the second and third mysteries. 

Finally, we found the wal replication problem and resume wal replay. All the problems listed above disappeared. So
that'smystery #4. 

My questions are:

1. Could wal replay on a hot streaming asynchronous slave really cause this? It certainly seems to have, and we do have
hot_standby_feedbackturned on, but we wouldn't have expected any symptoms from that which would have reduced the
effectivenessof an index on the master. 

2. Is it expected that during a vacuum, dead tuples show up as live tuples in pg_stat_user_tables?

3. Does a paused wal replay on an asynchronous slave count as a long running transaction, at least in terms of
vacuumingout dead tuples on the master? If not, what else might keep vacuum from removing dead rows? All I could find
onteh intarwebz was mention of long-running transactions, which pg_stat_activity and pg_locks didn't indicate. 

4. What might cause autovacuum analyze to make an index perform worse immediately, when a manual vacuum analyze does
nothave the same affect? And I'm not talking about changing things so the planner doesn't use the index, but rather,
havingthe index actually take longer.  

pgsql-general by date:

Previous
From: dinesh kumar
Date:
Subject: Re: Again, problem with pgbouncer
Next
From: Igor Neyman
Date:
Subject: Re: Postgres will not start due to corrupt index