diff --git a/profiler/README.rst b/profiler/README.rst new file mode 100644 index 000000000..42dd1f131 --- /dev/null +++ b/profiler/README.rst @@ -0,0 +1,95 @@ +.. image:: https://img.shields.io/badge/licence-AGPL--3-blue.svg + :target: http://www.gnu.org/licenses/agpl-3.0-standalone.html + :alt: License: AGPL-3 + +======== +Profiler +======== + +Integration of cProfile and PgBadger. + +Installation +============ + +To install this module, you need the following requirements: + +* Install `pgbadger `_ binary package. +* Install `pstats_print2list `_ python package. +* Set `PG_LOG_PATH` environment variable to know location of the `postgresql.log` file by default is `/var/lib/postgresql/9.X/main/pg_log/postgresql.log` +* Enable postgresql logs from postgresql's configuration file (Default location for Linux Debian is `/etc/postgresql/*/main/postgresql.conf`) + - Add the following lines at final (A postgresql restart is required `/etc/init.d/postgresql restart`) + +.. code-block:: text + + logging_collector=on + log_destination='stderr' + log_directory='pg_log' + log_filename='postgresql.log' + log_rotation_age=0 + log_checkpoints=on + log_hostname=on + log_line_prefix='%t [%p]: [%l-1] db=%d,user=%u ' + + +Configuration +============= + +By default profiler module adds two system parameters + - exclude_fnames > '/.repo_requirements,~/odoo-8.0,/usr/,>' + - exclude_query > 'ir_translation'. + +These parameters can be configurated in order to exclude some outputs from +profiling stats or pgbadger output. + +Usage +===== + +After installation, a player is add on the header bar, with following buttons: + + - .. figure:: static/description/player.png + :alt: Player to manage profiler + + +* Start profiling + - .. figure:: static/description/start_profiling.png + :alt: Start profiling + :height: 35px +* Stop profiling + - .. figure:: static/description/stop_profiling.png + :alt: Stop profiling + :height: 35px +* Download stats: download stats file + - .. figure:: static/description/dump_stats.png + :alt: Download cprofile stats file + :height: 35px +* Clear stats + - .. figure:: static/description/clear_stats.png + :alt: Clear and remove stats file + :height: 35px + + +Credits +======= + +Contributors +------------ + +* Georges Racinet + - Remotely inspired from ZopeProfiler, although there is no online visualisation and there may never be one. +* Moisés López +* Hugo Adan + +Maintainer +---------- + +.. image:: https://odoo-community.org/logo.png + :alt: Odoo Community Association + :target: https://odoo-community.org + +This module is maintained by the OCA. + +OCA, or the Odoo Community Association, is a nonprofit organization whose +mission is to support the collaborative development of Odoo features and +promote its widespread use. + +To contribute to this module, please visit https://odoo-community.org. diff --git a/profiler/__init__.py b/profiler/__init__.py new file mode 100644 index 000000000..5b85f8689 --- /dev/null +++ b/profiler/__init__.py @@ -0,0 +1,6 @@ +# coding: utf-8 +# License AGPL-3 or later (http://www.gnu.org/licenses/lgpl). +# Copyright 2014 Anybox +# Copyright 2016 Vauxoo (https://www.vauxoo.com) +from . import controllers +from .hooks import post_load diff --git a/profiler/__openerp__.py b/profiler/__openerp__.py new file mode 100644 index 000000000..666b062f6 --- /dev/null +++ b/profiler/__openerp__.py @@ -0,0 +1,32 @@ +# coding: utf-8 +# License AGPL-3 or later (http://www.gnu.org/licenses/lgpl). +# Copyright 2014 Anybox +# Copyright 2016 Vauxoo (https://www.vauxoo.com) + +{ + 'name': 'profiler', + 'version': '8.0.1.0.0', + 'category': 'Tools', + 'license': 'AGPL-3', + 'author': 'Anybox, Vauxoo, Odoo Community Association (OCA)', + 'website': 'https://odoo-community.org', + 'depends': ['website'], + 'data': [ + 'data/profiler_excluding.xml', + 'security/group.xml', + 'views/profiler.xml', + 'views/assets.xml', + ], + 'external_dependencies': { + 'python': [ + 'pstats_print2list', + ], + }, + 'qweb': [ + 'static/src/xml/player.xml', + ], + 'installable': True, + 'application': False, + 'auto_install': False, + 'post_load': 'post_load', +} diff --git a/profiler/controllers/__init__.py b/profiler/controllers/__init__.py new file mode 100644 index 000000000..ca5f234cf --- /dev/null +++ b/profiler/controllers/__init__.py @@ -0,0 +1,5 @@ +# coding: utf-8 +# License AGPL-3 or later (http://www.gnu.org/licenses/lgpl). +# Copyright 2014 Anybox +# Copyright 2016 Vauxoo (https://www.vauxoo.com) +from . import main diff --git a/profiler/controllers/main.py b/profiler/controllers/main.py new file mode 100644 index 000000000..5d3b78d66 --- /dev/null +++ b/profiler/controllers/main.py @@ -0,0 +1,228 @@ +# coding: utf-8 +# License AGPL-3 or later (http://www.gnu.org/licenses/lgpl). +# Copyright 2014 Anybox +# Copyright 2016 Vauxoo (https://www.vauxoo.com) +import errno +import logging +import os +import sys +import tempfile +from cStringIO import StringIO +from datetime import datetime + +from openerp import http, sql_db, tools +from openerp.addons.web.controllers.main import content_disposition +from openerp.http import request +from openerp.service.db import dump_db_manifest +from openerp.tools.misc import find_in_path + +from ..hooks import CoreProfile as core + +_logger = logging.getLogger(__name__) + +try: + from pstats_print2list import get_pstats_print2list, print_pstats_list +except ImportError as err: # pragma: no cover + _logger.debug(err) + +DFTL_LOG_PATH = '/var/lib/postgresql/%s/main/pg_log/postgresql.log' + +PGOPTIONS = ( + '-c client_min_messages=notice -c log_min_messages=warning ' + '-c log_min_error_statement=error ' + '-c log_min_duration_statement=0 -c log_connections=on ' + '-c log_disconnections=on -c log_duration=off ' + '-c log_error_verbosity=verbose -c log_lock_waits=on ' + '-c log_statement=none -c log_temp_files=0 ' +) + + +class Capturing(list): + def __enter__(self): + self._stdout = sys.stdout + sys.stdout = self._stringio = StringIO() + return self + + def __exit__(self, *args): + self.extend(self._stringio.getvalue().splitlines()) + del self._stringio # free up some memory + sys.stdout = self._stdout + + +class ProfilerController(http.Controller): + + _cp_path = '/web/profiler' + + player_state = 'profiler_player_clear' + begin_date = '' + end_date = '' + """Indicate the state(css class) of the player: + + * profiler_player_clear + * profiler_player_enabled + * profiler_player_disabled + """ + + @http.route(['/web/profiler/enable'], type='json', auth="user") + def enable(self): + _logger.info("Enabling") + core.enabled = True + ProfilerController.begin_date = datetime.now().strftime( + "%Y-%m-%d %H:%M:%S") + ProfilerController.player_state = 'profiler_player_enabled' + os.environ['PGOPTIONS'] = PGOPTIONS + self.empty_cursor_pool() + + @http.route(['/web/profiler/disable'], type='json', auth="user") + def disable(self, **post): + _logger.info("Disabling") + core.enabled = False + ProfilerController.end_date = datetime.now().strftime( + "%Y-%m-%d %H:%M:%S") + ProfilerController.player_state = 'profiler_player_disabled' + os.environ.pop("PGOPTIONS", None) + self.empty_cursor_pool() + + @http.route(['/web/profiler/clear'], type='json', auth="user") + def clear(self, **post): + core.profile.clear() + _logger.info("Cleared stats") + ProfilerController.player_state = 'profiler_player_clear' + ProfilerController.end_date = '' + ProfilerController.begin_date = '' + + @http.route(['/web/profiler/dump'], type='http', auth="user") + def dump(self, token, **post): + """Provide the stats as a file download. + + Uses a temporary file, because apparently there's no API to + dump stats in a stream directly. + """ + exclude_fname = self.get_exclude_fname() + with tools.osutil.tempdir() as dump_dir: + ts = datetime.now().strftime("%Y-%m-%d_%H-%M-%S") + filename = 'openerp_%s' % ts + stats_path = os.path.join(dump_dir, '%s.stats' % filename) + core.profile.dump_stats(stats_path) + _logger.info("Pstats Command:") + params = {'fnames': stats_path, 'sort': 'cumulative', 'limit': 45, + 'exclude_fnames': exclude_fname} + _logger.info( + "fnames=%(fnames)s, sort=%(sort)s," + " limit=%(limit)s, exclude_fnames=%(exclude_fnames)s", params) + pstats_list = get_pstats_print2list(**params) + with Capturing() as output: + print_pstats_list(pstats_list) + result_path = os.path.join(dump_dir, '%s.txt' % filename) + with open(result_path, "a") as res_file: + for line in output: + res_file.write('%s\n' % line) + # PG_BADGER + self.dump_pgbadger(dump_dir, 'pgbadger_output.txt', request.cr) + t_zip = tempfile.TemporaryFile() + tools.osutil.zip_dir(dump_dir, t_zip, include_dir=False) + t_zip.seek(0) + headers = [ + ('Content-Type', 'application/octet-stream; charset=binary'), + ('Content-Disposition', content_disposition( + '%s.zip' % filename))] + _logger.info('Download Profiler zip: %s', t_zip.name) + return request.make_response( + t_zip, headers=headers, cookies={'fileToken': token}) + + @http.route(['/web/profiler/initial_state'], type='json', auth="user") + def initial_state(self, **post): + user = request.env['res.users'].browse(request.uid) + return { + 'has_player_group': user.has_group( + 'profiler.group_profiler_player'), + 'player_state': ProfilerController.player_state, + } + + def dump_pgbadger(self, dir_dump, output, cursor): + pgbadger = find_in_path("pgbadger") + if not pgbadger: + _logger.error("Pgbadger not found") + return + filename = os.path.join(dir_dump, output) + pg_version = dump_db_manifest(cursor)['pg_version'] + log_path = os.environ.get('PG_LOG_PATH', DFTL_LOG_PATH % pg_version) + if not os.path.exists(os.path.dirname(filename)): + try: + os.makedirs(os.path.dirname(filename)) + except OSError as exc: + # error is different than File exists + if exc.errno != errno.EEXIST: + _logger.error("Folder %s can not be created", + os.path.dirname(filename)) + return + _logger.info("Generating PG Badger report.") + exclude_query = self.get_exclude_query() + dbname = cursor.dbname + command = [ + pgbadger, '-f', 'stderr', '-T', 'Odoo-Profiler', + '-o', '-', '-d', dbname, '-b', ProfilerController.begin_date, + '-e', ProfilerController.end_date, '--sample', '2', + '--disable-type', '--disable-error', '--disable-hourly', + '--disable-session', '--disable-connection', + '--disable-temporary', '--quiet'] + command.extend(exclude_query) + command.append(log_path) + + _logger.info("Pgbadger Command:") + _logger.info(command) + result = tools.exec_command_pipe(*command) + with open(filename, 'w') as fw: + fw.write(result[1].read()) + _logger.info("Done") + + def get_exclude_fname(self): + efnameid = request.env.ref( + 'profiler.default_exclude_fnames_pstas', raise_if_not_found=False) + if not efnameid: + return [] + return [os.path.expanduser(path) + for path in efnameid and efnameid.value.strip(',').split(',') + if path] + + def get_exclude_query(self): + """Example '^(COPY|COMMIT)' + """ + equeryid = request.env.ref( + 'profiler.default_exclude_query_pgbadger', + raise_if_not_found=False) + if not equeryid: + return [] + exclude_queries = [] + for path in equeryid and equeryid.value.strip(',').split(','): + exclude_queries.extend( + ['--exclude-query', '"^(%s)" ' % path.encode('UTF-8')]) + return exclude_queries + + def empty_cursor_pool(self): + """This method cleans (rollback) all current transactions over actual + cursor in order to avoid errors with waiting transactions. + - request.cr.rollback() + + Also connections on current database's only are closed by the next + statement + - dsn = openerp.sql_db.dsn(request.cr.dbname) + - openerp.sql_db._Pool.close_all(dsn[1]) + Otherwise next error will be trigger + 'InterfaceError: connection already closed' + + Finally new cursor is assigned to the request object, this cursor will + take the os.environ setted. In this case the os.environ is setted with + all 'PGOPTIONS' required to log all sql transactions in postgres.log + file. + + If this method is called one more time, it will create a new cursor and + take the os.environ again, this is usefully if we want to reset + 'PGOPTIONS' + + """ + request.cr._cnx.reset() + dsn = sql_db.dsn(request.cr.dbname) + sql_db._Pool.close_all(dsn[1]) + db = sql_db.db_connect(request.cr.dbname) + request._cr = db.cursor() diff --git a/profiler/data/profiler_excluding.xml b/profiler/data/profiler_excluding.xml new file mode 100644 index 000000000..d4ef12a4f --- /dev/null +++ b/profiler/data/profiler_excluding.xml @@ -0,0 +1,16 @@ + + + + + + exclude_fnames + /.repo_requirements,~/odoo-8.0,/usr/,> + + + + + exclude_query + ir_translation + + + diff --git a/profiler/hooks.py b/profiler/hooks.py new file mode 100644 index 000000000..7e192a5d4 --- /dev/null +++ b/profiler/hooks.py @@ -0,0 +1,103 @@ +# coding: utf-8 +# License AGPL-3 or later (http://www.gnu.org/licenses/lgpl). +# Copyright 2014 Anybox +# Copyright 2016 Vauxoo (https://www.vauxoo.com) +import logging +import os +from contextlib import contextmanager +from cProfile import Profile + +import openerp +from openerp import sql_db +from openerp.http import WebRequest +from openerp.service.server import ThreadedServer + +_logger = logging.getLogger(__name__) + + +class CoreProfile(object): + """The thread-shared profile object""" + profile = None + # Indicates if the whole profiling functionality is globally active or not. + enabled = False + + +@contextmanager +def profiling(): + """Thread local profile management, according to the shared :data:`enabled` + """ + if CoreProfile.enabled: + CoreProfile.profile.enable() + yield + + if CoreProfile.enabled: + CoreProfile.profile.disable() + + +def patch_odoo(): + """Modify Odoo entry points so that profile can record. + + Odoo is a multi-threaded program. Therefore, the :data:`profile` object + needs to be enabled/disabled each in each thread to capture all the + execution. + + For instance, Odoo spawns a new thread for each request. + + Modify database connect method to add options to enable postgresql logging + based on PGOPTIONS environment variable + """ + _logger.info('Patching openerp.http.WebRequest._call_function') + webreq_f_origin = WebRequest._call_function + + def webreq_f(*args, **kwargs): + with profiling(): + return webreq_f_origin(*args, **kwargs) + WebRequest._call_function = webreq_f + + _logger.info('Patching openerp.sql_db.db_connect') + db_connect_origin = sql_db.db_connect + + def dbconnect_f(to, *args, **kwargs): + try: + to += " options='%s' " % (os.environ['PGOPTIONS'] or '') + except KeyError: + pass + return db_connect_origin(to, *args, **kwargs) + sql_db.db_connect = dbconnect_f + + +def dump_stats(): + """Dump stats to standard file""" + _logger.info('Dump stats') + CoreProfile.profile.dump_stats( + os.path.expanduser('~/.openerp_server.stats')) + + +def create_profile(): + """Create the global, shared profile object.""" + _logger.info('Create profile') + CoreProfile.profile = Profile() + + +def patch_stop(): + """When the server is stopped then save the result of cProfile stats""" + origin_stop = ThreadedServer.stop + + _logger.info('Patching openerp.service.server.ThreadedServer.stop') + + def stop(*args, **kwargs): + if openerp.tools.config['test_enable']: + dump_stats() + return origin_stop(*args, **kwargs) + ThreadedServer.stop = stop + + +def post_load(): + _logger.info('Post load') + create_profile() + patch_odoo() + if openerp.tools.config['test_enable']: + # Enable profile in test mode for orm methods. + _logger.info('Enabling profiler and apply patch') + CoreProfile.enabled = True + patch_stop() diff --git a/profiler/security/group.xml b/profiler/security/group.xml new file mode 100644 index 000000000..980f27973 --- /dev/null +++ b/profiler/security/group.xml @@ -0,0 +1,11 @@ + + + + + Profiling capability + + + + + + diff --git a/profiler/static/description/clear_stats.png b/profiler/static/description/clear_stats.png new file mode 100644 index 000000000..8c66f4af8 Binary files /dev/null and b/profiler/static/description/clear_stats.png differ diff --git a/profiler/static/description/dump_stats.png b/profiler/static/description/dump_stats.png new file mode 100644 index 000000000..f007f5415 Binary files /dev/null and b/profiler/static/description/dump_stats.png differ diff --git a/profiler/static/description/player.png b/profiler/static/description/player.png new file mode 100644 index 000000000..86ff65760 Binary files /dev/null and b/profiler/static/description/player.png differ diff --git a/profiler/static/description/start_profiling.png b/profiler/static/description/start_profiling.png new file mode 100644 index 000000000..39e384868 Binary files /dev/null and b/profiler/static/description/start_profiling.png differ diff --git a/profiler/static/description/stop_profiling.png b/profiler/static/description/stop_profiling.png new file mode 100644 index 000000000..c8a49f480 Binary files /dev/null and b/profiler/static/description/stop_profiling.png differ diff --git a/profiler/static/src/css/player.css b/profiler/static/src/css/player.css new file mode 100644 index 000000000..b65a4d06d --- /dev/null +++ b/profiler/static/src/css/player.css @@ -0,0 +1,21 @@ +.oe_topbar_item.profiler_player i { + cursor: pointer; +} +.oe_topbar_item.profiler_player.profiler_player_enabled a.profiler_enable { + display: None; +} +.oe_topbar_item.profiler_player.profiler_player_enabled a.profiler_dump { + display: None; +} +.oe_topbar_item.profiler_player.profiler_player_disabled a.profiler_disable { + display: None; +} +.oe_topbar_item.profiler_player.profiler_player_clear a.profiler_disable { + display: None; +} +.oe_topbar_item.profiler_player.profiler_player_clear a.profiler_clear { + display: None; +} +.oe_topbar_item.profiler_player.profiler_player_clear a.profiler_dump { + display: None; +} diff --git a/profiler/static/src/js/player.js b/profiler/static/src/js/player.js new file mode 100644 index 000000000..82c2e07d2 --- /dev/null +++ b/profiler/static/src/js/player.js @@ -0,0 +1,52 @@ +openerp.profiler = function(instance) { + instance.profiler.Player = instance.web.Widget.extend({ + template: 'profiler.player', + events: { + "click .profiler_enable": "enable", + "click .profiler_disable": "disable", + "click .profiler_clear": "clear", + "click .profiler_dump": "dump" + }, + apply_class: function(css_class) { + this.$el.removeClass('profiler_player_enabled'); + this.$el.removeClass('profiler_player_disabled'); + this.$el.removeClass('profiler_player_clear'); + this.$el.addClass(css_class); + }, + enable: function() { + this.rpc('/web/profiler/enable', {}); + this.apply_class('profiler_player_enabled'); + }, + disable: function() { + this.rpc('/web/profiler/disable', {}); + this.apply_class('profiler_player_disabled'); + }, + clear: function() { + this.rpc('/web/profiler/clear', {}); + this.apply_class('profiler_player_clear'); + }, + dump: function() { + $.blockUI(); + this.session.get_file({ + url: '/web/profiler/dump', + complete: $.unblockUI + }); + } + }); + + instance.web.UserMenu.include({ + do_update: function () { + var self = this; + this.update_promise.done(function () { + self.rpc('/web/profiler/initial_state', {}).done(function(state) { + if (state.has_player_group) { + this.profiler_player = new instance.profiler.Player(this); + this.profiler_player.prependTo(instance.webclient.$('.oe_systray')); + this.profiler_player.apply_class(state.player_state); + } + }); + }); + return this._super(); + } + }); +}; diff --git a/profiler/static/src/js/test_profiler.js b/profiler/static/src/js/test_profiler.js new file mode 100644 index 000000000..ff072f711 --- /dev/null +++ b/profiler/static/src/js/test_profiler.js @@ -0,0 +1,52 @@ +(function(){ + 'use_strict'; + openerp.Tour.register({ + id: 'profile_run', + name: 'Profile run', + path: '/web', + mode: 'test', + steps: [ + { + title: 'Check if is cleared', + waitFor: 'li.oe_topbar_item.profiler_player.profiler_player_clear' + }, + { + title: 'Start profiling', + onload: function () { + $('a.profiler_enable').trigger('click'); + } + }, + { + title: 'Check if is enabled', + waitFor: 'li.oe_topbar_item.profiler_player.profiler_player_enabled' + }, + { + title: 'Stop profiling', + onload: function () { + $('a.profiler_disable').trigger('click'); + } + }, + { + title: 'Check if is disabled', + waitFor: 'li.oe_topbar_item.profiler_player.profiler_player_disabled' + }, + { + title: 'Dump profiling', + onload: function () { + $('a.profiler_dump').trigger('click'); + } + }, + { + title: 'Clear profiling', + onload: function () { + $('a.profiler_clear').trigger('click'); + } + }, + { + title: 'Check if is cleared again', + waitFor: 'li.oe_topbar_item.profiler_player.profiler_player_clear' + }, + + ] + }); +}()); diff --git a/profiler/static/src/less/player.less b/profiler/static/src/less/player.less new file mode 100644 index 000000000..3318f6b3e --- /dev/null +++ b/profiler/static/src/less/player.less @@ -0,0 +1,24 @@ +#oe_main_menu_navbar .o_menu_systray { + + .oe_topbar_item.profiler_player i { + cursor: pointer; + } + .oe_topbar_item.profiler_player.profiler_player_enabled a.profiler_enable { + display: None; + } + .oe_topbar_item.profiler_player.profiler_player_enabled a.profiler_dump { + display: None; + } + .oe_topbar_item.profiler_player.profiler_player_disabled a.profiler_disable { + display: None; + } + .oe_topbar_item.profiler_player.profiler_player_clear a.profiler_disable { + display: None; + } + .oe_topbar_item.profiler_player.profiler_player_clear a.profiler_clear { + display: None; + } + .oe_topbar_item.profiler_player.profiler_player_clear a.profiler_dump { + display: None; + } +} diff --git a/profiler/static/src/xml/player.xml b/profiler/static/src/xml/player.xml new file mode 100644 index 000000000..18e885989 --- /dev/null +++ b/profiler/static/src/xml/player.xml @@ -0,0 +1,26 @@ + + +
  • + + + +
    • +
  • + + + + +
    • +
  • + + + + +
    • +
  • + + + +
    • +     +     diff --git a/profiler/tests/__init__.py b/profiler/tests/__init__.py new file mode 100644 index 000000000..690d59efe --- /dev/null +++ b/profiler/tests/__init__.py @@ -0,0 +1,5 @@ +# coding: utf-8 +# License AGPL-3 or later (http://www.gnu.org/licenses/lgpl). +# Copyright 2014 Anybox +# Copyright 2016 Vauxoo (https://www.vauxoo.com) +from . import test_profiler diff --git a/profiler/tests/test_profiler.py b/profiler/tests/test_profiler.py new file mode 100644 index 000000000..9ce0a51d0 --- /dev/null +++ b/profiler/tests/test_profiler.py @@ -0,0 +1,17 @@ +# coding: utf-8 +# License AGPL-3 or later (http://www.gnu.org/licenses/lgpl). +# Copyright 2016 Vauxoo (https://www.vauxoo.com) + +import unittest + +from openerp import tests + + +@tests.at_install(False) +@tests.post_install(True) +class TestProfiler(tests.HttpCase): + + @unittest.skip("phantomjs tests async for 8.0 are so flaky") + def test_profiler_tour(self): + self.phantom_js('/web', "openerp.Tour.run('profile_run', 'test')", + 'openerp.Tour.tours.profile_run', login='admin') diff --git a/profiler/views/assets.xml b/profiler/views/assets.xml new file mode 100644 index 000000000..373acac0f --- /dev/null +++ b/profiler/views/assets.xml @@ -0,0 +1,12 @@ + + + +