From 5be6bfeb557802f9d75dfcfbf63397b4e65138ff Mon Sep 17 00:00:00 2001 From: Rob Crittenden Date: May 06 2021 19:33:00 +0000 Subject: Parse Apache log etime and display average per command Including execution time (etime) was added in commit 4d716d3fbc69760bc0f7bd1a7c83ab14f1a62f18 This is a parser that will collect API executions and average them by command. If > 5 requests of the same type then the fastest and slowest results will be dropped to try to smooth the average. These averages will be used for two purposes: 1. Identify potential bottlenecks in API performance 2. Provide a baseline so that future performance changes can be measured. It is included in contrib because this is not going to be shipped with a distribution but is useful to have with the code. A sample execution is: Successful commands: Mean user_show: 12234152.5 of 2 executions Mean command_defaults: 3284363.0 of 3 executions Mean user_add: 594369554.5 of 2 executions Exceptions: Mean user_del: 232540327 ns of 2 executions The parselog command was successful Times are in nanoseconds. https://pagure.io/freeipa/issue/8809 Signed-off-by: Rob Crittenden Reviewed-By: Florence Blanc-Renaud --- diff --git a/contrib/perflog b/contrib/perflog new file mode 100644 index 0000000..837d7fe --- /dev/null +++ b/contrib/perflog @@ -0,0 +1,154 @@ +#!/usr/bin/python3 +# +# Copyright (C) 2021 FreeIPA Contributors see COPYING for license +# + +# This program is free software; you can redistribute it and/or modify +# it under the terms of the GNU General Public License as published by +# the Free Software Foundation, either version 3 of the License, or +# (at your option) any later version. +# +# This program is distributed in the hope that it will be useful, +# but WITHOUT ANY WARRANTY; without even the implied warranty of +# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the +# GNU General Public License for more details. +# +# You should have received a copy of the GNU General Public License +# along with this program. If not, see . + +from __future__ import division + +from datetime import datetime +import logging +import re +from statistics import mean + +from ipapython import admintool +from ipalib.facts import is_ipa_configured + + +TIME_RE = re.compile( + r'\[(?P.*)\] \[.*\].* \[pid \d+:tid \d+\] \[remote .*\] ' + r'ipa: DEBUG: \[jsonserver_session\] (?P\S+): ' + r'(?P\S+)/1\(.*\): (?P\S+) etime=(?P\d+)' +) + +DATE_FORMAT = '%a %b %d %H:%M:%S.%f %Y' + +logger = logging.getLogger(__name__) + + +class parselog(admintool.AdminTool): + command_name = "parselog" + + usage = "%prog [options]" + description = "Parse the Apache error log for performance data. " \ + "Enable debugging by creating /etc/ipa/server.conf with " \ + "the contents: [global]\\ndebug = True" + + def __init__(self, options, args): + super(parselog, self).__init__(options, args) + self.times = {} + self.exceptions = {} + self.since = None + + @classmethod + def add_options(cls, parser): + super(parselog, cls).add_options(parser, debug_option=True) + parser.add_option( + "--command", + dest="command", + action="store", + default=None, + help="Command to analyze", + ) + parser.add_option( + "--start-time", + dest="start_time", + action="store", + default=None, + help="time to begin analyzing logfile from", + ) + parser.add_option( + "--file", + dest="file", + action="store", + default="/var/log/httpd/error_log", + help="Log file to parse", + ) + + def validate_options(self): + super(parselog, self).validate_options(needs_root=True) + + if self.options.start_time: + self.since = datetime.strptime( + self.options.start_time, + DATE_FORMAT + ) + + def display_times(self, data, title, empty): + print(title) + output = False + for command in data: + if not data[command]: + continue + # Average dropping the min and max + if len(data[command]) > 5: + meantime = mean(sorted(data[command])[1:-1]) + num = len(data[command]) - 2 + else: + meantime = mean(data[command]) + num = len(data[command]) + print( + ' Mean %s: %0.f ns of %d executions' % ( + command, + meantime, + num) + ) + output = True + if not output: + print(f' No {empty} found') + return + + def run(self): + super(parselog, self).run() + + if not is_ipa_configured(): + logger.error("IPA server is not configured on this system.") + raise admintool.ScriptError() + + with open(self.options.file, 'r') as f: + data = f.read() + + matches = list(re.finditer(TIME_RE, data)) + + if self.options.command: + command = self.options.command.replace('-', '_') + else: + command = None + + for match in matches: + if self.since: + logtime = datetime.strptime(match.group('date'), DATE_FORMAT) + if logtime < self.since: + continue + if command is None or match.group('command') == command: + cmd = match.group('command') + if cmd not in self.times: + self.times[cmd] = [] + if cmd not in self.exceptions: + self.exceptions[cmd] = [] + if match.group('result') == 'SUCCESS': + self.times[cmd].append(float(match.group('etime'))) + else: + self.exceptions[cmd].append(float(match.group('etime'))) + + if self.times or self.exceptions: + self.display_times(self.times, "Successful commands:", "commands") + self.display_times(self.exceptions, "Exceptions:", "exceptions") + else: + print('No commands or exceptions found') + + +if __name__ == '__main__': + parselog.run_cli()