On Wed, Jul 22, 2009 at 05:18:46PM -0400, Stef Telford wrote: >>> Ordered by: cumulative time >>> >>> ncalls tottime percall cumtime percall filename:lineno(function) >>> 1 0.127 0.127 83.346 83.346 sresults.py:175(__iter__) >>> 40001 0.308 0.000 79.876 0.002 dbconnection.py:649(next) >> >> Hmm. Does the program try to draw the entire table in one huge slurp? >> > Actually, no. This page does 40k of bookings (a single object type) but > the query isn't "Sequential" (it's not grabbing 0-40,000 is what I > mean).
Hmm. One call to SelectResults.__iter__ that spans the entire program's lifetime. "One huge SELECT" is the only way I can interpret this. > I can do a page which has lots of different object types if this > would help ? I doubt that would make difference. >>> 40000 0.375 0.000 39.282 0.001 main.py:872(get) >>> 40002 10.018 0.000 39.252 0.001 {method 'fetchone' of >>> 'psycopg2._psycopg.cursor' objects} >> >> Half of the time the program spends drawing rows one by one. This >> probably could be optimized by using fetchmany or fetchall. >> > Noted. Let me try this later tonight when I have some spare cycles :) It's not that easy. Changing fetchone to fetchmany required an additional loop over the results in Iteration.next - similar to what I did in InheritableIteration.next. >> My guess is that those Decimal.__new__ calls are inside DB API driver, >> and DecimalCol.to_python gets Decimal and returns it unchanged. This means >> that the lines >> >>> 40002 10.018 0.000 39.252 0.001 {method 'fetchone' of >>> 'psycopg2._psycopg.cursor' objects} >>> 1840006 16.887 0.000 29.234 0.000 decimal.py:515(__new__) >> >> should be read as follows: fetchone draws a row and converts values to >> Decimal, so 29.2 s are really a part of 39.2, and fetchone only waited for >> DB for 10 seconds. >> > 10seconds to fetch from the database is not bad (in my view). The 29s > for decimal is definitely 'killer' So we have 29 seconds in Decimal.__new__, 10 seconds in fetchone, and 23 seconds in _SO_selectInit. 63 seconds of 85... >>> 40000 0.214 0.000 23.323 0.001 main.py:912(_init) >>> 40000 10.475 0.000 23.069 0.001 main.py:1140(_SO_selectInit) >> >> _SO_selectInit is a rather simple function - it populates the row with >> values just fetched from the DB; the values are converted using calls to >> to_python. Those to_python calls are fast (if we ca believe the profiler) - >> see above. So where does _SO_selectInit spend its time?! Well, it is certainly not evals. I also doubt it has something with garbage collection. Not in this function. Oleg. -- Oleg Broytmann http://phd.pp.ru/ p...@phd.pp.ru Programmers don't die, they just GOSUB without RETURN. ------------------------------------------------------------------------------ _______________________________________________ sqlobject-discuss mailing list sqlobject-discuss@lists.sourceforge.net https://lists.sourceforge.net/lists/listinfo/sqlobject-discuss