Hmm... This gets stranger and stranger. When connecting to the
database with the psql client in 8.2's bin directory and using commands
such as \d the client hangs, or takes an extremely long time. If we
connect to the same 8.2 database with a psql client from 8.1.4, both
remotely and locally, \d responds immediately. Could the issue be with
the client programs somehow? Note also that we did our migration over
the xmas weekend using the dump straight into a restore command. We
kicked it off Saturday (12-23-06) night and it had just reached the
point of adding foreign keys the morning of the 26th. We stopped it
there, wrote a script to go through and build indexes (which finished in
a timely manner) and have added just the foreign keys strictly necessary
for our applications functionality (i.e. foreign keys set to cascade on
update/delete, etc...).

-------- Original Message --------
Subject: Re: [PERFORM] Slow dump?
Date: Tue, 02 Jan 2007 11:40:18 -0600
From: Erik Jones <erik@myemma.com>
To: Tom Lane <tgl@sss.pgh.pa.us>
CC: pgsql-performance@postgresql.org
References: <459A8B51.8000906@myemma.com> <5876.1167759024@sss.pgh.pa.us>



Tom Lane wrote:
> Erik Jones <erik@myemma.com> writes:
>
>> Hello, we recently migrated our system from 8.1.x to 8.2 and when
>> running dumps have noticed an extreme decrease in speed where the dump
>> is concerned (by more than a factor of 2).
>>
>
> That's odd. pg_dump is normally pretty much I/O bound, at least
> assuming your tables are sizable. The only way it wouldn't be is if you
> have a datatype with a very slow output converter. Have you looked into
> exactly which tables are slow to dump and what datatypes they contain?
> (Running pg_dump with log_min_duration_statement enabled would provide
> useful data about which steps take a long time, if you're not sure.)
>
> regards, tom lane
>
Well, all of our tables use pretty basic data types: integer (various
sizes), text, varchar, boolean, and timestamps without time zone. In
addition, other than not having a lot of our foreign keys in place,
there have been no other schema changes since the migration.

--
erik jones <erik@myemma.com>
software development
emma(r)


---------------------------(end of broadcast)---------------------------
TIP 1: if posting/reading through Usenet, please send an appropriate
subscribe-nomail command to majordomo@postgresql.org so that your
message can get through to the mailing list cleanly


--
erik jones <erik@myemma.com>
software development
emma(r)


---------------------------(end of broadcast)---------------------------
TIP 9: In versions below 8.0, the planner will ignore your desire to
choose an index scan if your joining column's datatypes do not
match

Erik Jones wrote:
> Hmm... This gets stranger and stranger. When connecting to the
> database with the psql client in 8.2's bin directory and using commands
> such as \d the client hangs, or takes an extremely long time. If we
> connect to the same 8.2 database with a psql client from 8.1.4, both
> remotely and locally, \d responds immediately. Could the issue be with
> the client programs somehow?

Couldn't be some DNS problems that only affect the 8.2 client I suppose?

--
Richard Huxton
Archonet Ltd

---------------------------(end of broadcast)---------------------------
TIP 1: if posting/reading through Usenet, please send an appropriate
subscribe-nomail command to majordomo@postgresql.org so that your
message can get through to the mailing list cleanly

Richard Huxton wrote:
> Erik Jones wrote:
>> Hmm... This gets stranger and stranger. When connecting to the
>> database with the psql client in 8.2's bin directory and using
>> commands such as \d the client hangs, or takes an extremely long
>> time. If we connect to the same 8.2 database with a psql client from
>> 8.1.4, both remotely and locally, \d responds immediately. Could the
>> issue be with the client programs somehow?
>
> Couldn't be some DNS problems that only affect the 8.2 client I suppose?
>
Hmm... I don't see how that would matter when the 8.2. client is being
run locally.

--
erik jones <erik@myemma.com>
software development
emma(r)


---------------------------(end of broadcast)---------------------------
TIP 2: Don't 'kill -9' the postmaster

Erik Jones <erik@myemma.com> writes:
> Hmm... This gets stranger and stranger. When connecting to the
> database with the psql client in 8.2's bin directory and using commands
> such as \d the client hangs, or takes an extremely long time.

Hangs at what point? During connection? Try strace'ing psql (or
whatever the Solaris equivalent is) to see what it's doing.

