pg_restore weirdness

From: Jie Liang <jie(at)stbernard(dot)com>
To: "'pgsql-admin(at)postgresql(dot)org'" <pgsql-admin(at)postgresql(dot)org>, "'pgsql-hacker(at)postgresql(dot)org'" <pgsql-hacker(at)postgresql(dot)org>
Subject: pg_restore weirdness
Date: 2002-08-06 17:20:25
Message-ID: 7C760DAA511DC74B99E7D22189F786F101BF214B@mail01.stbernard.com
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: pgsql-admin

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

Responses

Browse pgsql-admin by date

  From Date Subject
Next Message Stephan Szabo 2002-08-06 17:29:39 Re: pg_restore weirdness
Previous Message Chad R. Larson 2002-08-06 17:12:12 Re: Ouverture d'une session base de