[PATCH 0/7] tools/kvm_stat: add logfile support

[PATCH 0/7] tools/kvm_stat: add logfile support

[Stefan Raspl]

This patch series provides a couple of new options to make logging to
files feasible.
Specifically, we add command line switches to specify an arbitrary time
interval for logging, and to toggle between a .csv and the previous
file format. Furthermore, we allow logging to files, where we utilize a
rotating set of 6 logfiles, each with its own header for easy post-
processing, especially when using .csv format.
Since specifying logfile size limits might be a non-trivial exercise,
we're throwing in yet another command line option that allows to
specify the minimum timeframe that should be covered by logs.
Finally, there's a minimal systemd unit file to deploy kvm_stat-based
logging in Linux distributions.
Note that the decision to write our own logfiles rather than to log to
e.g. systemd journal is a conscious one: It is effectively impossible to
write csv records into the systemd journal, the header will either
disappear after a while or has to be repeated from time to time, which
defeats the purpose of having a .csv format that can be easily post-
processed, etc.
See individual patch description for further details.


Stefan Raspl (7):
  tools/kvm_stat: rework command line sequence and message texts
  tools/kvm_stat: switch to argparse
  tools/kvm_stat: add command line switch '-s' to set update interval
  tools/kvm_stat: add command line switch '-c' to log in csv format
  tools/kvm_stat: add rotating log support
  tools/kvm_stat: add command line switch '-T'
  tools/kvm_stat: add sample systemd unit file

 tools/kvm/kvm_stat/kvm_stat         | 434 +++++++++++++++++++++-------
 tools/kvm/kvm_stat/kvm_stat.service |  15 +
 tools/kvm/kvm_stat/kvm_stat.txt     |  59 ++--
 3 files changed, 384 insertions(+), 124 deletions(-)
 create mode 100644 tools/kvm/kvm_stat/kvm_stat.service

-- 
2.17.1

[PATCH 1/7] tools/kvm_stat: rework command line sequence and message texts

[Stefan Raspl]

From: Stefan Raspl <raspl@de.ibm.com>

Make sure command line arguments are sorted alphabetically
everywhere, and adjusted existing texts for interactive command 's' to
become consistent with the long form --set-delay.
Throwing in some PEP8 fixes (all cosmetics) for good measure.

Signed-off-by: Stefan Raspl <raspl@linux.ibm.com>
---
 tools/kvm/kvm_stat/kvm_stat     |  9 ++++----
 tools/kvm/kvm_stat/kvm_stat.txt | 40 ++++++++++++++++-----------------
 2 files changed, 25 insertions(+), 24 deletions(-)

diff --git a/tools/kvm/kvm_stat/kvm_stat b/tools/kvm/kvm_stat/kvm_stat
index ad1b9e646c49..8fa39eb43f64 100755
--- a/tools/kvm/kvm_stat/kvm_stat
+++ b/tools/kvm/kvm_stat/kvm_stat
@@ -1179,7 +1179,7 @@ class Tui(object):
 
         if not self._is_running_guest(self.stats.pid_filter):
             if self._gname:
-                try: # ...to identify the guest by name in case it's back
+                try:  # ...to identify the guest by name in case it's back
                     pids = self.get_pid_from_gname(self._gname)
                     if len(pids) == 1:
                         self._refresh_header(pids[0])
@@ -1332,8 +1332,8 @@ class Tui(object):
         msg = ''
         while True:
             self.screen.erase()
-            self.screen.addstr(0, 0, 'Set update interval (defaults to %.1fs).' %
-                               DELAY_DEFAULT, curses.A_BOLD)
+            self.screen.addstr(0, 0, 'Set update interval (defaults to %.1fs).'
+                               % DELAY_DEFAULT, curses.A_BOLD)
             self.screen.addstr(4, 0, msg)
             self.screen.addstr(2, 0, 'Change delay from %.1fs to ' %
                                self._delay_regular)
@@ -1541,7 +1541,7 @@ Interactive Commands:
    p     filter by PID
    q     quit
    r     reset stats
-   s     set update interval
+   s     set update interval (value range: 0.1-25.5 secs)
    x     toggle reporting of stats for individual child trace events
 Press any other key to refresh statistics immediately.
 """ % (PATH_DEBUGFS_KVM, PATH_DEBUGFS_TRACING)
@@ -1707,5 +1707,6 @@ def main():
     else:
         batch(stats)
 
+
 if __name__ == "__main__":
     main()
diff --git a/tools/kvm/kvm_stat/kvm_stat.txt b/tools/kvm/kvm_stat/kvm_stat.txt
index c057ba52364e..8e0658e79eb7 100644
--- a/tools/kvm/kvm_stat/kvm_stat.txt
+++ b/tools/kvm/kvm_stat/kvm_stat.txt
@@ -49,7 +49,7 @@ INTERACTIVE COMMANDS
 
 *r*::	reset stats
 
-*s*::   set update interval
+*s*::   set delay between refreshs
 
 *x*::	toggle reporting of stats for child trace events
  ::     *Note*: The stats for the parents summarize the respective child trace
@@ -64,37 +64,37 @@ OPTIONS
 --batch::
 	run in batch mode for one second
 
--l::
---log::
-	run in logging mode (like vmstat)
-
--t::
---tracepoints::
-	retrieve statistics from tracepoints
-
 -d::
 --debugfs::
 	retrieve statistics from debugfs
 
+-f<fields>::
+--fields=<fields>::
+        fields to display (regex), "-f help" for a list of available events
+
+-g<guest>::
+--guest=<guest_name>::
+        limit statistics to one virtual machine (guest name)
+
+-h::
+--help::
+        show help message
+
 -i::
 --debugfs-include-past::
 	include all available data on past events for debugfs
 
+-l::
+--log::
+        run in logging mode (like vmstat)
+
 -p<pid>::
 --pid=<pid>::
 	limit statistics to one virtual machine (pid)
 
--g<guest>::
---guest=<guest_name>::
-	limit statistics to one virtual machine (guest name)
-
--f<fields>::
---fields=<fields>::
-	fields to display (regex), "-f help" for a list of available events
-
--h::
---help::
-	show help message
+-t::
+--tracepoints::
+        retrieve statistics from tracepoints
 
 SEE ALSO
 --------
-- 
2.17.1

[PATCH 2/7] tools/kvm_stat: switch to argparse

[Stefan Raspl]

From: Stefan Raspl <raspl@de.ibm.com>

optparse is deprecated for a while, hence switching over to argparse
(which also works with python2).
As a consequence, help output has some subtle changes, the most
significant one being that the options are all listed explicitly
instead of a universal '[options]' indicator. Also, some of the error
messages are phrased slightly different.
While at it, squashed a number of minor PEP8 issues.

Signed-off-by: Stefan Raspl <raspl@linux.ibm.com>
---
 tools/kvm/kvm_stat/kvm_stat | 142 ++++++++++++++++--------------------
 1 file changed, 62 insertions(+), 80 deletions(-)

diff --git a/tools/kvm/kvm_stat/kvm_stat b/tools/kvm/kvm_stat/kvm_stat
index 8fa39eb43f64..2d9947f596fc 100755
--- a/tools/kvm/kvm_stat/kvm_stat
+++ b/tools/kvm/kvm_stat/kvm_stat
@@ -25,7 +25,7 @@ import sys
 import locale
 import os
 import time
-import optparse
+import argparse
 import ctypes
 import fcntl
 import resource
@@ -869,7 +869,7 @@ class Stats(object):
 
         if options.debugfs:
             providers.append(DebugfsProvider(options.pid, options.fields,
-                                             options.dbgfs_include_past))
+                                             options.debugfs_include_past))
         if options.tracepoints or not providers:
             providers.append(TracepointProvider(options.pid, options.fields))
 
@@ -1546,84 +1546,66 @@ Interactive Commands:
 Press any other key to refresh statistics immediately.
 """ % (PATH_DEBUGFS_KVM, PATH_DEBUGFS_TRACING)
 
