I got a very weird restore problem:
1. I use
pg_dump -Fc urldb > urldb
on one server(FreeBSD4.3 Pg7.2.0)
2. I use
pg_restore -l urldb > archive.list
on another server(FreeBSD4.6 Pg7.2.1)
then I use
pg_restore -v -L archive.lst -d urldb urldb
on this server(Pg7.2.1)
3. I vacuum tables, then run my sql function which was written in plpgsql
very simple, I got very surprised is that it run much slower on Pg7.2.1
machine then Pg7.2.0 machine!
4. When I dropped this function and reload it again(still in binary), it
much much faster then before.
I tested serveral times, same conclusion, I have no other backend running
there.
I cannot explain this, and it doesn't make any sence to me also!
following is my log:
urldb=# VACUUM FULL VERBOSE ANALYZE urlinfo;
NOTICE: --Relation urlinfo--
NOTICE: Pages 33840: Changed 0, reaped 0, Empty 0, New 0; Tup 2718061: Vac
0, Keep/VTL 0/0, UnUsed 0, MinLen 76, MaxLen 1992; Re-using: Free/Avail.
Space 1365860/459512; EndEmpty/Avail. Pages 0/5329.
CPU 0.66s/0.22u sec elapsed 0.89 sec.
NOTICE: Index urlinfo_pkey: Pages 9063; Tuples 2718061.
CPU 0.15s/0.17u sec elapsed 0.33 sec.
NOTICE: Index urlinfo_ukey: Pages 16869; Tuples 2718061.
CPU 0.38s/0.12u sec elapsed 0.50 sec.
NOTICE: Index urlinfo_on: Pages 7456; Tuples 2718061.
CPU 0.16s/0.11u sec elapsed 0.27 sec.
NOTICE: Index urlinfo_rt: Pages 5954; Tuples 2718061.
CPU 0.10s/0.14u sec elapsed 0.24 sec.
NOTICE: Rel urlinfo: Pages: 33840 --> 33835; Tuple(s) moved: 425.
CPU 0.05s/0.13u sec elapsed 0.20 sec.
NOTICE: Index urlinfo_pkey: Pages 9064; Tuples 2718061: Deleted 425.
CPU 0.19s/0.18u sec elapsed 0.38 sec.
NOTICE: Index urlinfo_ukey: Pages 16869; Tuples 2718061: Deleted 425.
CPU 0.41s/0.17u sec elapsed 0.59 sec.
NOTICE: Index urlinfo_on: Pages 7457; Tuples 2718061: Deleted 425.
CPU 0.17s/0.15u sec elapsed 0.34 sec.
NOTICE: Index urlinfo_rt: Pages 5956; Tuples 2718061: Deleted 425.
CPU 0.13s/0.15u sec elapsed 0.30 sec.
NOTICE: --Relation pg_toast_57618011--
NOTICE: Pages 1: Changed 1, reaped 0, Empty 0, New 0; Tup 4: Vac 0,
Keep/VTL 0/0, UnUsed 0, MinLen 827, MaxLen 2034; Re-using: Free/Avail. Space
1800/1800; EndEmpty/Avail. Pages 0/1.
CPU 0.00s/0.00u sec elapsed 0.00 sec.
NOTICE: Index pg_toast_57618011_idx: Pages 2; Tuples 4.
CPU 0.00s/0.00u sec elapsed 0.00 sec.
NOTICE: Rel pg_toast_57618011: Pages: 1 --> 1; Tuple(s) moved: 0.
CPU 0.00s/0.00u sec elapsed 0.00 sec.
NOTICE: Analyzing urlinfo
VACUUM
urldb=# VACUUM FULL VERBOSE ANALYZE ratings_by_serial;
NOTICE: --Relation ratings_by_serial--
NOTICE: Pages 20028: Changed 0, reaped 0, Empty 0, New 0; Tup 3705125: Vac
0, Keep/VTL 0/0, UnUsed 0, MinLen 40, MaxLen 40; Re-using: Free/Avail. Space
643316/2452; EndEmpty/Avail. Pages 0/1.
CPU 0.42s/0.16u sec elapsed 0.59 sec.
NOTICE: Index rbs_unidx: Pages 10162; Tuples 3705125.
CPU 0.24s/0.14u sec elapsed 0.38 sec.
NOTICE: Index ratings_by_serial_pid: Pages 8115; Tuples 3705125.
CPU 0.15s/0.17u sec elapsed 0.33 sec.
NOTICE: Rel ratings_by_serial: Pages: 20028 --> 20028; Tuple(s) moved: 0.
CPU 0.00s/0.00u sec elapsed 0.00 sec.
NOTICE: Analyzing ratings_by_serial
VACUUM
urldb=# explain analyze select codestr(16482429);
NOTICE: QUERY PLAN:
Result (cost=0.00..0.01 rows=1 width=0) (actual time=5602.67..5602.67
rows=1 loops=1)
Total runtime: 5602.72 msec
EXPLAIN
urldb=# explain analyze select codestr(16482429);
NOTICE: QUERY PLAN:
Result (cost=0.00..0.01 rows=1 width=0) (actual time=4889.69..4889.69
rows=1 loops=1)
Total runtime: 4889.73 msec
....................
-----------------------------------------------------------------
After I dropped this function and reload it again via pg_restore:
EXPLAIN
urldb=# explain analyze select codestr(16482429);
NOTICE: QUERY PLAN:
Result (cost=0.00..0.01 rows=1 width=0) (actual time=2.50..2.51 rows=1
loops=1)
Total runtime: 2.56 msec
EXPLAIN
urldb=# explain analyze select codestr(16482429);
NOTICE: QUERY PLAN:
Result (cost=0.00..0.01 rows=1 width=0) (actual time=0.28..0.28 rows=1
loops=1)
Total runtime: 0.32 msec
Jie Liang