openerp-community team mailing list archive

[Grahame Jordan <gbj@xxxxxxxxxxxxxxx>]

Hi,

I have a problem with the mrp scheduler when running on 7,000 products.

I am running on 2 x quad core 3.0GHz, 32 GB RAM, RAID10 SSD for DB, 
Ubuntu 12.04 LTS. V6.1.

When running from Warehouse -> Schedulers -> Compute Schedulers the 
performance is as expected. ~30 minutes to complete on 4351 procurements.

When running from ir.cron the performance is up to 20x worse.  6 - 10 hours.

Is there some extra overhead when running from ir.cron?
Is it possible to enhance this?

Some timings below to show the problem. The first one is from manually 
invoking the scheduler, the second is invoked from ir.cron.
Read from the bottom to the top.

2013-12-18 04:48:21,854 8706 INFO ? procurement: 
procurement.order._procure_orderpoint_confirm(): #1: qty: 385         
START::             44/100 : 2144/4351 : 2144 : V75-4x2.5
2013-12-18 04:48:21,884 8706 INFO ? stock: 
stock.move.create_chained_picking(): #1:                  
TIMING::            0.002s
2013-12-18 04:48:21,887 8706 INFO ? procurement: 
procurement.order._procure_orderpoint_confirm(): #6: button_confirm:  
TIMING::            0.048s
2013-12-18 04:48:21,911 8706 INFO ? procurement: 
procurement.order.check_produce(): #3:                  
TIMING::                    0.015s
2013-12-18 04:48:21,949 8706 INFO ? mrp: 
procurement.order.make_mo():                             #1: 
prod.create():   TIMING::                    0.036s
2013-12-18 04:48:21,985 8706 INFO ? mrp: 
mrp.bom._bom_explode():                                  #1: bom 
:          TIMING::                           0.005s
2013-12-18 04:48:21,985 8706 INFO ? mrp_geicp: 
mrp.production.action_compute():                   #1: bom :           
TIMING::                           0.026s
2013-12-18 04:48:21,986 8706 INFO ? mrp_geicp: 
mrp.production.action_compute():                   #2: :          
TIMING::                           0.000s
2013-12-18 04:48:22,050 8706 INFO ? mrp_geicp: 
mrp.production.workcenter.line.create():           #1: super:           
TIMING::                               0.107s
2013-12-18 04:48:22,074 8706 INFO ? mrp_geicp: 
mrp.production.workcenter.line.reset_states():     #1: :           
TIMING::                                   0.039s
2013-12-18 04:48:22,074 8706 INFO ? mrp_geicp: 
mrp.production.workcenter.line.create():           #2: reset_states():  
TIMING::                               0.040s
2013-12-18 04:48:22,142 8706 INFO ? mrp_geicp: 
mrp.production.workcenter.line.create():           #1: super:           
TIMING::                               0.113s
2013-12-18 04:48:22,178 8706 INFO ? mrp_geicp: 
mrp.production.workcenter.line.reset_states():     #1: :           
TIMING::                                   0.059s
2013-12-18 04:48:22,178 8706 INFO ? mrp_geicp: 
mrp.production.workcenter.line.create():           #2: reset_states():  
TIMING::                               0.060s
2013-12-18 04:48:22,258 8706 INFO ? mrp_geicp: 
mrp.production.workcenter.line.create():           #1: super:           
TIMING::                               0.134s
2013-12-18 04:48:22,305 8706 INFO ? mrp_geicp: 
mrp.production.workcenter.line.reset_states():     #1: :           
TIMING::                                   0.078s
2013-12-18 04:48:22,305 8706 INFO ? mrp_geicp: 
mrp.production.workcenter.line.create():           #2: reset_states():  
TIMING::                               0.079s
2013-12-18 04:48:22,381 8706 INFO ? mrp_geicp: 
mrp.production.workcenter.line.create():           #1: super:           
TIMING::                               0.126s
2013-12-18 04:48:22,437 8706 INFO ? mrp_geicp: 
mrp.production.workcenter.line.reset_states():     #1: :           
TIMING::                                   0.092s
2013-12-18 04:48:22,437 8706 INFO ? mrp_geicp: 
mrp.production.workcenter.line.create():           #2: reset_states():  
TIMING::                               0.093s
2013-12-18 04:48:22,437 8706 INFO ? mrp_geicp: 
mrp.production.action_compute():                   #3: :          
TIMING::                           0.752s
2013-12-18 04:48:22,479 8706 INFO ? mrp_geicp: 
mrp.production.update_production_bom_information():#1: :           
TIMING::                               0.070s
2013-12-18 04:48:22,505 8706 INFO ? mrp_geicp: 
mrp.production.update_production_bom_information():#2: :           
TIMING::                               0.043s
2013-12-18 04:48:22,534 8706 INFO ? mrp_geicp: 
mrp.production.update_production_bom_information():#3: :           
TIMING::                               0.048s
2013-12-18 04:48:22,534 8706 INFO ? mrp_geicp: 
mrp.production.action_compute():                   #4: update:          
TIMING::                           0.162s
2013-12-18 04:48:22,534 8706 INFO ? mrp: 
mrp.production.test_if_product():                        #1: 
action_compute:  TIMING::                        0.966s
2013-12-18 04:48:22,573 8706 INFO ? mrp: 
procurement.order.make_mo():                             #3: 
button_confirm:  TIMING::                    1.040s
2013-12-18 04:48:22,573 8706 INFO ? mrp_geicp: 
procurement.order.make_mo():                       #1: super.make_mo()  
TIMING::                1.079s
2013-12-18 04:48:22,582 8706 INFO ? procurement: 
procurement.order._procure_orderpoint_confirm(): #7: button_check:    
TIMING::            1.158s



