server-tools/profiler/models/profiler_profile.py

import base64
import logging
import os
import pstats
import re
import subprocess
import lxml.html
from contextlib import contextmanager
from cProfile import Profile
from io import StringIO

from psycopg2 import OperationalError, ProgrammingError

from odoo import api, exceptions, fields, models, sql_db, tools, _

DATETIME_FORMAT_FILE = "%Y%m%d_%H%M%S"
CPROFILE_EMPTY_CHARS = b"{0"
PGOPTIONS = {
    'log_min_duration_statement': '0',
    'client_min_messages': 'notice',
    'log_min_messages': 'warning',
    'log_min_error_statement': 'error',
    'log_duration': 'off',
    'log_error_verbosity': 'verbose',
    'log_lock_waits': 'on',
    'log_statement': 'none',
    'log_temp_files': '0',
}
PGOPTIONS_ENV = ' '.join(["-c %s=%s" % (param, value)
                          for param, value in PGOPTIONS.items()])
PY_STATS_FIELDS = [
    'ncalls',
    'tottime', 'tt_percall',
    'cumtime', 'ct_percall',
    'file', 'lineno', 'method',
]
LINE_STATS_RE = re.compile(
    r'(?P<%s>\d+/?\d+|\d+)\s+(?P<%s>\d+\.?\d+)\s+(?P<%s>\d+\.?\d+)\s+'
    r'(?P<%s>\d+\.?\d+)\s+(?P<%s>\d+\.?\d+)\s+(?P<%s>.*):(?P<%s>\d+)'
    r'\((?P<%s>.*)\)' % tuple(PY_STATS_FIELDS))

_logger = logging.getLogger(__name__)


class ProfilerProfilePythonLine(models.Model):
    _name = 'profiler.profile.python.line'
    _description = 'Profiler Python Line to save cProfiling results'
    _rec_name = 'cprof_fname'
    _order = 'cprof_cumtime DESC'

    profile_id = fields.Many2one('profiler.profile', required=True,
                                 ondelete='cascade')
    cprof_tottime = fields.Float("Total time")
    cprof_ncalls = fields.Float("Calls")
    cprof_nrcalls = fields.Float("Recursive Calls")
    cprof_ttpercall = fields.Float("Time per call")
    cprof_cumtime = fields.Float("Cumulative time")
    cprof_ctpercall = fields.Float("CT per call")
    cprof_fname = fields.Char("Filename:lineno(method)")


