Should create_uid/write_uid use lazy loading?

Support Developer
1

The following code:

products = Product.search([], order=[('id', 'ASC')], limit=500)
logger.info('Before: %s', t)
products[0].cost_price
logger.info('Elapsed: %s', t)

where t is a Timer class that helps measuring elapsed time results in as much as 3.6452 seconds in a real world database.

cProfile shows the following (just measuring products[0].cost_price):

Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
 312791/1    0.080    0.000    5.786    5.786 field.py:328(__get__)
  28001/1    0.444    0.000    5.786    5.786 modelstorage.py:1401(__getattr__)
     76/1    0.009    0.000    5.783    5.783 modelsql.py:682(read)
        1    0.000    0.000    5.782    5.782 function.py:84(get)
        2    0.006    0.003    5.782    2.891 function.py:106(<genexpr>)
        1    0.000    0.000    5.776    5.776 function.py:96(call)
      501    0.001    0.000    5.773    0.012 function.py:101(<genexpr>)
      500    0.001    0.000    5.772    0.012 multivalue.py:55(_multivalue_getter)
      500    0.002    0.000    5.768    0.012 model.py:21(get_multivalue)
      500    0.001    0.000    5.765    0.012 multivalue.py:43(get_multivalue)
      500    0.001    0.000    5.704    0.011 multivalue.py:37(__values)
      500    0.001    0.000    4.912    0.010 model.py:12(multivalue_records)
    86035    0.508    0.000    4.182    0.000 modelstorage.py:1493(instantiate)
--- cut ---

Although we only request 500 records, 86035 objects are instantiated. This is because cost_price is a MultiValue field and fetches the information from product.cost_price model.

However, that’s still a lots of instances and I tried making create_uid/write_uid fields use lazy loading (after all those fields are hardly ever used I guess). Here’s the output after this change:

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
 270693/1    0.067    0.000    4.073    4.073 field.py:328(__get__)
  28001/1    0.326    0.000    4.073    4.073 modelstorage.py:1401(__getattr__)
     76/1    0.008    0.000    4.070    4.070 modelsql.py:682(read)
        1    0.000    0.000    4.069    4.069 function.py:84(get)
        2    0.002    0.001    4.069    2.034 function.py:106(<genexpr>)
        1    0.000    0.000    4.067    4.067 function.py:96(call)
      501    0.000    0.000    4.062    0.008 function.py:101(<genexpr>)
      500    0.001    0.000    4.061    0.008 multivalue.py:55(_multivalue_getter)
      500    0.002    0.000    4.057    0.008 model.py:21(get_multivalue)
      500    0.001    0.000    4.053    0.008 multivalue.py:43(get_multivalue)
      500    0.001    0.000    4.002    0.008 multivalue.py:37(__values)
      500    0.001    0.000    3.446    0.007 model.py:12(multivalue_records)
    43929    0.311    0.000    2.730    0.000 modelstorage.py:1493(instantiate)
  --- cut ---

Only 50% of instances created, and the execution time drops to 2.5985 seconds (still a lot of time, but 30% less).

Time measured with cprofile disabled.

What do you think? Should we make create_uid/write_uid use lazy loading?

Other tricks we should use to lower the number of instances created? I’m wondering if the cache should just store id’s by default and create instances only if the field is actually accessed in any of the records of the cache.

2

Indeed it will probably be better to lazy instanciate all Many2One. By that I mean that for now, we have only one boolean attribute for loading which is used for two different thing (but linked). The pre-SELECT of column in search query (to fill the cache) and the instantiation/setup in ModelStorage.__getattr__. I think Many2One are a special case which does not fit well in the binary choice. It should be pre-SELECTed but not instantiated. The Reference field is also in the same situation (but by default it is lazy because less often used).
So I think we may introduce a third option.

3

I don’t understand the need for a third option. I understand that a third option could be useful if preSELECTING and instantiating brought some kind of performance advantage in some cases. But AFAIU instantiating on demand would be as fast as pre-instantiating. Isn’t it?

4

Instantiating has virtue also. If you know that the field will be used anyway, it avoid going through the __getattr__ machinery.
Indeed I even think it will be great to have a way to customize on runtime for a specific browse case the loading attribute of each field.

5

Yes, I think that would be great.

6

I did another test in another process. In this case, in the receive() button of a stock.shipment.in with a shipment with 250 lines.

Execution time on version 5.4: 186 seconds

