xcat-core/xCAT-probe/scripts/dbstats.py

#!/usr/bin/env python
# -*- encoding: utf-8 -*-
from __future__ import print_function
import argparse
import json
import os
import sys
import time

BUF_SIZE = 8192


class Reader(object):
    def __init__(self, file):
        self.f_size = os.stat(file).st_size
        self.f_pos = self.f_size
        self.file = file
        self.buf_list = []
        self.remain = None
        self.f = None

    def open(self):
        if self.f is None:
            self.f = open(self.file)

    def close(self):
        if self.f is not None:
            self.f.close()
            self.f = None

    def __enter__(self):
        self.open()
        return self

    def __exit__(self, exc_type, exc_val, exc_tb):
        self.close()

    def _read(self):
        if self.f_pos == 0:
            return None

        size = BUF_SIZE
        if self.f_pos - BUF_SIZE >= 0:
            self.f.seek(self.f_pos - BUF_SIZE)
        else:
            self.f.seek(0)
            size = self.f_pos - 0
        buf = self.f.read(size)
        if self.remain is not None:
            self.buf_list = (buf + self.remain).split('\n')
        else:
            self.buf_list = buf.split('\n')
        if size == BUF_SIZE:
            self.remain = self.buf_list[0]
            self.buf_list = self.buf_list[1:]
        else:
            self.remain = None
        self.f_pos -= size

        return self.buf_list

    def get_next(self):
        ret = self._get_next()
        if ret is not None:
            return ret

        while self._read() is not None:
            ret = self._get_next()
            if ret is not None:
                return ret

        return None


class CommandReader(Reader):
    def __init__(self, file):
        super(CommandReader, self).__init__(file)
        self.cmd = {}

    def _get_next(self):
        """ Extract data from the commands log file of xcat
        Format::

            [Date]       2017-09-04 17:52:10
            [ClientType] cli
            [Request]    xdsh c910f04x35v07 'echo "nameserver 9.0.2.1" >> /etc/resolv.conf'
            [Response]
            [ElapsedTime] 0 s
        :return: command dict if found, None if not found
        """
        for i, b in enumerate(self.buf_list[::-1]):
            if b.find('[ElapsedTime]') == 0:
                self.cmd['elapsed'] = float(b.split(' ')[1])
            elif b.find('[Request]') == 0:
                self.cmd['request'] = " ".join(
                    b.rstrip().split(' ')[1:]).strip().replace(',', ' ')
            elif b.find('[Date]') == 0:
                temp = b.split(' ')
                self.cmd['date'] = '%s %s' % (temp[-2], temp[-1])

                if all(k in self.cmd for k in ('date', 'request', 'elapsed')):
                    cmd = self.cmd
                    self.cmd = {}
                    self.buf_list = self.buf_list[0:len(self.buf_list) - i - 1]
                    return cmd
        return None


class DBTraceReader(Reader):
    def __init__(self, file):
        super(DBTraceReader, self).__init__(file)
        self.year = str(time.localtime().tm_year)

    def _get_next(self):
        """Extract information from syslog file of xcat
        Format::

            Sep  4 22:16:38 c910f04x12v02 xcat[6692]: [DB Trace]: {"msg":{"table":"nodegroup","method":"xCAT::Table::getAllEntries"},"type":"end_sql","elapsed":"0.00042s"}

        :return: A dict contains the time stamp and db dict if db trace log is
                 found. None if nothing about db trace log found.
        """
        for i, b in enumerate(self.buf_list[::-1]):
            pos = b.find('[DB Trace]:')
            if pos == -1:
                continue
            date = b[0:15]
            conv = time.strptime('%s %s' % (self.year, date),
                                 "%Y %b %d %H:%M:%S")
            # TODO: the year value is not included in the current syslog
            try:
                ret = {'stamp': int(time.mktime(conv)),
                       'db': json.loads(b[pos + 12:])}
            except ValueError:
                if b.find('message repeated') != -1:
                    # syslog will add [ ] around the json message.
                    ret = {'stamp': int(time.mktime(conv)),
                           'db': json.loads(b[pos + 12:-1])}
                else:
                    raise

            self.buf_list = self.buf_list[0:len(self.buf_list) - i - 1]
            return ret

        return None


