Logging/Debugging

About 25% of the time while running my nightly maintenance script, which
deletes and the copies in a large amount of new data, then vacuums and
recreates indexes, the vacuum command will hang. When I wake up in the
morning, everything is hosed and I have 6000 complaint emails. boohoo. :)
This behavior started a few weeks ago when I upgraded from 7.0 to 7.1.3.
Looking at the process list (ps -x on Readhat Linux 6.2) shows the
following,
4168 ? S 1:11 postgres: postgres ucc 207.132.206.57 idle in
transaction
5754 ? S 0:00 postgres: postgres ucc 207.132.206.65 idle
waiting
5755 ? S 0:00 postgres: postgres ucc 207.132.206.65 idle
waiting
5756 ? S 0:00 postgres: postgres ucc 207.132.206.65 idle
waiting
5757 ? S 0:00 postgres: postgres ucc 207.132.206.65 idle
waiting
5758 ? S 0:00 postgres: postgres ucc 207.132.206.65 idle
waiting
5759 ? S 0:00 postgres: postgres ucc 207.132.206.65 idle
waiting
5791 ? S 0:01 postgres: postgres ucc 207.132.206.57 VACUUM
waiting
5794 ? S 0:00 postgres: postgres ucc 207.132.206.65 idle
waiting
5796 ? S 0:00 postgres: postgres ucc 207.132.206.65 idle
waiting
5797 ? S 0:00 postgres: postgres ucc 207.132.206.65 idle
waiting
5798 ? S 0:00 postgres: postgres ucc 207.132.206.65 idle
waiting
5799 ? S 0:00 postgres: postgres ucc 207.132.206.65 idle
waiting
5800 ? S 0:00 postgres: postgres ucc 207.132.206.65 idle
waiting
5801 ? S 0:00 postgres: postgres ucc 207.132.206.65 idle
waiting
5802 ? S 0:00 postgres: postgres ucc 207.132.206.65 idle
waiting
5803 ? S 0:00 postgres: postgres ucc 207.132.206.65 idle
waiting
etc...
If I kill pid 4168, the idle in transaction process, then the vacuum and all
the other waiting processes will proceed fine. Any clues to what could be
hanging or how I could get more information from postmaster about what
transaction is hanging?
Thanks,
Rich

It looks like you've got a transaction which is staying open while holding
a lock. I'm not sure why it'd be different between versions.
If you turn up the debugging level and turn on at least log_pid you should
be able to see what statements the process from that pid has executed.

Colm

Thank you very much.

This in postgresql.conf gives me exactly what I wanted:

log_connections = true
log_timestamp = true
log_pid = true
debug_level = 2
debug_print_query = true

THOUGH I would prefer a further option to only display the
query/date/pid/db_name

(the rest are completely "lost' for an entry level user like me)

Logging the above information helps me to check when certain web pages take
exceptional strain, and when/if I should cache them to relive the strain ...

Tielman J de Villiers
BondNet Pty Ltd

-----Original Message-----
From: Colm McCartan [mailto:colmm@owl.co.uk]
Sent: Monday, December 10, 2001 11:23 AM
To: Tielman J de Villiers
Subject: Re: [GENERAL] Logging/Debugging

Tielman J de Villiers wrote:

Hi,

I went through the man pages for postmaster, as well as "pg_ctl
--help" for options to log a date/time stamp in the "serverlog" but
could not find it. It was also not clear to me what debug levels are
available (other than 1) and what they log. How would I go about this?

Tielman,

you'll find lots of basic information on this in the idocs at:

http://www.postgresql.org/idocs/index.php?runtime-config.html

However, I too would like a little more detail as to what each of the
debugging levels signifies - does anyone have any more detailed info?

Thanks,

colm

"Rich Ryan" <rich@usedcars.com> writes:

If I kill pid 4168, the idle in transaction process, then the vacuum and all
the other waiting processes will proceed fine.

You've got a client that is sitting with an open transaction block ---
ie, BEGIN, do something, go to sleep without issuing COMMIT/ROLLBACK.

In 7.1 the "do something" could just be a SELECT; that's still
sufficient to block VACUUM. I think that 7.0 might have been a little
laxer about that, and would not hold a lock for a SELECT-only
transaction.

regards, tom lane

Hi,

<history>
Sometime back my app had some probs with postgres 7.1.2- the app did a lot
of updates, and somehow after weeks the backend exited when I did a select
on a table.

I truncated the table and updated to 7.1.3 (did not pg_dump).

I'm trying to see if the problem recurs in 7.1.3.
</history>

Recently I vacummed the database (the postmasters were using a lot of cpu).
No vacuum analyze, just plain psql, vacuum.

The disk usage before vacuuming was 95MB.

After dropped to 45MB.

Then I noticed the postmaster for a particular table still using lots of
cpu 45-80%. Another postmaster on the same database, using different table
was using a lot less cpu.

I vacuumed again, this time the troublesome table specifically.

Then the disk usage dropped to 9MB. And the postmaster cpu usage went down.
I did not restart the app or postgres.

Is it normal to require two vacuums for it to be effective? AFAIK I was
connected to the correct database when vacuuming.

Should I have pg_dumped and reloaded?

Regards,
Link.