web2py perfomance

[Alexey Nezhdanov]

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

[mdipierro]

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.

When using sqlite you cannot use pooling and that means web2py has to
open the db every time.

Massimo

[Alexey Nezhdanov]

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.

[mdipierro]

Can you tell us more about the setup, os, hardward etc. is mysql on
the same machine?
How much is the the SQLDB() vs the define_tables? Do you have many
tables? how long?

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.

[mdipierro]

BTW... I had a Turion64. It is not a very fast machine.

[Alexey Nezhdanov]

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.

[mdipierro]

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.

Did you bytecode compile the app?

Does it make a difference?

Massimo

[Alexey Nezhdanov]

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.

[Alexey Nezhdanov]

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
----------

[mdipierro]

interesting. Perhaps this could default in new dal.

[DenesL]

Very interesting.
How about creating a test case app that people could run to report
performance results on different platforms and CPUs?.

[mdipierro]

I think it is a great idea.

Anyway, I would like to remind people the following web2py command
line option:

-F PROFILER_FILENAME, --profiler=PROFILER_FILENAME
profiler filename


Massimo

[vihang]

Very interesting mod.

@Massimo, as mentioned about the requires statement, is there a way to
address the following directly in the field definition?

db.some_table.field1.requires = IS_NOT_IN_DB(db,db.some_table.field1)

On Jun 6, 7:51 pm, mdipierro <mdipie...@cs.depaul.edu> wrote:
> I think it is a great idea.

> ,

[Hans Donner]

yep,
add requires=IS_NOT_IN_DB(db,db.some_table.field1)
in the SQField(....) statement as an argument

[mdipierro]

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.

Massimo

[Alexey Nezhdanov]

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).

[vihang]

Hans, that won't work if you are refering to the same db which is
being created (circular reference issue)...

On Jun 6, 11:23 pm, Hans Donner <hans.don...@pobox.com> wrote:
> yep,
> add requires=IS_NOT_IN_DB(db,db.some_table.field1)
> in the SQField(....) statement as an argument
>

[Alexey Nezhdanov]

On Sunday 07 June 2009 11:13:49 Alexey Nezhdanov wrote:
> 1) When initialising, SQLField uses dir() call to find any clashes
> with reserved names.

I was a bit incorrect here. It checks for already defined fields too.
Anyways - I optimised it by commenting it out :-P
In practice I'd recommend similar approach:
1) don't check for clashes in the production environment (SQLDB init
parameter?)
2) (optional) maintain cache of names for each table. Don't use dir().

> 2) is_integer is a fast call, but with 1.1k (!) calls ...
Replaced it with my own version:
integer_pat=re.compile('[0-9]+$')
is_integer=lambda x: integer_pat.match(x)
it's about 2.3 times faster. C version would be even better.

> 3) sqlhtml_validators is an obvious bug... 8/9 of work is wasted.
> ... I suspect that dictionary building may be moved into module namespace
did that with some tweaks (same validators get reused). Dangerous approach
may introduce hidden dataflow, but that could be prevented by somehow making
these validators read-only.

Got another 9.5% model time speedup. (0.096s vs 0.106s). Though this figures
get more and more meaningless as model init time reduces it's share in total
page generation time. Probably I'll just switch to time measuring of
urllib.urlopen().

...OK, switched. Here are stats. Each line is in the format
model_init_time/urlopen_measured_time - average over 100 calls
These timings are not comparable with my previous emails because I did some
additional arrangements that should make these times more than usual, but
more stable across tests. Also application is compiled this time.

1) no optimisations
0.1219/0.1649
2) skip CREATE TABLE in SQLTable init
0.0865/0.1261
3) + three steps, described above in this mail.
0.0439/0.0855
4) + lazy tables init in model
This one is application specific. For instance in my application it causes
4 tables out of 16 to be initialised in model and 2 more - in controller. This
is for front page. Other pages will have different figures. Yet, here are
timings:
0.0194/0.0622

5) And finally, for mere comparison, timings of (4) again, but this time with
non-compiled source.
0.0208/0.1216

