TOO MANY READS WHEN VIEWING A FORM VIEW: VERY SERIOUS PERF KILLER!

[Raphaël Valyi - http://www.akretion.com]

Hi,

When you are are in a tree view (products or partners for instance) and when you click on some item to display its form view, first the GTK client calls fields_view_get for the form view, and then it calls read. The big trouble is that instead too call read only for the selected resource, it calls it for ALL the items displayed in the tree!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!

The web-client on the contrary does it right.
On my PC, the GTK client is paying a 0.5 sec impact there when displaying a product in form view compared to the eTiny!!!!!!

I just instrumented my code to log server request and how long they take, in the server/bin/service/web_service.py, I changed the objects_proxy.execute method around line 366 into:

    def execute(self, db, uid, passwd, object, method, *args):
        security.check(db, uid, passwd)
        service = netsvc.LocalService("object_proxy")

        from mx import DateTime
        d1 = DateTime.now() #TODO remove
        res = service.execute(db, uid, object, method, *args)
        d2 = DateTime.now()
        print method + " " + str(args)
        print d2 - d1
        print "************"
        print "************"
        return res

Now here is what I get doing the explained scenario from my GTK client first:

1) Clicking on Products > Products (tree view):

get ('action', 'tree_but_open', [('ir.ui.menu', 126)], False, {'lang': u'en_US', 'tz': False})
00:00:00.03
************
************
fields_view_get (143, u'tree', {'lang': u'en_US', 'active_ids': [126], 'tz': False, 'active_id': 126}, True)
00:00:00.10
************
************
fields_view_get (False, 'form', {'lang': u'en_US', 'active_ids': [126], 'tz': False, 'active_id': 126})
00:00:00.23
************
************
fields_view_get (False, 'tree', {'lang': u'en_US', 'active_ids': [126], 'tz': False, 'active_id': 126})
00:00:00.01
************
************
search ([], 0.0, 80.0, 0, {'lang': u'en_US', 'active_ids': [126], 'tz': False, 'active_id': 126})
00:00:00.02
************
************
read ([1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14, 15, 16, 17, 18, 19, 20, 21, 22, 23, 24, 25, 26, 27, 28, 29, 30], ['virtual_available', 'name', 'price', 'standard_price', 'state', 'lst_price', 'default_code', 'qty_available', 'variants'], {'lang': u'en_US', 'bin_size': True, 'active_ids': [126], 'tz': False, 'active_id': 126})
00:00:00.11
************
************

2) Now selecting a product in the list to and clicking on it to display it in form view:

fields_view_get (False, u'form', {'lang': u'en_US', 'active_ids': [126], 'tz': False, 'active_id': 126}, True)
00:00:00.30
************
************
read ([1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14, 15, 16, 17, 18, 19, 20, 21, 22, 23, 24, 25, 26, 27, 28, 29, 30], ['warranty', 'property_stock_procurement', 'supply_method', 'uos_id', 'list_price', 'weight', 'ean13', 'incoming_qty', 'mes_type', 'uom_id', 'description_purchase', 'property_account_income', 'cost_method', 'is_maintenance', 'uos_coeff', 'procure_method', 'sale_ok', 'purchase_ok', 'product_manager', 'property_stock_account_output', 'track_outgoing', 'loc_rack', 'pricelist_sale', 'uom_po_id', 'type', 'property_stock_account_input', 'description', 'weight_net', 'property_stock_production', 'supplier_taxes_id', 'volume', 'outgoing_qty', 'active', 'property_stock_inventory', 'loc_row', 'loc_case', 'rental', 'packaging', 'sale_delay', 'pricelist_purchase', 'description_sale', 'property_account_expense', 'categ_id', 'track_production', 'track_incoming', 'taxes_id', 'produce_delay', 'seller_ids', 'unique_production_number'], {'lang': u'en_US', 'active_ids': [126], 'tz': False, 'active_id': 126})
00:00:00.69

The above is CRAZY: THIS IS COMPLETELY INSANE!!! Only one id (the selected one) should be read!
And notice that the server does answer all the stuff!!!

