Line profiling Python — Odoo 9 as example

Written by jasimmk | Published 2016/09/17
Tech Story Tags: python | odoo | postgres | profiling | logs

TLDRvia the TL;DR App

Chaining mammoths — Odoo/PostgreSQL — 1

Coding standards, DRY Code, design patterns, version management, standardized workflow, microservices, auto deployment, scalable systems..

Dreams to achieve for hackers in the startup. While you push hard to achieve these, you spend a lot of time fixing the legacy monolith. System with infinite series of quick fixes, repeated codes and millions of lines.

Its okay to start business with battery loaded ERP system like odoo. It helps you build your application with business requirements very quickly. But over the time, its gonna be harder for you to scale the application, as majority of the computing resources will be wasted for unwanted functionalities and supporting these ‘easy to develop’ features. Make sure that you are developing optimized application parallel and have a good migration plan for existing data. If you explore and hack the base/inner system of openerp you will see lot of optimization steps.

Profiling application code helps you to identify time/space issues in the application. You will get answers for typical questions like how long each function/method takes to execute? how good is the application at memory consumption etc. In the web apps world, long running or high memory consuming requests are threat to the application stability(Even in blocking and non blocking requests). If you keep these heavy loading endpoints with you, and don’t invest time to optimize it, and do scale out, you will end up a lot on your cloud provider’s invoices.

There are multiple tools and libraries available for profiling in python world. cProfile, valgrind are freely available. 3rd party web monitoring services like NewRelic, App dynamics, Dynatrace available for certain cost. This article focuses profiling odoo with python line profiler. Even though line profiler adds its own overheads to the code, and you can’t trust the exact timing from line profiler, for identifying relative time consumption, line profiler is a good choice.

Things we gonna do here

  • Setup Ubuntu 16.04 vagrant machine.
  • Setup Odoo 9/Postgres 9.5.
  • Insert 50 k contacts to Odoo.
  • Analyze the slow requests in odoo with log parser.
  • Setup line profiler for example script.
  • Setup line profiler for odoo.
  • Identify the performance bottlenecks in code.

Environments tested

Setup Vagrant

  • Install vagrant on your machine.
  • Download the vagrant file to folder
  • Run `vagrant up`
  • Run `vagrant ssh`,
  • Run `sudo su` to login as root

Vagrant with virtualmachine. Running ubuntu 16.04

Install Odoo and PostgreSQL

Lets see how we can setup odoo 9 for development.You could use the following script to auto configure the environment. Run the script to setup the odoo 9 and PostgreSQL 9.5. If you want to customize username, password etc for your environment, download the script and edit the configurations in the script itself and run it.

The script installs PostgreSQL 9.5 and dependency packages for odoo. Python packages are installed in a virtual environment under user ‘odoo’.

root@odoo-dev:~# wget --quiet http://bit.ly/2cE6pfY -O install_odoo9.sh && bash -u install_odoo9.sh

Odoo 9 and PostgreSQL 9.5 auto installation on Vagrant machine

Initial Setup of application

Lets setup initial odoo database and load some demonstration data. Used following configuration for initial database installation

Odoo admin password: odoo_adminOdoo database: odoo_testOdoo username: test123@mailinator.comOdoo password: 123456

Installed below odoo apps with the default installation

  • Project
  • Sales Management
  • Invoicing

Please see the script to populate around `50 thousand` contacts to odoo. Script is based on Odoo API. (It is very slow, Didn’t use any multiprocessing techniques to populate it faster. Took around 2 hours to populate full, while running in background).

Download Odoo contact insert script

Inserting 50 thousand contacts to Odoo

Running Odoo 9 for logging purpose

Lets log some request and response timing from odoo.

  • Stop existing odoo service
  • Login to odoo user
  • Activate odoo virtualenv
  • Run odoo in single worker mode (By default) from command line.
  • Log requests and responses to stdout and a file (`/opt/odoo/logs/odoo-server-request.log`)

root@odoo-dev:~# systemctl stop odoo-serverroot@odoo-dev:~# su odoo(venv) odoo@odoo-dev:~$ which python/opt/odoo/venv/bin/python(venv) odoo@odoo-dev:~$ python src/odoo.py --config /etc/odoo-server.conf --log-handler openerp.http.rpc.request:DEBUG --logfile /dev/stdout|tee /opt/odoo/logs/odoo-server-request.log

Please go through typical operations of odoo, to generate some random responses and timing in logs.

In worker mode of odoo, server will be running with wsgi standards using sync and non threaded mode. If we have 4 workers and each request taking 1 second to generate output, our system’s concurrency will be 4 requests per second.

Lets find out the requests taking long time. As a base measure, check the responses taking more than 500 ms to get generated. We can use any of the three methods for that.

  • Chrome webtools/Firebug and monitor the response timing from there.
  • If there is nginx proxy in front of odoo app, you can enable request/response timing in nginx log as specified here and log the request/response timing.
  • Enable ` — log-handler openerp.http.rpc.request:DEBUG` in odoo and parse the log file for request/response time (We will be using this method here)

