Re: Measuring CPU time use? (Another stupid question)

On Wed, 18 Dec 2002, Jessica Blank wrote:

Hi.. again, I feel stupid. But I Googled for this info, and could not find
it (and I call myself the Goddess of Google, and with good reason...)

I wish to find a way to measure the CPU time used by any given query (or
set of queries).

I could not find any information on how to do this...

Is there some secret internal table (like the V$ virtual tables in Oracle)
that contains this info?

I'd love to find a V$CPUTIME table or something, so I could best optimize
my SQL...

I don't want to have to do it the inefficient way... e.g. by running the
same group of queries 1000 times or so several times, and averaging the
times...

Well, you can kinda get a feel for this by using the time command in unix,
like:

time psql database -c 'explain analyze query goes here'

That will run the whole query but only output the explain analyze output,
adn the time command will tell you how long it took in user time, sys
time, and real time. Generally a large real time versus a small user+sys
time means there was lots of waiting on I/O. For instance, on my little
test database set up with 100,000 accounts for pgbench, this is what I
get:

time psql -c 'explain analyze select * from accounts'
QUERY PLAN
------------------------------------------------------------------------------------------------------------------
Seq Scan on accounts (cost=0.00..2640.00 rows=100000 width=100) (actual
time=0.10..1992.75 rows=100000 loops=1)
Total runtime: 2400.61 msec
(2 rows)

real 0m2.469s
user 0m0.000s
sys 0m0.020s

Which shows that the CPU was only working about 0.020 seconds, while
waiting for the I/O to finish up.

Note that often the most important optimization you can make in SQL isn't
in reducing your CPU load, but your I/O load. On most modern machines
with 1GHz processors, it's the hard drive subsystem's performance that is
your most limiting factor, so avoiding lots of head movement / I/O becomes
job one.

For somethings CPU load is an issue, and you can tell those things by the
above method, because the user+sys times will add up to almost the total
of the real time listed.

There are some profiling tools out there (OProfile comes to mind) that can
live in the kernel and profile any process, but they can be quite a
handful to setup, configure, and interpret the output.

But you realize that the time it took to run the query is NOT the same as
the CPU time, right? A heavy table with 100,000,000 rows may use only a
tiny percentage of CPU but take a minute to return, while your I/O
subsystem thrashes away dmaing the data into memory where it gets copied
to output in 30 milliseconds of CPU time.

Look for iostat to analyze your I/O load, which is often the greater load
factor for a db server than CPU use.

On Wed, 18 Dec 2002, Jessica Blank wrote:

On Wed, Dec 18, 2002 at 12:45:16PM -0700, scott.marlowe wrote:

Scott, Jessica,

On Wed, 18 Dec 2002, Jessica Blank wrote:

I wish to find a way to measure the CPU time used by any given query (or
set of queries).

Well, you can kinda get a feel for this by using the time command in unix,
like:

time psql -c 'explain analyze select * from accounts'
QUERY PLAN
------------------------------------------------------------------------------------------------------------------
Seq Scan on accounts (cost=0.00..2640.00 rows=100000 width=100) (actual
time=0.10..1992.75 rows=100000 loops=1)
Total runtime: 2400.61 msec
(2 rows)

real 0m2.469s
user 0m0.000s
sys 0m0.020s

I think this will only return the CPU usage for the psql command. As
you see, sys time is only 0.02s, and user time is 0. The 2.449s
reported by the "real" time probably be the time used by the backend to
process the query, plus any communication overhead and the like. This
is very close to the 2400msec returned by the explain command.

The way I'd do it is activate the usage reporting in postgresql.conf and
see the logs after each query. You can extract the CPU usage from
there, among other useful things. This is SHOW_QUERY_STATS,
SHOW_PARSER_STATS, SHOW_PLANNER_STATS, SHOW_EXECUTOR_STATS; see
http://www.ca.postgresql.org/users-lounge/docs/7.2/postgres/runtime-config.html#LOGGING

HTH,

--
Alvaro Herrera (<alvherre[a]dcc.uchile.cl>)
"I dream about dreams about dreams", sang the nightingale
under the pale moon" (Sandman)

