high CPU usage for stats collector in 8.2 - Mailing list pgsql-hackers

From Darcy Buskermolen
Subject high CPU usage for stats collector in 8.2
Date
Msg-id 200702271314.21002.darcyb@commandprompt.com
Whole thread Raw
Responses Re: high CPU usage for stats collector in 8.2
Possible Bug: high CPU usage for stats collector in 8.2
List 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
write18.22   7.701885         123     62808     12793 poll11.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
select3.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/


pgsql-hackers by date:

Previous
From: "Jonah H. Harris"
Date:
Subject: Re: COMMIT NOWAIT Performance Option
Next
From: Bruce Momjian
Date:
Subject: Re: COMMIT NOWAIT Performance Option