c2c-oerpscenario team mailing list archive
-
c2c-oerpscenario team
-
Mailing list archive
-
Message #08213
[Bug 624114] Re: Translation (GettextAlias _() ) performance bug? too slow to be usable (>1 sec per call)
This should be vastly improved after server revision 3114
odo@xxxxxxxxxxx-20101215121143-f1hgn5cp92alzdvx in trunk.
The call to inspect.stack() has been removed, the heuristics to locate
the language and cursor have been improved, and we now even attempt to
use the cache from ir.translation if available, by calling _get_source
instead of hitting the DB every time.
Profiling shows a nice difference, for example during a simple call to
action_ship_create() with mrp_jit (as in your example), I see this
difference:
Revision 3112: 4.17s, with __call__ (translate.py:183), 11 calls, cumulative time: 2.92918s (70.19% total time)
Revision 3114: 1.07s, with __call__ (translate.py:200), 11 calls, cumulative time: 0.00371s (00.36% total time)
Notice the difference in the percentage of the total time used by _( ),
not just the decreased overall duration.
** Changed in: openobject-server
Status: In Progress => Fix Released
--
You received this bug notification because you are a member of C2C
OERPScenario, which is subscribed to the OpenERP Project Group.
https://bugs.launchpad.net/bugs/624114
Title:
Translation (GettextAlias _() ) performance bug? too slow to be usable (>1 sec per call)
Status in OpenObject Addons Modules:
Invalid
Status in OpenObject Server:
Fix Released
Bug description:
The current implementation of the translation method "_()" seems to be extremely slow (about 1 second per call) on some circumstances, to the point that is the most time consuming method on some business process.
For example the confirming a sale order, with mrp_jit installed, will take about 40 seconds!
- Of those, about 28.44 seconds are spent on 27 calls to _() on the _check_make_to_stock_product calculation. And most of that time is spent by Python, not Postgres.
- The rest of the _check_make_to_stock_product calculation takes less than 5 total seconds on the 27 calls to it.
We profiled the action_ship_create method (of sale orders) with several methods, and the only conclusion is that the _() method (from tools.translate import _) is too slow to be usable (though it is used everywhere on OpenERP!!!), while the translate() method (from tools.translate import translate) proved to be hundreds of time faster.
Now we wonder:
- Is this a a general problem? (a problem with the current implementation of "_()" that relies on the inspect module)
- Should _() be deprecated? (and use "translate()" instead, which is lots of times faster?).
Now the proof:
--- BASIC TIME.TIME() PROFILING -------------------------------------------------------------
To do a basic profiling, just edit the GettextAlias source code, and where it looks like this:
class GettextAlias(object):
def __call__(self, source):
try:
frame = inspect.stack()[1][0]
except:
return source
Replace it with this to get the timings:
class GettextAlias(object):
def __call__(self, source):
import time
start = time.time()
try:
frame = inspect.stack()[1][0]
except:
return source
stop = time.time()
print "GettextAlias time: ", stop-start
Confirming one sale order will call the _() method 27 times, these are the timings of those 27 calls:
GettextAlias time: 1.10414505005
GettextAlias time: 1.10945105553
GettextAlias time: 1.10807609558
GettextAlias time: 0.989851951599
GettextAlias time: 0.996656179428
GettextAlias time: 0.986680030823
GettextAlias time: 1.00202202797
GettextAlias time: 1.01647782326
GettextAlias time: 0.956711053848
GettextAlias time: 1.03200602531
GettextAlias time: 0.976341962814
GettextAlias time: 1.1115489006
GettextAlias time: 0.962368965149
GettextAlias time: 1.09971618652
GettextAlias time: 1.02273511887
GettextAlias time: 0.996299982071
GettextAlias time: 0.975975036621
GettextAlias time: 1.00379395485
GettextAlias time: 1.00497484207
GettextAlias time: 1.08288192749
GettextAlias time: 0.96357011795
GettextAlias time: 1.02459406853
GettextAlias time: 0.991461038589
GettextAlias time: 0.961183071136
GettextAlias time: 0.976219892502
GettextAlias time: 0.969728946686
GettextAlias time: 1.00834703445
GettextAlias time: 1.00862288475
--- PROFILING WITH PROFILE - STATS -------------------------------------------------------------
This is the trace of a profile (http://docs.python.org/library/profile.html) of the action_ship_create method of the sale orders, sorted by cumulative time. Notice how 68.9 seconds are spent on the translate.py module (marked with **** for easier look up):
>>> stats.sort_stats("cumulative").print_stats()
Wed Aug 25 16:53:45 2010 prof.dat
37130567 function calls (37126505 primitive calls) in 78.907 CPU seconds
Ordered by: cumulative time
ncalls tottime percall cumtime percall filename:lineno(function)
1 0.000 0.000 78.911 78.911 /openerp-server/bin/tools/misc.py:941(__call__)
1 0.001 0.001 78.911 78.911 /openerp-server/bin/addons/sale/sale.py:570(action_ship_create_orig)
303/13 0.010 0.000 78.396 6.030 /openerp-server/bin/workflow/workitem.py:44(process)
37/4 0.001 0.000 78.372 19.593 /openerp-server/bin/workflow/wkf_service.py:75(trg_validate)
142/8 0.007 0.000 78.369 9.796 /openerp-server/bin/workflow/workitem.py:34(create)
220/12 0.010 0.000 78.367 6.531 /openerp-server/bin/workflow/workitem.py:148(_split_test)
37/4 0.001 0.000 78.367 19.592 /openerp-server/bin/workflow/instance.py:45(validate)
105/4 0.003 0.000 78.336 19.584 /openerp-server/bin/workflow/workitem.py:179(_join_test)
243/28 0.004 0.000 78.143 2.791 /openerp-server/bin/workflow/wkf_expr.py:44(_eval_expr)
208/24 0.016 0.000 78.140 3.256 {eval}
181/24 0.003 0.000 78.120 3.255 /openerp-server/bin/osv/orm.py:167(<lambda>)
142/20 0.002 0.000 77.939 3.897 /openerp-server/bin/workflow/workitem.py:86(_execute)
72/10 0.001 0.000 77.895 7.789 /openerp-server/bin/workflow/wkf_expr.py:67(execute)
3 0.000 0.000 77.622 25.874 /openerp-server/bin/addons/cc_mrp_packing_bom/mrp_procurement.py:32(action_produce_assign_product)
3 0.001 0.000 77.578 25.859 /openerp-server/bin/addons/mrp/mrp.py:1041(action_produce_assign_product)
3 0.010 0.003 76.721 25.574 /openerp-server/bin/addons/mrp/mrp.py:630(action_confirm)
28 0.002 0.000 68.910 2.461 /openerp-server/bin/tools/translate.py:128(__call__) ***********************************
28 0.000 0.000 68.909 2.461 /usr/lib/python2.5/inspect.py:882(stack)
28 0.025 0.001 68.909 2.461 /usr/lib/python2.5/inspect.py:858(getouterframes)
2887 0.057 0.000 68.881 0.024 /usr/lib/python2.5/inspect.py:820(getframeinfo)
442/440 0.004 0.000 68.565 0.156 /openerp-server/bin/workflow/wkf_expr.py:70(check)
27 0.001 0.000 67.363 2.495 /openerp-server/bin/addons/mrp/mrp.py:939(check_make_to_stock)
27 0.003 0.000 67.023 2.482 /openerp-server/bin/addons/mrp/mrp.py:1025(_check_make_to_stock_product)
6983 29.313 0.004 65.240 0.009 /usr/lib/python2.5/inspect.py:408(getmodule)
2887 0.049 0.000 47.001 0.016 /usr/lib/python2.5/inspect.py:454(findsource)
5778/5774 0.177 0.000 43.856 0.008 /usr/lib/python2.5/inspect.py:381(getsourcefile)
12041505 18.983 0.000 26.680 0.000 /usr/lib/python2.5/inspect.py:35(ismodule)
12223925 7.889 0.000 7.889 0.000 {isinstance}
--- PROFILING WITH PROFILE - CALLERS -------------------------------------------------------------
Ok, now we now that a lot of time is spent on the __call__ method of GettextAlias (that has _ as an alias/shortcut). Now the question is: who is calling it and how many times? and the answer is:
>>> stats.sort_stats("t").print_callers('__call__')
Ordered by: internal time
List reduced from 333 to 2 due to restriction <'__call__'>
Function was called by...
ncalls tottime cumtime
/openerp-server/bin/tools/translate.py:128(__call__) <- 1 0.000 2.816 /openerp-server/bin/addons/mrp/mrp.py:1018(action_move_assigned)
27 0.001 66.094 /openerp-server/bin/addons/mrp/mrp.py:1025(_check_make_to_stock_product)
/openerp-server/bin/tools/misc.py:941(__call__) <- 1 0.000 78.911 <string>:1(<module>)
So, _() is called 27 times from _check_make_to_stock_product (taking 66 seconds), and one time from action_move_assigned (taking 2.8 seconds). The _check_make_to_stock_product method looks like this:
def _check_make_to_stock_product(self, cr, uid, procurement, context={}):
ok = True
if procurement.move_id:
id = procurement.move_id.id
if not (procurement.move_id.state in ('done','assigned','cancel')):
ok = ok and self.pool.get('stock.move').action_assign(cr, uid, [id])
cr.execute('select count(id) from stock_warehouse_orderpoint where product_id=%s', (procurement.product_id.id,))
if not cr.fetchone()[0]:
cr.execute('update mrp_procurement set message=%s where id=%s', (_('from stock and no minimum orderpoint rule defined'), procurement.id))
return ok
And the sentence that is taking one second per call is the single "_('from stock and no minimum orderpoint rule defined')".
--- PROFILING WITH TRANSLATE() INSTEAD OF _() -------------------------------------------------------------
If we replace this line (that uses _):
cr.execute('update mrp_procurement set message=%s where id=%s', (_('from stock and no minimum orderpoint rule defined'), procurement.id))
With this one (that uses translate):
cr.execute('update mrp_procurement set message=%s where id=%s', (translate(cr, None, 'code', context.get('lang'), 'from stock and no minimum orderpoint rule defined'), procurement.id))
Then the time (with profiling enabled) is reduced to 10.498 seconds (instead of 68 seconds)!!!:
>>> stats2.sort_stats("cumulative").print_stats()
Wed Aug 25 17:12:19 2010 prof2.dat
900222 function calls (896164 primitive calls) in 10.494 CPU seconds
Ordered by: cumulative time
ncalls tottime percall cumtime percall filename:lineno(function)
1 0.000 0.000 10.498 10.498 /srv/openerp/openerp5/branches/5.0/openerp-server/bin/tools/misc.py:941(__call__)
1 0.001 0.001 10.498 10.498 /srv/openerp/openerp5/branches/5.0/openerp-server/bin/addons/sale/sale.py:570(action_ship_create_orig)
303/13 0.011 0.000 9.967 0.767 /home/omar/Escritorio/openerp-server/5.0/bin/workflow/workitem.py:44(process)
37/4 0.001 0.000 9.951 2.488 /srv/openerp/openerp5/branches/5.0/openerp-server/bin/workflow/wkf_service.py:75(trg_validate)
37/4 0.001 0.000 9.946 2.487 /home/omar/Escritorio/openerp-server/5.0/bin/workflow/instance.py:45(validate)
220/12 0.011 0.000 9.939 0.828 /home/omar/Escritorio/openerp-server/5.0/bin/workflow/workitem.py:148(_split_test)
142/8 0.007 0.000 9.938 1.242 /home/omar/Escritorio/openerp-server/5.0/bin/workflow/workitem.py:34(create)
105/4 0.003 0.000 9.913 2.478 /home/omar/Escritorio/openerp-server/5.0/bin/workflow/workitem.py:179(_join_test)
243/28 0.004 0.000 9.718 0.347 /home/omar/Escritorio/openerp-server/5.0/bin/workflow/wkf_expr.py:44(_eval_expr)
208/24 0.017 0.000 9.715 0.405 {eval}
181/24 0.003 0.000 9.695 0.404 /srv/openerp/openerp5/branches/5.0/openerp-server/bin/osv/orm.py:167(<lambda>)
142/20 0.002 0.000 9.501 0.475 /home/omar/Escritorio/openerp-server/5.0/bin/workflow/workitem.py:86(_execute)
72/10 0.001 0.000 9.457 0.946 /home/omar/Escritorio/openerp-server/5.0/bin/workflow/wkf_expr.py:67(execute)
3 0.000 0.000 9.165 3.055 /srv/openerp/openerp5/branches/5.0/openerp-server/bin/addons/cc_mrp_packing_bom/mrp_procurement.py:32(action_produce_assign_product)
3 0.001 0.000 9.117 3.039 /srv/openerp/openerp5/branches/5.0/openerp-server/bin/addons/mrp/mrp.py:1041(action_produce_assign_product)
3 0.011 0.004 8.288 2.763 /srv/openerp/openerp5/branches/5.0/openerp-server/bin/addons/mrp/mrp.py:630(action_confirm)
8382 0.054 0.000 6.611 0.001 /srv/openerp/openerp5/branches/5.0/openerp-server/bin/sql_db.py:73(wrapper)
4624 0.278 0.000 6.540 0.001 /srv/openerp/openerp5/branches/5.0/openerp-server/bin/sql_db.py:109(execute)
5114/5026 0.378 0.000 5.786 0.001 /srv/openerp/openerp5/branches/5.0/openerp-server/bin/osv/orm.py:154(__getitem__)
4866/4788 0.033 0.000 5.635 0.001 /srv/openerp/openerp5/branches/5.0/openerp-server/bin/osv/orm.py:237(__getattr__)
4624 5.130 0.001 5.201 0.001 {method 'execute' of 'psycopg2._psycopg.cursor' objects}
1328/1140 0.382 0.000 5.000 0.004 /srv/openerp/openerp5/branches/5.0/openerp-server/bin/osv/orm.py:2221(read)
1409/1140 0.444 0.000 4.359 0.004 /srv/openerp/openerp5/branches/5.0/openerp-server/bin/osv/orm.py:2256(_read_flat)
124 0.062 0.001 3.053 0.025 /srv/openerp/openerp5/branches/5.0/openerp-server/bin/osv/orm.py:2742(create)
442/440 0.004 0.000 2.587 0.006 /home/omar/Escritorio/openerp-server/5.0/bin/workflow/wkf_expr.py:70(check)
131/125 0.025 0.000 1.499 0.012 /srv/openerp/openerp5/branches/5.0/openerp-server/bin/osv/orm.py:2506(write)
30 0.003 0.000 1.428 0.048 /srv/openerp/openerp5/branches/5.0/openerp-server/bin/addons/mrp/mrp.py:991(action_confirm)
27 0.001 0.000 1.341 0.050 /srv/openerp/openerp5/branches/5.0/openerp-server/bin/addons/mrp/mrp.py:939(check_make_to_stock)
50/48 0.001 0.000 1.133 0.024 /srv/openerp/openerp5/branches/5.0/openerp-server/bin/osv/fields.py:654(get)
40 0.002 0.000 1.112 0.028 /srv/openerp/openerp5/branches/5.0/openerp-server/bin/osv/orm.py:2943(_store_set_values)
27 0.003 0.000 0.976 0.036 /srv/openerp/openerp5/branches/5.0/openerp-server/bin/addons/mrp/mrp.py:1025(_check_make_to_stock_product)
