Re: postgres.exe 100% CPU but no I/O - Mailing list pgsql-novice

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.-