lock contention, need profiling idea

On Tue, Jul 1, 2014 at 7:36 AM, AI Rumman <rummandba@gmail.com> wrote:

I see lots of similar log message at a certain time in a day on Postgresql
9,.1:

LOG: process 18855 still waiting for ShareLock on transaction 2856146023
after 1001.209 ms
STATEMENT: UPDATE table1 SET time = $1 WHERE id = $2

The table1 size is 17 G.

What could be the reason for this lock contention?
autovacuum?

This may be a CREATE INDEX query taking some time, perhaps combined with an
old prepared transaction still holding a lock? Perhaps a cron job running
behind that you are not aware of?
You should have a look at pg_stat_activity, pg_prepared_xacts and pg_locks
to get more information about the transactions running and the locks being
taken.
--
Michael

There was no CREATE INDEX command running on the host.

On Mon, Jun 30, 2014 at 5:06 PM, Michael Paquier <michael.paquier@gmail.com>
wrote:

On Mon, Jun 30, 2014 at 5:36 PM, AI Rumman <rummandba@gmail.com> wrote:

I see lots of similar log message at a certain time in a day on Postgresql
9,.1:

LOG: process 18855 still waiting for ShareLock on transaction 2856146023
after 1001.209 ms
STATEMENT: UPDATE table1 SET time = $1 WHERE id = $2

The table1 size is 17 G.

What could be the reason for this lock contention?
autovacuum?

Please give some idea.

Query pg_stat_activity and pg_locks on intervals and you'll get to the
bottom of this.

merlin

--
Sent via pgsql-general mailing list (pgsql-general@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-general

On Mon, Jun 30, 2014 at 5:06 PM, Michael Paquier
<michael.paquier@gmail.com> wrote:

On Tue, Jul 1, 2014 at 7:36 AM, AI Rumman <rummandba@gmail.com> wrote:

I see lots of similar log message at a certain time in a day on Postgresql
9,.1:

LOG: process 18855 still waiting for ShareLock on transaction 2856146023
after 1001.209 ms
STATEMENT: UPDATE table1 SET time = $1 WHERE id = $2

The table1 size is 17 G.

What could be the reason for this lock contention?
autovacuum?

This may be a CREATE INDEX query taking some time, perhaps combined with an
old prepared transaction still holding a lock? Perhaps a cron job running
behind that you are not aware of?

Wouldn't that be waiting on the table, not the transaction? I think
transaction lock waits are (almost?) always due to tuples, so "FOR
UPDATE", UPDATE, etc.

You should have a look at pg_stat_activity, pg_prepared_xacts and pg_locks
to get more information about the transactions running and the locks being
taken.

In 9.4, the log message will also include info on the blocking
process, not just the blocked process, for lock waits.

But until then, pg_stat_activity and pg_locks are the best bet.
Unless you can afford to turn log_statement to 'all' and dig through
the resulting mess.

Cheers,

Jeff

--
Sent via pgsql-general mailing list (pgsql-general@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-general

On Tue, Jul 1, 2014 at 2:28 PM, Jeff Janes <jeff.janes@gmail.com> wrote:

You should have a look at pg_stat_activity, pg_prepared_xacts and pg_locks
to get more information about the transactions running and the locks being
taken.

In 9.4, the log message will also include info on the blocking
process, not just the blocked process, for lock waits.

But until then, pg_stat_activity and pg_locks are the best bet.
Unless you can afford to turn log_statement to 'all' and dig through
the resulting mess.

log_min_duration_statement might be a middle ground -- set it to 1
second plus. on most applications this should cut out most of the
chaff.

merlin

--
Sent via pgsql-general mailing list (pgsql-general@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-general