c2c-oerpscenario team mailing list archive
-
c2c-oerpscenario team
-
Mailing list archive
-
Message #04572
[Bug 624114] Re: Translation (GettextAlias _() ) performance bug? too slow to be usable (>1 sec per call)
Basically we need to stop using 'inspect' just to access the last frames, because it is really only meant for debugging.
Obviously it will be O(n) according to the size of the stack, but it will also hit the disk to lookup line numbers in source code!
This refactoring is pending and will be merged before RC2.
Thanks for reporting!
** Changed in: openobject-server
Importance: Undecided => Medium
** Changed in: openobject-server
Status: Triaged => Confirmed
** Changed in: openobject-server
Milestone: None => 6.0-rc2
** Changed in: openobject-server
Assignee: (unassigned) => OpenERP's Framework R&D (openerp-dev-framework)
--
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)