Thanky thanky. That might work.

Still, I'd rather just have a way I could get a plain old figure.

E.g.:

DELETE FROM V$CPUUSE;
(DO THE QUERIES IN QUESTION HERE)
SELECT NANOSECONDS_USED FROM V$CPUUSE;

On Wed, 18 Dec 2002, Joe Conway wrote:

Jessica Blank wrote:

I wish to find a way to measure the CPU time used by any given query (or
set of queries).

I could not find any information on how to do this...

Is there some secret internal table (like the V$ virtual tables in Oracle)
that contains this info?

Well, I don't know of anything specific to CPU usage, but for monitoring your
server see Monitoring Database Activity in the manual:
http://www.us.postgresql.org/users-lounge/docs/7.3/postgres/monitoring.html

Also, one of the best and most commonly used tools for optimizing individual
queries is EXPLAIN ANALYZE; see:
http://www.us.postgresql.org/users-lounge/docs/7.3/postgres/sql-explain.html

HTH,

Joe

--
J e s s i c a L e a h B l a n k

I suppose I should rephrase.

I am trying to figure out which of two competing ideas of mine is the more
efficient.

Right now, I am running it on a "slow" machine-- a G3/220 with 148MB of
RAM, on OLD SCSI-1/2 hardware. Modern machines have much faster CPUs--
they also have much faster disk tho.

What is important is how long it takes to do a "typical" or "average"
search. I am coding a full-text search system and had two ideas on how to
do it (without implementing my own file-based database, using another
person's, writing stuff in C, or other stuff far more complex than what
the client is paying me for ;) )

So I guess what I'm saying is that I don't care so much about CPU time, or
I/O time, but *TOTAL* time. How long it takes from the instant the query
hits Postgres to the instant I get my results back...

So I need a way to run some 'typical' queries (common search terms for
this system) and figure out which of my algorithms works better... :)

On Wed, 18 Dec 2002, scott.marlowe wrote:

But you realize that the time it took to run the query is NOT the same as
the CPU time, right? A heavy table with 100,000,000 rows may use only a
tiny percentage of CPU but take a minute to return, while your I/O
subsystem thrashes away dmaing the data into memory where it gets copied
to output in 30 milliseconds of CPU time.

Look for iostat to analyze your I/O load, which is often the greater load
factor for a db server than CPU use.

On Wed, 18 Dec 2002, Jessica Blank wrote:

Thanky thanky. That might work.

Still, I'd rather just have a way I could get a plain old figure.

E.g.:

DELETE FROM V$CPUUSE;
(DO THE QUERIES IN QUESTION HERE)
SELECT NANOSECONDS_USED FROM V$CPUUSE;

On Wed, 18 Dec 2002, Joe Conway wrote:

Jessica Blank wrote:

I wish to find a way to measure the CPU time used by any given query (or
set of queries).

I could not find any information on how to do this...

Is there some secret internal table (like the V$ virtual tables in Oracle)
that contains this info?

Well, I don't know of anything specific to CPU usage, but for monitoring your
server see Monitoring Database Activity in the manual:
http://www.us.postgresql.org/users-lounge/docs/7.3/postgres/monitoring.html

Also, one of the best and most commonly used tools for optimizing individual
queries is EXPLAIN ANALYZE; see:
http://www.us.postgresql.org/users-lounge/docs/7.3/postgres/sql-explain.html

HTH,

Joe

--
J e s s i c a L e a h B l a n k

Jessica Blank wrote:

I suppose I should rephrase.

[...snip...]

So I guess what I'm saying is that I don't care so much about CPU time, or
I/O time, but *TOTAL* time. How long it takes from the instant the query
hits Postgres to the instant I get my results back...

That's pretty much exactly what EXPLAIN ANALYZE does for you. And along with
it, you get other useful information to help you improve the query.

Joe

Jessica,

I'm not sure, but for what you are asking it seems like you could whip
up something in a quick and dirty shell script around some psql calls
called using time:

$ time psql -d template1 -c "$YOURSQL"

this should report the time taken to run $YOURSQL.

example:
$ time psql -d template1 -c "select * from pg_language;"