Some conclusions:
1) always compile your app for production. It saves you about 50% CPU.
2) With very little effort it was possible to speedup web2py app further 2.65
times, dropping page generation times from tenths of second to hundredths.
I hope at least some of that work will find it's way into mainline. I'm
attaching all patches that I used to this mail. These patches are against
quite old web2py - Version 1.61.4 (2009-04-21 10:02:50) (I didn't like how
newer versions looked like so I stick to initially installed version).

[Iceberg]

On Jun7, 3:13pm, Alexey Nezhdanov <snak...@gmail.com> wrote:
> 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()

Just a remind. The try...except clause above should better change into
this one.
try:
query=t._create(...)
finally:
sql_locker.release()
Only in this way, any exception (if any) inside t._create(...) can
show its correct break point, rather than the line "raise e".

> BTW - your reminder on '-F' flag moved me into running some profiling.
> I use my own stats analyzer wich produces gprof2-like output.

> ...

> A short explanation for the people who didn't use gprof2 yet.

> ...

> Each line has the following format:
> (1) [index] - only the function in question has it

BTW, how to get a gprof2 output when profiling a python script and/or
a web2py instance? Google "gprof2 python" did not give much help, I
must be blind. :-/
I really like the "[index] - only the function in question has it",
which seems lack in the default standard python profiling module.
Thanks in advance.

[Alexey Nezhdanov]

On Sunday 07 June 2009 14:36:24 Iceberg wrote:
> > 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()
> Just a remind. The try...except clause above should better change into
> this one.

That's reminder to Massimo :) In that code sample I have only one line (if:)
everything other was there before me.

> try:
> query=t._create(...)
> finally:
> sql_locker.release()
> Only in this way, any exception (if any) inside t._create(...) can
> show its correct break point, rather than the line "raise e".

yes, and even better would be
with sql_locker:
query=....
just two lines - instead of 5 with the same breakpoint benefit.
On the other hand - it requires doing
from __future__ import with_statement
and that WILL break python 2.4 compartibility once again.

[mdipierro]

Alexey, you did an excellent job at identifying the problem. I will
look at your solutions and probably incorporate them.

Massimo

[Iceberg]

On Jun7, 6:35pm, Alexey Nezhdanov <snak...@gmail.com> wrote:
>
> > 2) is_integer is a fast call, but with 1.1k (!) calls ...
>
> Replaced it with my own version:
> integer_pat=re.compile('[0-9]+$')
> is_integer=lambda x: integer_pat.match(x)
> it's about 2.3 times faster. C version would be even better.
>

If so, perhaps this is even better:

integer_pat=re.compile('[0-9]+$')
is_integer=integer_pat.match

Because lambda is considered as much slower than built-in functions,
AFAIK.

[mdipierro]

Most of your patches are in but:

- is_integer: I am following Iceberg's suggestion

- skip_table_create: as proposed would have borken something so had to
move some code out of _create and in SQLTable.__init__. It i better
this way anyway

- no_dir_check: instead of removing it, I made it faster busing
hasattr and no more calls to dir

- validators, as proposed cannot be done. validators have customizable
error messages. they cannot be global, there must be one per field.

- lazy_define_table: I have not included this yet because it would be
more appropriate to implement a SQLTableLazy class. Before I do this I
would like to know how much speed-up we got already and what different
would the lazy tables do.

Thanks you Alexey. These were great patches and really made web2py
better.
Can you run your test again please and then we'll work on this more?

Massimo

>  is_integer.diff
> < 1KViewDownload
>
>  lazy_define_table.diff
> < 1KViewDownload
>
>  validators.diff
> 1KViewDownload
>
>  no_dir_check.diff
> < 1KViewDownload
>
>  skip_create_table.diff
> < 1KViewDownload

[mdipierro]

BTW... why you did not like the newer versions 1.63.5?

[mdipierro]

The way to fix it is to use SQLField(...,"reference [table]") instead
of SQLField(...,db[table])
This syntax is already supported and it must be required for lazy
tables.

It is still a problem to make lazy evals work with IS_IN_DB and
IS_NOT_IN_DB

