albert, I think you mean builtins (globals is module-global scope so it would not help much if any). But this should be in a different ticket.
-- 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) _______________________________________________ Mailing list: https://launchpad.net/~c2c-oerpscenario Post to : [email protected] Unsubscribe : https://launchpad.net/~c2c-oerpscenario More help : https://help.launchpad.net/ListHelp
