high CPU usage for stats collector in 8.2

From: Darcy Buskermolen <darcyb(at)commandprompt(dot)com>
To: pgsql-hackers(at)postgresql(dot)org
Subject: high CPU usage for stats collector in 8.2
Date: 2007-02-27 21:14:20
Message-ID: 200702271314.21002.darcyb@commandprompt.com
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: pgsql-hackers

I'm observing high CPU usage (95%) of a 2.6GHz opteron by the stats collector
on an 8.2.3 box investigation has lead me to belive that the stats file is
written a lot more often that once every 500ms the following shows this
behavior.

PostgreSQL 8.2.3 on x86_64-redhat-linux-gnu, compiled by GCC gcc (GCC) 3.4.6
20060404 (Red Hat 3.4.6-3)

I ran a
time for i in `psql -qtc "select generate_series(1,10000)"`; do psql -qtc
"select 1 from test where msg_id=$i" ; done

which took
real 1m23.288s
user 0m24.142s
sys 0m21.536s

to execute, during which time I ran a strace on the stats collector which
produces the following output. From this it looks like the stats file is
getting rewritten for each connection teardown, not just every 500ms.

Process 10061 attached - interrupt to quit
Process 10061 detached
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
68.14 28.811963 17 1663827 write
18.22 7.701885 123 62808 12793 poll
11.31 4.783082 365 13101 rename
0.58 0.246169 5 50006 recvfrom
0.57 0.241073 18 13101 open
0.43 0.182816 14 13101 munmap
0.18 0.076176 6 13101 mmap
0.17 0.072746 6 13101 close
0.14 0.060483 5 13101 setitimer
0.10 0.041344 3 13101 12793 rt_sigreturn
0.09 0.039240 3 13101 fstat
0.06 0.024041 2 13110 getppid
------ ----------- ----------- --------- --------- ----------------
100.00 42.281018 1894559 25586 total

As you can see rename was called more than the theroitcal 167 times for 500ms
slices that elapsed during the test

Compared to PostgreSQL 8.1.8 on x86_64-pc-linux-gnu, compiled by GCC
gcc-4.0.gcc-opt (GCC) 4.0.3 (Ubuntu 4.0.3-1ubuntu5)
[All be it this is slower hardware..]

time for i in `psql -qtc "select generate_series(1,10000)"`; do psql -qtc
"select 1 from test where msg_id=$i" ; done

which took
real 9m25.380s
user 6m51.254s
sys 1m47.687s
(and therefor should be about 1130 stat write cycles)

and yielded the following strace

% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
93.64 20.422006 334 61212 select
3.49 0.760963 7 110192 read
1.82 0.396654 19 21128 write
0.64 0.139679 126 1112 rename
0.27 0.057970 52 1112 open
0.06 0.012177 11 1112 munmap
0.04 0.008901 8 1112 mmap
0.03 0.006402 6 1112 close
0.02 0.004282 4 1112 fstat
------ ----------- ----------- --------- --------- ----------------
100.00 21.809034 199204 total

During this run the stats collector does not even show and CPU usage according
to top.

both 8.1 and 8.2 have the following postgresql.conf parameters

stats_command_string = off
stats_start_collector = on
stats_block_level = on
stats_row_level = on

--
Darcy Buskermolen
Command Prompt, Inc.
Sales/Support: +1.503.667.4564 || 24x7/Emergency: +1.800.492.2240
PostgreSQL solutions since 1997
http://www.commandprompt.com/

Responses

Browse pgsql-hackers by date

  From Date Subject
Next Message Bruce Momjian 2007-02-27 21:37:46 Re: COMMIT NOWAIT Performance Option
Previous Message Jonah H. Harris 2007-02-27 21:01:46 Re: COMMIT NOWAIT Performance Option