Re: Performance problems deleting data

Tom Lane wrote:
> Rafael Martinez <r(dot)m(dot)guerrero(at)usit(dot)uio(dot)no> writes:
>
>> Any ideas why it is taking 2462558.813 ms to finish when the total time
>> for the deletion is 2.546 ms + 3.422 ms + 0.603ms?
>

Hei Tom, I got this information from my colleague:

> Is the problem repeatable?

Repeatable as in about 30+ times every day, the deletion of a row takes
more than 100 seconds. I have not found a way to provoke it though.

> Is the delay consistent?

No. I see frequently everything from below the 8 seconds
log_min_duration_statement to about 4900 seconds. As for distribution,
about half of the 30+ takes more than 500 seconds to complete, the rest
(obviously) between 100 and 500 seconds.

> What do you see in pg_locks while it's delaying?

locktype | database | relation | page | tuple | transactionid |
classid | objid | objsubid | transaction | pid | mode |
granted
---------------+----------+----------+------+-------+---------------+---------+-------+----------+-------------+-------+------------------+---------
relation | 16393 | 16784 | | | |
| | | 82179843 | 19890 | AccessShareLock | t
relation | 16393 | 16784 | | | |
| | | 82179843 | 19890 | RowExclusiveLock | t
relation | 16393 | 17176 | | | |
| | | 82179843 | 19890 | RowExclusiveLock | t
relation | 16393 | 16794 | | | |
| | | 82180131 | 19907 | AccessShareLock | t
relation | 16393 | 16794 | | | |
| | | 82180131 | 19907 | RowExclusiveLock | t
relation | 16393 | 16977 | | | |
| | | 82179843 | 19890 | AccessShareLock | t
relation | 16393 | 16977 | | | |
| | | 82179843 | 19890 | RowExclusiveLock | t
relation | 16393 | 16800 | | | |
| | | 82179669 | 19906 | AccessShareLock | t
relation | 16393 | 16800 | | | |
| | | 82179669 | 19906 | RowExclusiveLock | t
relation | 16393 | 17174 | | | |
| | | 82179843 | 19890 | RowExclusiveLock | t
transactionid | | | | | 80430155 |
| | | 80430155 | 29569 | ExclusiveLock | t
relation | 16393 | 17164 | | | |
| | | 82179843 | 19890 | AccessShareLock | t
relation | 16393 | 16816 | | | |
| | | 82179669 | 19906 | AccessShareLock | t
relation | 16393 | 16816 | | | |
| | | 82179669 | 19906 | RowExclusiveLock | t
relation | 16393 | 16812 | | | |
| | | 82179669 | 19906 | AccessShareLock | t
relation | 16393 | 16812 | | | |
| | | 82179669 | 19906 | RowExclusiveLock | t
relation | 16393 | 17174 | | | |
| | | 82180131 | 19907 | RowExclusiveLock | t
relation | 16393 | 16977 | | | |
| | | 82180131 | 19907 | AccessShareLock | t
relation | 16393 | 16977 | | | |
| | | 82180131 | 19907 | RowExclusiveLock | t
relation | 16393 | 16784 | | | |
| | | 82180131 | 19907 | AccessShareLock | t
relation | 16393 | 16784 | | | |
| | | 82180131 | 19907 | RowExclusiveLock | t
relation | 16393 | 16766 | | | |
| | | 82179843 | 19890 | AccessShareLock | t
relation | 16393 | 16766 | | | |
| | | 82179843 | 19890 | RowExclusiveLock | t
relation | 16393 | 16977 | | | |
| | | 82179669 | 19906 | AccessShareLock | t
relation | 16393 | 16977 | | | |
| | | 82179669 | 19906 | RowExclusiveLock | t
relation | 16393 | 17164 | | | |
| | | 82179669 | 19906 | AccessShareLock | t
relation | 16393 | 16766 | | | |
| | | 82180131 | 19907 | AccessShareLock | t
relation | 16393 | 16766 | | | |
| | | 82180131 | 19907 | RowExclusiveLock | t
relation | 16393 | 10342 | | | |
| | | 82180134 | 31646 | AccessShareLock | t
relation | 16393 | 16794 | | | |
| | | 82179843 | 19890 | AccessShareLock | t
relation | 16393 | 16794 | | | |
| | | 82179843 | 19890 | RowExclusiveLock | t
relation | 16393 | 16835 | | | |
| | | 82179669 | 19906 | AccessShareLock | t
relation | 16393 | 16835 | | | |
| | | 82179669 | 19906 | RowExclusiveLock | t
relation | 16393 | 17176 | | | |
| | | 82180131 | 19907 | RowExclusiveLock | t
relation | 16393 | 16800 | | | |
| | | 82180131 | 19907 | AccessShareLock | t
relation | 16393 | 16800 | | | |
| | | 82180131 | 19907 | RowExclusiveLock | t
relation | 16393 | 16821 | | | |
| | | 82179669 | 19906 | AccessShareLock | t
relation | 16393 | 16821 | | | |
| | | 82179669 | 19906 | RowExclusiveLock | t
relation | 16393 | 17174 | | | |
| | | 82179669 | 19906 | RowExclusiveLock | t
relation | 16393 | 16730 | | | |
| | | 80430155 | 29569 | AccessShareLock | t
transactionid | | | | | 82179669 |
| | | 82179669 | 19906 | ExclusiveLock | t
relation | 16393 | 16800 | | | |
| | | 82179843 | 19890 | AccessShareLock | t
relation | 16393 | 16800 | | | |
| | | 82179843 | 19890 | RowExclusiveLock | t
relation | 16393 | 16784 | | | |
| | | 82179669 | 19906 | AccessShareLock | t
relation | 16393 | 16784 | | | |
| | | 82179669 | 19906 | RowExclusiveLock | t
relation | 16393 | 16766 | | | |
| | | 82179669 | 19906 | AccessShareLock | t
relation | 16393 | 16766 | | | |
| | | 82179669 | 19906 | RowExclusiveLock | t
relation | 16393 | 16794 | | | |
| | | 82179669 | 19906 | AccessShareLock | t
relation | 16393 | 16794 | | | |
| | | 82179669 | 19906 | RowExclusiveLock | t
transactionid | | | | | 82180134 |
| | | 82180134 | 31646 | ExclusiveLock | t
transactionid | | | | | 82179843 |
| | | 82179843 | 19890 | ExclusiveLock | t
relation | 16393 | 17176 | | | |
| | | 82179669 | 19906 | RowExclusiveLock | t
transactionid | | | | | 82180131 |
| | | 82180131 | 19907 | ExclusiveLock | t
relation | 16393 | 17164 | | | |
| | | 82180131 | 19907 | AccessShareLock | t
(54 rows)

> Also watch "vmstat 1" output --- is it consuming CPU and/or I/O?
>
>

CPU 50% idle, rest mainly used in "system". Virtually no IO. No
blocked processes. An impressive amount of context switches. No swap.

An strace(1) of the postgres process may give a hint about the "system"
part; this is what it does over and over and over again. The filename
does change to a different file in the same directory every now and
then, but not often.

semop(4227102, 0xbf8ef23a, 1) = 0
semop(4227102, 0xbf8ef67a, 1) = 0
open("pg_subtrans/047B", O_RDWR|O_LARGEFILE) = 12
_llseek(12, 139264, [139264], SEEK_SET) = 0
read(12, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"...,
8192) = 8192
close(12) = 0

regards
--
Rafael Martinez, <r(dot)m(dot)guerrero(at)usit(dot)uio(dot)no>
Center for Information Technology Services
University of Oslo, Norway

PGP Public Key: http://folk.uio.no/rafael/