-    class PlainHelpFormatter(optparse.IndentedHelpFormatter):
-        def format_description(self, description):
-            if description:
-                return description + "\n"
-            else:
-                return ""
-
-    def cb_guest_to_pid(option, opt, val, parser):
-        try:
-            pids = Tui.get_pid_from_gname(val)
-        except:
-            sys.exit('Error while searching for guest "{}". Use "-p" to '
-                     'specify a pid instead?'.format(val))
-        if len(pids) == 0:
-            sys.exit('Error: No guest by the name "{}" found'.format(val))
-        if len(pids) > 1:
-            sys.exit('Error: Multiple processes found (pids: {}). Use "-p" '
-                     'to specify the desired pid'.format(" ".join(pids)))
-        parser.values.pid = pids[0]
-
-    optparser = optparse.OptionParser(description=description_text,
-                                      formatter=PlainHelpFormatter())
-    optparser.add_option('-1', '--once', '--batch',
-                         action='store_true',
-                         default=False,
-                         dest='once',
-                         help='run in batch mode for one second',
-                         )
-    optparser.add_option('-i', '--debugfs-include-past',
-                         action='store_true',
-                         default=False,
-                         dest='dbgfs_include_past',
-                         help='include all available data on past events for '
-                              'debugfs',
-                         )
-    optparser.add_option('-l', '--log',
-                         action='store_true',
-                         default=False,
-                         dest='log',
-                         help='run in logging mode (like vmstat)',
-                         )
-    optparser.add_option('-t', '--tracepoints',
-                         action='store_true',
-                         default=False,
-                         dest='tracepoints',
-                         help='retrieve statistics from tracepoints',
-                         )
-    optparser.add_option('-d', '--debugfs',
-                         action='store_true',
-                         default=False,
-                         dest='debugfs',
-                         help='retrieve statistics from debugfs',
-                         )
-    optparser.add_option('-f', '--fields',
-                         action='store',
-                         default='',
-                         dest='fields',
-                         help='''fields to display (regex)
-                                 "-f help" for a list of available events''',
-                         )
-    optparser.add_option('-p', '--pid',
-                         action='store',
-                         default=0,
-                         type='int',
-                         dest='pid',
-                         help='restrict statistics to pid',
-                         )
-    optparser.add_option('-g', '--guest',
-                         action='callback',
-                         type='string',
-                         dest='pid',
-                         metavar='GUEST',
-                         help='restrict statistics to guest by name',
-                         callback=cb_guest_to_pid,
-                         )
-    options, unkn = optparser.parse_args(sys.argv)
-    if len(unkn) != 1:
-        sys.exit('Error: Extra argument(s): ' + ' '.join(unkn[1:]))
+    class Guest_to_pid(argparse.Action):
+        def __call__(self, parser, namespace, values, option_string=None):
+            try:
+                pids = Tui.get_pid_from_gname(values)
+            except:
+                sys.exit('Error while searching for guest "{}". Use "-p" to '
+                         'specify a pid instead?'.format(values))
+            if len(pids) == 0:
+                sys.exit('Error: No guest by the name "{}" found'
+                         .format(values))
+            if len(pids) > 1:
+                sys.exit('Error: Multiple processes found (pids: {}). Use "-p"'
+                         ' to specify the desired pid'.format(" ".join(pids)))
+            namespace.pid = pids[0]
+
+    argparser = argparse.ArgumentParser(description=description_text,
+                                        formatter_class=argparse
+                                        .RawTextHelpFormatter)
+    argparser.add_argument('-1', '--once', '--batch',
+                           action='store_true',
+                           default=False,
+                           help='run in batch mode for one second',
+                           )
+    argparser.add_argument('-d', '--debugfs',
+                           action='store_true',
+                           default=False,
+                           help='retrieve statistics from debugfs',
+                           )
+    argparser.add_argument('-f', '--fields',
+                           default='',
+                           help='''fields to display (regex)
+"-f help" for a list of available events''',
+                           )
+    argparser.add_argument('-g', '--guest',
+                           type=str,
+                           help='restrict statistics to guest by name',
+                           action=Guest_to_pid,
+                           )
+    argparser.add_argument('-i', '--debugfs-include-past',
+                           action='store_true',
+                           default=False,
+                           help='include all available data on past events for'
+                                ' debugfs',
+                           )
+    argparser.add_argument('-l', '--log',
+                           action='store_true',
+                           default=False,
+                           help='run in logging mode (like vmstat)',
+                           )
+    argparser.add_argument('-p', '--pid',
+                           type=int,
+                           default=0,
+                           help='restrict statistics to pid',
+                           )
+    argparser.add_argument('-t', '--tracepoints',
+                           action='store_true',
+                           default=False,
+                           help='retrieve statistics from tracepoints',
+                           )
+    options = argparser.parse_args()
     try:
         # verify that we were passed a valid regex up front
         re.compile(options.fields)
-- 
2.17.1

[PATCH 3/7] tools/kvm_stat: add command line switch '-s' to set update interval

[Stefan Raspl]

From: Stefan Raspl <raspl@de.ibm.com>

This now controls both, the refresh rate of the interactive mode as well
as the logging mode. Which, as a consequence, means that the default of
logging mode is now 3s, too (use command line switch '-s' to adjust to
your liking).

Signed-off-by: Stefan Raspl <raspl@linux.ibm.com>
---
 tools/kvm/kvm_stat/kvm_stat     | 46 ++++++++++++++++++++++++---------
 tools/kvm/kvm_stat/kvm_stat.txt |  4 +++
 2 files changed, 38 insertions(+), 12 deletions(-)

diff --git a/tools/kvm/kvm_stat/kvm_stat b/tools/kvm/kvm_stat/kvm_stat
index 2d9947f596fc..8ed25bf1d048 100755
--- a/tools/kvm/kvm_stat/kvm_stat
+++ b/tools/kvm/kvm_stat/kvm_stat
@@ -970,15 +970,17 @@ DELAY_DEFAULT = 3.0
 MAX_GUEST_NAME_LEN = 48
 MAX_REGEX_LEN = 44
 SORT_DEFAULT = 0
+MIN_DELAY = 0.1
+MAX_DELAY = 25.5
 
 
 class Tui(object):
     """Instruments curses to draw a nice text ui."""
-    def __init__(self, stats):
+    def __init__(self, stats, opts):
         self.stats = stats
         self.screen = None
         self._delay_initial = 0.25
-        self._delay_regular = DELAY_DEFAULT
+        self._delay_regular = opts.set_delay
         self._sorting = SORT_DEFAULT
         self._display_guests = 0
 
@@ -1278,7 +1280,8 @@ class Tui(object):
                '   p     filter by guest name/PID',
                '   q     quit',
                '   r     reset stats',
-               '   s     set update interval',
+               '   s     set delay between refreshs (value range: '
+               '%s-%s secs)' % (MIN_DELAY, MAX_DELAY),
                '   x     toggle reporting of stats for individual child trace'
                ' events',
                'Any other key refreshes statistics immediately')
@@ -1344,11 +1347,9 @@ class Tui(object):
             try:
                 if len(val) > 0:
                     delay = float(val)
-                    if delay < 0.1:
-                        msg = '"' + str(val) + '": Value must be >=0.1'
-                        continue
-                    if delay > 25.5:
-                        msg = '"' + str(val) + '": Value must be <=25.5'
+                    err = is_delay_valid(delay)
+                    if err is not None:
+                        msg = err
                         continue
                 else:
                     delay = DELAY_DEFAULT
@@ -1484,7 +1485,7 @@ def batch(stats):
         pass
 
 
-def log(stats):
+def log(stats, opts):
     """Prints statistics as reiterating key block, multiple value blocks."""
     keys = sorted(stats.get().keys())
 
@@ -1502,7 +1503,7 @@ def log(stats):
     banner_repeat = 20
     while True:
         try:
-            time.sleep(1)
+            time.sleep(opts.set_delay)
             if line % banner_repeat == 0:
                 banner()
             statline()
