Re: Possible Bug: high CPU usage for stats collector in 8.2 - Mailing list pgsql-hackers

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@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
poll28.31   0.094600           9     10398           rename16.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/