anyway, we made so many improvements that perhaps lazy evals will be
less important... let's way for more tests from Alexey.

Massimo

[Alexey Nezhdanov]

On Sunday 07 June 2009 15:49:31 Iceberg wrote:
> On Jun7, 6:35pm, Alexey Nezhdanov <snak...@gmail.com> wrote:
> > > 2) is_integer is a fast call, but with 1.1k (!) calls ...
> >
> > Replaced it with my own version:
> > integer_pat=re.compile('[0-9]+$')
> > is_integer=lambda x: integer_pat.match(x)
> > it's about 2.3 times faster. C version would be even better.
>
> If so, perhaps this is even better:
>
> integer_pat=re.compile('[0-9]+$')
> is_integer=integer_pat.match

OH! You win almost 1.5 times.
2.340s vs mine 0m3.328s for 20k operations.

> Because lambda is considered as much slower than built-in functions,
> AFAIK.

--
Sincerely yours
Alexey Nezhdanov

[Alexey Nezhdanov]

On Sunday 07 June 2009 16:10:10 mdipierro wrote:
> BTW... why you did not like the newer versions 1.63.5?

I'm all for simplistic designs.
I didn't like these things:
1) session.flash as semi-transparent window over content.
2) popup menus. I prefer clicking on them
3) I wasn't able to find site admin link from the first time. Found it only on
next day or may be ever the next day after that. Before I had to navigate
through menu of admin for current application.

P.S. Let me run some tests now.
Thank you for incorporating these changes. I knew that they couldn't be there
as is - because I knew that I possible breaking other people's apps. But
these changes were too effective to not try.

[mdipierro]

I see. But that is just the scaffoling app. Keep the old welcome.w2p
if you like or make your own scaffolding app (replace welcome.w2p with
any packed app). There are many bug fixes in the library and new
features that you would otherwise miss.

Massimo

[Alexey Nezhdanov]

On Sunday 07 June 2009 16:09:40 mdipierro wrote:
> Can you run your test again please and then we'll work on this more?

I don't have bzr installed (and not really want to) and didn't find how to
download tree tip out of launchpad. So I just downloaded single sql.py
and put it into gluon/. That should be fine since my changes are at any
rate only for sql.py.
Under the same conditions I got this figures for upstream sql.py:
0.0646/0.1044
As I understand - that should be compared to my

>3) + three steps, described above in this mail.
>0.0439/0.0855

So about 18% slower than in my case but still 1.58 times faster than
yesterday.
I'll run profiling now and provide it as attachment.
...
attached. Also for a reference I attach sql.py which is a stock version from
BZR with only one line commented out (json support) to let it live with older
web2py.
...
oh...I looked into profile file and then into sql.py.
You omitted the validators patch completely. Why?
W/o it all that testing is loss of time. :(

I need to go now. I'll provide backwards-compartible validators patch when I
return (something like 5 hours from now).

[Alexey Nezhdanov]

You are right. Somehow I thought that if I upgrade - I'll get new design to my
(already existing app). :)
Will upgrade later today.

[mdipierro]

I implemented a backward compatible speedup of the default validators.
I also realized that those many calls to is_integer could be avoided.
I think I fixed it.

Please check out the latest trunk.

Massimo

[Alexey Nezhdanov]

On Sunday 07 June 2009 18:41:30 mdipierro wrote:
> I implemented a backward compatible speedup of the default validators.
> I also realized that those many calls to is_integer could be avoided.
> I think I fixed it.