2013-12-18 03:59:53,691 7820 INFO ? procurement: 
procurement.order._procure_orderpoint_confirm(): #1: qty: 3075        
START::             60/100 : 1460/4351 : 1460 : 50-100-0812
2013-12-18 03:59:54,182 7820 INFO ? stock: 
stock.move.create_chained_picking(): GBJ #0: moves = 
[browse_record(stock.move, 405450)] : context = None
2013-12-18 03:59:54,196 7820 INFO ? stock: stock.move.action_confirm(): 
#1:                  TIMING::            0.12s : 0.12s
2013-12-18 03:59:54,295 7820 INFO ? procurement: 
procurement.order._procure_orderpoint_confirm(): #6: button_confirm:  
TIMING::            0.856s
2013-12-18 03:59:54,581 7820 INFO ? procurement: 
procurement.order.check_produce(): #3:                  
TIMING::                    0.07s
2013-12-18 03:59:54,913 7820 INFO ? mrp: 
procurement.order.make_mo():                             #1: 
prod.create():   TIMING::                    0.33s
2013-12-18 03:59:56,177 7820 INFO ? mrp_geicp: 
mrp.production.action_compute():                   #1: bom :           
TIMING::                           0.261s
2013-12-18 03:59:56,177 7820 INFO ? mrp_geicp: 
mrp.production.action_compute():                   #2: :          
TIMING::                           0.000s
2013-12-18 03:59:56,873 7820 INFO ? mrp_geicp: 
mrp.production.workcenter.line.create():           #1: super:           
TIMING::                               1.160s
2013-12-18 03:59:57,084 7820 INFO ? mrp_geicp: 
mrp.production.workcenter.line.reset_states():     #1: :           
TIMING::                                   0.350s
2013-12-18 03:59:57,084 7820 INFO ? mrp_geicp: 
mrp.production.workcenter.line.create():           #2: reset_states():  
TIMING::                               0.351s
2013-12-18 03:59:57,786 7820 INFO ? mrp_geicp: 
mrp.production.workcenter.line.create():           #1: super:           
TIMING::                               1.170s
2013-12-18 03:59:58,111 7820 INFO ? mrp_geicp: 
mrp.production.workcenter.line.reset_states():     #1: :           
TIMING::                                   0.541s
2013-12-18 03:59:58,111 7820 INFO ? mrp_geicp: 
mrp.production.workcenter.line.create():           #2: reset_states():  
TIMING::                               0.542s
2013-12-18 03:59:58,831 7820 INFO ? mrp_geicp: 
mrp.production.workcenter.line.create():           #1: super:           
TIMING::                               1.200s
2013-12-18 03:59:59,269 7820 INFO ? mrp_geicp: 
mrp.production.workcenter.line.reset_states():     #1: :           
TIMING::                                   0.729s
2013-12-18 03:59:59,269 7820 INFO ? mrp_geicp: 
mrp.production.workcenter.line.create():           #2: reset_states():  
TIMING::                               0.730s
2013-12-18 04:00:00,001 7820 INFO ? mrp_geicp: 
mrp.production.workcenter.line.create():           #1: super:           
TIMING::                               1.219s
2013-12-18 04:00:00,542 7820 INFO ? mrp_geicp: 
mrp.production.workcenter.line.reset_states():     #1: :           
TIMING::                                   0.901s
2013-12-18 04:00:00,542 7820 INFO ? mrp_geicp: 
mrp.production.workcenter.line.create():           #2: reset_states():  
TIMING::                               0.902s
2013-12-18 04:00:01,273 7820 INFO ? mrp_geicp: 
mrp.production.workcenter.line.create():           #1: super:           
TIMING::                               1.218s
2013-12-18 04:00:01,915 7820 INFO ? mrp_geicp: 
mrp.production.workcenter.line.reset_states():     #1: :           
TIMING::                                   1.069s
2013-12-18 04:00:01,915 7820 INFO ? mrp_geicp: 
mrp.production.workcenter.line.create():           #2: reset_states():  
TIMING::                               1.070s
2013-12-18 04:00:01,915 7820 INFO ? mrp_geicp: 
mrp.production.action_compute():                   #3: :          
TIMING::                           9.563s
2013-12-18 04:00:02,421 7820 INFO ? mrp_geicp: 
mrp.production.update_production_bom_information():#1: :           
TIMING::                               0.843s
2013-12-18 04:00:02,652 7820 INFO ? mrp_geicp: 
mrp.production.update_production_bom_information():#2: :           
TIMING::                               0.385s
2013-12-18 04:00:03,043 7820 INFO ? mrp_geicp: 
mrp.production.update_production_bom_information():#3: :           
TIMING::                               0.652s
2013-12-18 04:00:03,043 7820 INFO ? mrp_geicp: 
mrp.production.action_compute():                   #4: update:          
TIMING::                           1.880s
2013-12-18 04:00:03,043 7820 INFO ? mrp: 
mrp.production.test_if_product():                        #1: 
action_compute:  TIMING::                        13.44s
2013-12-18 04:00:03,310 7820 INFO ? mrp: 
procurement.order.make_mo():                             #3: 
button_confirm:  TIMING::                    14.00s
2013-12-18 04:00:03,488 7820 INFO ? procurement: 
procurement.order._procure_orderpoint_confirm(): #7: button_check:    
TIMING::            15.323s


Appreciate your expert help and insight.

Grahame Jordan