class ProfilerProfile(models.Model):
    _name = 'profiler.profile'
    _description = 'Profiler Profile'

    @api.model
    def _find_loggers_path(self):
        self.env.cr.execute("SHOW log_directory")
        log_directory = self.env.cr.fetchone()[0]
        self.env.cr.execute("SHOW log_filename")
        log_filename = self.env.cr.fetchone()[0]
        log_path = os.path.join(log_directory, log_filename)
        if not os.path.isabs(log_path):
            # It is relative path then join data_directory
            self.env.cr.execute("SHOW data_directory")
            data_dir = self.env.cr.fetchone()[0]
            log_path = os.path.join(data_dir, log_path)
        return log_path

    name = fields.Char(required=True)
    enable_python = fields.Boolean(default=True)
    enable_postgresql = fields.Boolean(
        default=False,
        help="It requires postgresql server logs seudo-enabled")
    use_py_index = fields.Boolean(
        name="Get cProfiling report", default=False,
        help="Index human-readable cProfile attachment."
        "\nTo access this report, you must open the cprofile attachment view "
        "using debug mode.\nWarning: Uses more resources.")
    date_started = fields.Char(readonly=True)
    date_finished = fields.Char(readonly=True)
    state = fields.Selection([
        ('enabled', 'Enabled'),
        ('disabled', 'Disabled'),
    ], default='disabled', readonly=True, required=True)
    description = fields.Text(readonly=True)
    attachment_count = fields.Integer(compute="_compute_attachment_count")
    pg_log_path = fields.Char(help="Getting the path to the logger",
                              default=_find_loggers_path)
    pg_remote = fields.Char()
    pg_stats_slowest_html = fields.Html(
        "PostgreSQL Stats - Slowest", readonly=True)
    pg_stats_time_consuming_html = fields.Html(
        "PostgreSQL Stats - Time Consuming", readonly=True)
    pg_stats_most_frequent_html = fields.Html(
        "PostgreSQL Stats - Most Frequent", readonly=True)
    py_stats_lines = fields.One2many(
        "profiler.profile.python.line", "profile_id", "PY Stats Lines")

    @api.multi
    def _compute_attachment_count(self):
        for record in self:
            self.attachment_count = self.env['ir.attachment'].search_count([
                ('res_model', '=', self._name), ('res_id', '=', record.id)])

    @api.onchange('enable_postgresql')
    def onchange_enable_postgresql(self):
        if not self.enable_postgresql:
            return
        self.env.cr.execute("SHOW config_file")
        pg_config_file = self.env.cr.fetchone()[0]
        db_host = tools.config.get('db_host')
        if db_host == 'localhost' or db_host == '127.0.0.1':
            db_host = False
        if db_host:
            pg_config_file = 'postgres@%s:%s' % (db_host, pg_config_file)
            self.pg_remote = db_host

        self.description = (
            "You need seudo-enable logs from your "
            "postgresql-server configuration file.\n"
            "Common paths:\n\t- %s\n"
            "or your can looking for the service using: "
            "'ps aux | grep postgres'\n\n"
        ) % pg_config_file
        self.description += """Adds the following parameters:
# Pre-enable logs
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 '
log_connections=on
log_disconnections=on
lc_messages='en_US.UTF-8'

Reload configuration using the following query:
 - select pg_reload_conf()
Or restart the postgresql server service.

FYI This module will enable the following parameter from the client
    It's not needed added them to configuration file if database user is
     superuser or use PGOPTIONS environment variable in the terminal
     that you start your odoo server.
    If you don't add these parameters or PGOPTIONS this module will try do it.
# Enable logs from postgresql.conf
log_min_duration_statement=0
client_min_messages=notice
log_min_messages=warning
log_min_error_statement=error
log_duration=off
log_error_verbosity=verbose
log_lock_waits=on
log_statement=none
log_temp_files=0

#  Or enable logs from PGOPTIONS environment variable before to start odoo
#     server
export PGOPTIONS="-c log_min_duration_statement=0 \\
-c client_min_messages=notice -c log_min_messages=warning \\
-c log_min_error_statement=error -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"
~/odoo_path/odoo-bin ...
"""

    profile = Profile()
    enabled = None
    pglogs_enabled = None

    # True to activate it False to inactivate None to do nothing
    activate_deactivate_pglogs = None

    # Params dict with values before to change it.
    psql_params_original = {}

    @api.model
    def now_utc(self):
        self.env.cr.execute("SELECT to_char(current_timestamp AT TIME "
                            "ZONE 'UTC', 'YYYY-MM-DD HH24:MI:SS')")
        now = self.env.cr.fetchall()[0][0]
        # now = fields.Datetime.to_string(
        #     fields.Datetime.context_timestamp(self, datetime.now()))
        return now

    @api.multi
    def enable(self):
        self.ensure_one()
        if tools.config.get('workers'):
            raise exceptions.UserError(
                _("Start the odoo server using the parameter '--workers=0'"))
        _logger.info("Enabling profiler")
        self.write(dict(
            date_started=self.now_utc(),
            state='enabled'
        ))
        ProfilerProfile.enabled = self.enable_python
        self._reset_postgresql()

    @api.multi
    def _reset_postgresql(self):
        if not self.enable_postgresql:
            return
        if ProfilerProfile.pglogs_enabled:
            _logger.info("Using postgresql.conf or PGOPTIONS predefined.")
            return
        os.environ['PGOPTIONS'] = (
            PGOPTIONS_ENV if self.state == 'enabled' else '')
        self._reset_connection(self.state == 'enabled')

    def _reset_connection(self, enable):
        for connection in sql_db._Pool._connections:
            with connection[0].cursor() as pool_cr:
                params = (PGOPTIONS if enable
                          else ProfilerProfile.psql_params_original)
                for param, value in params.items():
                    try:
                        pool_cr.execute('SET %s TO %s' % (param, value))
                    except (OperationalError, ProgrammingError) as oe:
                        pool_cr.connection.rollback()
                        raise exceptions.UserError(
                            _("It's not possible change parameter.\n%s\n"
                              "Please, disable postgresql or re-enable it "
                              "in order to read the instructions") % str(oe))
            ProfilerProfile.activate_deactivate_pglogs = enable

    def get_stats_string(self, cprofile_path):
        pstats_stream = StringIO()
        pstats_obj = pstats.Stats(cprofile_path, stream=pstats_stream)
        pstats_obj.sort_stats('cumulative')
        pstats_obj.print_stats()
        pstats_stream.seek(0)
        stats_string = pstats_stream.read()
        pstats_stream = None
        return stats_string

    @api.multi
    def dump_postgresql_logs(self, indexed=None):
        self.ensure_one()
        self.description = ''
        pgbadger_cmd = self._get_pgbadger_command()
        if pgbadger_cmd is None:
            return
        pgbadger_cmd_str = subprocess.list2cmdline(pgbadger_cmd)
        self.description += (
            '\nRunning the command: %s') % pgbadger_cmd_str
        result = tools.exec_command_pipe(*pgbadger_cmd)
        datas = result[1].read()
        if not datas:
            self.description += "\nPgbadger output is empty!"
            return
        fname = self._get_attachment_name("pg_stats", ".html")
        self.env['ir.attachment'].create({
            'name': fname,
            'res_id': self.id,
            'res_model': self._name,
            'datas': base64.b64encode(datas),
            'datas_fname': fname,
            'description': 'pgbadger html output',
        })
        xpaths = [
            '//*[@id="slowest-individual-queries"]',
            '//*[@id="time-consuming-queries"]',
            '//*[@id="most-frequent-queries"]',
        ]
        # pylint: disable=unbalanced-tuple-unpacking
        self.pg_stats_slowest_html, self.pg_stats_time_consuming_html, \
            self.pg_stats_most_frequent_html = self._compute_pgbadger_html(
                datas, xpaths)

    @staticmethod
    def _compute_pgbadger_html(html_doc, xpaths):
        html = lxml.html.document_fromstring(html_doc)
        result = []
        for this_xpath in xpaths:
            this_result = html.xpath(this_xpath)
            result.append(
                tools.html_sanitize(lxml.html.tostring(this_result[0])))
        return result

    @api.multi
    def _get_pgbadger_command(self):
        self.ensure_one()
        # TODO: Catch early the following errors.
        try:
            pgbadger_bin = tools.find_in_path('pgbadger')
        except IOError:
            self.description += (
                "\nInstall 'apt-get install pgbadger'")
        try:
            with open(self.pg_log_path, "r"):
                pass
        except IOError:
            self.description += (
                "\nCheck if exists and has permission to read the log file."
                "\nMaybe running: chmod 604 '%s'"
            ) % self.pg_log_path

        pgbadger_cmd = [
            pgbadger_bin, '-f', 'stderr', '--sample', '15',
            '-o', '-', '-x', 'html', '--quiet',
            '-T', self.name,
            '-d', self.env.cr.dbname,
            '-b', self.date_started,
            '-e', self.date_finished,
            self.pg_log_path,
        ]
        return pgbadger_cmd

    def _get_attachment_name(self, prefix, suffix):
        started = fields.Datetime.from_string(
            self.date_started).strftime(DATETIME_FORMAT_FILE)
        finished = fields.Datetime.from_string(
            self.date_finished).strftime(DATETIME_FORMAT_FILE)
        fname = '%s_%d_%s_to_%s%s' % (
            prefix, self.id, started, finished, suffix)
        return fname

    @api.model
    def dump_stats(self):
        attachment = None
        with tools.osutil.tempdir() as dump_dir:
            cprofile_fname = self._get_attachment_name("py_stats", ".cprofile")
            cprofile_path = os.path.join(dump_dir, cprofile_fname)
            _logger.info("Dumping cProfile '%s'", cprofile_path)
            ProfilerProfile.profile.dump_stats(cprofile_path)
            with open(cprofile_path, "rb") as f_cprofile:
                datas = f_cprofile.read()
            if datas and datas != CPROFILE_EMPTY_CHARS:
                attachment = self.env['ir.attachment'].create({
                    'name': cprofile_fname,
                    'res_id': self.id,
                    'res_model': self._name,
                    'datas': base64.b64encode(datas),
                    'datas_fname': cprofile_fname,
                    'description': 'cProfile dump stats',
                })
                _logger.info("A datas was saved, here %s", attachment.name)
                try:
                    if self.use_py_index:
                        py_stats = self.get_stats_string(cprofile_path)
                        self.env['profiler.profile.python.line'].search([
                            ('profile_id', '=', self.id)]).unlink()
                        for py_stat_line in py_stats.splitlines():
                            py_stat_line = py_stat_line.strip('\r\n ')
                            py_stat_line_match = LINE_STATS_RE.match(
                                py_stat_line) if py_stat_line else None
                            if not py_stat_line_match:
                                continue
                            data = dict((
                                field, py_stat_line_match.group(field))
                                for field in PY_STATS_FIELDS)
                            data['rcalls'], data['calls'] = (
                                "%(ncalls)s/%(ncalls)s" % data).split('/')[:2]
                            self.env['profiler.profile.python.line'].create({
                                'cprof_tottime': data['tottime'],
                                'cprof_ncalls': data['calls'],
                                'cprof_nrcalls': data['rcalls'],
                                'cprof_ttpercall': data['tt_percall'],
                                'cprof_cumtime': data['cumtime'],
                                'cprof_ctpercall': data['ct_percall'],
                                'cprof_fname': (
                                    "%(file)s:%(lineno)s (%(method)s)" % data),
                                'profile_id': self.id,
                            })
                        attachment.index_content = py_stats
                except IOError:
                    # Fancy feature but not stop process if fails
                    _logger.info("There was an error while getting the stats"
                                 "from the cprofile_path")
                    # pylint: disable=unnecessary-pass
                    pass
                self.dump_postgresql_logs()
                _logger.info("cProfile stats stored.")
            else:
                _logger.info("cProfile stats empty.")
        return attachment

    @api.multi
    def clear(self, reset_date=True):
        self.ensure_one()
        _logger.info("Clear profiler")
        if reset_date:
            self.date_started = self.now_utc()
        ProfilerProfile.profile.clear()

    @api.multi
    def disable(self):
        self.ensure_one()
        _logger.info("Disabling profiler")
        ProfilerProfile.enabled = False
        self.state = 'disabled'
        self.date_finished = self.now_utc()
        self.dump_stats()
        self.clear(reset_date=False)
        self._reset_postgresql()

    @staticmethod
    @contextmanager
    def profiling():
        """Thread local profile management, according to the shared "enabled"
        """
        if ProfilerProfile.enabled:
            _logger.debug("Catching profiling")
            ProfilerProfile.profile.enable()
        try:
            yield
        finally:
            if ProfilerProfile.enabled:
                ProfilerProfile.profile.disable()

    @api.multi
    def action_view_attachment(self):
        attachments = self.env['ir.attachment'].search([
            ('res_model', '=', self._name), ('res_id', '=', self.id)])
        action = self.env.ref("base.action_attachment").read()[0]
        action['domain'] = [('id', 'in', attachments.ids)]
        return action

    @api.model
    def set_pgoptions_enabled(self):
        """Verify if postgresql has configured the parameters for logging"""
        ProfilerProfile.pglogs_enabled = True
        pgoptions_enabled = bool(os.environ.get('PGOPTIONS'))
        _logger.info('Logging enabled from environment '
                     'variable PGOPTIONS? %s', pgoptions_enabled)
        if pgoptions_enabled:
            return
        pgparams_required = {
            'log_min_duration_statement': '0',
        }
        for param, value in pgparams_required.items():
            # pylint: disable=sql-injection
            self.env.cr.execute("SHOW %s" % param)
            db_value = self.env.cr.fetchone()[0].lower()
            if value.lower() != db_value:
                ProfilerProfile.pglogs_enabled = False
                break
        ProfilerProfile.psql_params_original = self.get_psql_params(
            self.env.cr, PGOPTIONS.keys())
        _logger.info('Logging enabled from postgresql.conf? %s',
                     ProfilerProfile.pglogs_enabled)

    @staticmethod
    def get_psql_params(cr, params):
        result = {}
        for param in set(params):
            # pylint: disable=sql-injection
            cr.execute('SHOW %s' % param)
            result.update(cr.dictfetchone())
        return result

    @api.model
    def _setup_complete(self):
        self.set_pgoptions_enabled()
        return super(ProfilerProfile, self)._setup_complete()