0.0429/0.0844
Somehow consistency is not kept across reboots :(
... about a hour later: and actually now I get about 10% noise so it become
very hard to make any good measurements. I'll try tomorrow on better
hardware. In the meanwhile, I'll try to profile it once again.
...
ok, there are still two perfomance hogs left: SQLTable.__init__ (about 11%)
and SQLField.__init__ (about 6,5%). These percentages are 'self' times - i.e.
it was spent directly in lines 1099-1149, 1693-1752.
Python profiling doesn't allow to attribute CPU consumption to individual
lines so for now I don't have any more precise pointers. But that could be
split into functional blocks and narrowed further down.

In any case - we collected almost all low-hanging fruits. Any further
optimisation will give gains of range 2-5%, not times anymore.

Except lazy tables which still may give tens of percents. BTW - Massimo, you
said something about SQLLazyTable class. You should implement SQLLazyField
too then. Or may be just wait a day or two until I do deeper profiling.

> Please check out the latest trunk.
>
> Massimo
>

P.S. Here is small fix to is_integer. We forgot about negative numbers:
Also this version is tiny bit faster
is_integer=re.compile('-?[\d]+).match

[Alexey Nezhdanov]

Hi again.
Here are another testing results.

First of all, let me remind you about is_integer bug. It doesn't allow
negative numbers. Correct code is:
is_integer=re.compile('-?[\d]+).match

Now. I've run more timings, more profiling and more code tweaks.
This time it was Core2 Duo @2.20GHz with 1G RAM. Ubuntu 8.04.
Testing strategy: 20 sets of 1000 GET requests to the main page. Same
application as before. For each set I have average GET request time.
For a group of 20 sets I get minimum average, global average and
maximum average. Also I have average model init time for 20k requests
(no splitting into each set).

1) Upstream sql.py
model 0.01646
min 0.02979
avg 0.03267
max 0.03597

2) Optimised SQLTable.__init__ and SQLField.__init__ (patches
attached, backwards compartible, though you may want to remove my
testing marks)
model 0.01380
min 0.02697
avg 0.03003
max 0.03189
So - about 8% speedup (by avg time) here.

3) Now lazy tables (patch attached).
Since I expect that you will not find any objections to my patches for
(2) here are cumulative results, i.e. optimised __init__s + lazy
tables
...
hmmm. It doesn't improves results significantly anymore. It looks like
these patches are interchangeable. I've run my test three times,
results are:

model 0.01009
min 0.02555
avg 0.0297105
max 0.033360

model 0.01012
min 0.02369
avg 0.02983
max 0.03340

model 0.00966
min 0.02415
avg 0.02850
max 0.03208

So it makes some improvement about 1%-5% but somehow it also makes
testing results more disperse. Do not know if it worths including.
Massimo, your opinion?

4) Also I've tried to further speedup validator generation w/o losing
backwards compartibility, but improvement was about 1% and below the
margin of error (even less noticeable than with lazy tables).

[mdipierro]

Thanks Alexey, since these tests are on a different architecture, can
you give the total relative speedup on the same architecture for
executing your original model (code in trunk vs original code)?

Massimo

On Jun 8, 5:49 am, Alexey Nezhdanov <snak...@gmail.com> wrote:
> Hi again.
> Here are another testing results.
>
> First of all, let me remind you about is_integer bug. It doesn't allow
> negative numbers. Correct code is:
> is_integer=re.compile('-?[\d]+).match

This is not a bug. Since ID values cannot be negative.

>  x_table.diff
> 6KViewDownload
>
>  x_field.diff
> 2KViewDownload
>
>  lazy_define_table2.diff
> 2KViewDownload

[Alexey Nezhdanov]

On Monday 08 June 2009 17:57:36 mdipierro wrote:
> Thanks Alexey, since these tests are on a different architecture, can
> you give the total relative speedup on the same architecture for
> executing your original model (code in trunk vs original code)?

You see, I switched to another architecture because testing it on my laptop
become unreliable and obtaining more-or-less stable values required a lot of
time. Powersave and CPU frequency scaling features kick in and introduce a
great deal of noise. So I switched to powerful desktop to run tests at high
speed in greater volume to gain at least one more digit of preciseness.

And may be you missed it - I actually provided comparison numbers. See below.
If you want me to measure also old code (2 days old) on same box - I'll do
that.

> > First of all, let me remind you about is_integer bug. It doesn't allow
> > negative numbers. Correct code is:
> > is_integer=re.compile('-?[\d]+).match
>
> This is not a bug. Since ID values cannot be negative.

Then it is a bug in name. It should be is_id_int or is_non_negative_int.

Here are the figures for the code in trunk

> > 1) Upstream sql.py
> > model 0.01646
> > min 0.02979
> > avg 0.03267
> > max 0.03597

Here are the figures for the first two patches. They give about 8% speedup.

> > 2) Optimised SQLTable.__init__ and SQLField.__init__ (patches
> > attached, backwards compartible, though you may want to remove my
> > testing marks)
> > model 0.01380
> > min 0.02697
> > avg 0.03003
> > max 0.03189
> > So - about 8% speedup (by avg time) here.