class TimeStamp(object):
    def __init__(self, kwargs):
        if 'date' in kwargs:
            a = time.strptime(kwargs['date'], "%Y-%m-%d %H:%M:%S")
            self.start = int(time.mktime(a))
        else:
            raise
        if 'elapsed' in kwargs:
            self.end = self.start + int(kwargs['elapsed']) + 1
        else:
            raise


class Analysis(object):
    def __init__(self, command_log_file, cluster_log_file):
        self.command_log_file = command_log_file
        self.cluster_log_file = cluster_log_file

    def _stat(self, record, data):
        elapsed = 0
        if 'elapsed' in data:
            # elapsed = float('%.3f' % float(data['elapsed'][:-1]))
            elapsed = float(data['elapsed'][:-1])
        if data['type'] == 'end_sql':
            if data['msg']['method'].startswith('xCAT::Table::get'):
                record['get_sql_time'] += elapsed
            elif data['msg']['method'].startswith('xCAT::Table::set'):
                record['set_sql_time'] += elapsed
            elif data['msg']['method'].startswith('xCAT::Table::del'):
                record['del_sql_time'] += elapsed
        elif data['type'] == 'end':
            if data['msg']['method'].startswith('xCAT::Table::get'):
                record['get_sub_time'] += elapsed
            elif data['msg']['method'].startswith('xCAT::Table::set'):
                record['set_sub_time'] += elapsed
            elif data['msg']['method'].startswith('xCAT::Table::del'):
                record['del_sub_time'] += elapsed
        elif data['type'] == 'start_sql':
            if data['msg']['method'].startswith('xCAT::Table::get'):
                if data['msg']['table'] not in record['get_tables']:
                    record['get_tables'][data['msg']['table']] = 1
                else:
                    record['get_tables'][data['msg']['table']] += 1
            elif data['msg']['method'].startswith('xCAT::Table::set'):
                if data['msg']['table'] not in record['set_tables']:
                    record['set_tables'][data['msg']['table']] = 1
                else:
                    record['set_tables'][data['msg']['table']] += 1
            elif data['msg']['method'].startswith('xCAT::Table::del'):
                if data['msg']['table'] not in record['del_tables']:
                    record['del_tables'][data['msg']['table']] = 1
                else:
                    record['del_tables'][data['msg']['table']] += 1
        elif data['type'] == 'build_cache':
            if data['msg']['table'] not in record['build_cache']:
                record['build_cache'][data['msg']['table']] = 1
            else:
                record['build_cache'][data['msg']['table']] += 1
        elif data['type'] == 'cache_hit':
            if data['msg']['table'] not in record['cache_hit']:
                record['cache_hit'][data['msg']['table']] = 1
            else:
                record['cache_hit'][data['msg']['table']] += 1

    def process(self, latest, specific_cmd):
        if specific_cmd is not None:
            latest = None

        self._print_header()
        with CommandReader(self.command_log_file) as cmd_reader:
            cmd = cmd_reader.get_next()
            trace = None
            index = 0
            db_reader = DBTraceReader(self.cluster_log_file)
            db_reader.open()
            while cmd is not None:
                if specific_cmd is not None and not cmd['request'].startswith(
                        specific_cmd):
                    cmd = cmd_reader.get_next()
                    continue

                stamp = TimeStamp(cmd)
                if trace is None:
                    trace = db_reader.get_next()

                while trace and trace['stamp'] > stamp.end:
                    trace = db_reader.get_next()
                key = '%s(%s)' % (cmd['request'], cmd['date'])

                record = {'command': key,
                          'elapsed': cmd['elapsed'],
                          'get_sql_time': float(0),
                          'set_sql_time': float(0),
                          'del_sql_time': float(0),
                          'set_sub_time': float(0),
                          'get_sub_time': float(0),
                          'del_sub_time': float(0),
                          'get_tables': {},
                          'set_tables': {},
                          'del_tables': {},
                          'build_cache': {},
                          'cache_hit': {}}

                while trace and trace['stamp'] >= stamp.start:
                    self._stat(record, trace['db'])
                    trace = db_reader.get_next()

                self._print_csv(record)
                index += 1
                if latest is not None and index == latest:
                    break
                cmd = cmd_reader.get_next()
            db_reader.close()

    def _print_header(self):
        print("command,elapsed(precision: 1s),"
              "get_sub_time(s),set_sub_time(s),del_sub_time(s),"
              "get_sql_time(s),set_sql_time(s),del_sql_time(s),"
              "build_cache(times),cache_hit(times),"
              "get_tables(times),set_tables(times),del_tables(times)")

    def _print_csv(self, record):
        print("%(command)s,%(elapsed)f,"
              "%(get_sub_time)f,%(set_sub_time)f,%(del_sub_time)f,"
              "%(get_sql_time)f,%(set_sql_time)f,%(del_sql_time)f,"
              "%(build_cache)s,%(cache_hit)s,"
              "%(get_tables)s,%(set_tables)s,%(del_tables)s\n" %
              {'command': record['command'],
               'elapsed': record['elapsed'],
               'get_sub_time': float('%.3f' % record['get_sub_time']),
               'set_sub_time': float('%.3f' % record['set_sub_time']),
               'del_sub_time': float('%.3f' % record['del_sub_time']),
               'get_sql_time': float('%.3f' % record['get_sql_time']),
               'set_sql_time': float('%.3f' % record['set_sql_time']),
               'del_sql_time': float('%.3f' % record['del_sql_time']),
               'build_cache': self._format_dict(record['build_cache']),
               'cache_hit': self._format_dict(record['cache_hit']),
               'get_tables': self._format_dict(record['get_tables']),
               'set_tables': self._format_dict(record['set_tables']),
               'del_tables': self._format_dict(record['del_tables'])})

    def _format_list(self, a):
        return " ".join(a)

    def _format_dict(self, d):
        ret = []
        for k, v in d.items():
            if type(v) is list:
                ret.append('%s:[%s]', k, " ".join(v))
            elif type(v) is str or type(v) is int:
                ret.append('%s:%s' % (k, str(v)))
        return " ".join(ret)


