Script to generate slow request table from Odoo logs. Make sure you pass `--log-handler openerp.http.rpc.request:DEBUG` when you run odoo server. This make sure response timing in Odoo logs. Script is expecting log entries like below. 2016-09-16 05:50:33,880 23231 DEBUG odoo_test openerp.http.rpc.request: call_kw: ir.model.data xmlid_to_res_id: …

odoo_request_log_parser.py

#!/usr/bin/env python
# MIT License

# Copyright (c) 2016 Jasim Muhammed

# Permission is hereby granted, free of charge, to any person obtaining a copy
# of this software and associated documentation files (the "Software"), to deal
# in the Software without restriction, including without limitation the rights
# to use, copy, modify, merge, publish, distribute, sublicense, and/or sell
# copies of the Software, and to permit persons to whom the Software is
# furnished to do so, subject to the following conditions:

# The above copyright notice and this permission notice shall be included in all
# copies or substantial portions of the Software.

# THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR
# IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY,
# FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE
# AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER
# LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM,
# OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE
# SOFTWARE.


import re
import glob
import argparse


HELP = """
Script to generate slow request table from Odoo logs.
"""
LOG_LINE_SAMPLE = "2016-09-16 05:50:33,880 23231 DEBUG odoo_test openerp.http.rpc.request: call_kw: ir.model.data xmlid_to_res_id: time:0.070s mem: 1012428k -> 1020624k (diff: 8196k)"
EPILOG_USAGE = """
Make sure you pass `--log-handler openerp.http.rpc.request:DEBUG`
when you run odoo server. This make sure response timing in Odoo logs.

Script is expecting log entries like below.
{}

Apdex score is calculated based on this formula http://bit.ly/2csTdzd
""".format(LOG_LINE_SAMPLE)

APDEX_SATISFIED = 0.5  # 1 second is satisfactory
APDEX_TOLERABLE = 5.0  # Upto 5 seconds its tolerable
TABLE_FORMAT = "{0:<50}{1:>10}{2:>20}{3:>10}{4:>10}"
ODOO_LOG_REQTIME_PATTERN = re.compile("\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}.*?openerp\\.http\\.rpc\\.request: (.*?):? time:(\d+.\d+)s")


def print_table(table):
    """
    Print table according to the format defined
    Sorted based on low apdex, high rank, high count
    """
    table = sorted(table, key=lambda x: (x.apdex, -x.rank, -x.count))
    line = 100 * '-'
    print "{:100}".format(line)
    print TABLE_FORMAT.format('Function', 'Count', 'AvgExec time', 'Rank', 'Apdex')
    print "{:100}".format(line)
    for row in table:
        print row


class FnData(object):
    """
    Class to store method execution times

    """

    name = None
    avg_exec_time = 0.0
    count = 0
    apdex = -1.0

    def __init__(self, name, exec_time):
        """
        Initialize data structure for fn analysis
        :param name: Name of the funciton with parameters
        :param exec_time: execution time of the functino
        """
        self.name = name
        self.count = 1
        self.avg_exec_time = exec_time
        self.apdex = self._calculate_apdex(exec_time)

    @property
    def rank(self):
        return self.count * self.avg_exec_time

    def add_item(self, exec_time):
        """
        Add new execution time for the function
        :param exec_time: execution time of the functino
        """
        self.count += 1
        self.avg_exec_time = (self.avg_exec_time + exec_time) / 2
        self.apdex = self._calculate_apdex(exec_time)

    def _calculate_apdex(self, new_val):
        """
        Calculate apdex score for the function

        :param new_val: float between 0 - 1.0
        :returns float
        """
        if new_val <= APDEX_SATISFIED:
            numerator = 1.0
        elif new_val <= APDEX_TOLERABLE:
            numerator = 0.5
        else:
            numerator = 0
        if 0 <= self.apdex <= 1.0:
            return (numerator + self.apdex) / 2
        else:
            return numerator

    def __eq__(self, other):
        return self.name == other

    def __str__(self):
        return TABLE_FORMAT.format(self.name, self.count, "%.3f" % self.avg_exec_time, "%.3f" % self.rank, "%.3f" % self.apdex)


def generate_fn_table(glob_pattern):
    """
    Main function
    :param glob_pattern: accepts the pattern to scan for odoo log files with entries in below format
    """
    fns = []
    files = False
    # load_log_file
    for f in glob.glob(glob_pattern):
        files = True
        with open(f) as log:
            for l in log:
                match = ODOO_LOG_REQTIME_PATTERN.search(l)
                if match:
                    groups = match.groups()
                    name = groups[0]
                    exec_time = float(groups[1])
                    if name in fns:
                        idx = fns.index(name)
                        fns[idx].add_item(exec_time)
                    else:
                        fns.append(FnData(name, exec_time))

    if files and fns:
        print_table(fns)
    elif not fns:
        print "No log line in the specified format could be detected.\nWe are expecting log lines like below in the log files\n{}\n".format(LOG_LINE_SAMPLE)
    else:
        print "No files are found with the passed file search format :{}".format(glob_pattern)

if __name__ == '__main__':
    parser = argparse.ArgumentParser(epilog=EPILOG_USAGE,
                                     formatter_class=argparse.RawDescriptionHelpFormatter,
                                     description=HELP
                                     )
    parser.add_argument('-l', '--logs',
                        dest='glob_pattern',
                        required=True,
                        help='Log files glob. Eg: /var/log/odoo*.log)')

    args = parser.parse_args()
    generate_fn_table(args.glob_pattern)

Hi @jasimmk, the way you calculate avg_exec_time is incorrect.

Hi @nilshamerlinck why do you think it is incorrect?