Which endpoint/url we will choose to optimize?

  1. Simple ranking: Generate a table of number of requests per url * average response time, and select the one with highest value
  2. Apdex rule: https://en.wikipedia.org/wiki/Apdex

According to the previous command, we are logging requests and response timing to stdout along to `/opt/odoo/logs/odoo-server-request.log`.

Lets use the odoo log line parser. To generate the log files, we need to pass the log handler argument

--log-handler openerp.http.rpc.request:DEBUG

when running odoo. This handler will add request and response timing to log file. Please see the attached file for parser.

Download parser script

You can run the following to generate the log slow responding odoo requests.

root@odoo-dev:~# wget --quiet http://bit.ly/2ceKpfa -O odoo_request_log_parser.py && python odoo_request_log_parser.py -l '/opt/odoo/logs/odoo*.log'

Analyzing the response times

I played with `Unlimited` listing of `0.1 million` contacts multiple times. The unlimited listing in odoo is a dangerous feature, if the number of records is very high for a table, the ‘All’ listing will be a big blocking operation for web workers. Processing these records consumes huge memory as well.

Odoo request/response apdex score analysis

Lets check the functions listed here from log parser. `poll` is used for long polling and in production ERP, we can configure it with `gevent` async port. So its not a big issue for us. `search_read: res.partner` has an apdex score of 0.240 and average execution time of 14 seconds. OMG!!. its not acceptable at all. `get_session_info` has apdex score of 0.5 and taking 520 ms to generate.

We could do line profile of these functions to identify the bottlenecks.

Lineprofiler

Cpython as interpreted language, gives advantage on profiling code line by line. We can identify the time difference between each line and number of times the line got called. Narrowing performance bottlenecks allows us for straight forward optimization of code. Though there are multiple profilers for cpython, line profiler is simple to use and direct us to focusable areas.

Installing line profiler

Activate virtual environment. Install

(venv) odoo@odoo-dev:~$ pip install cython(venv) odoo@odoo-dev:~$ pip install line_profiler

See how we can check the line by line consumption in our log parser script.

Edit the file and add decorator `@profile` to the main function generate_fn_table. And run command along with -lv options.

(venv) odoo@odoo-dev:~$ kernprof -lv -o /tmp/lp.prof odoo_log_parser.py -l '/opt/odoo/logs/*.log'

PS: We will be ignoring profile outputs in the file /tmp/lp.prof, the verbose mode `-v` make sure we get profile report when we terminate the application using Using CTRL + C (Sending the SIGINT signal).

Setting up line profiling for Odoo

To enable profiling in Odoo

  • disable the worker mode and enable threaded mode(By default its threaded mode, unless you put number `— workers` option in command line or `workers = X` in `odoo-server.conf` file
  • Activate virtual env and run the odoo app. Make sure you are in virtual env.

We identified the endpoint methods to debug. Which has low apdex scores. Lets go through this method first.

  • search_read: res.partner None

Make sure you have created your own git profiling branch. As this involves editing code parts at some places.

(venv) odoo@odoo-dev:~$ kernprof -lv -o /tmp/odoo.lprof ~/src/odoo.py --config /etc/odoo-server.conf --logfile /dev/stdout

  • Ensure you are running the `odoo.py` script using ‘kernprof’. It injects `profile` method to scope.
  • Put `@profile` as decorator before the function you need to profile.
  • Sometimes some methods are decorated using meta classes. For `@profile` decorator, the ordering is important. Sometime we need to dig though the method calls and override function as `fn = profile(fn)`

Perform the slow loading operations in Odoo web interface multiple time. Press CTRL +C to terminate the application. You will get the profile report.

  • If you hit NameError: name ‘profile’ is not defined. It might be because of multiple issues.
  • Make sure you are running the odoo.py script with kernprof which injects profile to builtin.
  • You might have installed future package, in your virtual env. in this case, you need to install `line_profiler` from master branch as specified in this pull request
  • Server might be running in multiprocessing mode, or you might have enabled `allow_reload` option in werkzeug. As the profiler loses code injection to builtins with multiprocessing

Fixing the code after profiling

Profiling gives us bottle necks on codes. We need to do different aproaches to speed up the code execution. Some techniques we could use are

  • Loop optimization
  • Direct Query instead of ORM
  • Adding indexes for table columns
  • Applying different algorithms
  • Removing unwanted code executions

Summary

  • Its good to start your business with existing ERP systems like Odoo
  • Over the time think about a standalone solution, with microservices approach. Something that utilize computing resources effectively, easily distribute the load to multiple nodes.
  • Line profiling helps you to identify the bottlenecks of performance.

Review Credits:

Cover Image:


Published by HackerNoon on 2016/09/17