************
************
fields_view_get (False, 'tree', {'lang': u'en_US', 'tz': False}, False)
00:00:00.01
************
************
fields_view_get (False, 'tree', {'lang': u'en_US', 'tz': False}, False)
00:00:00.01
************
************
fields_view_get (False, 'tree', {'lang': u'en_US', 'tz': False}, False)
00:00:00.04
************
************
fields_view_get (False, 'tree', {'lang': u'en_US', 'tz': False}, False)
00:00:00.02
************
************
read ([5], ['delay', 'product_code', 'qty', 'name', 'sequence'], {'lang': u'en_US', 'tz': False})
00:00:00.03
************
************

#######################
#######################

Now doing the same from eTiny which does it correctly:
1) Tree view:

get ('action', 'tree_but_open', [(u'ir.ui.menu', 126)], False, {'lang': u'en_US', 'client': 'web', 'tz': False})
00:00:00.03
************
************
fields_view_get (143, u'tree', {'lang': u'en_US', '_view_name': u'Products', '_terp_target': u'current', 'client': 'web', 'tz': False, 'active_ids': [126], 'active_id': 126}, True)
00:00:00.07
************
************
search ([], 0, 80, 0, {'_view_name': u'Products', 'active_ids': [126], '_terp_target': u'current', 'active_id': 126})
00:00:00.02
************
************
search_count ([], {'_view_name': u'Products', 'active_ids': [126], '_terp_target': u'current', 'active_id': 126})
00:00:00.02
************
************
read ([1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14, 15, 16, 17, 18, 19, 20, 21, 22, 23, 24, 25, 26, 27, 28, 29, 30], ['virtual_available', 'name', 'price', 'standard_price', 'state', 'lst_price', 'default_code', 'qty_available', 'variants'], {'lang': u'en_US', '_view_name': u'Products', '_terp_target': u'current', 'client': 'web', 'tz': False, 'active_ids': [126], 'active_id': 126})
00:00:00.12
************
************
fields_view_get (False, 'form', {'lang': u'en_US', 'client': 'web', 'tz': False}, True)
00:00:00.34
************
************
fields_view_get (False, 'tree', {'lang': u'en_US', 'client': 'web', 'tz': False}, True)
00:00:00.07
************
************
search ([('osv', '=', u'product.product')], 0, 0, 0, {'lang': u'en_US', 'client': 'web', 'tz': False})
00:00:00.05
************
************

2) Form view: only one item is requested:

fields_view_get (False, 'form', {'lang': u'en_US', '_view_name': u'Products', '_terp_target': u'current', 'client': 'web', 'tz': False, 'active_ids': [126], 'active_id': 126}, True)
00:00:00.28
************
************
read ([3], ['warranty', 'property_stock_procurement', 'supply_method', 'uos_id', 'list_price', 'weight', 'ean13', 'incoming_qty', 'standard_price', 'mes_type', 'uom_id', 'description_purchase', 'default_code', 'property_account_income', 'qty_available', 'variants', 'is_maintenance', 'uos_coeff', 'virtual_available', 'sale_ok', 'purchase_ok', 'product_manager', 'track_outgoing', 'state', 'loc_rack', 'pricelist_sale', 'uom_po_id', 'type', 'property_stock_account_input', 'description', 'weight_net', 'property_stock_production', 'supplier_taxes_id', 'volume', 'outgoing_qty', 'loc_row', 'description_sale', 'procure_method', 'property_stock_inventory', 'cost_method', 'active', 'name', 'rental', 'packaging', 'sale_delay', 'pricelist_purchase', 'loc_case', 'property_stock_account_output', 'property_account_expense', 'categ_id', 'track_production', 'track_incoming', 'taxes_id', 'produce_delay', 'seller_ids', 'unique_production_number'], {'lang': u'en_US', '_view_name': u'Products', '_terp_target': u'current', 'bin_size': True, 'client': 'web', 'tz': False, 'active_ids': [126], 'active_id': 126})
00:00:00.11
************
************
fields_view_get (False, 'tree', {'lang': u'en_US', 'client': 'web', 'tz': False}, False)
00:00:00.01
************
************
read ([5], ['delay', 'product_code', 'qty', 'name', 'sequence'], {'lang': u'en_US', 'client': 'web', 'tz': False})
00:00:00.02
************
************
read ([5],)
00:00:00.02