@@ -1511,6 +1512,16 @@ def log(stats):
             break
 
 
+def is_delay_valid(delay):
+    """Verify delay is in valid value range."""
+    msg = None
+    if delay < MIN_DELAY:
+        msg = '"' + str(delay) + '": Delay must be >=%s' % MIN_DELAY
+    if delay > MAX_DELAY:
+        msg = '"' + str(delay) + '": Delay must be <=%s' % MAX_DELAY
+    return msg
+
+
 def get_options():
     """Returns processed program arguments."""
     description_text = """
@@ -1600,6 +1611,13 @@ Press any other key to refresh statistics immediately.
                            default=0,
                            help='restrict statistics to pid',
                            )
+    argparser.add_argument('-s', '--set-delay',
+                           type=float,
+                           default=DELAY_DEFAULT,
+                           metavar='DELAY',
+                           help='set delay between refreshs (value range: '
+                                '%s-%s secs)' % (MIN_DELAY, MAX_DELAY),
+                           )
     argparser.add_argument('-t', '--tracepoints',
                            action='store_true',
                            default=False,
@@ -1671,6 +1689,10 @@ def main():
         sys.stderr.write('Did you use a (unsupported) tid instead of a pid?\n')
         sys.exit('Specified pid does not exist.')
 
+    err = is_delay_valid(options.set_delay)
+    if err is not None:
+        sys.exit('Error: ' + err)
+
     stats = Stats(options)
 
     if options.fields == 'help':
@@ -1682,9 +1704,9 @@ def main():
         sys.exit(0)
 
     if options.log:
-        log(stats)
+        log(stats, options)
     elif not options.once:
-        with Tui(stats) as tui:
+        with Tui(stats, options) as tui:
             tui.show_stats()
     else:
         batch(stats)
diff --git a/tools/kvm/kvm_stat/kvm_stat.txt b/tools/kvm/kvm_stat/kvm_stat.txt
index 8e0658e79eb7..20928057cc9e 100644
--- a/tools/kvm/kvm_stat/kvm_stat.txt
+++ b/tools/kvm/kvm_stat/kvm_stat.txt
@@ -92,6 +92,10 @@ OPTIONS
 --pid=<pid>::
 	limit statistics to one virtual machine (pid)
 
+-s::
+--set-delay::
+        set delay between refreshs (value range: 0.1-25.5 secs)
+
 -t::
 --tracepoints::
         retrieve statistics from tracepoints
-- 
2.17.1

[PATCH 4/7] tools/kvm_stat: add command line switch '-c' to log in csv format

[Stefan Raspl]

From: Stefan Raspl <raspl@de.ibm.com>

Add an alternative format that can be more easily used for further
processing later on.
Note that we add a timestamp in the first column for both, the regular
and the new csv format.

Signed-off-by: Stefan Raspl <raspl@linux.ibm.com>
---
 tools/kvm/kvm_stat/kvm_stat     | 63 +++++++++++++++++++++++++--------
 tools/kvm/kvm_stat/kvm_stat.txt |  4 +++
 2 files changed, 53 insertions(+), 14 deletions(-)

diff --git a/tools/kvm/kvm_stat/kvm_stat b/tools/kvm/kvm_stat/kvm_stat
index 8ed25bf1d048..7fe767bd2625 100755
--- a/tools/kvm/kvm_stat/kvm_stat
+++ b/tools/kvm/kvm_stat/kvm_stat
@@ -33,6 +33,8 @@ import struct
 import re
 import subprocess
 from collections import defaultdict, namedtuple
+from functools import reduce
+from datetime import datetime
 
 VMX_EXIT_REASONS = {
     'EXCEPTION_NMI':        0,
@@ -1485,28 +1487,49 @@ def batch(stats):
         pass
 
 
-def log(stats, opts):
-    """Prints statistics as reiterating key block, multiple value blocks."""
-    keys = sorted(stats.get().keys())
-
-    def banner():
+class StdFormat(object):
+    def __init__(self, keys):
+        self._banner = ''
         for key in keys:
-            print(key.split(' ')[0], end=' ')
-        print()
+            self._banner += key.split(' ')[0] + ' '
 
-    def statline():
-        s = stats.get()
+    def get_banner(self):
+        return self._banner
+
+    @staticmethod
+    def get_statline(keys, s):
+        res = ''
         for key in keys:
-            print(' %9d' % s[key].delta, end=' ')
-        print()
+            res += ' %9d' % s[key].delta
+        return res
+
+
+class CSVFormat(object):
+    def __init__(self, keys):
+        self._banner = 'timestamp'
+        self._banner += reduce(lambda res, key: "{},{!s}".format(res,
+                               key.split(' ')[0]), keys, '')
+
+    def get_banner(self):
+        return self._banner
+
+    @staticmethod
+    def get_statline(keys, s):
+        return reduce(lambda res, key: "{},{!s}".format(res, s[key].delta),
+                      keys, '')
+
+
+def log(stats, opts, frmt, keys):
+    """Prints statistics as reiterating key block, multiple value blocks."""
     line = 0
     banner_repeat = 20
     while True:
         try:
             time.sleep(opts.set_delay)
             if line % banner_repeat == 0:
-                banner()
-            statline()
+                print(frmt.get_banner())
+            print(datetime.now().strftime("%Y-%m-%d %H:%M:%S") +
+                  frmt.get_statline(keys, stats.get()))
             line += 1
         except KeyboardInterrupt:
             break
@@ -1580,6 +1603,11 @@ Press any other key to refresh statistics immediately.
                            default=False,
                            help='run in batch mode for one second',
                            )
+    argparser.add_argument('-c', '--csv',
+                           action='store_true',
+                           default=False,
+                           help='log in csv format - requires option -l/--log',
+                           )
     argparser.add_argument('-d', '--debugfs',
                            action='store_true',
                            default=False,
@@ -1624,6 +1652,8 @@ Press any other key to refresh statistics immediately.
                            help='retrieve statistics from tracepoints',
                            )
     options = argparser.parse_args()
+    if options.csv and not options.log:
+        sys.exit('Error: Option -c/--csv requires -l/--log')
     try:
         # verify that we were passed a valid regex up front
         re.compile(options.fields)
@@ -1704,7 +1734,12 @@ def main():
         sys.exit(0)
 
     if options.log:
-        log(stats, options)
+        keys = sorted(stats.get().keys())
+        if options.csv:
+            frmt = CSVFormat(keys)
+        else:
+            frmt = StdFormat(keys)
+        log(stats, options, frmt, keys)
     elif not options.once:
         with Tui(stats, options) as tui:
             tui.show_stats()
diff --git a/tools/kvm/kvm_stat/kvm_stat.txt b/tools/kvm/kvm_stat/kvm_stat.txt
index 20928057cc9e..a97ded2aedad 100644
--- a/tools/kvm/kvm_stat/kvm_stat.txt
+++ b/tools/kvm/kvm_stat/kvm_stat.txt
@@ -64,6 +64,10 @@ OPTIONS
 --batch::
 	run in batch mode for one second
 
+-c::
+--csv=<file>::
+        log in csv format - requires option -l/--log
+
 -d::
 --debugfs::
 	retrieve statistics from debugfs
-- 
2.17.1

[PATCH 5/7] tools/kvm_stat: add rotating log support

[Stefan Raspl]

From: Stefan Raspl <raspl@de.ibm.com>

Add new command line switches -r to log output to a rotating set of
files. Number of files fixed to a total of 6 for now. Set maximum total

size via -S <size>, i.e. no file will exceed <size> / 6.
Note that each file has a header, so you can easily load each file
individually in an editor. On the downside, the first line of successive
files needs to be stripped in case somebody wants to concatenate them.

Signed-off-by: Stefan Raspl <raspl@linux.ibm.com>
---
 tools/kvm/kvm_stat/kvm_stat     | 119 ++++++++++++++++++++++++++++++--
 tools/kvm/kvm_stat/kvm_stat.txt |  13 +++-
 2 files changed, 126 insertions(+), 6 deletions(-)

diff --git a/tools/kvm/kvm_stat/kvm_stat b/tools/kvm/kvm_stat/kvm_stat
index 7fe767bd2625..2275ab1b070b 100755
--- a/tools/kvm/kvm_stat/kvm_stat
+++ b/tools/kvm/kvm_stat/kvm_stat
@@ -35,6 +35,10 @@ import subprocess
 from collections import defaultdict, namedtuple
 from functools import reduce
 from datetime import datetime
+import glob
+import string
+import logging
+from logging.handlers import RotatingFileHandler
 
 VMX_EXIT_REASONS = {
     'EXCEPTION_NMI':        0,
@@ -974,6 +978,8 @@ MAX_REGEX_LEN = 44
 SORT_DEFAULT = 0
 MIN_DELAY = 0.1
 MAX_DELAY = 25.5
+SIZE_DEFAULT = '10M'
+LOGCOUNT_DEFAULT = 6
 
 
 class Tui(object):
@@ -1535,6 +1541,64 @@ def log(stats, opts, frmt, keys):
             break
 
 
+def rotating_log(stats, opts, frmt, keys):
+    """Prints statistics to file in csv format."""
+    def init(opts, frmt):
+        # Regular RotatingFileHandler doesn't add a header to each file,
+        # so we create our own version
+        class MyRotatingFileHandler(RotatingFileHandler):
+            def __init__(self, logfile):
+                super(MyRotatingFileHandler,
+                      self).__init__(logfile, mode='w', maxBytes=opts.size_num,
+                                     backupCount=LOGCOUNT_DEFAULT-1)
+                self._header = ""
+                self._log = None
+
+            def doRollover(self):
+                super(MyRotatingFileHandler, self).doRollover()
+                if self._log is not None and self._header != "":
+                    self._log.debug(self._header)
+
+            def setHeader(self, header, log):
+                self._header = header
+                self._log = log
+                if not self.stream or self.stream.tell() == 0:
+                    self._log.debug(self._header)
+
+        # Regular Formatter would prepend a timestamp to the header,
+        # so we create our own version again
+        class MyFormatter(logging.Formatter):
+            def __init__(self, fmt, datefmt):
+                logging.Formatter.__init__(self, fmt=fmt, datefmt=datefmt)
+
+            def format(self, record):
+                if record.levelno == logging.DEBUG:
+                    return record.getMessage()
+                return logging.Formatter.format(self, record)
+        try:
+            hdl = MyRotatingFileHandler(opts.rotating_log)
+        except:
+            sys.exit("Error setting up csv log with file '%s'"
+                     % opts.rotating_log)
+        formatter = MyFormatter('%(asctime)s%(message)s', '%Y-%m-%d %H:%M:%S')
+        hdl.setFormatter(formatter)
+
+        logger = logging.getLogger('MyLogger')
+        logger.setLevel(logging.DEBUG)
+        logger.addHandler(hdl)
+        hdl.setHeader(frmt.get_banner(), logger)
+
+        return logger
+
+    log = init(opts, frmt)
+    while True:
+        try:
+            time.sleep(opts.set_delay)
+            log.info(frmt.get_statline(keys, stats.get()))
+        except KeyboardInterrupt:
+            break
+
+
 def is_delay_valid(delay):
     """Verify delay is in valid value range."""
     msg = None
@@ -1580,6 +1644,26 @@ Interactive Commands:
 Press any other key to refresh statistics immediately.
 """ % (PATH_DEBUGFS_KVM, PATH_DEBUGFS_TRACING)
 
