Possible Bug: high CPU usage for stats collector in 8.2

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