c2c-oerpscenario team mailing list archive
-
c2c-oerpscenario team
-
Mailing list archive
-
Message #04571
[Bug 624114] Re: Translation (GettextAlias _() ) performance bug? too slow to be usable (>1 sec per call)
Closing for addons, as this really should be handled on the server side
** Summary changed:
- [5.0] Translation (GettextAlias _() ) performance bug? too slow to be usable (>1 sec per call)
+ Translation (GettextAlias _() ) performance bug? too slow to be usable (>1 sec per call)
** Changed in: openobject-addons
Status: Triaged => Invalid
--
Translation (GettextAlias _() ) performance bug? too slow to be usable (>1 sec per call)
https://bugs.launchpad.net/bugs/624114
You received this bug notification because you are a member of C2C
OERPScenario, which is subscribed to the OpenERP Project Group.
Status in OpenObject Addons Modules: Invalid
Status in OpenObject Server: Confirmed
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)
