Received: from localhost (unknown [200.46.204.183]) by postgresql.org (Postfix) with ESMTP id 52E7A2E013C for ; Tue, 4 Mar 2008 04:28:45 -0400 (AST) Received: from postgresql.org ([200.46.204.71]) by localhost (mx1.hub.org [200.46.204.183]) (amavisd-maia, port 10024) with ESMTP id 46552-05 for ; Tue, 4 Mar 2008 04:28:42 -0400 (AST) X-Greylist: from auto-whitelisted by SQLgrey-1.7.5 Received: from pat.uio.no (pat.uio.no [129.240.10.15]) by postgresql.org (Postfix) with ESMTP id 864742E0145 for ; Tue, 4 Mar 2008 04:28:41 -0400 (AST) Received: from mail-mx6.uio.no ([129.240.10.47]) by pat.uio.no with esmtp (Exim 4.67) (envelope-from ) id 1JWSVs-0005Jr-C7; Tue, 04 Mar 2008 09:28:40 +0100 Received: from smtp.uio.no ([129.240.10.9] helo=mail-mx6.uio.no) by mail-mx6.uio.no with esmtp (Exim 4.67) (envelope-from ) id 1JWSVr-0001Wx-Gz; Tue, 04 Mar 2008 09:28:40 +0100 Received: from bbking.uio.no ([129.240.202.248]) by mail-mx6.uio.no with esmtpsa (TLSv1:AES256-SHA:256) (Exim 4.67) (envelope-from ) id 1JWSVr-0001Wq-C9; Tue, 04 Mar 2008 09:28:39 +0100 Message-ID: <47CD0836.2060808@usit.uio.no> Date: Tue, 04 Mar 2008 09:28:38 +0100 From: Rafael Martinez User-Agent: Thunderbird 2.0.0.9 (X11/20071031) MIME-Version: 1.0 To: Tom Lane CC: pgsql-performance@postgresql.org Subject: Re: Performance problems deleting data References: <47CC1139.4070708@usit.uio.no> <26742.1204565113@sss.pgh.pa.us> In-Reply-To: <26742.1204565113@sss.pgh.pa.us> X-Enigmail-Version: 0.95.5 Content-Type: text/plain; charset=ISO-8859-1 Content-Transfer-Encoding: 7bit X-UiO-Resend: resent X-UiO-Spam-info: not spam, SpamAssassin (score=-5.0, required=5.0, autolearn=disabled, UIO_MAIL_IS_INTERNAL=-5) X-UiO-Scanned: 55FA64DA29DE1C53941E780C7F6E2204C5D1EA30 X-UiO-SR-test: 86E04BC270A0C543627C551BF9F5A6B950AEF3CC X-UiO-SPAM-Test: remote_host: 129.240.10.9 spam_score: -49 maxlevel 200 minaction 2 bait 0 mail/h: 846 total 7204709 max/h 8345 blacklist 0 greylist 0 ratelimit 0 X-Virus-Scanned: Maia Mailguard 1.0.1 X-Archive-Number: 200803/42 X-Sequence-Number: 28996 Tom Lane wrote: > Rafael Martinez 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, Center for Information Technology Services University of Oslo, Norway PGP Public Key: http://folk.uio.no/rafael/