Hello all, I frequently find that TRUNCATE table and CREATE or REPLACE FUNCTION are both very slow taking 50 secs or more to complete. We have to run both commands every minute, so this makes our application non-functional. But it is not a slow deterioration over time.
Sometimes they run under a second, and sometimes take over 50secs. As for other jobs in the system, there is nothing that accesses these tables/function when this happens. Also, when I do a strace on the postgres backend that is running either of the commands, I find it doing a ton of llseek/read as below. I don't find it in S state or sleeping on a semop (I understand this would happen if the function was being used by some other client).
So I believe most of this time is spent in I/O. Now, there is no reason to believe slow I/O is the cause since the I/O on the system does not vary much from one minute to the other.
pg_autovacuum is enabled. And this behavior does not necessarily coincide with any vacuums being run simultaneously (although vacuum of pg_class seems to slow down these commands considerably).
I suspect that pg_class has too many pages (49182 as below) and for some reason the above commands spend a lot of time updating it. vacuum/analyze on pg_class has not helped. Also, since the time taken for these commands is not consistently fast or slow, I'm puzzled.
Any help/feedback will be great.
data ------- _llseek(9, 81469440, [81469440], SEEK_SET) = 0 read(9, "\335\1\0\0P10s\23\0\0\0\\\0\244\0\0 \1 @\236z\3\214\234"..., 8192) = 8192 _llseek(9, 81461248, [81461248], SEEK_SET) = 0 read(9, "\335\1\0\0l\310\311q\23\0\0\0\\\0\260\0\0 \1 D\236r\3\214"..., 8192) = 8192 _llseek(9, 81453056, [81453056], SEEK_SET) = 0 ...
Query took 78 seconds:
CREATE OR REPLACE FUNCTION a() RETURNS SETOF a_type AS' DECLARE q TEXT := ''''; rec a_type%ROWTYPE;
BEGIN q := ''SELECT * FROM a1'';
FOR rec IN EXECUTE q LOOP RETURN NEXT rec;
END LOOP;
RETURN; end; ' language 'plpgsql';
db=# select reltuples, relpages from pg_class where relname = 'pg_class';
reltuples | relpages
-----------+----------
1425 | 49182
(1 row)db=# vacuum analyze verbose pg_class;
INFO: vacuuming "pg_catalog.pg_class"
INFO: index "pg_class_oid_index" now contains 1404 row versions in 14486 pages
DETAIL: 443 index row versions were removed.
14362 index pages have been deleted, 14350 are currently reusable.
CPU 0.04s/0.03u sec elapsed 0.07 sec.
INFO: index "pg_class_relname_nsp_index" now contains 1404 row
versions in 52396 pages
DETAIL: 443 index row versions were removed.
51453 index pages have been deleted, 20000 are currently reusable.
CPU 0.13s/0.09u sec elapsed 0.23 sec.
INFO: "pg_class": removed 443 row versions in 37 pages
DETAIL: CPU 0.00s/0.00u sec elapsed 0.00 sec.
INFO: "pg_class": found 443 removable, 1404 nonremovable row versions
in 49182 pages
DETAIL: 114 dead row versions cannot be removed yet.
There were 2546542 unused item pointers.
0 pages are entirely empty.
CPU 0.32s/0.28u sec elapsed 0.67 sec.
INFO: analyzing "pg_catalog.pg_class"
INFO: "pg_class": 49182 pages, 1290 rows sampled, 1290 estimated total rows
VACUUM
-Joe
---------------------------(end of broadcast)--------------------------- TIP 7: don't forget to increase your free space map settings