+    def convert_from_si(opts):
+        try:
+            factor = 1000000
+            num = int(opts.size.rstrip(string.ascii_letters))
+            unit = opts.size.lstrip(string.digits)
+        except ValueError:
+            sys.exit("Error: Invalid argument to -S/--size: '%s'" % opts.size)
+        if num <= 0:
+            sys.exit("Error: Argument to -S/--size must be >0")
+        if unit != '':
+            if unit in ['m', 'M']:
+                factor = 1000000
+            elif unit in ['g', 'G']:
+                factor = 1000000000
+            elif unit in ['t', 'T']:
+                factor = 1000000000000
+            else:
+                sys.exit("Error: Unsupported unit suffix '%s'" % unit)
+        opts.size_num = int(num * factor / LOGCOUNT_DEFAULT)
+
     class Guest_to_pid(argparse.Action):
         def __call__(self, parser, namespace, values, option_string=None):
             try:
@@ -1606,7 +1690,8 @@ Press any other key to refresh statistics immediately.
     argparser.add_argument('-c', '--csv',
                            action='store_true',
                            default=False,
-                           help='log in csv format - requires option -l/--log',
+                           help='log in csv format - requires option -l/--log '
+                                'or -r/--rotating-log'
                            )
     argparser.add_argument('-d', '--debugfs',
                            action='store_true',
@@ -1639,6 +1724,12 @@ Press any other key to refresh statistics immediately.
                            default=0,
                            help='restrict statistics to pid',
                            )
+    argparser.add_argument('-r', '--rotating-log',
+                           type=str,
+                           default='',
+                           metavar='FILE',
+                           help='write a rotating log to FILE'
+                           )
     argparser.add_argument('-s', '--set-delay',
                            type=float,
                            default=DELAY_DEFAULT,
@@ -1646,14 +1737,28 @@ Press any other key to refresh statistics immediately.
                            help='set delay between refreshs (value range: '
                                 '%s-%s secs)' % (MIN_DELAY, MAX_DELAY),
                            )
+    argparser.add_argument('-S', '--size',
+                           type=str,
+                           default='',
+                           help='''maximum total file size
+supported suffixes: MGT (Megabytes (default), Gigabytes, Terabytes)
+default: %s''' % SIZE_DEFAULT,
+                           )
     argparser.add_argument('-t', '--tracepoints',
                            action='store_true',
                            default=False,
                            help='retrieve statistics from tracepoints',
                            )
     options = argparser.parse_args()
-    if options.csv and not options.log:
-        sys.exit('Error: Option -c/--csv requires -l/--log')
+    if options.csv and not options.log and not options.rotating_log:
+        sys.exit('Error: Option -c/--csv requires one of -l/--log or '
+                 '-r/--rotating-log')
+    if options.rotating_log:
+        if options.log:
+            sys.exit('Error: Cannot mix -l/--log and -r/--rotating-log')
+        if not options.size:
+            options.size = SIZE_DEFAULT
+        convert_from_si(options)
     try:
         # verify that we were passed a valid regex up front
         re.compile(options.fields)
@@ -1733,13 +1838,17 @@ def main():
         sys.stdout.write('  ' + '\n  '.join(sorted(set(event_list))) + '\n')
         sys.exit(0)
 
-    if options.log:
+    if options.log or options.rotating_log:
         keys = sorted(stats.get().keys())
         if options.csv:
             frmt = CSVFormat(keys)
         else:
             frmt = StdFormat(keys)
-        log(stats, options, frmt, keys)
+
+        if options.log:
+            log(stats, options, frmt, keys)
+        else:
+            rotating_log(stats, options, frmt, keys)
     elif not options.once:
         with Tui(stats, options) as tui:
             tui.show_stats()
diff --git a/tools/kvm/kvm_stat/kvm_stat.txt b/tools/kvm/kvm_stat/kvm_stat.txt
index a97ded2aedad..35df0b1261a2 100644
--- a/tools/kvm/kvm_stat/kvm_stat.txt
+++ b/tools/kvm/kvm_stat/kvm_stat.txt
@@ -66,7 +66,7 @@ OPTIONS
 
 -c::
 --csv=<file>::
-        log in csv format - requires option -l/--log
+        log in csv format - requires option -l/--log or -r/--rotating-log
 
 -d::
 --debugfs::
@@ -96,10 +96,21 @@ OPTIONS
 --pid=<pid>::
 	limit statistics to one virtual machine (pid)
 