Here are the figures for the last patch. Uncertain 1-5% speedup.

[mdipierro]

I understand what you say below but I think it is important to measure
the total speedup from the original/stable sql.py and the one in trunk
on the same machine and same complex model that you have.

Massimo

[Alexey Nezhdanov]

On Monday 08 June 2009 19:18:26 mdipierro wrote:
> I understand what you say below but I think it is important to measure
> the total speedup from the original/stable sql.py and the one in trunk
> on the same machine and same complex model that you have.

NP, it is running right now. Quite slow, will finish in ~10minutes.

Preliminary results (10 sets:)
min 0.05579
avg 0.055944
max 0.05611
model time unknown

That is against revision 875.

[Alexey Nezhdanov]

On Monday 08 June 2009 19:27:29 Alexey Nezhdanov wrote:
> On Monday 08 June 2009 19:18:26 mdipierro wrote:
> > I understand what you say below but I think it is important to measure
> > the total speedup from the original/stable sql.py and the one in trunk
> > on the same machine and same complex model that you have.
>
> NP, it is running right now. Quite slow, will finish in ~10minutes.

Revision 875:
model 0.04167
min 0.05579
avg 0.0559455
max 0.05647

Revision 882:

model 0.01646
min 0.02979
avg 0.03267
max 0.03597

882+optimised inits:

model 0.01380
min 0.02697
avg 0.03003
max 0.03189

882+optimised inits + lazy tables:

model 0.01009
min 0.02555
avg 0.0297105
max 0.033360

model 0.01012
min 0.02369
avg 0.02983
max 0.03340

model 0.00966
min 0.02415
avg 0.02850
max 0.03208

--
Sincerely yours
Alexey Nezhdanov

[mdipierro]

So for everybody.... let me summarize this:

Thanks to Alexey,
the web2py in trunk can execute models 2.5x faster than the current
stable/production version (requires migrate=False and bytecode
compiled models). This is a general result since each define_table
speeds up the same. For his particular app, this results on a speedup
of 70% when serving pages (this number depends on the app).

There is also the possibility of an additional 70% speedup of the
models by implementing additional tricks. We'll keep working on this.

Massimo

[JorgeR]

Thats really good news.

Thank you massimo, and alexey (for pointing this out).

;)

[Alexey Nezhdanov]

В сообщении от Monday 08 June 2009 19:54:35 mdipierro написал(а):

> So for everybody.... let me summarize this:
>
> Thanks to Alexey,
> the web2py in trunk can execute models 2.5x faster than the current
> stable/production version (requires migrate=False and bytecode
> compiled models). This is a general result since each define_table
> speeds up the same. For his particular app, this results on a speedup
> of 70% when serving pages (this number depends on the app).
>
> There is also the possibility of an additional 70% speedup of the
> models by implementing additional tricks. We'll keep working on this.

A pity really that we didn't yet hit 100% barrier.
If you don't mind - I'll continue working on it.
And btw - I just realised that my 'optimised inits' patch is not optimal. I
can do it better. Stand by.

> Massimo

[Markus Gritsch]

On Mon, Jun 8, 2009 at 5:54 PM, mdipierro<mdip...@cs.depaul.edu> wrote:
>
> the web2py in trunk can execute models 2.5x faster than the current
> stable/production version (requires migrate=False and bytecode
> compiled models).

Will this speedup also has an effect on GAE? IMO one uploads no .pyc files?

Markus

[mdipierro]

Good point.

None of the issue discussed has yet been implemented on GAE. Some can
implemented, some not.