Hope this helps! That's a crazy bug. How the hell could you have missed it ?????????

Raphaël Valyi

[Fabien (Open ERP) (fp-tinyerp)]

This is fine.

GTK loads the list of 80 items, only for the selected products. It is also smart in the way, it loads only fields that were not in the list view.

Loading one or 80 items is nearly the same time for postgresql (which is the bottelneck of the ERP) as it is the same number of queries. It allows to cache the data and work in cache when you do Next, Previous. The result is much less queries and server-client transactions. For complex fields (binaries, one2many, many2many) it loads only when you go on the record.

So, in my sense, GTK is much more faster than etiny, mainly because it is able to cache the selected records, in the client side. It allows you to do: next, next, next,... very fastly for a server-client application.

Please don't write bugs in uppercase, we set priority if we think it's important.

[Fabien (Open ERP) (fp-tinyerp)]

The multiple fields_view_get are on different objects: partner, address, partner events, ...
Open ERP integrate several views together when it's important for perfs, but not in all cases.

[Raphaël Valyi - http://www.akretion.com (rvalyi)]

OK, I understand what you mean.

Still, opening a product form is very slow at first access: After my experiments:
* the GTK Client would busy the server arround 1.2 seconds for that.
* Among those 1.2 seconds, nearly 0.8 seconds is for the fat read all the world request I was talking about (0.69 here)

* After what does the web client instead, we can infer that reading only the selected id, would on the contrary take only 0.1 second

=> This means the request could take 0.5 sec instead of 1.2 sec. More than twice as fast. Of course next requests (NEXT and PREVIOUS buttons) would be slower.

Still, as many user find this first product form access very slow, I think that would be better to double the speed here as it's easy to do.
Then, why not eventually load the other items once the selected product is loaded so that NEXT and PREVIOUS buttons will be as fast as now? Of course that would increase the overall server load a bit, but that would make a better user experience.

For me a workaround is to decrease the number of products shown here in the list as for now.

Technically speking I don't know why the number of selected products in the read is so much important indeed (this it what number tells, sorry). You say they are part of the same SQL request and it looks like but there must be something because numbers are so different. I was wondering if that was because of Python computed fields, but I'm not sure it is, because I couldn't find them listed in the giant read. Any thought why the number in the read has so much impact?

[Fabien (Open ERP) (fp-tinyerp)]

I am thinking about loading nested_view by default so that the client
just have to do one and only one fields_view_get.

The product form is special, because you have all computations for the
stock in this form. And we can not compute/store these values based on
stock moves.
If you remove some of these fields (incoming, outgoing, ...) it will be
much more faster. May be putting a button on the form to display stock
and it computes only if you click on this button.

Thanks,

Raphaël Valyi - http://www.Smile.fr wrote:
> OK, I understand what you mean.
>
> Still, opening a product form is very slow at first access: After my experiments:
> * the GTK Client would busy the server arround 1.2 seconds for that.
> * Among those 1.2 seconds, nearly 0.8 seconds is for the fat read all the world request I was talking about (0.69 here)
>
>
> * After what does the web client instead, we can infer that reading only the selected id, would on the contrary take only 0.1 second
>
> => This means the request could take 0.5 sec instead of 1.2 sec. More
> than twice as fast. Of course next requests (NEXT and PREVIOUS buttons)
> would be slower.
>
> Still, as many user find this first product form access very slow, I think that would be better to double the speed here as it's easy to do.
> Then, why not eventually load the other items once the selected product is loaded so that NEXT and PREVIOUS buttons will be as fast as now? Of course that would increase the overall server load a bit, but that would make a better user experience.
>
> For me a workaround is to decrease the number of products shown here in
> the list as for now.
>
> Technically speking I don't know why the number of selected products in
> the read is so much important indeed (this it what number tells, sorry).
> You say they are part of the same SQL request and it looks like but
> there must be something because numbers are so different. I was
> wondering if that was because of Python computed fields, but I'm not
> sure it is, because I couldn't find them listed in the giant read. Any
> thought why the number in the read has so much impact?
>

--
Fabien Pinckaers
CEO Tiny - OpenERP Editor
Chaussée de Namur 40
B-1367 Grand-Rosière
Belgium
Phone: [phone]
Fax: [phone]
Web: http://openerp.com

Great Achievements Start With Tiny Investments
   -- Marty, 2005

[Raphaël Valyi - http://www.akretion.com (rvalyi)]

May be a good policy might be to load python non cached computed fields in form views only when loading the form record, so you would benefit both:
* load static fields for all the listed records in a single Postgres Query
* load load the form view very quickly, be it the product form view or an other one

BTW, this might not be a priority for v5. And there is the workaround of using eTiny or decreasing the number of listed recored for products (or removing the problematic fields), but I think (and our customer too) that this is annoying, and we thought that much before discovering the reason why it's so slow. So may be good to scope it for the very next version. You might also add a flag that would disable the "load the world" behavior at the window action level and we would typically do it for the product list when stock management is loaded. That might even be a temporary workaround. Anyway, I understand you have things more urgent to do, like the final release, so no problem with you not scoping it for 5.0 final.

Regards,

Raphaël Valyi.

[Raphaël Valyi - http://www.akretion.com (rvalyi)]

Some experiments with a real near-production database:

With a limit of 80 products in the product list, opening a product form taks 5''90 (nearly 6 seconds, far too much!)

But if I decrease that number of records, here is the figures I'm getting:

80 records -> time: 5''90
40 records -> time: 3''
20 records -> time: 1''60
10 records -> time: 0''80

1 record -> time 0''18

So I mean, this is nothing like 'it will be the same single request for Posgres...' No, th reality is that the number of records in the list makes the time to open the first product form almost linear (nothing like almost time constant). So I mean it does matter. Decreasing the number of records to around 20 for us in that form might be an acceptable workaround for us, but I mean, this is certainly an hot topic for you.

Oh, by the way, it means that if you weren't pre-caching the all the records at the first request, switching to the next ond previous records here will only take around 0.18 seconds so I mean this would probably be far more acceptable than the 6 seonds lag at first access. Sorry, but can't really understand your default choice, I mean at least letting a per-action window choice would be great.

Hope this helps,

Raphaël Valyi.

[Fabien (Open ERP) (fp-tinyerp)]

Ok, after analysing the queries at SQL level, here is the results for
products.

In list view (without opening the form view before)::w

Reading 1 product: 32 queries
Reading 29 products: 34 queries

So we can assume it's the same. But in form views:

Reading 1 product: 147 queries
Reading 29 products: 1033 queries

After analysis, the problem come from the fields computing prices for
each pricelists. I stored them in DB, the result is now, in form view:

Reading 1 product: 76 queries
Reading 29 products: 76 queries

After having activated the cache on translations of fields:

Reading 1 product: 52 queries
Reading 29 products: 54 queries

So, we went from O(n) to O(1) for products. Let me know if you find
others objects that are in O(1).

Such number of queries is really normal. For instance, just displaying
the category in a product: All Products / Sellable Products /

So, please du bzr up and tell me if it's ok. To avoid such problems in
the futur (bad developped fields.function that results in O(1)
computations), we developped a module that analyses the quality of a
module: base_module_quality. It checks for O(n) or O(n2) in readings
records.

Tell me if it's ok now.
Thanks for the good feedback,

Raphaël Valyi - http://www.Smile.fr wrote:
> Some experiments with a real near-production database:
>
> With a limit of 80 products in the product list, opening a product form
> taks 5''90 (nearly 6 seconds, far too much!)
>
> But if I decrease that number of records, here is the figures I'm
> getting:
>
> 80 records -> time: 5''90
> 40 records -> time: 3''
> 20 records -> time: 1''60
> 10 records -> time: 0''80
>
> 1 record -> time 0''18
>
>
> So I mean, this is nothing like 'it will be the same single request for Posgres...' No, th reality is that the number of records in the list makes the time to open the first product form almost linear (nothing like almost time constant). So I mean it does matter. Decreasing the number of records to around 20 for us in that form might be an acceptable workaround for us, but I mean, this is certainly an hot topic for you.
>
> Oh, by the way, it means that if you weren't pre-caching the all the
> records at the first request, switching to the next ond previous records
> here will only take around 0.18 seconds so I mean this would probably be
> far more acceptable than the 6 seonds lag at first access. Sorry, but
> can't really understand your default choice, I mean at least letting a
> per-action window choice would be great.
>
>
> Hope this helps,
>
> Raphaël Valyi.
>

--
Fabien Pinckaers
CEO Tiny - OpenERP Editor
Chaussée de Namur 40
B-1367 Grand-Rosière
Belgium
Phone: [phone]
Fax: [phone]
Web: http://openerp.com

Great Achievements Start With Tiny Investments
   -- Marty, 2005

[Raphaël Valyi - http://www.akretion.com (rvalyi)]

Hey very good, O(1) for me! So with your caching it sounds like reading all the selected records is perfectly OK!
Ah, ah I chatted with the Tryton guys, Krier was saying your cache was not a good solution... Well one more proof it is!

Okay, I don't know about any other object suffering that kind of trouble, but if we find some we will let you know.

Saw your quality module. Last time I check some one week ago, I had very non consistent/absurd result like overall -3/10 for the built'in sale module, same kind of numbers for my own modules... So I hopped it's properly calibrated by now.

Oh, by the way: I think the first criteria of quality should be: if you find a module with less than 5 lines in its terp meta description, please just rate it 0, this should force people to document their stuff in a Googlable fashion.

Oh, by the way, about documentation and your cache system: both Pedro Tarafeta and I couldn't find out how your cache in sale order really does:
            store={
                'sale.order': (lambda self, cr, uid, ids, c={}: ids, None, 10),
                'sale.order.line': (_get_order, None, 10),
            },

What does that mean, what 10 means? I have a case where I should also trigger a cache invalidation, please could you document that in your dev wiki? Is 10 some kind of constant key? If yes, in Java we usually name constant key with an UPPER_CASE_STRING as an explicit indirection, nothing similar in Python?

Thank your, keep it up with the great work!

[Raphaël Valyi - http://www.akretion.com (rvalyi)]

Fabien,

actually we checked: there is the same issue of O(n) access for the form view in the sale orders!

Hope you can fix it.

Raphaël Valyi

[Fabien (Open ERP) (fp-tinyerp)]

Raphaël Valyi - http://www.Smile.fr wrote:
> Hey very good, O(1) for me! So with your caching it sounds like reading all the selected records is perfectly OK!
> Ah, ah I chatted with the Tryton guys, Krier was saying your cache was not a good solution... Well one more proof it is!

Of course it is. On such objects (sales, products) we are up to 80% faster.
And we have: seaches on computed fields, reports on computed fields
(always good to be able to report on total of sales)
I know Tryton like to criticise Open ERP. But most of the time they are
not right.

> Saw your quality module. Last time I check some one week ago, I had very
> non consistent/absurd result like overall -3/10 for the built'in sale
> module, same kind of numbers for my own modules... So I hopped it's
> properly calibrated by now.

Yes, still in development.

> Oh, by the way, about documentation and your cache system: both Pedro Tarafeta and I couldn't find out how your cache in sale order really does:
> store={
> 'sale.order': (lambda self, cr, uid, ids, c={}: ids, None, 10),
> 'sale.order.line': (_get_order, None, 10),
> },
>
> What does that mean, what 10 means? I have a case where I should also
> trigger a cache invalidation, please could you document that in your dev
> wiki?

It's not like a cache system, we don't do invalidation and everything is
stored, not only some records cached. The cached value is ALWAYS correct.

For example, if you change a field in the sale order line that may
change the sale order total (None), then it recomputes the total of SO.

> Is 10 some kind of constant key? If yes, in Java we usually name
> constant key with an UPPER_CASE_STRING as an explicit indirection,
> nothing similar in Python?
10 is the priority of the computation. If you have the total included
taxes in SO line and in SO, you should better compute the total per line
and after on the SO.

We are working on new technical doc on this project:
   https://code.launchpad.net/openobject-doc
To improve the current wiki.

Thanks,

--
Fabien Pinckaers
CEO Tiny - OpenERP Editor
Chaussée de Namur 40
B-1367 Grand-Rosière
Belgium
Phone: [phone]
Fax: [phone]
Web: http://openerp.com

Great Achievements Start With Tiny Investments
   -- Marty, 2005

[Raphaël Valyi - http://www.akretion.com (rvalyi)]

Fabien, look my comment just before your last comment, we have trouble with sale orders too to this respect, re-opening the bug, just to make sure you don't miss it.

Regards,

Raphaël Valyi.

[Fabien (Open ERP) (fp-tinyerp)]

I am reading a list of 26 records in 7 queries in list, 20 in form, and 20 in list with all fields of the form view. So this can not be O(n), it's correct, with O(1). If you have problems, it may be related to one of your module ?
Can you give me this list of installed modules ?

[Fabien (Open ERP) (fp-tinyerp)]

I tested with sale_margin, and I have 21 queries so I confirm it's O(1).

[Raphaël Valyi - http://www.akretion.com (rvalyi)]

Ok, might be on our side then. Not time to check again.

Still, your default choice makes coding modules harder. I'm not sure that's a good policy to make it the only choice because customers already tend not to be willing to pay for all the verticalization development (which certainly balance a part of the open source and free of charge advantage), and this extra quality requirement only add to this. I mean it's very okay to have it and even great for customers who can afford having only top O(1) modules, but I'm still not sure it's smart to impose it. We will look after this later on then.

[Fabien (Open ERP) (fp-tinyerp)]

Hello Raphaël,

Open ERP does not impose O(1) results for everything. For us, the
editor, O(1) is part of our quality policies (and the
base_module_quality module has been made to check it). To be more exact,
we try to make module with a complexity of max: O(log(n)).

But you can develop modules in O(n) complexities. Most of the time it's
not a problem (having 80 requests to load a list of 80 records is
acceptable for the end-users delay).

The big problem is not in the O(n). O(n) is acceptable in all
computations. The real problem is O(n²), it's when a module has a
complexity for some computation of O(n) and, this modules call another
module that also has a function of a complexity of O(n). Then, it can
become a O(n²) which is not acceptable. As integrator, most of the time,
simply adds a layer above editor's module, if the editor continues to
develop module with complexity of maximum O(1), then integrators can
develop modules of O(n) without too much risks of time explosion. That's
why I am strict. But being strict at the editor side, allows integrators
to be less strict for customers's specific modules.

Raphaël Valyi - http://www.Smile.fr wrote:
> Ok, might be on our side then. Not time to check again.
>
> Still, your default choice makes coding modules harder. I'm not sure
> that's a good policy to make it the only choice because customers
> already tend not to be willing to pay for all the verticalization
> development (which certainly balance a part of the open source and free
> of charge advantage), and this extra quality requirement only add to
> this. I mean it's very okay to have it and even great for customers who
> can afford having only top O(1) modules, but I'm still not sure it's
> smart to impose it. We will look after this later on then.

Another point: if you don't do this quality checks in upstream, you may
have to pay more later to fix this, when the customer will think his
software is slow, when you have more data.

--
Fabien Pinckaers
CEO Tiny - OpenERP Editor
Chaussée de Namur 40
B-1367 Grand-Rosière
Belgium
Phone: [phone]
Fax: [phone]
Web: http://openerp.com

Great Achievements Start With Tiny Investments
   -- Marty, 2005