+-r<file>::
+--rotating-log=<file>::
+	log output to rotating logfiles prefixed <file> - also
+            see option -S/--size
+
 -s::
 --set-delay::
         set delay between refreshs (value range: 0.1-25.5 secs)
 
+-S<size>::
+--size=<size>::
+	maximum total file size for option -r/--rotating-log.
+            Supported suffixes: MGT (Megabytes (default), Gigabytes, Terabytes).
+            Default: 10M
+
 -t::
 --tracepoints::
         retrieve statistics from tracepoints
-- 
2.17.1

[PATCH 6/7] tools/kvm_stat: add command line switch '-T'

[Stefan Raspl]

From: Stefan Raspl <raspl@de.ibm.com>

Allow to specify logfile size using a timeframe as specified by option
'-T'. Since .csv files have varying record lengths, the estimate might be
off, especially in case only a subset of (pathological) fields is chosen
via '-f'. But we try to over- rather than understimate the required space
to make up for it.

Signed-off-by: Stefan Raspl <raspl@linux.ibm.com>
---
 tools/kvm/kvm_stat/kvm_stat     | 73 ++++++++++++++++++++++++++++++++-
 tools/kvm/kvm_stat/kvm_stat.txt |  6 +++
 2 files changed, 78 insertions(+), 1 deletion(-)

diff --git a/tools/kvm/kvm_stat/kvm_stat b/tools/kvm/kvm_stat/kvm_stat
index 2275ab1b070b..d402ef97bf10 100755
--- a/tools/kvm/kvm_stat/kvm_stat
+++ b/tools/kvm/kvm_stat/kvm_stat
@@ -1509,6 +1509,10 @@ class StdFormat(object):
             res += ' %9d' % s[key].delta
         return res
 
+    def get_statline_len(self, keys, stats):
+        # Note: 19 chars for timestamp plus one for linefeed
+        return 20 + len(self.get_statline(keys, stats.get()))
+
 
 class CSVFormat(object):
     def __init__(self, keys):
@@ -1524,6 +1528,12 @@ class CSVFormat(object):
         return reduce(lambda res, key: "{},{!s}".format(res, s[key].delta),
                       keys, '')
 
+    def get_statline_len(self, keys, stats):
+        # csv statlines are of variable length - need to
+        # apply horrible heuristics to get a projection
+        # Note: 19 chars for timestamp plus one for linefeed
+        return 20 + len(keys) * 5
+
 
 def log(stats, opts, frmt, keys):
     """Prints statistics as reiterating key block, multiple value blocks."""
@@ -1543,6 +1553,14 @@ def log(stats, opts, frmt, keys):
 
 def rotating_log(stats, opts, frmt, keys):
     """Prints statistics to file in csv format."""
+    def convert_to_si(val):
+        if val / 1000000000000. > 1:
+            return "%.2fTB" % (val / 1000000000000.)
+        elif val / 1000000000. > 1:
+            return "%.2fGB" % (val / 1000000000.)
+        else:
+            return "%.2fMB" % (val / 1000000.)
+
     def init(opts, frmt):
         # Regular RotatingFileHandler doesn't add a header to each file,
         # so we create our own version
@@ -1580,6 +1598,18 @@ def rotating_log(stats, opts, frmt, keys):
         except:
             sys.exit("Error setting up csv log with file '%s'"
                      % opts.rotating_log)
+
+        def determine_logsize(opts, keys, stats):
+            if opts.time_frame != '':
+                opts.size = LOGCOUNT_DEFAULT * (len(frmt.get_banner()) + 1) + \
+                            opts.time_frame / opts.set_delay * \
+                            frmt.get_statline_len(keys, stats)
+                # Account for the current file being reset when we roll over
+                opts.size = opts.size / (LOGCOUNT_DEFAULT-1) * LOGCOUNT_DEFAULT
+                print("Estimated required total logfile size: %s" %
+                      convert_to_si(opts.size))
+
+        determine_logsize(opts, keys, stats)
         formatter = MyFormatter('%(asctime)s%(message)s', '%Y-%m-%d %H:%M:%S')
         hdl.setFormatter(formatter)
 