The possiblities seem endless from here. You could do multiple
iterations counting averages, mins or maxs.

I understand this is external to postgres, but it sounds like it solves
your problem.

Keehan

--- Jessica Blank <jb@twu.net> wrote:

I suppose I should rephrase.

I am trying to figure out which of two competing ideas of mine is the
more
efficient.

Right now, I am running it on a "slow" machine-- a G3/220 with 148MB
of
RAM, on OLD SCSI-1/2 hardware. Modern machines have much faster
CPUs--
they also have much faster disk tho.

What is important is how long it takes to do a "typical" or "average"

search. I am coding a full-text search system and had two ideas on
how to
do it (without implementing my own file-based database, using another

person's, writing stuff in C, or other stuff far more complex than
what
the client is paying me for ;) )

So I guess what I'm saying is that I don't care so much about CPU
time, or
I/O time, but *TOTAL* time. How long it takes from the instant the
query
hits Postgres to the instant I get my results back...

So I need a way to run some 'typical' queries (common search terms
for
this system) and figure out which of my algorithms works better... :)

On Wed, 18 Dec 2002, scott.marlowe wrote:

But you realize that the time it took to run the query is NOT the

same as

the CPU time, right? A heavy table with 100,000,000 rows may use

only a

tiny percentage of CPU but take a minute to return, while your I/O
subsystem thrashes away dmaing the data into memory where it gets

copied

to output in 30 milliseconds of CPU time.

Look for iostat to analyze your I/O load, which is often the

greater load

factor for a db server than CPU use.

On Wed, 18 Dec 2002, Jessica Blank wrote:

Thanky thanky. That might work.

Still, I'd rather just have a way I could get a plain old figure.

E.g.:

DELETE FROM V$CPUUSE;
(DO THE QUERIES IN QUESTION HERE)
SELECT NANOSECONDS_USED FROM V$CPUUSE;

On Wed, 18 Dec 2002, Joe Conway wrote:

Jessica Blank wrote:

I wish to find a way to measure the CPU time used by any

given query (or

set of queries).

I could not find any information on how to do this...

Is there some secret internal table (like the V$ virtual

tables in Oracle)

that contains this info?

Well, I don't know of anything specific to CPU usage, but for

monitoring your

server see Monitoring Database Activity in the manual:

http://www.us.postgresql.org/users-lounge/docs/7.3/postgres/monitoring.html

Also, one of the best and most commonly used tools for

optimizing individual

queries is EXPLAIN ANALYZE; see:

http://www.us.postgresql.org/users-lounge/docs/7.3/postgres/sql-explain.html

HTH,

Joe

--
J e s s i c a L e a h B l a n k

---------------------------(end of
broadcast)---------------------------
TIP 4: Don't 'kill -9' the postmaster

__________________________________________________
Do you Yahoo!?
Yahoo! Mail Plus - Powerful. Affordable. Sign up now.
http://mailplus.yahoo.com

Joe Conway wrote:

Jessica Blank wrote:

I suppose I should rephrase.

[...snip...]

So I guess what I'm saying is that I don't care so much about CPU
time, or I/O time, but *TOTAL* time. How long it takes from the
instant the query hits Postgres to the instant I get my results back...

That's pretty much exactly what EXPLAIN ANALYZE does for you. And along
with it, you get other useful information to help you improve the query.

Red Hat recently released their "Visual Explain 1.1" tool as well, and that looks like it could be very useful for what
Jessica's after too:

http://sources.redhat.com/rhdb/tools.html

:-)

Regards and best wishes,

Justin Clift

Joe

--
"My grandfather once told me that there are two kinds of people: those
who work and those who take the credit. He told me to try to be in the
first group; there was less competition there."
- Indira Gandhi

Actually, I'd be more bothered by the "Visual" in the name :-)

Just because it comes from RedHat doesn't mean it's shite. Some of their
stuff is quite nice. Just use the 'explain' or 'explain analyze' sql
statement, it'll get you what you need. But, pay attention to the CPU/IO
usage, as that will tell you what your limiting factors are.

On Wed, 18 Dec 2002, Jessica Blank wrote:

Bllllleleeeuuuughhh...

I'd rather not touch Red Hat's stuff.. or ANYTHING with "Explain" in the
name >G< Thank you for the info tho...

I would much rather just get the info via a simple command line, or a line
of SQL, or something I can do in Perl....

On Thu, 19 Dec 2002, Justin Clift wrote:

Joe Conway wrote:

Jessica Blank wrote:

I suppose I should rephrase.

[...snip...]

So I guess what I'm saying is that I don't care so much about CPU
time, or I/O time, but *TOTAL* time. How long it takes from the
instant the query hits Postgres to the instant I get my results back...

That's pretty much exactly what EXPLAIN ANALYZE does for you. And along
with it, you get other useful information to help you improve the query.

Red Hat recently released their "Visual Explain 1.1" tool as well, and that looks like it could be very useful for what
Jessica's after too:

http://sources.redhat.com/rhdb/tools.html

:-)

Regards and best wishes,

Justin Clift

Joe

--
J e s s i c a L e a h B l a n k

Oh, I meant "Visual". Just had one too many neurons misfire... :)

On Wed, 18 Dec 2002, scott.marlowe wrote:

Actually, I'd be more bothered by the "Visual" in the name :-)

Just because it comes from RedHat doesn't mean it's shite. Some of their
stuff is quite nice. Just use the 'explain' or 'explain analyze' sql
statement, it'll get you what you need. But, pay attention to the CPU/IO
usage, as that will tell you what your limiting factors are.

On Wed, 18 Dec 2002, Jessica Blank wrote:

Bllllleleeeuuuughhh...

I'd rather not touch Red Hat's stuff.. or ANYTHING with "Explain" in the
name >G< Thank you for the info tho...

I would much rather just get the info via a simple command line, or a line
of SQL, or something I can do in Perl....

On Thu, 19 Dec 2002, Justin Clift wrote:

Joe Conway wrote:

Jessica Blank wrote:

I suppose I should rephrase.

[...snip...]

So I guess what I'm saying is that I don't care so much about CPU
time, or I/O time, but *TOTAL* time. How long it takes from the
instant the query hits Postgres to the instant I get my results back...

That's pretty much exactly what EXPLAIN ANALYZE does for you. And along
with it, you get other useful information to help you improve the query.

Red Hat recently released their "Visual Explain 1.1" tool as well, and that looks like it could be very useful for what
Jessica's after too:

http://sources.redhat.com/rhdb/tools.html

:-)

Regards and best wishes,

Justin Clift

Joe

--
J e s s i c a L e a h B l a n k

Joe Conway <mail@joeconway.com> writes:

Jessica Blank wrote:

So I guess what I'm saying is that I don't care so much about CPU time, or
I/O time, but *TOTAL* time. How long it takes from the instant the query
hits Postgres to the instant I get my results back...

That's pretty much exactly what EXPLAIN ANALYZE does for you. And along with
it, you get other useful information to help you improve the query.

Also, in 7.3 psql has a "\timing" setting that automatically gives you
elapsed time for each query.

I concur with the recommendation to pay more attention to elapsed time
than CPU time (even if you could get the latter, which you can't
easily).

If you really feel a need for CPU time, you could turn on
"log_statement_stats" (that's what current sources call it anyway,
but I think Bruce renamed it from something else recently) and then
look in the postmaster log for entries like so:

LOG: QUERY STATISTICS
! system usage stats:
! 3.843989 elapsed 2.220000 user 0.340000 system sec
! [2.260000 user 0.360000 sys total]
! 1797/0 [1874/4] filesystem blocks in/out
! 0/0 [0/1] page faults/reclaims, 0 [0] swaps
! 0 [0] signals rcvd, 0/144 [5/149] messages rcvd/sent
! 1410/238 [1458/246] voluntary/involuntary context switches
! buffer usage stats:
! Shared blocks: 1799 read, 0 written, buffer hit rate = 7.08%
! Local blocks: 0 read, 0 written, buffer hit rate = 0.00%
! Direct blocks: 0 read, 0 written

But I think EXPLAIN ANALYZE is much more useful.

regards, tom lane