Tonight I will implement some of the same tricks on GAE. The effect
will not be as big (2.5x) but I expect to be significant.

yes, the problem with GAE is the impossibility to upload pyc files.
pyc files are cached but only speed up hot request, not cold requests.

Massimo

On Jun 8, 1:05 pm, Markus Gritsch <m.grit...@gmail.com> wrote:

[Alexey Nezhdanov]

Somehow I got confused in so many similar-named sql.py's floating around.
So I decided to re-run all tests to make sure that now I'm really using
revisions that I claim that I use. Got very strange results.

Long story short - I got too much noise into my results. It seems that trunk
currently only about 40% faster than stable, not 70%.

As it appears - it is very important if I have any print statements in my
application. I had couple in the model, then I commented them out.
Somehow that decreased(!!!) perfomance by about 1/3.

I'll not be doing any more work today. Have to work out new plan. Probably we
won't hit 100% barrier :(

I'm sorry guys. So much excitement...

[mdipierro]

This is still good news because I assume your originally benchmark of
stable (which appeared to be slow) already contained the print
statement. This means that stable is already 30% faster than computed
(with print statements).

[mdipierro]

Please try launchpad 893. I think it should be faster on GAE.
We can do better with lazy tables but at least the validators and
calls to getitem are eliminated.

Massimo

On Jun 8, 1:05 pm, Markus Gritsch <m.grit...@gmail.com> wrote:

[Alexey Nezhdanov]

Ok. Now the confusion is resolved.
1) Speed improvements of 70% and up that I reported yesterday are
really exist. I just reproduced a 3.47 times model speedup and 2.15
overall speedup for my app (r875 vs r822+inits).
BUT this app is atypical. I have added some time measuring code there
so it prints out two lines per each model init. So when I am testing
perfomance - screen very quickly scrolls up

2) Simply commenting out two print statements gives me only 1.67
overall speedup given equal other conditions. I think that processor
receive additional interrupts from videocard that in turn results in
more often checks of tasks queue.

3) I declare all my previous testing results spoiled by noise
generated by print statement and inappropriate kernel scheduler
setting.
I've set up yet another test box with these parameters:

Intel Core2 Duo 2.66GHz, 2G RAM, Ubuntu 9.04, 'server' flavour kernel
2.6.28-11.42. Initially I considered to install a 'realtime' kernel,
but it appeared to be unstable on that hardware (and afterall - it's
for sound/video processing and 'server' type is more likely to be
installed on servers).

Will report new testing results (and finally I hope to write
'optimised inits ver.2' patch) later today.

[Alexey Nezhdanov]

new testing:

---- SERVER KERNEL ----
--prints
r875 0.04898
r822ini 0.03070 1.60x
--silent
r875 0.04914
r822ini 0.03049 1.61x

So I get much more consistent results on this hardware.
While this is obviously not the best perfomance (my weaker box,
with less RAM, troubled with video output 1280x1024,
software 90deg rotation - performs BETTER), that does not matter.
What does - is that I can now be sure that these results are
noise-free so I can safely compare timings from various patches.
Proceeding with writing 'inits v2'.

[Yarko Tymciurak]

it might help to have tests in a state that you can ask others to run them;   a dozen or so other random boxes will help you gain the confidence you seek I think....

[Alexey Nezhdanov]

You probably right. But I can't give away the project I'm testing it
on and don't yet 'ready' to write a separate one exclusively for
testing.

I'm still fighting with getting stable results even on this box :(

[Alexey Nezhdanov]

Wrote 'optimised inits v2' patch. Tested everything.

Once again I changed my testing pattern a bit.

1) I dumped my own timing tool in favor of much more standard
'ab' (apache benchmark).