Then, I changed the loading to ‘lazy’ for all Many2One fields and execution time goes down to just 7 seconds.

7

I must clarify that both measures where with profiling enabled and that the first execution (the one taking 186 seconds) already had applied a patch that made create_uid and write_uid load lazily.

8

I was very impressive about this results so I decided to make a similar test in 5.0 with a shipment (in) with 200 lines. But I haven’t got those great results …

  • with current loading configuration (eager) execution time was: 166 seconds
  • with lazy loading as default value for all many2one execution time was: 106 seconds.

It is a 36% of improvement on execution time, not bad … but too far from your results. I will test on 5.4.

9

Probable the performance depends on the number of diferent products on the supplier lines.

It will be great if you can share a script (in proteus or using trytond-console) in order to create the shipment with 200 lines and test the computation of 200 lines. This will allow everyone to test with the same values and have more similar results.

10

That’s simply because:

  • Version 5.4 executes the purchase’s “process” method in a worker. And although I did not have the workers enabled
  • I only tested part of the execution of the receive method

But if you use verson 5.4 and use the workers you may get similar results.

11

If you do not have any workers there should be no diference as the task is executed add the end of the transaction.

12

Version 4.8 executes process in batch and on the write operation. It is not comparable.

13

All moves are from same product.

I did a little script for adding moves to an existing shipment in a filled database. I will try to completed it to execute on an empty one.

Indeed 5.0 has workers as well and I tested without enable them.
But as I said on the other post I want to test it on 5.4 to discard code refactoring among versions.

Same here: receive an shipment in with no purchase.

14

Probably the difference is due to the modules installed.

For example, in my database there’s the production and many other modules installed. Production itself adds several m2o fields to stock moves, so in my case it’s going to be slower without the patch. And thus the patch will have a more positive impact.

There could be other factors: the size of the database, the hardware…

I don’t think it’s worth trying to reproduce exactly the same performance improvement. +30% is already a huge difference and you can easily reproduce such a gain in lots of places if you have enough records and m2o fields in the model (although create_uid/write_uid are already enough to see the difference).

15

I can not reproduce your performance on latest trunk. I’ve created a proteus script (see below) to create 200 products and add a shipment which recives 4 units of one of them. I’ve run on a postgresql database with stock, sale, stock_lot and production modules activated. Here are my results:

With eager loading:

Shipment created 0:00:07.425063
Shipment received 0:00:02.891001
Shipment done 0:00:01.724375

With lazy loading:

Shipment created 0:00:06.377097
Shipment received 0:00:02.791547
Shipment done 0:00:01.463134

Here is the script:

import datetime                                                                
from decimal import Decimal                                                    
                                                                               
from proteus import Model, config                                              
                                                                               
config.set_trytond()                                                           
                                                                               
Product = Model.get('product.product')                                         
products = Product.find([])                                                    
if not products:                                                               
    print('Creating products')                                                 
    Uom = Model.get('product.uom')                                             
    unit, = Uom.find([('symbol', '=', 'u')])                                   
    Template = Model.get('product.template')                                   
    templates = []                                                             
    for i in range(200):                                                       
        template = Template()                                                  
        template.name = 'Product %s' % (i + 1)                                 
        template.type = 'goods'                                                
        template.default_uom = unit                                            
        template.list_price = Decimal(0)                                       
        product, = template.products                                           
        product.code = 'PROD%s' % (i + 1)                                      
        product.cost_price = Decimal(0)                                        
        templates.append(template)                                             
    Template.save(templates)                                                   
    products = Product.find([])                                                
                                                                               
ShipmentIn = Model.get('stock.shipment.in')                                    
Location = Model.get('stock.location')                                         
warehouse_loc, = Location.find([('code', '=', 'WH')])                          
Party = Model.get('party.party')                                               
party, = Party.find([], limit=1)                                               
                                                                               
start = datetime.datetime.now()                                                
print('Creating shipment')                                                     
shipment = ShipmentIn()                                                        
shipment.supplier = party                                                      
for product in products:                                                       
    move = shipment.inventory_moves.new()                                      
    move.from_location = party.supplier_location                               
    move.to_location = shipment.warehouse.input_location                       
    move.product = product                                                     
    move.quantity = 4.0                                                        
    move.unit_price = product.cost_price                                       
