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

Hi all, I recently noticed that I have a postgres.exe process running at
100% CPU but is not doing any I/O.  This is fresh off of starting the
service.  This is a local db so I am the only one using it and it will
do this even if I do not have any queries running.  I have let it run
for about 2 days (not running any queries) but it never stops so I
figured I'd ask for some advice.  I upgraded to 8.2.11 about a month ago
and haven't had any issues so this seems to be a recent development
within the last week.  I guess my question is how should I go about
tracking down the cause of this running wild?  I'm running Win XP64 SP2,
Postgre 8.2.11.

Thanks in advance for any pointers.
Bob

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

On Sat, Jan 24, 2009 at 3:01 PM, Robert Schnabel <schnabelr@missouri.edu> wrote:
> Hi all, I recently noticed that I have a postgres.exe process running at
> 100% CPU but is not doing any I/O.  This is fresh off of starting the
> service.  This is a local db so I am the only one using it and it will do
> this even if I do not have any queries running.  I have let it run for about
> 2 days (not running any queries) but it never stops so I figured I'd ask for
> some advice.  I upgraded to 8.2.11 about a month ago and haven't had any
> issues so this seems to be a recent development within the last week.  I
> guess my question is how should I go about tracking down the cause of this
> running wild?  I'm running Win XP64 SP2, Postgre 8.2.11.
>
> Thanks in advance for any pointers.
> Bob
>
>
> --
> Sent via pgsql-novice mailing list (pgsql-novice@postgresql.org)
> To make changes to your subscription:
> http://www.postgresql.org/mailpref/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.-