On Sunday 07 June 2009 06:51:42 mdipierro wrote:
> Turns out the current DAL spends lots of time in building the SQL
> representation of a table (CREATE TABLE) even if the table does not
> need to be created. I will fix this and it will speed it up a lot
> without need for lazy evaluations.
Hmm. Tried this:
if args['migrate']:
sql_locker.acquire()
try:
query = t._create(migrate=args['migrate'])
except BaseException, e:
sql_locker.release()
raise e
sql_locker.release()
Got 0.106s per model init. 12% improvement (somehow w/o that option today my
model runs couple of milliseconds faster). Not exactly "a lot" of time, but
yes, good improvement with
seemingly (so far) no downsides.
BTW - your reminder on '-F' flag moved me into running some profiling.
I use my own stats analyzer wich produces gprof2-like output.
The top5 are the following. All figures except percentage must be
divided by 100 - this data is for 100 calls of the 'front page'.
A short explanation for the people who didn't use gprof2 yet.
Each section describes a function. Function in question is marked in the
left column. Before the function go it's callers, after it go callees
(function that this one has used).
Each line has the following format:
(1) [index] - only the function in question has it
(2) absolute processor time this function was executed.
Methods like main() usually take 100% or nearly so
(3) 'self' time - the time was actually spent in this function body
not counting the time was spent in functions, called from this one.
This is the column that is used for sorting
(4) 'kids' time - how much time was spent in functions, called from this one.
(5) function name in the format: module:function(lineno) [index]
===================================================
index %ab.tim self kids called filename:func(lineno) [index]
31.39 0.00 0.00 20/19900 sql.py:define_table(916) [30]
30.68 0.02 0.00 179/19900 sql.py:__init__(1591) [4]
[1] 11.19 2.41 0.05 19900 ~:<dir>(0)
2.79 0.00 0.00 40/28900 sql.py:__getattr__(499) [25]
========================
3.98 0.00 0.00 293/112100 sql.py:__setitem__(1118) [14]
10.18 0.01 0.00 828/112100 sql.py:__getitem__(1109) [6]
[2] 7.87 1.73 0.00 112100 sql.py:is_integer(1052)
========================
30.68 0.01 0.01 178/17800 sql.py:__init__(1591) [4]
[3] 11.54 1.50 1.04 17800 sql.py:sqlhtml_validators(334)
2.34 0.01 0.00 356/36100 validators.py:__init__(315) [12]
0.77 0.00 0.00 534/53400 validators.py:__init__(111) [28]
0.62 0.00 0.00 178/18200 validators.py:__init__(344) [34]
0.43 0.00 0.00 178/17800 validators.py:__init__(1423)
[40]
0.35 0.00 0.00 178/17800 validators.py:__init__(1350)
[49]
0.25 0.00 0.00 178/17900 validators.py:__init__(1385)
[64]
0.00 0.00 0.00 3/16 socket.py:__del__(238) [278]
========================
10.85 0.00 0.00 13/17900 tools.py:define_tables(429) [60]
22.70 0.00 0.01 20/17900 sql.py:__init__(1074) [5]
68.73 0.01 0.05 146/17900 models_db.py:<module>(2) [7]
[4] 30.68 1.19 5.56 17900 sql.py:__init__(1591)
11.54 0.01 0.01 178/17800 sql.py:sqlhtml_validators(334)
[3]
11.19 0.02 0.00 179/19900 ~:<dir>(0) [1]
3.27 0.00 0.00 179/19900 sql.py:cleanup(422) [24]
12.34 0.00 0.00 25/80500 sql.py:__getattr__(1132) [10]
0.33 0.00 0.00 179/18100 ~:<method 'upper' of 'str'
objects>(0) [52]
0.27 0.00 0.00 109/12001 ~:<method 'split' of 'str'
objects>(0) [61]
1.61 0.00 0.00 179/145030 ~:<isinstance>(0) [16]
0.15 0.00 0.00 160/16000 ~:<method 'capitalize' of 'str'
objects>(0) [74]
0.28 0.00 0.00 109/24902 ~:<method 'join' of 'str'
objects>(0) [59]
========================
31.39 0.01 0.04 20/2000 sql.py:define_table(916) [30]
[5] 22.70 1.06 3.94 2000 sql.py:__init__(1074)
12.34 0.00 0.01 537/80500 sql.py:__getattr__(1132) [10]
30.68 0.00 0.01 20/17900 sql.py:__init__(1591) [4]
3.98 0.00 0.00 179/29300 sql.py:__setitem__(1118) [14]
2.27 0.00 0.00 100/11400 sql.py:__setattr__(1135) [37]
0.58 0.00 0.00 338/53451 ~:<method 'append' of 'list'
objects>(0) [38]
1.61 0.00 0.00 159/145030 ~:<isinstance>(0) [16]
0.03 0.00 0.00 20/2100 ~:<method 'insert' of 'list'
objects>(0) [143]
0.03 0.00 0.00 20/2000 sql.py:__init__(1033) [150]
=========================================================
1) When initialising, SQLField uses dir() call to find any clashes
with reserved names. That takes 11% of TOTAL execution
time, including controller and view. Very easy to optimise out -
for instance use 'migrate' as a flag that we running on production
environment so skip this check.
2) is_integer is a fast call, but with 1.1k (!) calls _per_singe_ GET request
makes it consume almost 8% of absolute processor time. I didn't research
though why it is used at all so can't comment if and how it could be optimised.
3) sqlhtml_validators is an obvious bug. It creates 9 different validators on
each call
and then throws out 8 of them! 8/9 of work is wasted. More than that - I suspect
that dictionary building may be moved into module namespace, moving this
function
far-far down in this list.
4) lazy tables init is on, but even with that SQLField.__init__ takes 30% (!!!)
of time. That expense happens mostly in the kids, but the function itself
takes a good share too. Definitely worths looking closer.
5) another __init__, now the SQLTable's. Same strings attached as to (4).
> Massimo
>
> On Jun 6, 1:14 am, Alexey Nezhdanov <snak...@gmail.com> wrote:
> > Switched to lazy table definitions.
> > Model init time was cut down to 0.046s.
> > Some of excess time is eliminated, some (my guess is 30%) is moved into
> > controller execution. At any rate - this is faster than before.
> >
> > Next step would be full-scale profiling but not yet.
> >
> > Here is excerpt from my SQLStorage:
> > --------------
> > def __getitem__(self, key):
> > value = dict.__getitem__(self, str(key))
> > if not callable(value) or key[0]=='_' or isinstance(value,
> > SQLCallableList): return value
> > value.__call__() # That must redefine table in-place
> > return dict.__getitem__(self, str(key))
> > ------------
> > and here is excerpt from my db.py:
> > ----------
> > def define_table_system_participant():
> > db.define_table('system_participant',
> > SQLField('firm_id','integer'),
> > migrate=migrate,
> > )
> > db.system_participant=define_table_system_participant
> > ----------
> >
> > On Saturday 06 June 2009 07:53:18 Alexey Nezhdanov wrote:
> > > ON Saturday 06 June 2009 00:25:47 mdipierro wrote:
> > > > One other trick you can try is replace
> > > >
> > > > db.define_table('table',SQLField('field'),...)
> > > > db.table.field.requires=....
> > > >
> > > > with
> > > >
> > > > db.define_table('table',SQLfield('field',requires=...),...)
> > > >
> > > > and so for all the other attributes.
> > >
> > > That will make minor difference. I do not have too many 'requires' and
> > > mod of what I have are set up through function call.
> > >
> > > > Did you bytecode compile the app?
> > > > Does it make a difference?
> > >
> > > I just run some automated tests. Here is average time over 100 runs
> > > each:
> > >
> > > sqlite+nomigrate+py 0.123
> > > sqlite+nomigrate+pyc 0.122
> > > mysql+nomigrate+py 0.123
> > > mysql+nomigrate+pyc 0.123
> > >
> > > I think I'll try this approach:
> > > 1) define each table as a function which yelds a table.
> > > 2) modify sql.py so that db object will test the type of table.
> > > if it has __exec__ method - execute it and replace it with return
> > > result.
> > >
> > > This way my tables will be lazily defined when controller actually
> > > needs them.
> > >
> > > > Massimo
> > > >
> > > > On Jun 5, 3:05 pm, Alexey Nezhdanov <snak...@gmail.com> wrote:
> > > > > On Friday 05 June 2009 21:03:20 mdipierro wrote:> Can you tell us
> > > > > more about the setup, os, hardward etc. is mysql on
> > > > >
> > > > > > the same machine?
> > > > >
> > > > > Kubuntu 8.04. Turion64 1.6GHz, 1.6G RAM. MySQL is on the same box.
> > > > > SiS motherboard w/ nForce chipset. Laptop 3 years old (and it was
> > > > > about 1 year old model when was bought).
> > > > >
> > > > > > How much is the the SQLDB() vs the define_tables? Do you have
> > > > > > many tables? how long?
> > > > >
> > > > > 16 tables, 152 SQLFields. single SQLDB (currently MySQL, but I'll
> > > > > switch it back to SQLite)
> > > > >
> > > > > > One trick is to add is statements in the model so that only those
> > > > > > tables needed are defined, depending on request.controller and
> > > > > > request.action.
> > > > >
> > > > > yes, I thought of that. But that makes it inflexible. That's why I
> > > > > suggested lazy tables init.
> > > > >
> > > > > And regarding 'turion is not very fast'. I don't really have any
> > > > > load on this box. So 0.5 seconds per GET is VERY slow. 8-years old
> > > > > Celeron 800 should be behaving something like 0.05 seconds per
> > > > > request (of course with ad-hoc programming, no DAL).
> > > > >
> > > > > This is not the empty complaint. We can't really afford saying
> > > > > 'throw in more CPU'. If web2py targets GAE - then it absolutely
> > > > > must be CPU-friendly. GAE can help with adding more nodes but it
> > > > > charges for processor time anyways. And actually the same goes
> > > > > about dedicated hosting too. If someone targets only a few visitors
> > > > > per day - it's ok. But not if we want tens and hundreds pageloads
> > > > > per second.
> > > > >
> > > > > > On Jun 5, 11:29 am, Alexey Nezhdanov <snak...@gmail.com> wrote:
> > > > > > > On Friday 05 June 2009 17:07:55 mdipierro wrote:> In a
> > > > > > > production environment you would be using mysql or postgresql.
> > > > > > > In
> > > > > > >
> > > > > > > > this case you should be using
> > > > > > > >
> > > > > > > > SQLDB(...,pool_size=10)
> > > > > > > > dn.define_table(....,migrate=False)
> > > > > > > >
> > > > > > > > the connection pooling and migrations off make a big
> > > > > > > > difference. Perhaps you can run some tests and quantify this.
> > > > > > >
> > > > > > > migrate=False makes cuts the model init time in half - now I'm
> > > > > > > getting about 0.15-0.17s each time. Testing MySQL, stand by...
> > > > > > >
> > > > > > > Hmmm.
> > > > > > > 0.21...0.25s with mysql and migrations off... and pool_size=10.
> > > > > > >
> > > > > > > > When using sqlite you cannot use pooling and that means
> > > > > > > > web2py has to open the db every time.
> > > > > > > >
> > > > > > > > Massimo
> > > > > > > >
> > > > > > > > On Jun 5, 2:58 am, Alexey Nezhdanov <snak...@gmail.com> wrote:
> > > > > > > > > Hello again.
> > > > > > > > > Recently I measured the perfomance of web2py regarding to
> > > > > > > > > 'milliseconds per request'. Got some unexpected results.
> > > > > > > > > The most slow part of the application is the model. It
> > > > > > > > > takes 40-60% of total time. Measurement was done simply by
> > > > > > > > > putting import time;print time.time(),'model start'
> > > > > > > > > at the beginning of db.py and similar line at the end of
> > > > > > > > > it. Here is what it produces on my laptop (Turion64,
> > > > > > > > > 1.6GHz, 1.5G RAM):
> > > > > > > > >
> > > > > > > > > 1244187446.32 model start
> > > > > > > > > 1244187446.62 model stop
> > > > > > > > > 0.3 second just to set up the model! I can live with 0.05
> > > > > > > > > for it, may be even 0.1, but 0.3 for _each_ GET or POST
> > > > > > > > > request is a bit too much, don't you think?
> > > > > > > > > That is for not too complex model - 17 tables, averaging
> > > > > > > > > 8.6 SQLFields per one. On another web2py project it takes
> > > > > > > > > 0.38...0.42 second each time
> > > > > > > > >
> > > > > > > > > :(
> > > > > > > > >
> > > > > > > > > I tried compiling my app and measuring again:
> > > > > > > > > 1244187625.31 model start
> > > > > > > > > 1244187625.69 model stop
> > > > > > > > > Not any better. In fact, it's even worse, but since results
> > > > > > > > > vary from run to run I suspect that it is just the same
> > > > > > > > > perfomance.
> > > > > > > > >
> > > > > > > > > Massimo, as I know you've been working on new model for
> > > > > > > > > some time already. Is there any hope of having a faster
> > > > > > > > > model? I suspect more lazy evaluation should do the magic,
> > > > > > > > > but I didn't do any research yet.
> > > > > > > > >
> > > > > > > > > Frankly speaking when I first discovered the fact that
> > > > > > > > > web2py always _executes_ model, controller, view, I thought
> > > > > > > > > that it may be a perfomance hog. Until I actually did that
> > > > > > > > > check I thought that it will execute db.py each time it
> > > > > > > > > changes on-disk and then just keep built structures
> > > > > > > > > somewhere around, probably pickled. May be it is still
> > > > > > > > > possible to use that approach to some extent?
> > > > > > > > >
> > > > > > > > > Or may be I am just completely missing the point. Please
> > > > > > > > > comment.
> > > > > > > > >
> > > > > > > > > --
> > > > > > > > > Sincerely yours
> > > > > > > > > Alexey Nezhdanov
> > > > > > >
> > > > > > > --
> > > > > > > Sincerely yours
> > > > > > > Alexey Nezhdanov
> > > > >
> > > > > --
> > > > > Sincerely yours
> > > > > Alexey Nezhdanov
> >
> > --
> > Sincerely yours
> > Alexey Nezhdanov
>
>
--
Sincerely yours
Alexey Nezhdanov
--~--~---------~--~----~------------~-------~--~----~
You received this message because you are subscribed to the Google Groups
"web2py Web Framework" group.
To post to this group, send email to web2py@googlegroups.com
To unsubscribe from this group, send email to
web2py+unsubscr...@googlegroups.com
For more options, visit this group at
http://groups.google.com/group/web2py?hl=en
-~----------~----~----~----~------~----~------~--~---