2) I decidedly will publish all these results in two main.
I just finished first round of testing. Here are results (reported
values are average request time in milliseconds. If anyone interested
- I'm attaching a full output from my console).
I will do all that testing again and publish same results again so
that the amount of noise in all this will be public and clearly
visible (here I'm fighting with my own temptation to rerun the tests
if timings seem to be 'too away' to me).

First four lines share my app's db.py. Last two require a modified
db.py, but modification is cosmetical - each define_table is put into
separate function and I do db.tablename=create_table_tablename after
each function. Model init time was not measured.

No more words. Dry figures only. Each line represents result of 10k requests.
r875 46.025ms
r882 21.048ms
inits v.1 18.918ms
inits v.2 18.122ms
inits1+lazyT 16.032ms
inits2+lazyT 14.391ms

P.S. I'm surprised about last line... Noise?

[Alexey Nezhdanov]

Results of second set of test runs:

r875 45.523ms
r882 20.614ms
inits v.1 18.464ms
inits v.2 18.677ms
inits1+lazyT 15.377ms
inits2+lazyT 15.280ms

Observed noise was 0.502ms for slowest execution (90:1
signal-to-noise) and 0.889ms for fastest execution (16:1
signal-to-noise).
Given than, I think it is safe enough to say that
"this particular application on this particular hardware/OS
combination was sped up 2.88...3.31 times".

As in last case - for completeness I'm attaching full console output

I think I know what I'll do. Currently I do not want to release my
project as any kind of open-source. But I can
1) Strip out any code I do not use in this perfomance testing
2) rename all sensitive fieldnames/variables to something like field1,
field2, var3, var4.
Release resulting package. It would be useless as it is, but it will
have same perfomance parameters so could be used for testing.

[Alexey Nezhdanov]

Forgot about patches. Here they are.
'optimised inits v.2'
'lazy tables' (this one is modified to be applicable to trunk version of sql.py)

[Alexey Nezhdanov]

Finally, I started migration (before I was just slapping sql.py, checked out of the trunk over my ancient 1.61.4 install).
Migration is not easy, I've been bending source for my needs so now I have to port all this to 1.63.5. Massimo, do you have any objections to this patch? I proposed it some time ago, but you were too busy at the time.
The purpose is - if we want custom forms instead of SQLFORM then we have to write our own view.html. But on the other hand - that is double work in the regard that we need to write down <input type='xxx' length='yyy' id='zzz' name='nnn' /> each time while we already generated all this in controller.
I'd really like to be able to write in my controller:
<table><tr>
<td>{{=form.custom.label.my_input}}</td>
<td>{{=form.custom.widget.my_input}}</td>
</tr></table>
See attached patch.

[Alexey Nezhdanov]

Wanted to attach test data as well but automatically clicked 'send' and oops... it gone.
Here are couple of test runs:
1.63.544.572

[Alexey Nezhdanov]

:( using web interface is inconvenient. Ignore last mail, resending:
-------------

Wanted to attach test data as well but automatically clicked 'send' and oops... it gone.
Here are couple of test runs:

1.63.5              44.572ms
1.63.5              44.898ms
detected noise 0.326ms (136:1 signal-to-noise).
full 'ab' output attached

[mdipierro]

This confirms the 2.5x speedup of trunk vs stable.
It will take me some time to go over the other patches but I will.
Thanks Alexey.

Massimo

On Jun 9, 6:10 am, Alexey Nezhdanov <snak...@gmail.com> wrote:
> Results of second set of test runs:
>
> r875            45.523ms
> r882            20.614ms
> inits v.1       18.464ms
> inits v.2       18.677ms
> inits1+lazyT    15.377ms
> inits2+lazyT    15.280ms
>
> Observed noise was 0.502ms for slowest execution (90:1
> signal-to-noise) and 0.889ms for fastest execution (16:1
> signal-to-noise).
> Given than, I think it is safe enough to say that
> "this particular application on this particular hardware/OS
> combination was sped up 2.88...3.31 times".
>
> As in last case - for completeness I'm attaching full console output
>
> I think I know what I'll do. Currently I do not want to release my
> project as any kind of open-source. But I can
> 1) Strip out any code I do not use in this perfomance testing
> 2) rename all sensitive fieldnames/variables to something like field1,
> field2, var3, var4.
> Release resulting package. It would be useless as it is, but it will
> have same perfomance parameters so could be used for testing.
>