shipment.save()                                                                
print('Shipment created', (datetime.datetime.now() - start))                   
start = datetime.datetime.now()                                                
shipment.click('receive')                                                      
print('Shipment received', (datetime.datetime.now() - start))                  
start = datetime.datetime.now()                                                
shipment.click('done')                                                         
print('Shipment done', (datetime.datetime.now() - start))
16

As I said, the performance improvement will highly depend on the number of modules you’ve installed.

Your simple script already shows 15% performance improvement in several of the steps you showed.

Add several m2o fields and you’ll probably see a bigger difference.

17

But the issue may also come because a module has something that is not properly implemented. So the module must be fixed and not anything else.

Which fields do I have to add? AFAIK there aren’t so much Many2One fields on the stock.shipmen.in and stock.move models.

What it’s strange to me is that receiving a shipment with 260 lines lasts for 160seconds. This is a huge amount of time and it reduced.

Are you using average cost price? This may add some seconds to compute the cost price but probably not as much.

BTW I’ve just modified the script to also create the purchase and here are the results:

With lazy loading:

Purchase created 0:00:49.893981
Purchase confirmed 0:00:01.399725
Creating shipment
Shipment created 0:00:00.426459
Shipment received 0:00:01.103032
Shipment done 0:00:00.494885

With eager loading:

Purchase created 0:00:52.913379
Purchase confirmed 0:00:01.365182
Creating shipment
Shipment created 0:00:00.453029
Shipment received 0:00:01.195862
Shipment done 0:00:00.490862

Note that i’ve reduced the number of products to 100 because the for each purchase line proteus calls on_change_lines to recompute the amounts and this was slowing the testing.

But for the shipment reception part I get very similar results comparing the patch and without the patch.

Here is the modified script if you want to test it:

import datetime
from decimal import Decimal

from proteus import Model, config

config.set_trytond()

Product = Model.get('product.product')
products = Product.find([('purchasable', '=', 'True')])
if not products:
    print('Creating products')
    Uom = Model.get('product.uom')
    unit, = Uom.find([('symbol', '=', 'u')])
    Template = Model.get('product.template')
    Category = Model.get('product.category')
    category = Category()
    category.accounting = True
    category.name = 'category'
    category.save()
    templates = []
    for i in range(100):
        template = Template()
        template.name = 'Product %s' % (i + 1)
        template.type = 'goods'
        template.default_uom = unit
        template.purchasable = True
        template.salable = True
        template.list_price = Decimal(0)
        template.account_category = category
        product, = template.products
        product.code = 'PROD%s' % (i + 1)
        product.cost_price = Decimal(0)
        templates.append(template)
    Template.save(templates)
    products = Product.find([('purchasable', '=', True)])

Purchase = Model.get('purchase.purchase')
ShipmentIn = Model.get('stock.shipment.in')
Location = Model.get('stock.location')
Move = Model.get('stock.move')
warehouse_loc, = Location.find([('code', '=', 'WH')])
Party = Model.get('party.party')
party, = Party.find([], limit=1)

start = datetime.datetime.now()
print('Create purchase')
purchase = Purchase()
purchase.party = party
purchase.purchase_date = datetime.date.today()
for product in products:
    line = purchase.lines.new()
    line.product = product
    line.quantity = 4.0
    print(product.rec_name)
purchase.save()
print('Purchase created', (datetime.datetime.now() - start))
start = datetime.datetime.now()
purchase.click('quote')
purchase.click('confirm')
print('Purchase confirmed', (datetime.datetime.now() - start))

start = datetime.datetime.now()
print('Creating shipment')
shipment = ShipmentIn()
shipment.supplier = party
for move in purchase.moves:
    incoming_move = Move(id=move.id)
    shipment.incoming_moves.append(incoming_move)
shipment.save()
print('Shipment created', (datetime.datetime.now() - start))
start = datetime.datetime.now()
shipment.click('receive')
print('Shipment received', (datetime.datetime.now() - start))
start = datetime.datetime.now()
shipment.click('done')
print('Shipment done', (datetime.datetime.now() - start))

It will be great to share some way to reproduce your performance issues.

18

I’m wondering if this changeset is what produces most diference on the patch.

I’ve done my test with this change applied so if fields are already on the cache they will not be loaded providing a speedup!

19

Here is Issue 10026: Instantiate only requested field attribute - Tryton issue tracker which should bring the best of the two loading behavior for the Many2One and Reference without any change in the field definition.

20

Thanks for proposing a patch. Did you test any the provided scripts to see if there is any performance gain in the mentionen cases?