@@ -1645,6 +1675,32 @@ Press any other key to refresh statistics immediately.
 """ % (PATH_DEBUGFS_KVM, PATH_DEBUGFS_TRACING)
 
     def convert_from_si(opts):
+        if opts.time_frame != '':
+            try:
+                    num = int(opts.time_frame.rstrip(string.ascii_letters))
+                    unit = opts.time_frame.lstrip(string.digits)
+            except ValueError:
+                sys.exit("Error: Invalid argument to -T/--time-frame: '%s'"
+                         % opts.size)
+            if num <= 0:
+                sys.exit("Error: Argument to -S/--size must be >0")
+            factor = 3600
+            if unit != '':
+                if unit in ['h', 'H']:
+                    factor = 3600
+                elif unit in ['d', 'D']:
+                    factor = 24*3600
+                elif unit in ['w', 'W']:
+                    factor = 7*24*3600
+                elif unit in ['m', 'M']:
+                    factor = 30*24*3600
+                elif unit in ['y', 'Y']:
+                    factor = 365*24*3600
+                else:
+                    sys.exit("Error: Unsupported unit suffix '%s' for "
+                             "-T/--time-frame" % unit)
+            opts.time_frame = int(num * factor)
+
         try:
             factor = 1000000
             num = int(opts.size.rstrip(string.ascii_letters))
@@ -1749,6 +1805,13 @@ default: %s''' % SIZE_DEFAULT,
                            default=False,
                            help='retrieve statistics from tracepoints',
                            )
+    argparser.add_argument('-T', '--time-frame',
+                           type=str,
+                           default='',
+                           help='''determine total logfile size by minimum \
+time it should hold
+supported suffixes: hdwmy (hours (default), days, weeks, months, years)''',
+                           )
     options = argparser.parse_args()
     if options.csv and not options.log and not options.rotating_log:
         sys.exit('Error: Option -c/--csv requires one of -l/--log or '
@@ -1756,9 +1819,17 @@ default: %s''' % SIZE_DEFAULT,
     if options.rotating_log:
         if options.log:
             sys.exit('Error: Cannot mix -l/--log and -r/--rotating-log')
-        if not options.size:
+        if options.size:
+            if options.time_frame:
+                sys.exit('Error: Cannot specify -S/--size and -T/--time-frame '
+                         'together')
+        else:
             options.size = SIZE_DEFAULT
         convert_from_si(options)
+    else:
+        if options.size or options.time_frame:
+            sys.exit('Error: Options -S/--size and -T/--time-frame only valid '
+                     'with -r/--rotating-log')
     try:
         # verify that we were passed a valid regex up front
         re.compile(options.fields)
diff --git a/tools/kvm/kvm_stat/kvm_stat.txt b/tools/kvm/kvm_stat/kvm_stat.txt
index 35df0b1261a2..2531c3bf56eb 100644
--- a/tools/kvm/kvm_stat/kvm_stat.txt
+++ b/tools/kvm/kvm_stat/kvm_stat.txt
@@ -115,6 +115,12 @@ OPTIONS
 --tracepoints::
         retrieve statistics from tracepoints
 
+-T::
+--time-frame::
+        determine total logfile size by minimum time it should hold.
+            Supported suffixes: hd (hours (default), days, weeks, months,
+            years). Might be inaccurate for .csv format.
+
 SEE ALSO
 --------
 'perf'(1), 'trace-cmd'(1)
-- 
2.17.1

[PATCH 7/7] tools/kvm_stat: add sample systemd unit file

[Stefan Raspl]

From: Stefan Raspl <raspl@de.ibm.com>

Add a sample unit file as a basis for systemd integration of kvm_stat
logs.
Note that output is written to a rotating set of logfiles in .csv format
for easy post-processing.

Signed-off-by: Stefan Raspl <raspl@linux.ibm.com>
---
 tools/kvm/kvm_stat/kvm_stat.service | 15 +++++++++++++++
 1 file changed, 15 insertions(+)
 create mode 100644 tools/kvm/kvm_stat/kvm_stat.service

diff --git a/tools/kvm/kvm_stat/kvm_stat.service b/tools/kvm/kvm_stat/kvm_stat.service
new file mode 100644
index 000000000000..5854b285c669
--- /dev/null
+++ b/tools/kvm/kvm_stat/kvm_stat.service
@@ -0,0 +1,15 @@
+# SPDX-License-Identifier: GPL-2.0-only
+
+[Unit]
+Description=Service that logs KVM kernel module trace events
+Before=qemu-kvm.service
+
+[Service]
+Type=simple
+ExecStart=/root/kvm_stat -dtcr /var/log/kvm_stat.csv -T 1w -s 10
+Restart=always
+SyslogIdentifier=kvm_stat
+SyslogLevel=debug
+
+[Install]
+WantedBy=multi-user.target
-- 
2.17.1

Re: [PATCH 0/7] tools/kvm_stat: add logfile support

[Stefan Raspl]

On 2020-03-06 12:42, Stefan Raspl wrote:
> This patch series provides a couple of new options to make logging to
> files feasible.
> Specifically, we add command line switches to specify an arbitrary time
> interval for logging, and to toggle between a .csv and the previous
> file format. Furthermore, we allow logging to files, where we utilize a
> rotating set of 6 logfiles, each with its own header for easy post-
> processing, especially when using .csv format.
> Since specifying logfile size limits might be a non-trivial exercise,
> we're throwing in yet another command line option that allows to
> specify the minimum timeframe that should be covered by logs.
> Finally, there's a minimal systemd unit file to deploy kvm_stat-based
> logging in Linux distributions.
> Note that the decision to write our own logfiles rather than to log to
> e.g. systemd journal is a conscious one: It is effectively impossible to
> write csv records into the systemd journal, the header will either
> disappear after a while or has to be repeated from time to time, which
> defeats the purpose of having a .csv format that can be easily post-
> processed, etc.
> See individual patch description for further details.
> 
> 
> Stefan Raspl (7):
>   tools/kvm_stat: rework command line sequence and message texts
>   tools/kvm_stat: switch to argparse
>   tools/kvm_stat: add command line switch '-s' to set update interval
>   tools/kvm_stat: add command line switch '-c' to log in csv format
>   tools/kvm_stat: add rotating log support
>   tools/kvm_stat: add command line switch '-T'
>   tools/kvm_stat: add sample systemd unit file
> 
>  tools/kvm/kvm_stat/kvm_stat         | 434 +++++++++++++++++++++-------
>  tools/kvm/kvm_stat/kvm_stat.service |  15 +
>  tools/kvm/kvm_stat/kvm_stat.txt     |  59 ++--
>  3 files changed, 384 insertions(+), 124 deletions(-)
>  create mode 100644 tools/kvm/kvm_stat/kvm_stat.service
> 

Any consideration yet...?

Ciao,
Stefan

Re: [PATCH 0/7] tools/kvm_stat: add logfile support

[Paolo Bonzini]

On 06/03/20 12:42, Stefan Raspl wrote:
> This patch series provides a couple of new options to make logging to
> files feasible.
> Specifically, we add command line switches to specify an arbitrary time
> interval for logging, and to toggle between a .csv and the previous
> file format. Furthermore, we allow logging to files, where we utilize a
> rotating set of 6 logfiles, each with its own header for easy post-
> processing, especially when using .csv format.
> Since specifying logfile size limits might be a non-trivial exercise,
> we're throwing in yet another command line option that allows to
> specify the minimum timeframe that should be covered by logs.
> Finally, there's a minimal systemd unit file to deploy kvm_stat-based
> logging in Linux distributions.
> Note that the decision to write our own logfiles rather than to log to
> e.g. systemd journal is a conscious one: It is effectively impossible to
> write csv records into the systemd journal, the header will either
> disappear after a while or has to be repeated from time to time, which
> defeats the purpose of having a .csv format that can be easily post-
> processed, etc.
> See individual patch description for further details.
> 
> 
> Stefan Raspl (7):
>   tools/kvm_stat: rework command line sequence and message texts
>   tools/kvm_stat: switch to argparse
>   tools/kvm_stat: add command line switch '-s' to set update interval
>   tools/kvm_stat: add command line switch '-c' to log in csv format
>   tools/kvm_stat: add rotating log support
>   tools/kvm_stat: add command line switch '-T'
>   tools/kvm_stat: add sample systemd unit file
> 
>  tools/kvm/kvm_stat/kvm_stat         | 434 +++++++++++++++++++++-------
>  tools/kvm/kvm_stat/kvm_stat.service |  15 +
>  tools/kvm/kvm_stat/kvm_stat.txt     |  59 ++--
>  3 files changed, 384 insertions(+), 124 deletions(-)
>  create mode 100644 tools/kvm/kvm_stat/kvm_stat.service
> 

I queued patches 1-4.  For the others, however, I would prefer to add
support for SIGHUP instead (to reopen the logfile), so that one can use
the usual logrotate services.

Paolo

Re: [PATCH 0/7] tools/kvm_stat: add logfile support

[Stefan Raspl]

On 2020-03-19 12:54, Paolo Bonzini wrote:
> On 06/03/20 12:42, Stefan Raspl wrote:
>> This patch series provides a couple of new options to make logging to
>> files feasible.
>> Specifically, we add command line switches to specify an arbitrary time
>> interval for logging, and to toggle between a .csv and the previous
>> file format. Furthermore, we allow logging to files, where we utilize a
>> rotating set of 6 logfiles, each with its own header for easy post-
>> processing, especially when using .csv format.
>> Since specifying logfile size limits might be a non-trivial exercise,
>> we're throwing in yet another command line option that allows to
>> specify the minimum timeframe that should be covered by logs.
>> Finally, there's a minimal systemd unit file to deploy kvm_stat-based
>> logging in Linux distributions.
>> Note that the decision to write our own logfiles rather than to log to
>> e.g. systemd journal is a conscious one: It is effectively impossible to
>> write csv records into the systemd journal, the header will either
>> disappear after a while or has to be repeated from time to time, which
>> defeats the purpose of having a .csv format that can be easily post-
>> processed, etc.
>> See individual patch description for further details.
>>
>>
>> Stefan Raspl (7):
>>   tools/kvm_stat: rework command line sequence and message texts
>>   tools/kvm_stat: switch to argparse
>>   tools/kvm_stat: add command line switch '-s' to set update interval
>>   tools/kvm_stat: add command line switch '-c' to log in csv format
>>   tools/kvm_stat: add rotating log support
>>   tools/kvm_stat: add command line switch '-T'
>>   tools/kvm_stat: add sample systemd unit file
>>
>>  tools/kvm/kvm_stat/kvm_stat         | 434 +++++++++++++++++++++-------
>>  tools/kvm/kvm_stat/kvm_stat.service |  15 +
>>  tools/kvm/kvm_stat/kvm_stat.txt     |  59 ++--
>>  3 files changed, 384 insertions(+), 124 deletions(-)
>>  create mode 100644 tools/kvm/kvm_stat/kvm_stat.service
>>
> 
> I queued patches 1-4.  For the others, however, I would prefer to add
> support for SIGHUP instead (to reopen the logfile), so that one can use
> the usual logrotate services.

Thx!
As for SIGHUP: The problem that I see with logrotate and likewise approaches is
how the heading is being handled: If it is reprinted every x lines (like the
original logging format in kvmstat does), then it messes up any chance of
loading the output in external tools for further processing.
If the heading is printed once only, then it will get pushed out of the log
files at some time - which is fatal, since '-f <fields>' allows to specify
custom fields, so one cannot reconstruct what the fields were.
That's why I did things as I did - which works great for .csv output.
I'd really like to preserve the use-case where a user has a chance to
post-process the output, especially .csv, in other tools. So how how about we do
both, add support for SIGHUP for users who want to use logrotate (I imagine this
would be used with the original logging format only), and keep the suggested
support for 'native' log-rotation for .csv users?

Ciao,
Stefan

Re: [PATCH 0/7] tools/kvm_stat: add logfile support

[Paolo Bonzini]

On 23/03/20 10:58, Stefan Raspl wrote:
> Thx!
> As for SIGHUP: The problem that I see with logrotate and likewise approaches is
> how the heading is being handled: If it is reprinted every x lines (like the
> original logging format in kvmstat does), then it messes up any chance of
> loading the output in external tools for further processing.
> If the heading is printed once only, then it will get pushed out of the log
> files at some time - which is fatal, since '-f <fields>' allows to specify
> custom fields, so one cannot reconstruct what the fields were.

For CSV output, can't you print the heading immediately after SIGHUP
reopens the files?  (Maybe I am missing something and this is a stupid
suggestion, I don't know).

Paolo

> That's why I did things as I did - which works great for .csv output.
> I'd really like to preserve the use-case where a user has a chance to
> post-process the output, especially .csv, in other tools. So how how about we do
> both, add support for SIGHUP for users who want to use logrotate (I imagine this
> would be used with the original logging format only), and keep the suggested
> support for 'native' log-rotation for .csv users?

Re: [PATCH 0/7] tools/kvm_stat: add logfile support

[Stefan Raspl]

On 2020-03-23 11:12, Paolo Bonzini wrote:
> On 23/03/20 10:58, Stefan Raspl wrote:
>> Thx!
>> As for SIGHUP: The problem that I see with logrotate and likewise approaches is
>> how the heading is being handled: If it is reprinted every x lines (like the
>> original logging format in kvmstat does), then it messes up any chance of
>> loading the output in external tools for further processing.
>> If the heading is printed once only, then it will get pushed out of the log
>> files at some time - which is fatal, since '-f <fields>' allows to specify
>> custom fields, so one cannot reconstruct what the fields were.
> 
> For CSV output, can't you print the heading immediately after SIGHUP
> reopens the files?  (Maybe I am missing something and this is a stupid
> suggestion, I don't know).

(Same for me LOL)
To be able to make use of the logfiles, we'd need to have the heading appear at
the top of each of the files.
Couldn't find much info on how logrotate works internally, but from what I
gathered, it seems it moves out the current logfile e.g. /var/log/kvm.log to
become /var/log/kvm.log.1, and sends a SIGHUP to kvm_stat so that it re-opens
/var/log/kvm.log - which would then start out with a header again.
That should work, but can you confirm that this is what you're suggesting?
If so: Keep the current semantics for the original logging mode, where we have
the heading printed every 20 lines? I would assume so, as that format is better
suited for console logs, but just in case you wanted that changed...

Ciao,
Stefan

Re: [PATCH 0/7] tools/kvm_stat: add logfile support

[Paolo Bonzini]

On 24/03/20 09:26, Stefan Raspl wrote:
> To be able to make use of the logfiles, we'd need to have the heading appear at
> the top of each of the files.
> Couldn't find much info on how logrotate works internally, but from what I
> gathered, it seems it moves out the current logfile e.g. /var/log/kvm.log to
> become /var/log/kvm.log.1, and sends a SIGHUP to kvm_stat so that it re-opens
> /var/log/kvm.log - which would then start out with a header again.
> That should work, but can you confirm that this is what you're suggesting?
> If so: Keep the current semantics for the original logging mode, where we have
> the heading printed every 20 lines? I would assume so, as that format is better
> suited for console logs, but just in case you wanted that changed...

Yes to all. :)

Paolo

Re: [PATCH 0/7] tools/kvm_stat: add logfile support

[Stefan Raspl]

On 2020-03-24 11:32, Paolo Bonzini wrote:
> On 24/03/20 09:26, Stefan Raspl wrote:
>> To be able to make use of the logfiles, we'd need to have the heading appear at
>> the top of each of the files.
>> Couldn't find much info on how logrotate works internally, but from what I
>> gathered, it seems it moves out the current logfile e.g. /var/log/kvm.log to
>> become /var/log/kvm.log.1, and sends a SIGHUP to kvm_stat so that it re-opens
>> /var/log/kvm.log - which would then start out with a header again.
>> That should work, but can you confirm that this is what you're suggesting?
>> If so: Keep the current semantics for the original logging mode, where we have
>> the heading printed every 20 lines? I would assume so, as that format is better
>> suited for console logs, but just in case you wanted that changed...
> 
> Yes to all. :)

I wrote a respective patch and tried it out, and found this approach not to be
workable for a number of reasons:
- The implicit buffering that takes place when redirecting output of kvm_stat in
  logging mode to a file messes up the format: logrotate moves the files on the
  disks, but there might be still data buffered that hasn't been written out
  yet. The SIGHUP triggers a new header to be written with the patch I came up
  with, but that header would sometimes appear only after a couple of lines
  written to the file, which messes up the format. Flushing stdout in the signal
  handler won't help, either - it's already too late by then.
- When restarting kvm_stat logging (e.g. after a reboot), appending to an
  existing file should suppress a new header from being written, or it would end
  up somewhere in the middle of the file, messing up the format. kvm_stat
  doesn't know that or where its output is redirected to, so no chance of
  suppressing it within kvm_stat. We would probably require some kind of wrapper
  script (and possibly an extra cmd-line option to suppress the header on
  start).
- I was surprised to realize that SIGHUP is actually not part of logrotate -
  one has to write that manually into the logrotate config as a postrotate...
  and I'll openly admit that writing a respective killall-command that aims at a
  python script doesn't seem to be trivial...

Any idea how to address these issues?

As much as I sympathize with re-use of existing components, I'd like to point
out that my original patch was also re-using existing python code for rotating
logs, and made things just _so_ much easier from a user perspective.

Ciao,
Stefan

Re: [PATCH 7/7] tools/kvm_stat: add sample systemd unit file

[Stefan Raspl]

On 2020-03-06 12:42, Stefan Raspl wrote:
> From: Stefan Raspl <raspl@de.ibm.com>
> 
> Add a sample unit file as a basis for systemd integration of kvm_stat
> logs.
> Note that output is written to a rotating set of logfiles in .csv format
> for easy post-processing.
> 
> Signed-off-by: Stefan Raspl <raspl@linux.ibm.com>
> ---
>  tools/kvm/kvm_stat/kvm_stat.service | 15 +++++++++++++++
>  1 file changed, 15 insertions(+)
>  create mode 100644 tools/kvm/kvm_stat/kvm_stat.service
> 
> diff --git a/tools/kvm/kvm_stat/kvm_stat.service b/tools/kvm/kvm_stat/kvm_stat.service
> new file mode 100644
> index 000000000000..5854b285c669
> --- /dev/null
> +++ b/tools/kvm/kvm_stat/kvm_stat.service
> @@ -0,0 +1,15 @@
> +# SPDX-License-Identifier: GPL-2.0-only
> +
> +[Unit]
> +Description=Service that logs KVM kernel module trace events
> +Before=qemu-kvm.service
> +
> +[Service]
> +Type=simple
> +ExecStart=/root/kvm_stat -dtcr /var/log/kvm_stat.csv -T 1w -s 10
             ^^^^^^
Oooops - this isn't supposed to be a full qualified path, and especially not
this one.

Ciao,
Stefan

Re: [PATCH 0/7] tools/kvm_stat: add logfile support

[Paolo Bonzini]

On 29/03/20 13:22, Stefan Raspl wrote:
> I wrote a respective patch and tried it out, and found this approach not to be
> workable for a number of reasons:
> - The implicit buffering that takes place when redirecting output of kvm_stat in
>   logging mode to a file messes up the format: logrotate moves the files on the
>   disks, but there might be still data buffered that hasn't been written out
>   yet. The SIGHUP triggers a new header to be written with the patch I came up
>   with, but that header would sometimes appear only after a couple of lines
>   written to the file, which messes up the format. Flushing stdout in the signal
>   handler won't help, either - it's already too late by then.

I don't understand this.  Unless you were using copytruncate, the
sequence should be:

- logrotate moves file A to B

- your file descriptor should point to B, so kvm_stat keeps writing to
file B

- you send the signal to kvm_stat

- kvm_stat closes file B, so all pending records are written

- kvm_stat reopens file A and writes the header.

If you have a race of some sort, try having the signal handler do
nothing but set a flag that is examined in the main loop.

> - When restarting kvm_stat logging (e.g. after a reboot), appending to an
>   existing file should suppress a new header from being written, or it would end
>   up somewhere in the middle of the file, messing up the format. kvm_stat
>   doesn't know that or where its output is redirected to, so no chance of
>   suppressing it within kvm_stat. We would probably require some kind of wrapper
>   script (and possibly an extra cmd-line option to suppress the header on
>   start).

You could stat the output file, and suppress the header if it is a
regular non-empty file.  But it would be a problem anyway if the header
has changed since the last boot, which prompts the stupid and lazy
question: how does your series deal with this?

This one seems the biggest of the three problems to me.

> - I was surprised to realize that SIGHUP is actually not part of logrotate -
>   one has to write that manually into the logrotate config as a postrotate...
>   and I'll openly admit that writing a respective killall-command that aims at a
>   python script doesn't seem to be trivial...

This one is easy, put "ExecReload=/bin/kill -HUP $MAINPID" in the
systemd unit and use "systemctl reload kvm_stat.service" in the
postrotate command.

> As much as I sympathize with re-use of existing components, I'd like to point
> out that my original patch was also re-using existing python code for rotating
> logs, and made things just _so_ much easier from a user perspective.

I understand that, yes.  My request was more about not requiring
kvm_stat-specific configuration than about reusing existing components,
though.

Paolo

Re: [PATCH 0/7] tools/kvm_stat: add logfile support

[Stefan Raspl]

On 2020-03-30 12:43, Paolo Bonzini wrote:
> On 29/03/20 13:22, Stefan Raspl wrote:
>> I wrote a respective patch and tried it out, and found this approach not to be
>> workable for a number of reasons:
>> - The implicit buffering that takes place when redirecting output of kvm_stat in
>>   logging mode to a file messes up the format: logrotate moves the files on the
>>   disks, but there might be still data buffered that hasn't been written out
>>   yet. The SIGHUP triggers a new header to be written with the patch I came up
>>   with, but that header would sometimes appear only after a couple of lines
>>   written to the file, which messes up the format. Flushing stdout in the signal
>>   handler won't help, either - it's already too late by then.
> 
> I don't understand this.  Unless you were using copytruncate, the
> sequence should be:
> 
> - logrotate moves file A to B
> 
> - your file descriptor should point to B, so kvm_stat keeps writing to
> file B
> 
> - you send the signal to kvm_stat
> 
> - kvm_stat closes file B, so all pending records are written
> 
> - kvm_stat reopens file A and writes the header.

I was using copytruncate indeed. But removing it, things still don't work
(kvm_stat continues to write to B). But maybe there's a deeper misunderstanding:
My assumption is you'd do something like 'kvm_stat -l > /var/log/kvm_stat.txt'.
If so, how could kvm_stat ever be aware of where its output gets redirected to,
nevermind open/closing any of those files? Or did you mean kvm_stat should close
& open stdout?!

> If you have a race of some sort, try having the signal handler do
> nothing but set a flag that is examined in the main loop.
> 
>> - When restarting kvm_stat logging (e.g. after a reboot), appending to an
>>   existing file should suppress a new header from being written, or it would end
>>   up somewhere in the middle of the file, messing up the format. kvm_stat
>>   doesn't know that or where its output is redirected to, so no chance of
>>   suppressing it within kvm_stat. We would probably require some kind of wrapper
>>   script (and possibly an extra cmd-line option to suppress the header on
>>   start).
> 
> You could stat the output file, and suppress the header if it is a
> regular non-empty file.  But it would be a problem anyway if the header
> has changed since the last boot, which prompts the stupid and lazy
> question: how does your series deal with this?

How could we stat the output file if kvm_stat is just writing to a console?
My previous patch series was built on top of the RotatingFileHandler class,
which was making sure that we wouldn't repeat the header in case we're appending
to an existing file.
I don't believe there is any way of dealing with changes in the fields selected
- unless we just rotate files whenever we restart logging to be on the safe
side. But with the target scenario at hand (routinely logging in the background
as part of systemd or the like), the only plausible scenario would be that we
introduce new fields that get printed by kvm_stat per default.

> This one seems the biggest of the three problems to me.
> 
>> - I was surprised to realize that SIGHUP is actually not part of logrotate -
>>   one has to write that manually into the logrotate config as a postrotate...
>>   and I'll openly admit that writing a respective killall-command that aims at a
>>   python script doesn't seem to be trivial...
> 
> This one is easy, put "ExecReload=/bin/kill -HUP $MAINPID" in the
> systemd unit and use "systemctl reload kvm_stat.service" in the
> postrotate command.

Ah, OK - was searching for a solution within the realms of logrotate.

>> As much as I sympathize with re-use of existing components, I'd like to point
>> out that my original patch was also re-using existing python code for rotating
>> logs, and made things just _so_ much easier from a user perspective.
> 
> I understand that, yes.  My request was more about not requiring
> kvm_stat-specific configuration than about reusing existing components,
> though.

Taking a step back and looking at the tightly integrated kvm_stat - logrotate -
systemd approach outlined above, I'd bet most users would prefer a
self-contained solution in kvm_stat that merely requires adding a single extra
command line switch. And they can still add systemd on top, which wouldn't need
to interact with any of the other components except to start kvm_stat initally.

Ciao,
Stefan

Re: [PATCH 0/7] tools/kvm_stat: add logfile support

[Paolo Bonzini]

On 30/03/20 14:24, Stefan Raspl wrote:
> I was using copytruncate indeed. But removing it, things still don't work
> (kvm_stat continues to write to B). But maybe there's a deeper misunderstanding:
> My assumption is you'd do something like 'kvm_stat -l > /var/log/kvm_stat.txt'.
> If so, how could kvm_stat ever be aware of where its output gets redirected to,
> nevermind open/closing any of those files? Or did you mean kvm_stat should close
> & open stdout?!

You're right, we need to have a file name command line option for
kvm_stat, for logrotate to work.  (BTW the file would be opened with
O_APPEND, so the equivalent shell command line would use >> rather than >).

>> You could stat the output file, and suppress the header if it is a
>> regular non-empty file.  But it would be a problem anyway if the header
>> has changed since the last boot, which prompts the stupid and lazy
>> question: how does your series deal with this?
> 
> How could we stat the output file if kvm_stat is just writing to a console?

You can fstat it---either stdout or the file opened with the new command
line option.

>>> As much as I sympathize with re-use of existing components, I'd like to point
>>> out that my original patch was also re-using existing python code for rotating
>>> logs, and made things just _so_ much easier from a user perspective.
>>
>> I understand that, yes.  My request was more about not requiring
>> kvm_stat-specific configuration than about reusing existing components,
>> though.
>
> Taking a step back and looking at the tightly integrated kvm_stat - logrotate -
> systemd approach outlined above, I'd bet most users would prefer a
> self-contained solution in kvm_stat that merely requires adding a single extra
> command line switch. And they can still add systemd on top, which wouldn't need
> to interact with any of the other components except to start kvm_stat initally.

It seems to me that using systemd and logrotate makes it possible to
support progressive enhancement of kvm_stat's logging capabilities:

- curses-based logging
- manual CSV logging to disk (using > or >>)
- CSV logging to /var via systemd unit
- CSV logging to /var via systemd unit, with log rotation

Indeed using logrotate would not make it possible to do manual CSV
logging with log rotation, since the postrotate command uses systemctl.
 However it's only log rotation that would require using the systemd
unit, and systemd does not have to interact with logrotate, so the
integration seems relatively loose to me.

Paolo