Thread: Postgres Query Plan Live Lock
We have been running into a (live lock?) issue on our production Postgres instance causing queries referencing a particular table to become extremely slow and our application to lock up.
This tends to occur on a particular table that gets a lot of queries against it after a large number of deletes. When this happens, the following symptoms occur when queries referencing that table are run (even it we stop the deleting):
SELECT * FROM table_name LIMIT 10; -- takes ~45 seconds to complete
EXPLAIN SELECT * FROM table_name LIMIT 10; -- takes ~45 seconds to complete the explain query, the query plan looks reasonable
EXPLAIN SELECT * FROM table_name LIMIT 10; -- takes ~45 seconds to complete the explain analyze query, query plan looks reasonable, timing stats says query took sub millisecond time to complete
SELECT * FROM another_table LIMIT 10; -- takes sub millisecond time
EXPLAIN * FROM another_table LIMIT 10; -- takes sub millisecond time, query plan looks reasonable
This behavior only stops and the queries go back to taking sub millisecond time if we take the application issuing the SELECTs offline and wait for the active queries to finish (or terminate them).
There is not a particularly large load on the database machine at the time, neither are there a particularly large number of wal logs being written (although there is a burst of wal log writes immediately after the queue is cleared).
table_name stats:
~ 400,000,000 rows
We are deleting 10,000,000s of rows in 100,000 row increments over a few days time prior/during this slowdown.
Simultaneously a web app is querying this table continuously.
table_name has 4 btree indexes on it (one of which is set to CLUSTER) and one foreign key constraint.
The obvious workaround is to not delete so much data on the table on our production database, but we would like to figure out why Postgres is live locking this table. Do you have any ideas why this is happening and how to prevent it while still doing mass deletes on the table?
-------------------------------------------------------------------------
System information:
Postgres Version - PostgreSQL 9.2.3 on x86_64-unknown-linux-gnu, compiled by gcc (Ubuntu/Linaro 4.6.3-1ubuntu5) 4.6.3, 64-bit
OS - Ubuntu 12.04 LTS
Autovacuum is on.
--------------------------------------------------------------------------
SELECT name, current_setting(name), source
FROM pg_settings
WHERE source NOT IN ('default');
name | current_setting | source
------------------------------+------------------------------------------+----------------------
application_name | psql | client
archive_command | /bin/true | configuration file
archive_mode | on | configuration file
bytea_output | escape | configuration file
checkpoint_completion_target | 0.9 | configuration file
checkpoint_segments | 24 | configuration file
client_encoding | UTF8 | session
DateStyle | ISO, MDY | configuration file
default_text_search_config | pg_catalog.english | configuration file
effective_cache_size | 54GB | configuration file
effective_io_concurrency | 2 | configuration file
listen_addresses | * | configuration file
log_checkpoints | on | configuration file
log_connections | on | configuration file
log_disconnections | on | configuration file
log_hostname | on | configuration file
log_line_prefix | %t | configuration file
logging_collector | on | configuration file
maintenance_work_mem | 256MB | configuration file
max_connections | 600 | configuration file
max_stack_depth | 2MB | environment variable
max_wal_senders | 3 | configuration file
random_page_cost | 1.75 | configuration file
server_encoding | UTF8 | override
shared_buffers | 12GB | configuration file
synchronous_commit | off | configuration file
tcp_keepalives_idle | 180 | configuration file
track_activity_query_size | 8192 | configuration file
transaction_deferrable | off | override
transaction_isolation | read committed | override
transaction_read_only | off | override
vacuum_freeze_min_age | 20000000 | configuration file
vacuum_freeze_table_age | 800000000 | configuration file
wal_buffers | 16MB | override
wal_keep_segments | 16384 | configuration file
wal_level | hot_standby | configuration file
wal_writer_delay | 330ms | configuration file
work_mem | 512MB | configuration file
Thank You,
Pweaver (pweaver@panjiva.com)
On Mon, Feb 3, 2014 at 1:35 PM, Pweaver (Paul Weaver) <pweaver@panjiva.com> wrote: > We have been running into a (live lock?) issue on our production Postgres > instance causing queries referencing a particular table to become extremely > slow and our application to lock up. Livelock? Really? That would imply that the query would never finish. A livelock is morally equivalent to an undetected deadlock. > This tends to occur on a particular table that gets a lot of queries against > it after a large number of deletes. When this happens, the following > symptoms occur when queries referencing that table are run (even it we stop > the deleting): > > SELECT * FROM table_name LIMIT 10; -- takes ~45 seconds to complete > EXPLAIN SELECT * FROM table_name LIMIT 10; -- takes ~45 seconds to complete > the explain query, the query plan looks reasonable > EXPLAIN SELECT * FROM table_name LIMIT 10; -- takes ~45 seconds to complete > the explain analyze query, query plan looks reasonable, timing stats says > query took sub millisecond time to complete Why should explain analyze say that? You'd need to catch the problem as it is run. > SELECT * FROM another_table LIMIT 10; -- takes sub millisecond time > EXPLAIN * FROM another_table LIMIT 10; -- takes sub millisecond time, query > plan looks reasonable > > This behavior only stops and the queries go back to taking sub millisecond > time if we take the application issuing the SELECTs offline and wait for the > active queries to finish (or terminate them). > > There is not a particularly large load on the database machine at the time, > neither are there a particularly large number of wal logs being written > (although there is a burst of wal log writes immediately after the queue is > cleared). Are you aware of hint bits? https://wiki.postgresql.org/wiki/Hint_Bits -- Regards, Peter Geoghegan
On Monday, February 3, 2014, Pweaver (Paul Weaver) <pweaver@panjiva.com> wrote:
We have been running into a (live lock?) issue on our production Postgres instance causing queries referencing a particular table to become extremely slow and our application to lock up.This tends to occur on a particular table that gets a lot of queries against it after a large number of deletes. When this happens, the following symptoms occur when queries referencing that table are run (even it we stop the deleting):
What do you mean by "stop the deleting"? Are you pausing the delete but without either committing or rolling back the transaction, but just holding it open? Are you stopping it cleanly, between transactions?
Also, how many queries are happening concurrently? Perhaps you need a connection pooler.
Is the CPU time user time or system time? What kernel version do you have?
SELECT * FROM table_name LIMIT 10; -- takes ~45 seconds to completeEXPLAIN SELECT * FROM table_name LIMIT 10; -- takes ~45 seconds to complete the explain query, the query plan looks reasonable
This sounds like the problem we heard quite a bit about recently, where processes spend a lot of time fighting over the proclock while they try to check the commit status of open transactions while. But I don't see how deletes could trigger that behavior. If the delete has not committed, the tuples are still visible and the LIMIT 10 is quickly satisfied. If the delete has committed, the tuples quickly get hinted, and so the next query along should be faster.
I also don't see why the explain would be slow. A similar problem was tracked down to digging through in-doubt tuples while trying to use an index to find the true the min or max during estimating the cost of a merge join. But I don't think a simple table query should lead to that, unless table_name is a view. And I don't see how deletes, rather than uncommitted inserts, could trigger it either.
max_connections | 600 | configuration file
That is quite extreme. If a temporary load spike (like from the deletes and the hinting needed after them) slows down the select queries and you start more and more of them, soon you could tip the system over into kernel scheduler insanity with high system time. Once in this mode, it will stay there until the incoming stream of queries stops and the existing ones clear out. But, if that is what is occurring, I don't know why queries on other tables would still be fast.
Cheers,
Jeff
On Mon, Feb 3, 2014 at 1:35 PM, Pweaver (Paul Weaver) <pweaver@panjiva.com> wrote:
table_name stats:~ 400,000,000 rowsWe are deleting 10,000,000s of rows in 100,000 row increments over a few days time prior/during this slowdown.
If you issue "VACUUM" or "VACUUM ANALYZE" after each DELETE, do the SELECTs become more responsive?
On Tue, Feb 4, 2014 at 9:03 PM, Peter Geoghegan <peter.geoghegan86@gmail.com> wrote:
On Mon, Feb 3, 2014 at 1:35 PM, Pweaver (Paul Weaver)Livelock? Really? That would imply that the query would never finish.
<pweaver@panjiva.com> wrote:
> We have been running into a (live lock?) issue on our production Postgres
> instance causing queries referencing a particular table to become extremely
> slow and our application to lock up.
A livelock is morally equivalent to an undetected deadlock.
Livelock is bad term.
Why should explain analyze say that? You'd need to catch the problem
> This tends to occur on a particular table that gets a lot of queries against
> it after a large number of deletes. When this happens, the following
> symptoms occur when queries referencing that table are run (even it we stop
> the deleting):
>
> SELECT * FROM table_name LIMIT 10; -- takes ~45 seconds to complete
> EXPLAIN SELECT * FROM table_name LIMIT 10; -- takes ~45 seconds to complete
> the explain query, the query plan looks reasonable
> EXPLAIN SELECT * FROM table_name LIMIT 10; -- takes ~45 seconds to complete
> the explain analyze query, query plan looks reasonable, timing stats says
> query took sub millisecond time to complete
as it is run.Are you aware of hint bits?
> SELECT * FROM another_table LIMIT 10; -- takes sub millisecond time
> EXPLAIN * FROM another_table LIMIT 10; -- takes sub millisecond time, query
> plan looks reasonable
>
> This behavior only stops and the queries go back to taking sub millisecond
> time if we take the application issuing the SELECTs offline and wait for the
> active queries to finish (or terminate them).
>
> There is not a particularly large load on the database machine at the time,
> neither are there a particularly large number of wal logs being written
> (although there is a burst of wal log writes immediately after the queue is
> cleared).
https://wiki.postgresql.org/wiki/Hint_Bits
No, but why would this cause the EXPLAIN queries to be slow?
--
Regards,
Peter Geoghegan
Thank You,
Pweaver (pweaver@panjiva.com)
On Wed, Feb 5, 2014 at 9:52 AM, Jeff Janes <jeff.janes@gmail.com> wrote:
On Monday, February 3, 2014, Pweaver (Paul Weaver) <pweaver@panjiva.com> wrote:We have been running into a (live lock?) issue on our production Postgres instance causing queries referencing a particular table to become extremely slow and our application to lock up.This tends to occur on a particular table that gets a lot of queries against it after a large number of deletes. When this happens, the following symptoms occur when queries referencing that table are run (even it we stop the deleting):What do you mean by "stop the deleting"? Are you pausing the delete but without either committing or rolling back the transaction, but just holding it open? Are you stopping it cleanly, between transactions?
We are repeatedly running delete commands in their own transactions. We stop issuing new deletes and let them finish cleanly.
Also, how many queries are happening concurrently? Perhaps you need a connection pooler.
Usually between 1 and 20. When it gets locked up closer to 100-200.
We should add a connection pooler. Would the number of active queries on the table be causing the issue?
Is the CPU time user time or system time? What kernel version do you have?
Real time - 3.2.0-26
SELECT * FROM table_name LIMIT 10; -- takes ~45 seconds to completeEXPLAIN SELECT * FROM table_name LIMIT 10; -- takes ~45 seconds to complete the explain query, the query plan looks reasonableThis sounds like the problem we heard quite a bit about recently, where processes spend a lot of time fighting over the proclock while they try to check the commit status of open transactions while. But I don't see how deletes could trigger that behavior. If the delete has not committed, the tuples are still visible and the LIMIT 10 is quickly satisfied. If the delete has committed, the tuples quickly get hinted, and so the next query along should be faster.I also don't see why the explain would be slow. A similar problem was tracked down to digging through in-doubt tuples while trying to use an index to find the true the min or max during estimating the cost of a merge join. But I don't think a simple table query should lead to that, unless table_name is a view. And I don't see how deletes, rather than uncommitted inserts, could trigger it either.max_connections | 600 | configuration fileThat is quite extreme. If a temporary load spike (like from the deletes and the hinting needed after them) slows down the select queries and you start more and more of them, soon you could tip the system over into kernel scheduler insanity with high system time. Once in this mode, it will stay there until the incoming stream of queries stops and the existing ones clear out. But, if that is what is occurring, I don't know why queries on other tables would still be fast.
We probably want a connection pooler anyways, but in this particular case, the load average is fairly low on the machine running Postrgres.
Cheers,Jeff
Thank You,
Pweaver (pweaver@panjiva.com)
On Wed, Feb 5, 2014 at 4:47 PM, Pweaver (Paul Weaver) <pweaver@panjiva.com> wrote: >> That is quite extreme. If a temporary load spike (like from the deletes >> and the hinting needed after them) slows down the select queries and you >> start more and more of them, soon you could tip the system over into kernel >> scheduler insanity with high system time. Once in this mode, it will stay >> there until the incoming stream of queries stops and the existing ones clear >> out. But, if that is what is occurring, I don't know why queries on other >> tables would still be fast. > > We probably want a connection pooler anyways, but in this particular case, > the load average is fairly low on the machine running Postrgres. Indeed, if lack of connection pooling was the cause, I'd expect a huge load average (around 100). Can you post the output of "vmstat 6 10" and "iostat -x -m -d 6 10" while the server is overloaded? (try to run them at the same time so results can be correlated). Also, some details on the hardware wouldn't hurt, like amount of RAM, number of processors, kind of processor, whether it's a virtual machine or a bare metal one, number of disks and disk configuration, etc...
On Wed, Feb 5, 2014 at 11:47 AM, Pweaver (Paul Weaver) <pweaver@panjiva.com> wrote:
On Wed, Feb 5, 2014 at 9:52 AM, Jeff Janes <jeff.janes@gmail.com> wrote:On Monday, February 3, 2014, Pweaver (Paul Weaver) <pweaver@panjiva.com> wrote:We have been running into a (live lock?) issue on our production Postgres instance causing queries referencing a particular table to become extremely slow and our application to lock up.This tends to occur on a particular table that gets a lot of queries against it after a large number of deletes. When this happens, the following symptoms occur when queries referencing that table are run (even it we stop the deleting):What do you mean by "stop the deleting"? Are you pausing the delete but without either committing or rolling back the transaction, but just holding it open? Are you stopping it cleanly, between transactions?We are repeatedly running delete commands in their own transactions. We stop issuing new deletes and let them finish cleanly.Also, how many queries are happening concurrently? Perhaps you need a connection pooler.Usually between 1 and 20. When it gets locked up closer to 100-200.We should add a connection pooler. Would the number of active queries on the table be causing the issue?
100 to 200 active connections cannot be helpful. That number should not be *inherently* harmful, but certainly can be very harmful in conjunction with something else. One thing it could be harmful in conjunction with would be contention on the PROCLOCK spinlock, but if you don't have open transactions that have touched a lot of tuples (which it sounds like you do not) then that probably isn't the case. Another thing could be kernel scheduler problems. I think some of the early 3-series kernels had some problems with the scheduler under many concurrently active processes, which lead to high % system CPU time. There are also problems with NUMA, and with transparent huge pages, from around the same kernel versions.
Is the CPU time user time or system time? What kernel version do you have?Real time - 3.2.0-26
I meant using "top" or "sar" during a lock up, is the CPU time being spent in %user, or in %system?
Unfortunately I don't know exactly when in the 3-series kernels the problems showed up, or were fixed.
In any case, lowering the max_connections will probably prevent you from accidentally poking the beast, even if we can't figure out exactly what kind of beast it is.
max_connections | 600 | configuration fileThat is quite extreme. If a temporary load spike (like from the deletes and the hinting needed after them) slows down the select queries and you start more and more of them, soon you could tip the system over into kernel scheduler insanity with high system time. Once in this mode, it will stay there until the incoming stream of queries stops and the existing ones clear out. But, if that is what is occurring, I don't know why queries on other tables would still be fast.We probably want a connection pooler anyways, but in this particular case, the load average is fairly low on the machine running Postrgres.
Is the load average low even during the problem event?
Cheers,
Jeff