I have an Odoo 10 production system that has been running for about 5 years. As time has gone by, the Confirm Order action in Sales module has become slower and slower, with no obvious explanation. As it's now taking about 50 seconds to complete, I decided to take an in-depth look at the issue.
After extensive debugging and logging, I managed to track down the problem to multiple SELECT statements being fired when confirming the sales order. The following SELECT statement is fired 66 times when a sales order is confirmed, and it takes about 500ms for each to complete:
SELECT "stock_picking"."date_done" as "date_done","stock_picking"."group_id" as "group_id","stock_picking"."printed" as "printed","stock_picking"."min_date" as "min_date","stock_picking"."picking_type_id" as "picking_type_id","stock_picking"."message_last_post" as "message_last_post","stock_picking"."id" as "id","stock_picking"."state" as "state","stock_picking"."origin" as "origin","stock_picking"."note" as "note","stock_picking"."write_date" as "write_date","stock_picking"."create_date" as "create_date","stock_picking"."priority" as "priority","stock_picking"."reverse_picking_orders_id" as "reverse_picking_orders_id","stock_picking"."backorder_id" as "backorder_id","stock_picking"."max_date" as "max_date","stock_picking"."move_type" as "move_type","stock_picking"."recompute_pack_op" as "recompute_pack_op","stock_picking"."owner_id" as "owner_id","stock_picking"."mark2cancel" as "mark2cancel","stock_picking"."location_dest_id" as "location_dest_id","stock_picking"."partner_id" as "partner_id","stock_picking"."name" as "name","stock_picking"."create_uid" as "create_uid","stock_picking"."launch_pack_operations" as "launch_pack_operations","stock_picking"."write_uid" as "write_uid","stock_picking"."location_id" as "location_id","stock_picking"."company_id" as "company_id","stock_picking"."date" as "date" FROM "stock_picking" WHERE "stock_picking".id IN %s ORDER BY "stock_picking"."priority" DESC,"stock_picking"."date" ASC,"stock_picking"."id" DESC
It's just a simple query, but why is it being called so many times? There are many custom fields in the stock picking table, but this should not be an issue, as they are just extra data. The issue is why the same query is being run 66 times, adding over 30 seconds to the time it takes to confirm a sales order.
I also made some tests with a brand new Odoo 10 database (no custom modules with only sample data) with only sales, invoicing and inventory modules, and can see that the same query (without the extra custom fields) is run 12 times on order confirmation. So although it seems the issue is exacerbated by our custom modules and slowness due to the amount of records, it still seems to be a problem with Odoo 10 version itself.
Has anyone come across this issue before? I'm stumped.
UPDATE 1:
Upon further investigation I have narrowed down the point where the multiple queries are fired:
Odoo 10 code for /addons/sale/models/sale.py in function _action_procurement_create calls this line: new_procs.run()
there is a single procurement_order record in new_procs according to logging.
the procurement_order.run() function executes once and before it returns True, no queries have been fired. After the return True, when program flow is back to _action_procurement_create function, the 65 superfluous queries have executed.
This is even weirder, as it doesn't appear to be code that actually executes the queries. They just happen after the function procurement_order.run() finishes running ONCE. Maybe code is being executed by a callback?
I did find this comment in Odoo code for procurement_order.run()
def run(self, autocommit=False):
# TDE FIXME: avoid browsing everything -> avoid prefetching ?
for procurement in self:
# we intentionnaly do the browse under the for loop to avoid caching all ids which would be resource greedy
# and useless as we'll make a refresh later that will invalidate all the cache (and thus the next iteration
# will fetch all the ids again)
if procurement.state not in ("running", "done"):
which might be a clue. But according to logging, the function is only run once. I also made sure all procurement_order records are either in running or done state in the database.
Issue was caused by a (very) badly coded custom module which inherited from stock_picking.create() and introduced an N+1 query. Be careful of what issues may be introduced by function inheritance in Odoo. With great power comes great responsibility.