surprising behavior or nothing to see here?

From: Ben Chobot <bench(at)silentmedia(dot)com>
To: Postgresql General <pgsql-general(at)postgresql(dot)org>
Subject: surprising behavior or nothing to see here?
Date: 2012-10-03 18:13:30
Message-ID: 2C8C4B2D-7815-42AA-8079-6067B398DD17@silentmedia.com
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: 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, or this 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 usually just 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 going on, queries were now taking almost 2 seconds each, and the CPUs were pegged. Eventually, we noticed that if we rebuilt the index that was being used by that query, things would speed right back up again.... until autovacuum analyze kicked off, at which point things would immediately start taking 2 seconds again. Manually analyzing would not immediately cause things to get bad, but they would eventually revert back to being too slow. To be clear, even with the 2s query times, the proper index was still being used - it was just taking hundreds of ms, instead of a few ms. We tried increasing column stats to try to tease out any change in value distribution but this had no effect. So this was our first mystery.

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, would go back to being dead tuples. Vacuum verbose showed that these tuples were not yet removable, even though there was no 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's mystery #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_feedback turned on, but we wouldn't have expected any symptoms from that which would have reduced the effectiveness of 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 vacuuming out dead tuples on the master? If not, what else might keep vacuum from removing dead rows? All I could find on teh 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 not have the same affect? And I'm not talking about changing things so the planner doesn't use the index, but rather, having the index actually take longer.

Responses

Browse pgsql-general by date

  From Date Subject
Next Message Igor Neyman 2012-10-03 18:19:22 Re: Postgres will not start due to corrupt index
Previous Message dinesh kumar 2012-10-03 18:13:17 Re: Again, problem with pgbouncer