Re: postgres.exe 100% CPU but no I/O

Thanks for giving me a place to start. I set log_min_duration_statement
= 0 and log_min_messages = debug5. Below is the log entry for the first
2 minutes after I restarted the server. This repeats exactly every 60
seconds. As I said in the original post, there is no disk I/O being
performed, just 100% CPU load. Any suggestions as to what may be
causing this or where to look next? I'm a novice, hence posting to the
novice list, so just saying RTFM! :) doesn't do the novice much good
when they've already done that and just needs some pointers to isolate a
problem. I apologize for the long log but I'm not sure exactly what is
relevant and what is not.

Bob

--

*************************************************
Robert Schnabel
Research Assistant Professor
University of Missouri-Columbia
Animal Sciences Unit, Rm.162
920 East Campus Drive
Columbia, MO 65211-5300
Phone: 573-884-4106
Fax: 573-882-6827
http://animalgenomics.missouri.edu

"Don't speak unless you can improve the silence"
-various sources
*************************************************

2009-01-26 07:14:07 LOG: database system was shut down at 2009-01-26
07:13:02
2009-01-26 07:14:07 DEBUG: mapped win32 error code 2 to 2
2009-01-26 07:14:07 DEBUG: mapped win32 error code 2 to 2
2009-01-26 07:14:07 DEBUG: mapped win32 error code 2 to 2
2009-01-26 07:14:07 LOG: checkpoint record is at 160/932590C8
2009-01-26 07:14:07 LOG: redo record is at 160/932590C8; undo record is
at 0/0; shutdown TRUE
2009-01-26 07:14:07 LOG: next transaction ID: 0/370293; next OID: 25596
2009-01-26 07:14:07 LOG: next MultiXactId: 1; next MultiXactOffset: 0
2009-01-26 07:14:07 LOG: database system is ready
2009-01-26 07:14:07 DEBUG: mapped win32 error code 80 to 17
2009-01-26 07:14:07 DEBUG: transaction ID wrap limit is 2147484173,
limited by database "postgres"
2009-01-26 07:14:07 DEBUG: mapped win32 error code 80 to 17
2009-01-26 07:14:07 DEBUG: mapped win32 error code 80 to 17
2009-01-26 07:14:07 DEBUG: proc_exit(0)
2009-01-26 07:14:07 DEBUG: shmem_exit(0)
2009-01-26 07:14:07 DEBUG: exit(0)
2009-01-26 07:14:07 DEBUG: reaping dead processes
2009-01-26 07:14:07 DEBUG: waiting on 2 children
2009-01-26 07:14:07 DEBUG: waiting on 3 children
2009-01-26 07:14:07 DEBUG: StartTransaction
2009-01-26 07:14:07 DEBUG: name: unnamed; blockState: DEFAULT;
state: INPROGR, xid/subid/cid: 370293/1/0, nestlvl: 1, children: <>
2009-01-26 07:14:07 DEBUG: mapped win32 error code 2 to 2
2009-01-26 07:14:07 DEBUG: CommitTransaction
2009-01-26 07:14:07 DEBUG: name: unnamed; blockState: STARTED;
state: INPROGR, xid/subid/cid: 370293/1/0, nestlvl: 1, children: <>
2009-01-26 07:14:07 DEBUG: autovacuum: processing database "postgres"
2009-01-26 07:14:07 DEBUG: StartTransaction
2009-01-26 07:14:07 DEBUG: name: unnamed; blockState: DEFAULT;
state: INPROGR, xid/subid/cid: 370294/1/0, nestlvl: 1, children: <>
2009-01-26 07:14:07 DEBUG: pg_authid: vac: 0 (threshold 500), anl: 0
(threshold 250)
2009-01-26 07:14:07 DEBUG: pg_statistic: vac: 0 (threshold 560), anl: 0
(threshold 280)
2009-01-26 07:14:07 DEBUG: pg_type: vac: 0 (threshold 548), anl: 0
(threshold 274)
2009-01-26 07:14:07 DEBUG: pg_attribute: vac: 0 (threshold 826), anl: 0
(threshold 413)
2009-01-26 07:14:07 DEBUG: pg_proc: vac: 0 (threshold 886), anl: 0
(threshold 443)
2009-01-26 07:14:07 DEBUG: pg_class: vac: 0 (threshold 541), anl: 0
(threshold 270)
2009-01-26 07:14:07 DEBUG: pg_autovacuum: vac: 0 (threshold 500), anl:
0 (threshold 250)
2009-01-26 07:14:07 DEBUG: pg_inherits: vac: 0 (threshold 500), anl: 0
(threshold 250)
2009-01-26 07:14:07 DEBUG: pg_index: vac: 0 (threshold 515), anl: 0
(threshold 258)
2009-01-26 07:14:07 DEBUG: pg_operator: vac: 0 (threshold 633), anl: 0
(threshold 317)
2009-01-26 07:14:07 DEBUG: pg_opclass: vac: 0 (threshold 520), anl: 0
(threshold 260)
2009-01-26 07:14:07 DEBUG: pg_am: vac: 0 (threshold 501), anl: 0
(threshold 250)
2009-01-26 07:14:07 DEBUG: pg_amop: vac: 0 (threshold 589), anl: 0
(threshold 295)
2009-01-26 07:14:07 DEBUG: pg_amproc: vac: 0 (threshold 545), anl: 0
(threshold 272)
2009-01-26 07:14:07 DEBUG: pg_language: vac: 0 (threshold 501), anl: 0
(threshold 250)
2009-01-26 07:14:07 DEBUG: pg_aggregate: vac: 0 (threshold 523), anl: 0
(threshold 261)
2009-01-26 07:14:07 DEBUG: pg_rewrite: vac: 0 (threshold 515), anl: 0
(threshold 257)
2009-01-26 07:14:07 DEBUG: pg_trigger: vac: 0 (threshold 501), anl: 0
(threshold 250)
2009-01-26 07:14:07 DEBUG: pg_cast: vac: 0 (threshold 551), anl: 0
(threshold 276)
2009-01-26 07:14:07 DEBUG: pg_namespace: vac: 0 (threshold 501), anl: 0
(threshold 251)
2009-01-26 07:14:07 DEBUG: pg_conversion: vac: 0 (threshold 525), anl:
0 (threshold 262)
2009-01-26 07:14:07 DEBUG: pg_tablespace: vac: 0 (threshold 500), anl:
0 (threshold 250)
2009-01-26 07:14:07 DEBUG: pg_shdepend: vac: 0 (threshold 500), anl: 0
(threshold 250)
2009-01-26 07:14:07 DEBUG: pg_shdescription: vac: 0 (threshold 500),
anl: 0 (threshold 250)
2009-01-26 07:14:07 DEBUG: pg_database: vac: 0 (threshold 500), anl: 0
(threshold 250)
2009-01-26 07:14:07 DEBUG: pg_auth_members: vac: 0 (threshold 500),
anl: 0 (threshold 250)
2009-01-26 07:14:07 DEBUG: CommitTransaction
2009-01-26 07:14:07 DEBUG: name: unnamed; blockState: STARTED;
state: INPROGR, xid/subid/cid: 370294/1/0, nestlvl: 1, children: <>
2009-01-26 07:14:07 DEBUG: proc_exit(0)
2009-01-26 07:14:07 DEBUG: shmem_exit(0)
2009-01-26 07:14:07 DEBUG: exit(0)
2009-01-26 07:14:07 DEBUG: reaping dead processes
2009-01-26 07:14:07 DEBUG: waiting on 4 children
2009-01-26 07:14:07 DEBUG: waiting on 3 children
2009-01-26 07:14:07 DEBUG: forked new backend, pid=4220 socket=568
2009-01-26 07:14:07 DEBUG: proc_exit(0)
2009-01-26 07:14:07 DEBUG: shmem_exit(0)
2009-01-26 07:14:07 DEBUG: exit(0)
2009-01-26 07:14:07 DEBUG: reaping dead processes
2009-01-26 07:14:07 DEBUG: waiting on 4 children
2009-01-26 07:14:07 DEBUG: server process (PID 4220) exited with exit
code 0
2009-01-26 07:14:07 DEBUG: waiting on 3 children
2009-01-26 07:15:07 DEBUG: StartTransaction
2009-01-26 07:15:07 DEBUG: name: unnamed; blockState: DEFAULT;
state: INPROGR, xid/subid/cid: 370295/1/0, nestlvl: 1, children: <>
2009-01-26 07:15:07 DEBUG: CommitTransaction
2009-01-26 07:15:07 DEBUG: name: unnamed; blockState: STARTED;
state: INPROGR, xid/subid/cid: 370295/1/0, nestlvl: 1, children: <>
2009-01-26 07:15:07 DEBUG: autovacuum: processing database "postgres"
2009-01-26 07:15:07 DEBUG: StartTransaction
2009-01-26 07:15:07 DEBUG: name: unnamed; blockState: DEFAULT;
state: INPROGR, xid/subid/cid: 370296/1/0, nestlvl: 1, children: <>
2009-01-26 07:15:07 DEBUG: pg_authid: vac: 0 (threshold 500), anl: 0
(threshold 250)
2009-01-26 07:15:07 DEBUG: pg_statistic: vac: 0 (threshold 560), anl: 0
(threshold 280)
2009-01-26 07:15:07 DEBUG: pg_type: vac: 0 (threshold 548), anl: 0
(threshold 274)
2009-01-26 07:15:07 DEBUG: pg_attribute: vac: 0 (threshold 826), anl: 0
(threshold 413)
2009-01-26 07:15:07 DEBUG: pg_proc: vac: 0 (threshold 886), anl: 0
(threshold 443)
2009-01-26 07:15:07 DEBUG: pg_class: vac: 0 (threshold 541), anl: 0
(threshold 270)
2009-01-26 07:15:07 DEBUG: pg_autovacuum: vac: 0 (threshold 500), anl:
0 (threshold 250)
2009-01-26 07:15:07 DEBUG: pg_inherits: vac: 0 (threshold 500), anl: 0
(threshold 250)
2009-01-26 07:15:07 DEBUG: pg_index: vac: 0 (threshold 515), anl: 0
(threshold 258)
2009-01-26 07:15:07 DEBUG: pg_operator: vac: 0 (threshold 633), anl: 0
(threshold 317)
2009-01-26 07:15:07 DEBUG: pg_opclass: vac: 0 (threshold 520), anl: 0
(threshold 260)
2009-01-26 07:15:07 DEBUG: pg_am: vac: 0 (threshold 501), anl: 0
(threshold 250)
2009-01-26 07:15:07 DEBUG: pg_amop: vac: 0 (threshold 589), anl: 0
(threshold 295)
2009-01-26 07:15:07 DEBUG: pg_amproc: vac: 0 (threshold 545), anl: 0
(threshold 272)
2009-01-26 07:15:07 DEBUG: pg_language: vac: 0 (threshold 501), anl: 0
(threshold 250)
2009-01-26 07:15:07 DEBUG: pg_aggregate: vac: 0 (threshold 523), anl: 0
(threshold 261)
2009-01-26 07:15:07 DEBUG: pg_rewrite: vac: 0 (threshold 515), anl: 0
(threshold 257)
2009-01-26 07:15:07 DEBUG: pg_trigger: vac: 0 (threshold 501), anl: 0
(threshold 250)
2009-01-26 07:15:07 DEBUG: pg_cast: vac: 0 (threshold 551), anl: 0
(threshold 276)
2009-01-26 07:15:07 DEBUG: pg_namespace: vac: 0 (threshold 501), anl: 0
(threshold 251)
2009-01-26 07:15:07 DEBUG: pg_conversion: vac: 0 (threshold 525), anl:
0 (threshold 262)
2009-01-26 07:15:07 DEBUG: pg_tablespace: vac: 0 (threshold 500), anl:
0 (threshold 250)
2009-01-26 07:15:07 DEBUG: pg_shdepend: vac: 0 (threshold 500), anl: 0
(threshold 250)
2009-01-26 07:15:07 DEBUG: pg_shdescription: vac: 0 (threshold 500),
anl: 0 (threshold 250)
2009-01-26 07:15:07 DEBUG: pg_database: vac: 0 (threshold 500), anl: 0
(threshold 250)
2009-01-26 07:15:07 DEBUG: pg_auth_members: vac: 0 (threshold 500),
anl: 0 (threshold 250)
2009-01-26 07:15:07 DEBUG: CommitTransaction
2009-01-26 07:15:07 DEBUG: name: unnamed; blockState: STARTED;
state: INPROGR, xid/subid/cid: 370296/1/0, nestlvl: 1, children: <>
2009-01-26 07:15:07 DEBUG: proc_exit(0)
2009-01-26 07:15:07 DEBUG: shmem_exit(0)
2009-01-26 07:15:07 DEBUG: exit(0)
2009-01-26 07:15:08 DEBUG: reaping dead processes
2009-01-26 07:15:08 DEBUG: waiting on 4 children
2009-01-26 07:15:08 DEBUG: waiting on 3 children

Guido Barosio wrote:
> Robert,
>
> As a first attempt, set log_min_duration_statement to 0 in your
> configuration file and restart the service, do not forget to tail your
> log file in order to understand what is going on. There are other
> parameter that will help you identify potential problems, all of them
> related with log_*. RTFM! :)
>
> Another tip, Process Explorer, a tool for Windows that shows all
> the stuff running in windows such as the Linux 'ps' program but with a
> fancy UI. It's a freeware tool, so try it. It should present you the
> PID of the offending process; this PID plus some SQL magic and the
> pg_stat_* tables will let you know what's going on.
>
> 2 cents
> gb.-