Re: Possible Bug: high CPU usage for stats collector in 8.2

Joshua D. Drake wrote:
> Darcy Buskermolen wrote:
>> 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.

I have just done a test separate from darcy on my workstation:

jd(at)scratch:~/82$ strace -c -p 16130
Process 16130 attached - interrupt to quit
Process 16130 detached
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
50.00 0.167103 3 60264 10225 poll
28.31 0.094600 9 10398 rename
16.89 0.056457 5 10398 open
2.48 0.008278 0 50023 recvfrom
1.14 0.003804 0 10398 setitimer
0.53 0.001781 0 20796 write
0.43 0.001432 0 10398 close
0.21 0.000690 0 10398 munmap
0.02 0.000057 0 10398 mmap
0.00 0.000000 0 10398 fstat
0.00 0.000000 0 10398 10225 rt_sigreturn
0.00 0.000000 0 10414 getppid
------ ----------- ----------- --------- --------- ----------------
100.00 0.334202 224681 20450 total

Query:

time for i in `bin/psql -p8000 -d postgres -c "select
generate_series(1,10000)"`; do bin/psql -p8000 -d postgres -qc "select 1
from pg_database where datname = 'postgres'"; done;

Time:

real 2m5.077s
user 0m28.414s
sys 0m39.762s

PostgreSQL 8.2.0, Ubuntu Edgy 64bit.

Seems like something is extremely wonky here.

Joshua D. Drake

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

--

=== The PostgreSQL Company: Command Prompt, Inc. ===
Sales/Support: +1.503.667.4564 || 24x7/Emergency: +1.800.492.2240
Providing the most comprehensive PostgreSQL solutions since 1997
http://www.commandprompt.com/

Donate to the PostgreSQL Project: http://www.postgresql.org/about/donate
PostgreSQL Replication: http://www.commandprompt.com/products/