regards, tom lane

---------------------------(end of broadcast)---------------------------
TIP 5: don't forget to increase your free space map settings

Tom Lane wrote:
> Erik Jones <erik@myemma.com> writes:
>
>> Hmm... This gets stranger and stranger. When connecting to the
>> database with the psql client in 8.2's bin directory and using commands
>> such as \d the client hangs, or takes an extremely long time.
>>
>
> Hangs at what point? During connection? Try strace'ing psql (or
> whatever the Solaris equivalent is) to see what it's doing.
>
Ok, here's the truss output when attached to psql with "\d pg_class", I
put a marker where the pause is. Note that today the pause is only
(sic) about 3-4 seconds long before the command completes and the output
is displayed and that the only difference in the system between
yesterday and today is that today we don't have a dump running. I
realize that most of this output below is unnecessary, but while I know
what most of this is doing individually, I wouldn't know what to cut out
for brevity's sake without accidentally also clipping something that is
needed.

read(0, 0x08047B7B, 1) (sleeping...)
read(0, " \", 1) = 1
write(1, " \", 1) = 1
read(0, " d", 1) = 1
write(1, " d", 1) = 1
read(0, " ", 1) = 1
write(1, " ", 1) = 1
read(0, " ", 1) = 1
write(1, " ", 1) = 1
read(0, " p", 1) = 1
write(1, " p", 1) = 1
read(0, "7F", 1) = 1
write(1, "\b \b", 3) = 3
read(0, "7F", 1) = 1
write(1, "\b \b", 3) = 3
read(0, " p", 1) = 1
write(1, " p", 1) = 1
read(0, " g", 1) = 1
write(1, " g", 1) = 1
read(0, " _", 1) = 1
write(1, " _", 1) = 1
read(0, " c", 1) = 1
write(1, " c", 1) = 1
read(0, " l", 1) = 1
write(1, " l", 1) = 1
read(0, " a", 1) = 1
write(1, " a", 1) = 1
read(0, " s", 1) = 1
write(1, " s", 1) = 1
read(0, " s", 1) = 1
write(1, " s", 1) = 1
read(0, "\r", 1) = 1
write(1, "\n", 1) = 1
lwp_sigmask(SIG_SETMASK, 0x00000002, 0x00000000) = 0xFFBFFEFF [0x0000FFFF]
ioctl(0, TCSETSW, 0xFEF431E0) = 0
lwp_sigmask(SIG_SETMASK, 0x00000000, 0x00000000) = 0xFFBFFEFF [0x0000FFFF]
sigaction(SIGINT, 0x08047B80, 0x08047BD0) = 0
sigaction(SIGTERM, 0x08047B80, 0x08047BD0) = 0
sigaction(SIGQUIT, 0x08047B80, 0x08047BD0) = 0
sigaction(SIGALRM, 0x08047B80, 0x08047BD0) = 0
sigaction(SIGTSTP, 0x08047B80, 0x08047BD0) = 0
sigaction(SIGTTOU, 0x08047B80, 0x08047BD0) = 0
sigaction(SIGTTIN, 0x08047B80, 0x08047BD0) = 0
sigaction(SIGWINCH, 0x08047B80, 0x08047BD0) = 0
sigaction(SIGWINCH, 0x08047B80, 0x08047BD0) = 0
sigaction(SIGPIPE, 0x08046E20, 0x08046E70) = 0
send(4, " Q\0\0\0E5 S E L E C T ".., 230, 0) = 230
<----------------------------------------------------------- Hang is
right here!
sigaction(SIGPIPE, 0x08046E20, 0x08046E70) = 0
pollsys(0x08046EE8, 1, 0x00000000, 0x00000000) (sleeping...)
pollsys(0x08046EE8, 1, 0x00000000, 0x00000000) = 1
recv(4, " T\0\0\0 P\003 o i d\0\0".., 16384, 0) = 140
sigaction(SIGPIPE, 0x08046E20, 0x08046E70) = 0
send(4, " Q\0\0\08F S E L E C T ".., 144, 0) = 144
sigaction(SIGPIPE, 0x08046E20, 0x08046E70) = 0
pollsys(0x08046EE8, 1, 0x00000000, 0x00000000) = 1
recv(4, " T\0\0\0D3\007 r e l h a".., 16384, 0) = 272
sigaction(SIGPIPE, 0x08046E20, 0x08046E70) = 0
send(4, " Q\0\00186 S E L E C T ".., 391, 0) = 391
sigaction(SIGPIPE, 0x08046E20, 0x08046E70) = 0
pollsys(0x08046EE8, 1, 0x00000000, 0x00000000) = 1
recv(4, " T\0\0\08F\005 a t t n a".., 16384, 0) = 1375
sigaction(SIGPIPE, 0x08046E20, 0x08046E70) = 0
send(4, " Q\0\001 g S E L E C T ".., 360, 0) = 360
sigaction(SIGPIPE, 0x08046E20, 0x08046E70) = 0
pollsys(0x08046EE8, 1, 0x00000000, 0x00000000) = 1
recv(4, " T\0\0\0DD\007 r e l n a".., 16384, 0) = 526
sigaction(SIGPIPE, 0x08046E20, 0x08046E70) = 0
send(4, " Q\0\0\090 S E L E C T ".., 145, 0) = 145
sigaction(SIGPIPE, 0x08046E20, 0x08046E70) = 0
pollsys(0x08046EE8, 1, 0x00000000, 0x00000000) = 1
recv(4, " T\0\0\0 \001 r e l n a".., 16384, 0) = 51
ioctl(0, TCGETA, 0x08046F24) = 0
ioctl(1, TCGETA, 0x08046F24) = 0
ioctl(1, TIOCGWINSZ, 0x08046F58) = 0
write(1, " T a b l e ".., 34) = 34
write(1, " C o l u m n ".., 41) = 41
write(1, " - - - - - - - - - - - -".., 41) = 41
write(1, " r e l n a m e ".., 39) = 39
write(1, " r e l n a m e s p a c".., 39) = 39
write(1, " r e l t y p e ".., 39) = 39
write(1, " r e l o w n e r ".., 39) = 39
write(1, " r e l a m ".., 39) = 39
write(1, " r e l f i l e n o d e".., 39) = 39
write(1, " r e l t a b l e s p a".., 39) = 39
write(1, " r e l p a g e s ".., 39) = 39
write(1, " r e l t u p l e s ".., 39) = 39
write(1, " r e l t o a s t r e l".., 39) = 39
write(1, " r e l t o a s t i d x".., 39) = 39
write(1, " r e l h a s i n d e x".., 39) = 39
write(1, " r e l i s s h a r e d".., 39) = 39
write(1, " r e l k i n d ".., 39) = 39
write(1, " r e l n a t t s ".., 39) = 39
write(1, " r e l c h e c k s ".., 39) = 39
write(1, " r e l t r i g g e r s".., 39) = 39
write(1, " r e l u k e y s ".., 39) = 39
write(1, " r e l f k e y s ".., 39) = 39
write(1, " r e l r e f s ".., 39) = 39
write(1, " r e l h a s o i d s ".., 39) = 39
write(1, " r e l h a s p k e y ".., 39) = 39
write(1, " r e l h a s r u l e s".., 39) = 39
write(1, " r e l h a s s u b c l".., 39) = 39
write(1, " r e l f r o z e n x i".., 39) = 39
write(1, " r e l a c l ".., 31) = 31
write(1, " r e l o p t i o n s ".., 31) = 31
write(1, " I n d e x e s :\n", 9) = 9
write(1, " " p g _ c l a s".., 45) = 45
write(1, " " p g _ c l a s".., 71) = 71
write(1, "\n", 1) = 1
lwp_sigmask(SIG_SETMASK, 0x00000002, 0x00000000) = 0xFFBFFEFF [0x0000FFFF]
ioctl(0, TIOCGWINSZ, 0x08047B58) = 0
ioctl(0, TIOCSWINSZ, 0x08047B58) = 0
ioctl(0, TCGETS, 0x08047BB0) = 0
ioctl(0, TCSETSW, 0x08047BB0) = 0
lwp_sigmask(SIG_SETMASK, 0x00000000, 0x00000000) = 0xFFBFFEFF [0x0000FFFF]
sigaction(SIGINT, 0x08047AA0, 0x08047B10) = 0
sigaction(SIGTERM, 0x08047AA0, 0x08047B10) = 0
sigaction(SIGQUIT, 0x08047AA0, 0x08047B10) = 0
sigaction(SIGALRM, 0x08047B00, 0x08047B70) = 0
sigaction(SIGTSTP, 0x08047AA0, 0x08047B10) = 0
sigaction(SIGTTOU, 0x08047AA0, 0x08047B10) = 0
sigaction(SIGTTIN, 0x08047AA0, 0x08047B10) = 0
sigaction(SIGWINCH, 0x08047AA0, 0x08047B10) = 0
write(1, " e m m a 2 = # ", 8) = 8
read(0, 0x08047B7B, 1) (sleeping...)

--
erik jones <erik@myemma.com>
software development
emma(r)


---------------------------(end of broadcast)---------------------------
TIP 5: don't forget to increase your free space map settings

Erik Jones <erik@myemma.com> writes:
> ...
> sigaction(SIGPIPE, 0x08046E20, 0x08046E70) = 0
> send(4, " Q\0\0\0E5 S E L E C T ".., 230, 0) = 230
> <----------------------------------------------------------- Hang is
> right here!
> sigaction(SIGPIPE, 0x08046E20, 0x08046E70) = 0
> pollsys(0x08046EE8, 1, 0x00000000, 0x00000000) (sleeping...)
> pollsys(0x08046EE8, 1, 0x00000000, 0x00000000) = 1
> recv(4, " T\0\0\0 P\003 o i d\0\0".., 16384, 0) = 140
> ...

Hmph. So it seems the delay really is on the server's end. Any chance
you could truss the connected backend process too and see what it's doing?

Actually ... before you do that, the first query for "\d pg_class"
should look like

SELECT c.oid,
n.nspname,
c.relname
FROM pg_catalog.pg_class c
LEFT JOIN pg_catalog.pg_namespace n ON n.oid = c.relnamespace
WHERE c.relname ~ '^(pg_class)$'
AND pg_catalog.pg_table_is_visible(c.oid)
ORDER BY 2, 3;

I could see this taking an unreasonable amount of time if you had a huge
number of pg_class rows or a very long search_path --- is your database
at all out of the ordinary in those ways?

regards, tom lane

---------------------------(end of broadcast)---------------------------
TIP 3: Have you checked our extensive FAQ?

http://www.postgresql.org/docs/faq

Tom Lane wrote:
> Erik Jones <erik@myemma.com> writes:
>
>> ...
>> sigaction(SIGPIPE, 0x08046E20, 0x08046E70) = 0
>> send(4, " Q\0\0\0E5 S E L E C T ".., 230, 0) = 230
>> <----------------------------------------------------------- Hang is
>> right here!
>> sigaction(SIGPIPE, 0x08046E20, 0x08046E70) = 0
>> pollsys(0x08046EE8, 1, 0x00000000, 0x00000000) (sleeping...)
>> pollsys(0x08046EE8, 1, 0x00000000, 0x00000000) = 1
>> recv(4, " T\0\0\0 P\003 o i d\0\0".., 16384, 0) = 140
>> ...
>>
>
> Hmph. So it seems the delay really is on the server's end. Any chance
> you could truss the connected backend process too and see what it's doing?
>
> Actually ... before you do that, the first query for "\d pg_class"
> should look like
>
> SELECT c.oid,
> n.nspname,
> c.relname
> FROM pg_catalog.pg_class c
> LEFT JOIN pg_catalog.pg_namespace n ON n.oid = c.relnamespace
> WHERE c.relname ~ '^(pg_class)$'
> AND pg_catalog.pg_table_is_visible(c.oid)
> ORDER BY 2, 3;
>
> I could see this taking an unreasonable amount of time if you had a huge
> number of pg_class rows or a very long search_path --- is your database
> at all out of the ordinary in those ways?
>
Well, running "select count(*) from pg_class;" returns 524699 rows and
our search path is the default. I'd also like to reiterate that \d
pg_class returns instantly when run from the 8.1.4 psql client connected
to the 8.2 db. How would I go about determining which backend server
process psql was attached to?

--
erik jones <erik@myemma.com>
software development
emma(r)


---------------------------(end of broadcast)---------------------------
TIP 3: Have you checked our extensive FAQ?

http://www.postgresql.org/docs/faq

Erik,

Could you set log_min_duration_statement=0 on your server and enable
logging (tutorial here if you don't know how to do that:
http://pgfouine.projects.postgresql.org/tutorial.html).

You should see which queries are executed in both cases and find the
slow one easily.

Regards,

--
Guillaume

---------------------------(end of broadcast)---------------------------
TIP 3: Have you checked our extensive FAQ?

http://www.postgresql.org/docs/faq

Erik Jones <erik@myemma.com> writes:
> Tom Lane wrote:
>> I could see this taking an unreasonable amount of time if you had a huge
>> number of pg_class rows or a very long search_path --- is your database
>> at all out of the ordinary in those ways?
>>
> Well, running "select count(*) from pg_class;" returns 524699 rows

Ouch.

> our search path is the default. I'd also like to reiterate that \d
> pg_class returns instantly when run from the 8.1.4 psql client connected
> to the 8.2 db.

I think I know where the problem is: would you compare timing of

select * from pg_class where c.relname ~ '^(pg_class)$';

select * from pg_class where c.relname ~ '^pg_class$';

Recent versions of psql put parentheses into the regex pattern for
safety in case it's got "|", but I just realized that that probably
confuses the optimizer's check for an indexable regex :-(

However, this only explains slowdown in psql's \d commands, which
wasn't your original complaint ...

regards, tom lane

---------------------------(end of broadcast)---------------------------
TIP 2: Don't 'kill -9' the postmaster

Tom Lane wrote:
> Erik Jones <erik@myemma.com> writes:
>
>> Tom Lane wrote:
>>
>>> I could see this taking an unreasonable amount of time if you had a huge
>>> number of pg_class rows or a very long search_path --- is your database
>>> at all out of the ordinary in those ways?
>>>
>>>
>> Well, running "select count(*) from pg_class;" returns 524699 rows
>>
>
> Ouch.
>
>
>> our search path is the default. I'd also like to reiterate that \d
>> pg_class returns instantly when run from the 8.1.4 psql client connected
>> to the 8.2 db.
>>
>
> I think I know where the problem is: would you compare timing of
>
> select * from pg_class where c.relname ~ '^(pg_class)$';
>
Approximately 4 seconds.
> select * from pg_class where c.relname ~ '^pg_class$';
>
Instant.
> Recent versions of psql put parentheses into the regex pattern for
> safety in case it's got "|", but I just realized that that probably
> confuses the optimizer's check for an indexable regex :-(
>
> However, this only explains slowdown in psql's \d commands, which
> wasn't your original complaint ...
>
Well, it explains the slowdown wrt a query against the catalog tables by
a postgres client application. Were there any changes made like this to
pg_dump and/or pg_restore?

--
erik jones <erik@myemma.com>
software development
emma(r)


---------------------------(end of broadcast)---------------------------
TIP 7: You can help support the PostgreSQL project by donating at

http://www.postgresql.org/about/donate