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

On Wednesday 28 February 2007 14:31, Joshua D. Drake wrote:
> 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.

And just so that noone thinks it's linux specific, I tried the same test on a
FreeBSD box with 8.2 on it and got the following. Ignore the time portion of
the results, but what is important is the number of calls occuring in the
timeframe (given this test took about 38:30, it should have resulted in about
4620 calls to rename)

% time seconds usecs/call calls err syscall
------ ----------- ----------- --------- --------- ----------------
149.23 1170797349.233781 464000015 2519188 2 write
57.71 452768432.575458 2036010019 71515 20238 poll
17.59 138017435.049569 -1944030463 20766 getppid
-136.71 -1072628999.112811 -1254412922 20317 rename
-136.71 -1072629000.340448 -1254412960 20317 close
-136.71 -1072629001.605166 -1254412996 20317 setitimer
-146.81 -1151850347.801977 -861500230 20316 open
-146.81 -1151850349.967150 -861500320 20316 fstat
-226.75 -1779034289.1666093 -639263959 50831 recvfrom
------ ----------- ----------- --------- --------- ----------------

real 38m29.897s
user 0m40.641s
sys 0m47.487s

....

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

--

Darcy Buskermolen
The PostgreSQL company, Command Prompt Inc.
http://www.commandprompt.com/