Hello Oleg, Everyone,
    So.. please find attached the results from the same lowlevel program 
as the last run. I changed the psycopg2 to use the gmpy.mpq types as 
opposed to the Decimal type. I also (of course) had to hack col.py to 
use gmpy.mpq's instead of Decimal..

    After everything is said and done..

   Ordered by: internal time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1   23.905   23.905   23.905   23.905 {method 'fetchall' of 
'psycopg2._psycopg.cursor' objects}
        1   16.336   16.336   16.336   16.336 {method 'execute' of 
'psycopg2._psycopg.cursor' objects}
        1   11.495   11.495   52.079   52.079 t.lowlevel:3(<module>)
        1    0.317    0.317   52.396   52.396 {execfile}
        1    0.031    0.031    0.031    0.031 
pgconnection.py:108(makeConnection)
   371/62    0.015    0.000    0.050    0.001 sre_parse.py:385(_parse)
        1    0.014    0.014   40.287   40.287 
dbconnection.py:257(_runWithConnection)
     4824    0.012    0.000    0.015    0.000 sre_parse.py:188(__next)
   740/61    0.011    0.000    0.033    0.001 sre_compile.py:38(_compile)
      261    0.010    0.000    0.011    0.000 {eval}
      339    0.010    0.000    0.015    0.000 
sre_compile.py:213(_optimize_charset)
 1054/380    0.008    0.000    0.009    0.000 sre_parse.py:146(getwidth)
16310/15895    0.007    0.000    0.007    0.000 {len}
      668    0.006    0.000    0.009    0.000 {built-in method sub}
    12099    0.005    0.000    0.005    0.000 {method 'append' of 'list' 
objects}
     4074    0.005    0.000    0.018    0.000 sre_parse.py:207(get)
        1    0.005    0.005    0.033    0.033 converters.py:1(<module>)
       43    0.004    0.000    0.004    0.000 sre_compile.py:264(_mk_bitmap)
      130    0.004    0.000    0.018    0.000 
pkg_resources.py:1645(find_on_path)

    Which would -definitely- seem to suggest Decimal is gawd awful slow. 
The entire program finished in roughly 1/8th of the time. True, memory 
consumption went from around 880mb for 220k objects upto 1.4gb for the 
same 220k objects. However, look at that speed gain. It's insane.

    So.. urm.. yeah. I honestly don't know what to say.. anyone else 
interested in an 8 fold speed improvement ? ;)

    Regards
    Stef


Oleg Broytmann wrote:
> On Tue, Jul 28, 2009 at 09:37:56PM -0400, Stef Telford wrote:
>   
>>    Here is the output from the lowlevel connection select as you  
>> suggested above (mostly) ordered by internal time. Note that it selects  
>>     
>
>    Thank you!
>
>   
>> all 220k bookings, as opposed to last time when it 'only' selected 40k.  
>> It seems that decimal.__new__ is killer .. I could be reading this wrong  
>> (of course) but.. the tottime would seem to back that up I think.
>>     
>
>    It's the point that I wanted to prove, really - to time fetchall and
> Decimal without SQLObject.
>
>   
>>         133167599 function calls (133165268 primitive calls) in 392.615  
>> CPU seconds
>>
>>   Ordered by: internal time
>>     
>
>   
>>   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
>>     
>
>   
>>        1   16.715   16.715  392.589  392.589 t.lowlevel:3(<module>)
>>     
>
>    This is the entire script - 392 seconds.
>
>   
>>        1   53.209   53.209  295.902  295.902 {method 'fetchall' of  
>> 'psycopg2._psycopg.cursor' objects}
>>     
>
>    295 seconds in the most interesting part of the program.
>
>   
>>  9883851   90.187    0.000  242.693    0.000 decimal.py:515(__new__)
>>     
>
>    243 seconds were spent in Decimal.__new__. I.e., Decimal.__new__ is
> called from DB API driver; so we can trust the profiler when it shown us
> last time .to_python() calls were fast - they were really fast 'cause they
> didn't have a need to call Decimal.
>
>   
>>  9883845   35.014    0.000   42.012    0.000 decimal.py:830(__str__)
>>  9883845   21.096    0.000   63.108    0.000 decimal.py:825(__repr__)
>>     
>
>    This is printing.
>
>   
>>  9884218   25.102    0.000   25.102    0.000 {built-in method match}
>> 39536056   20.103    0.000   20.103    0.000 {built-in method group}
>>        1   16.522   16.522   16.522   16.522 {method 'execute' of  
>> 'psycopg2._psycopg.cursor' objects}
>>  9883846    6.461    0.000    6.461    0.000 {method 'lstrip' of 'str'  
>> objects}
>>  9885976    4.971    0.000    4.971    0.000 {isinstance}
>>     
>
>    And some internal stuff.
>
>    Well, fetchall + print spans the entire program, so we can see
> sqlbuilder is fast. With this (and with more trust in the profiler) we can
> return to analyze SQLObject timing.
>
> Oleg.
>   


------------------------------------------------------------------------------
Let Crystal Reports handle the reporting - Free Crystal Reports 2008 30-Day 
trial. Simplify your report design, integration and deployment - and focus on 
what you do best, core application coding. Discover what's new with 
Crystal Reports now.  http://p.sf.net/sfu/bobj-july
_______________________________________________
sqlobject-discuss mailing list
sqlobject-discuss@lists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/sqlobject-discuss

Reply via email to