Re: [HACKERS] Where does the time go?
On Wed, 2006-03-22 at 21:59 -0500, Tom Lane wrote: I'm betting that a big part of your issue is that the EXPLAIN ANALYZE instrumentation overhead is (1) significant I would like to implement an additional mode for EXPLAIN ANALYZE that does no timing instrumentation at all. Most of the time just looking for differences between estimated and actual row counts is all you need. For long queries, the additional time can make the execution infeasible, yet frequently they are the ones you want to see the output for. EXPLAIN ANALYZE NOTIMING sounds a little dry, any ideas? Best Regards, Simon Riggs ---(end of broadcast)--- TIP 2: Don't 'kill -9' the postmaster
Re: [HACKERS] Where does the time go?
Simon Riggs [EMAIL PROTECTED] writes: I would like to implement an additional mode for EXPLAIN ANALYZE that does no timing instrumentation at all. Most of the time just looking for differences between estimated and actual row counts is all you need. I don't really agree with that premise ... without timings, you cannot for instance tell if the planner has over/underestimated the cost of an index fetch. regards, tom lane ---(end of broadcast)--- TIP 2: Don't 'kill -9' the postmaster
Re: [HACKERS] Where does the time go?
On Sat, Mar 25, 2006 at 10:00:51AM -0500, Tom Lane wrote: Simon Riggs [EMAIL PROTECTED] writes: I would like to implement an additional mode for EXPLAIN ANALYZE that does no timing instrumentation at all. Most of the time just looking for differences between estimated and actual row counts is all you need. I don't really agree with that premise ... without timings, you cannot for instance tell if the planner has over/underestimated the cost of an index fetch. I agree. However, if it's the overhead of calling gettimeofday() that slows everything down, perhaps we should tackle that end. For example, have a sampling mode that only times say 5% of the executed nodes. EXPLAIN ANALYZE SAMPLE blah; And then in InstrStart have a quick test that skips the gettimeofday for this interation sometimes. You'd probably need some heuristics because you always want to catch the first iteration but after the 10,000th tuple in an indexscan, you're probably not going to learn anything new. You could do a non-random sampling fairly easily: if( ntuples 16 ) yes else if( ntuples 16*16 (ntuples%16) == 0) yes else if( ntuples 16*16*16 ntuples%(16*16) == 0) yes else etc etc etc This mean that the more often a node is executed, the less often you actually time it. Note, we store ntuples as a doulbe so the mod operation won't work... How does this sound? -- Martijn van Oosterhout kleptog@svana.org http://svana.org/kleptog/ Patent. n. Genius is 5% inspiration and 95% perspiration. A patent is a tool for doing 5% of the work and then sitting around waiting for someone else to do the other 95% so you can sue them. signature.asc Description: Digital signature
Re: [HACKERS] Where does the time go?
On Sat, Mar 25, 2006 at 04:24:05PM +0100, Martijn van Oosterhout wrote:
I agree. However, if it's the overhead of calling gettimeofday() that
slows everything down, perhaps we should tackle that end. For example,
have a sampling mode that only times say 5% of the executed nodes.
EXPLAIN ANALYZE SAMPLE blah;
snip
You could do a non-random sampling fairly easily:
Actually, I thought of a better way to control the sampling that's
probably better than the crude if-then-else structure I gave which also
takes advantage of the fact that the numbers are floating point:
InstrInit:
next_sample = 0;
InstrStart:
if( ntuples 16 )
dosample = yes;
else if( ntuples next_sample )
{
dosample = yes;
next_sample += log2(ntuples);
}
else
dosample = no;
This will sample approxiamtly log2 of the actual executions. You could
use log10(), sqrt() or any other function you find reflects the sample
you want.
Have a nice day,
--
Martijn van Oosterhout kleptog@svana.org http://svana.org/kleptog/
Patent. n. Genius is 5% inspiration and 95% perspiration. A patent is a
tool for doing 5% of the work and then sitting around waiting for someone
else to do the other 95% so you can sue them.
signature.asc
Description: Digital signature
Re: [HACKERS] Where does the time go?
On Sat, 2006-03-25 at 16:24 +0100, Martijn van Oosterhout wrote: I agree. However, if it's the overhead of calling gettimeofday() that slows everything down, perhaps we should tackle that end. For example, have a sampling mode that only times say 5% of the executed nodes. EXPLAIN ANALYZE SAMPLE blah; I like this idea. Why not do this all the time? I'd say we don't need the SAMPLE clause at all, just do this for all EXPLAIN ANALYZEs. And then in InstrStart have a quick test that skips the gettimeofday for this interation sometimes. You'd probably need some heuristics because you always want to catch the first iteration but after the 10,000th tuple in an indexscan, you're probably not going to learn anything new. How does this sound? Something even simpler? First 40 plus 5% random sample after that? I'd prefer a random sample so we have the highest level of trust in the numbers produced. Otherwise we might accidentally introduce bias from systematic effects such as nested loops queries speeding up towards the end of their run. (I know we would do that at the start, but we are stuck because we don't know the population size ahead of time and we know we need a reasonable number of data points). Best Regards, Simon Riggs ---(end of broadcast)--- TIP 5: don't forget to increase your free space map settings
Re: [HACKERS] Where does the time go?
On Sat, Mar 25, 2006 at 05:38:26PM +, Simon Riggs wrote: On Sat, 2006-03-25 at 16:24 +0100, Martijn van Oosterhout wrote: I agree. However, if it's the overhead of calling gettimeofday() that slows everything down, perhaps we should tackle that end. For example, have a sampling mode that only times say 5% of the executed nodes. EXPLAIN ANALYZE SAMPLE blah; I like this idea. Why not do this all the time? I'd say we don't need the SAMPLE clause at all, just do this for all EXPLAIN ANALYZEs. I was wondering about that. But then you may run into wierd results if a subselect takes a long time for just a few value. But maybe it should be the default, and have a FULL mode to say you want to measure everything. Something even simpler? First 40 plus 5% random sample after that? I'd prefer a random sample so we have the highest level of trust in the numbers produced. Otherwise we might accidentally introduce bias from systematic effects such as nested loops queries speeding up towards the end of their run. (I know we would do that at the start, but we are stuck because we don't know the population size ahead of time and we know we need a reasonable number of data points). Well, I was wondering if a fixed percentage was appropriate. 5% of 10 million is still a lot for possibly not a lot of benefit. The followup email suggested a sampling that keeps happening less often as the number of tuples increases it a logorithmic based way. But we could add dome randomness that'd be cool. The question is, what's the overhead of calling random()? Have a nice day, -- Martijn van Oosterhout kleptog@svana.org http://svana.org/kleptog/ Patent. n. Genius is 5% inspiration and 95% perspiration. A patent is a tool for doing 5% of the work and then sitting around waiting for someone else to do the other 95% so you can sue them. signature.asc Description: Digital signature
Re: [HACKERS] Where does the time go?
On Wed, Mar 22, 2006 at 8:59 pm, in message [EMAIL PROTECTED], Tom Lane [EMAIL PROTECTED] wrote: Kevin Grittner [EMAIL PROTECTED] writes: You didn't show us the explain analyze results, The below is cut paste directly from a psql run without editing. bigbird= UPDATE User SET isActive = TRUE WHERE countyNo = 13 and isActive = FALSE; UPDATE 0 bigbird= cluster User; CLUSTER bigbird= vacuum analyze User; VACUUM bigbird= select current_timestamp; now 2006-03-22 16:30:55.875-06 (1 row) bigbird= explain analyze bigbird- UPDATE User bigbird- SET isActive = FALSE bigbird- WHERE countyNo = 13 bigbird- AND (userId, countyNo) NOT IN (SELECT userId, countyNo FROM UserAuthority) bigbird- AND (userId, countyNo) NOT IN (SELECT userId, countyNo FROM UserDivision) bigbird- AND (userId, countyNo) NOT IN (SELECT userId, countyNo FROM UserCtofcAuthority); QUERY PLAN --- Index Scan using User_pkey on User (cost=2365.43..2499.34 rows=44 width=126) (actual time=145.968..147.061 rows=153 loops=1) Index Cond: ((countyNo)::smallint = 13) Filter: ((NOT (hashed subplan)) AND (NOT (hashed subplan)) AND (NOT (hashed subplan))) SubPlan - Seq Scan on UserCtofcAuthority (cost=0.00..332.65 rows=15565 width=14) (actual time=0.003..10.105 rows=15565 loops=1) - Seq Scan on UserDivision (cost=0.00..326.65 rows=15765 width=14) (actual time=0.003..10.409 rows=15764 loops=1) - Seq Scan on UserAuthority (cost=0.00..1451.24 rows=70624 width=14) (actual time=0.007..45.823 rows=70626 loops=1) Total runtime: 150.340 ms (8 rows) bigbird= select current_timestamp; now 2006-03-22 16:30:56.046-06 (1 row) bigbird= UPDATE User SET isActive = TRUE WHERE countyNo = 13 and isActive = FALSE; UPDATE 153 bigbird= cluster User; CLUSTER bigbird= vacuum analyze User; VACUUM bigbird= select current_timestamp; now 2006-03-22 16:30:56.203-06 (1 row) bigbird= UPDATE User bigbird- SET isActive = FALSE bigbird- WHERE countyNo = 13 bigbird- AND (userId, countyNo) NOT IN (SELECT userId, countyNo FROM UserAuthority) bigbird- AND (userId, countyNo) NOT IN (SELECT userId, countyNo FROM UserDivision) bigbird- AND (userId, countyNo) NOT IN (SELECT userId, countyNo FROM UserCtofcAuthority); UPDATE 153 bigbird= select current_timestamp; now 2006-03-22 16:30:56.343-06 (1 row) bigbird= UPDATE User SET isActive = TRUE WHERE countyNo = 13 and isActive = FALSE; UPDATE 153 bigbird= cluster User; CLUSTER bigbird= vacuum analyze User; VACUUM bigbird= select current_timestamp; now 2006-03-22 16:30:56.484-06 (1 row) bigbird= explain analyze bigbird- UPDATE User bigbird- SET isActive = FALSE bigbird- WHERE countyNo = 13 bigbird- AND NOT EXISTS (SELECT * FROM UserAuthority a where a.countyNo = User.countyNo and a.userId = User.userId) bigbird- AND NOT EXISTS (SELECT * FROM UserDivision b where b.countyNo = User.countyNo and b.userId = User.userId) bigbird- AND NOT EXISTS (SELECT * FROM UserCtofcAuthority c where c.countyNo = User.countyNo and c.userId = User.userId); QUERY PLAN - Index Scan using User_pkey on User (cost=0.00..3650.67 rows=42 width=111) (actual time=0.057..5.722 rows=153 loops=1) Index Cond: ((countyNo)::smallint = 13) Filter: ((NOT (subplan)) AND (NOT (subplan)) AND (NOT (subplan))) SubPlan - Index Scan using UserCtofcAuthority_pkey on UserCtofcAuthority c (cost=0.00..3.48 rows=1 width=50) (actual time=0.004..0.004 rows=0 loops=153) Index Cond: (((countyNo)::smallint = ($0)::smallint) AND ((userId)::bpchar = ($1)::bpchar)) - Index Scan using UserDivision_pkey on UserDivision b (cost=0.00..3.53 rows=1 width=42) (actual time=0.006..0.006 rows=0 loops=156) Index Cond: (((countyNo)::smallint = ($0)::smallint) AND ((userId)::bpchar = ($1)::bpchar)) - Index Scan using UserAuthority_pkey on UserAuthority a (cost=0.00..3.60 rows=1 width=42) (actual time=0.007..0.007 rows=1 loops=341) Index Cond: (((countyNo)::smallint = ($0)::smallint) AND ((userId)::bpchar = ($1)::bpchar)) Total runtime: 9.136 ms (11 rows) bigbird= select current_timestamp; now 2006-03-22 16:30:56.546-06 (1 row) bigbird= UPDATE User SET isActive = TRUE WHERE countyNo = 13 and isActive = FALSE; UPDATE 153 bigbird= cluster User;
Re: [HACKERS] Where does the time go?
Kevin Grittner [EMAIL PROTECTED] writes: Tom Lane [EMAIL PROTECTED] wrote: You didn't show us the explain analyze results, The below is cut paste directly from a psql run without editing. OK, so the two plans do indeed have much different node execution counts. The EXPLAIN ANALYZE instrumentation overhead is basically proportional to (rows+1)*loops summed over all the nodes in the plan, so I count about 102112 node executions in the NOT IN plan versus 1145 in the NOT EXISTS plan --- in other words, 100x more overhead for the former. The run time of the NOT IN query, as measured by elapsed time between SELECT CURRENT_TIMESTAMP executions, increased by 31 ms. Works out to about 30 microsec per node execution, which seems a bit high for modern machines ... and the coarse quantization of the CURRENT_TIMESTAMP results is odd too. What platform is this on exactly? That leaves an unaccounted difference between the time reported by EXPLAIN ANALYZE and the timestamp elapsed time of (on average) 9 ms for the NOT IN form of the query, and 41 ms for the NOT EXISTS for of the query. (In the run shown above, it's higher.) I'm guessing that this is the time spent in parsing and planning the query. Parse/plan time is one component, and another is the time spent by EXPLAIN preparing its output display, which is not an area we've spent any time at all optimizing --- I wouldn't be surprised if it's kinda slow. However, these plans are relatively similar in terms of the complexity of the display, so it is odd that there'd be so much difference. What is the best way to see where this time is going? Profiling with gprof or some such tool might be educational. regards, tom lane ---(end of broadcast)--- TIP 3: Have you checked our extensive FAQ? http://www.postgresql.org/docs/faq
Re: [HACKERS] Where does the time go?
On Thu, Mar 23, 2006 at 11:27 am, in message [EMAIL PROTECTED], Tom Lane [EMAIL PROTECTED] wrote: The run time of the NOT IN query, as measured by elapsed time between SELECT CURRENT_TIMESTAMP executions, increased by 31 ms. Works out to about 30 microsec per node execution, which seems a bit high for modern machines ... and the coarse quantization of the CURRENT_TIMESTAMP results is odd too. What platform is this on exactly? This is a smaller machine with a copy of the full production database. A single 3.6 GHz Xeon with 4 GB RAM running Windows Server 2003. It was being used to test update scripts before applying them to the production machines. I stumbled across a costing issue I thought worth posting, and in the course of gathering data noticed this time difference I didn't understand. What is the best way to see where this time is going? Profiling with gprof or some such tool might be educational. Our builds are all done with --enable-debug, but this machine doesn't even have msys installed. I'll try to put together some way to profile it on this machine or some other. (It might be easier to move it to a Linux machine and confirm the problem there, then profile.) Thanks, -Kevin ---(end of broadcast)--- TIP 9: In versions below 8.0, the planner will ignore your desire to choose an index scan if your joining column's datatypes do not match
Re: [HACKERS] Where does the time go?
On Thu, Mar 23, 2006 at 11:27 am, in message [EMAIL PROTECTED], Tom Lane [EMAIL PROTECTED] wrote: Profiling with gprof or some such tool might be educational. I've never used gprof before, and from a quick scan of the info, it appears that I need to compile and link a special version of the software to generate the file that gprof needs. Is this correct? Does it work on a Windows build, or will I need to use Linux? Any tips? Thanks, all. -Kevin ---(end of broadcast)--- TIP 6: explain analyze is your friend
Re: [HACKERS] Where does the time go?
On Thu, Mar 23, 2006 at 12:29:27PM -0600, Kevin Grittner wrote: Works out to about 30 microsec per node execution, which seems a bit high for modern machines ... and the coarse quantization of the CURRENT_TIMESTAMP results is odd too. What platform is this on exactly? This is a smaller machine with a copy of the full production database. A single 3.6 GHz Xeon with 4 GB RAM running Windows Server 2003. It was being used to test update scripts before applying them to the production machines. I stumbled across a costing issue I thought worth posting, and in the course of gathering data noticed this time difference I didn't understand. This may be the cause of the problem (windows). On UNIX platforms the gettimeofday() call is used to calculate the timings in both cases. On Windows the EXPLAIN ANALYZE measures time in a different way using the CPU counters. It uses the interface but it will run into issues if the CPU speed is not properly calculated or there is drift between the different CPUs. Here's one person who claims that the performance counter frequency is often wrong: http://archives.postgresql.org/pgsql-hackers-win32/2005-03/msg00063.php It's also been pointed out before that the code actually divides by the wrong number (it uses GetTimerFrequency() rather than QueryPerformenceFrequency()). If you can find the values of these two functions on your machine, see how it compares to your actual clock speed. Have a nice day, -- Martijn van Oosterhout kleptog@svana.org http://svana.org/kleptog/ Patent. n. Genius is 5% inspiration and 95% perspiration. A patent is a tool for doing 5% of the work and then sitting around waiting for someone else to do the other 95% so you can sue them. signature.asc Description: Digital signature
Re: [HACKERS] Where does the time go?
Kevin Grittner [EMAIL PROTECTED] writes: I've never used gprof before, and from a quick scan of the info, it appears that I need to compile and link a special version of the software to generate the file that gprof needs. Is this correct? Does it work on a Windows build, or will I need to use Linux? Any tips? I dunno anything about profiling on Windows. If you don't mind moving the test case to Linux it's pretty easy: ./configure --enable-debug --whatever-other-options make PROFILE=-pg -DLINUX_PROFILE install postgres executable (On non-Linux Unixen you can omit that -D flag, but otherwise the recipe is the same.) Run the test case (you'll want a test script that does the same thing over and over, enough times to build up a decent set of statistics; I like to have about a minute's worth of accumulated CPU time in a profile run). Exit the session --- the gmon.out file will only be dumped at backend process exit. Then do gprof /path/to/postgres-executable $PGDATA/gmon.out outfile BTW, in 8.1 you want to be sure to do this with autovacuum off, else exit of the autovacuum process might clobber the gmon.out file before you can run gprof. regards, tom lane ---(end of broadcast)--- TIP 3: Have you checked our extensive FAQ? http://www.postgresql.org/docs/faq
Re: [HACKERS] Where does the time go?
Kevin Grittner [EMAIL PROTECTED] writes: I have some odd results from timing two versions of an update query, and was hoping to get a better handle on how to interpret this. You didn't show us the explain analyze results, but I'm betting that a big part of your issue is that the EXPLAIN ANALYZE instrumentation overhead is (1) significant and (2) different for the two query plans. The instrumentation overhead should be about the same for any one plan node execution, but the two plans could involve very different numbers of plan node executions ... regards, tom lane ---(end of broadcast)--- TIP 3: Have you checked our extensive FAQ? http://www.postgresql.org/docs/faq