class StatsShell(object):
    def get_base_parser(self):
        parser = argparse.ArgumentParser(
            prog='dbstats',
            add_help=False,
            formatter_class=HelpFormatter,
        )
        parser.add_argument('-h', '--help',
                            action='store_true',
                            help=argparse.SUPPRESS,
                            )
        parser.add_argument('--clusterlog',
                            help="The syslog file of xcat.",
                            default='/var/log/xcat/cluster.log',
                            type=str)
        parser.add_argument('--commandlog',
                            help="The command log file of xcat.",
                            default='/var/log/xcat/commands.log',
                            type=str)
        parser.add_argument('-n', '--num',
                            help="The recent count of commands to analyze",
                            type=int,
                            default=10)
        parser.add_argument('-c', '--command',
                            help="The specified command to track",
                            type=str,
                            default=None)
        return parser

    def do_help(self, args):
        self.parser.print_help()

    def main(self, argv):
        self.parser = self.get_base_parser()
        (options, args) = self.parser.parse_known_args(argv)

        if options.help:
            self.do_help(options)
            return 0

        a = Analysis(options.commandlog, options.clusterlog)
        a.process(options.num, options.command)


class HelpFormatter(argparse.HelpFormatter):
    def start_section(self, heading):
        # Title-case the headings
        heading = '%s%s' % (heading[0].upper(), heading[1:])
        super(HelpFormatter, self).start_section(heading)


if __name__ == "__main__":
    StatsShell().main(sys.argv[1:])