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

Reply via email to