> > On Tue, Jun 9, 2009 at 11:12 AM, Alexey Nezhdanov<snak...@gmail.com> wrote:
> >> new testing:
>
> >> ---- SERVER KERNEL ----
> >> --prints
> >> r875    0.04898
> >> r822ini 0.03070 1.60x
> >> --silent
> >> r875    0.04914
> >> r822ini 0.03049 1.61x
>
> >> So I get much more consistent results on this hardware.
> >> While this is obviously not the best perfomance (my weaker box,
> >> with less RAM, troubled with video output 1280x1024,
> >> software 90deg rotation - performs BETTER), that does not matter.
> >> What does - is that I can now be sure that these results are
> >> noise-free so I can safely compare timings from various patches.
> >> Proceeding with writing 'inits v2'.
>

> >> On Tue, Jun 9, 2009 at 10:43 AM, Alexey Nezhdanov<snak...@gmail.com> wrote:
> >>> Ok. Now the confusion is resolved.
> >>> 1) Speed improvements of 70% and up that I reported yesterday are
> >>> really exist. I just reproduced a 3.47 times model speedup and 2.15
> >>> overall speedup for my app (r875 vs r822+inits).
> >>> BUT this app is atypical. I have added some time measuring code there
> >>> so it prints out two lines per each model init. So when I am testing
> >>> perfomance - screen very quickly scrolls up
>
> >>> 2) Simply commenting out two print statements gives me only 1.67
> >>> overall speedup given equal other conditions. I think that processor
> >>> receive additional interrupts from videocard that in turn results in
> >>> more often checks of tasks queue.
>
> >>> 3) I declare all my previous testing results spoiled by noise
> >>> generated by print statement and inappropriate kernel scheduler
> >>> setting.
> >>> I've set up yet another test box with these parameters:
>
> >>> Intel Core2 Duo 2.66GHz, 2G RAM, Ubuntu 9.04, 'server' flavour kernel
> >>> 2.6.28-11.42. Initially I considered to install a 'realtime' kernel,
> >>> but it appeared to be unstable on that hardware (and afterall - it's
> >>> for sound/video processing and 'server' type is more likely to be
> >>> installed on servers).
>
> >>> Will report new testing results (and finally I hope to write
> >>> 'optimised inits ver.2' patch) later today.
>

> >>> On Tue, Jun 9, 2009 at 5:14 AM, mdipierro<mdipie...@cs.depaul.edu> wrote:
>
> >>>> Please try launchpad 893. I think it should be faster on GAE.
> >>>> We can do better with lazy tables but at least the validators and
> >>>> calls to getitem are eliminated.
>
> >>>> Massimo
>
> >>>> On Jun 8, 1:05 pm, Markus Gritsch <m.grit...@gmail.com> wrote:
> >>>>> On Mon, Jun 8, 2009 at 5:54 PM, mdipierro<mdipie...@cs.depaul.edu> wrote:
>
> >>>>> > the web2py in trunk can execute models 2.5x faster than the current
> >>>>> > stable/production version (requires migrate=False and bytecode
> >>>>> > compiled models).
>
> >>>>> Will this speedup also has an effect on GAE?  IMO one uploads no .pyc files?
>
> >>>>> Markus
>
>
>

>  ab-runs2.gz
> 1KViewDownload

[AchipA]

Any particular reason not doing is_integer via a 'try: int(i) except:
return False' statement ? It should be faster than regexes.

On Jun 7, 1:49 pm, Iceberg <iceb...@21cn.com> wrote:
> On Jun7, 6:35pm, Alexey Nezhdanov <snak...@gmail.com> wrote:
>
>
>
> > > 2) is_integer is a fast call, but with 1.1k (!) calls ...
>
> > Replaced it with my own version:
> > integer_pat=re.compile('[0-9]+$')
> > is_integer=lambda x: integer_pat.match(x)
> > it's about 2.3 times faster. C version would be even better.
>
> If so, perhaps this is even better:
>
>   integer_pat=re.compile('[0-9]+$')
>   is_integer=integer_pat.match
>
> Because lambda is considered as much slower than built-in functions,
> AFAIK.