Skip to contentSkip to conversation

tools/kvm_stat: add logfile support

PATCH Applied Stefan Raspl 2 participants 7 messages Apr 2, 2020 – Apr 16, 2020 KVM

lore
Share & tools
lore
#0 lore raw

v2 cover tools/kvm_stat: add logfile support

Next attempt to come up with support for logfiles that can be combined with a solution for rotating logs.
Adding another patch to skip records with all zeros to preserve space.

Changes in v2:
- Addressed feedback from patch review
- Beefed up man page descriptions of --csv and --log-to-file (fixing a glitch in the former)
- Use a metavar for -L in the --help output

Stefan Raspl (3):
tools/kvm_stat: add command line switch '-z' to skip zero records tools/kvm_stat: Add command line switch '-L' to log to file tools/kvm_stat: add sample systemd unit file

 tools/kvm/kvm_stat/kvm_stat         | 84 ++++++++++++++++++++++++-----
 tools/kvm/kvm_stat/kvm_stat.service | 16 ++++++
 tools/kvm/kvm_stat/kvm_stat.txt     | 15 +++++-
 3 files changed, 101 insertions(+), 14 deletions(-)
 create mode 100644 tools/kvm/kvm_stat/kvm_stat.service
Signature · 1 line
2.17.1
#1 lore raw

PATCH v2 1/3 tools/kvm_stat: add command line switch '-z' to skip zero records

From: Stefan Raspl <[email protected]>

When running in logging mode, skip records with all zeros (=empty records) to preserve space when logging to files.

---
 tools/kvm/kvm_stat/kvm_stat     | 28 ++++++++++++++++++++--------
 tools/kvm/kvm_stat/kvm_stat.txt |  4 ++++
 2 files changed, 24 insertions(+), 8 deletions(-)
tools/kvm/kvm_stat/kvm_stat +20 -8
index e83fc8e868f4..d6cced4e1ef4 100755
@@ -1500,8 +1500,7 @@ class StdFormat(object):
     def get_banner(self):
         return self._banner
 
-    @staticmethod
-    def get_statline(keys, s):
+    def get_statline(self, keys, s):
         res = ''
         for key in keys:
             res += ' %9d' % s[key].delta
@@ -1517,8 +1516,7 @@ class CSVFormat(object):
     def get_banner(self):
         return self._banner
 
-    @staticmethod
-    def get_statline(keys, s):
+    def get_statline(self, keys, s):
         return reduce(lambda res, key: "{},{!s}".format(res, s[key].delta),
                       keys, '')
 
@@ -1527,14 +1525,21 @@ def log(stats, opts, frmt, keys):
     """Prints statistics as reiterating key block, multiple value blocks."""
     line = 0
     banner_repeat = 20
+    banner_printed = False
+
     while True:
         try:
             time.sleep(opts.set_delay)
-            if line % banner_repeat == 0:
+            if line % banner_repeat == 0 and not banner_printed:
                 print(frmt.get_banner())
-            print(datetime.now().strftime("%Y-%m-%d %H:%M:%S") +
-                  frmt.get_statline(keys, stats.get()))
-            line += 1
+                banner_printed = True
+            values = stats.get()
+            if (not opts.skip_zero_records or
+                any(values[k].delta != 0 for k in keys)):
+                print(datetime.now().strftime("%Y-%m-%d %H:%M:%S") +
+                      frmt.get_statline(keys, values))
+                line += 1
+                banner_printed = False
         except KeyboardInterrupt:
             break
 
@@ -1655,9 +1660,16 @@ Press any other key to refresh statistics immediately.
                            default=False,
                            help='retrieve statistics from tracepoints',
                            )
+    argparser.add_argument('-z', '--skip-zero-records',
+                           action='store_true',
+                           default=False,
+                           help='omit records with all zeros in logging mode',
+                           )
     options = argparser.parse_args()
     if options.csv and not options.log:
         sys.exit('Error: Option -c/--csv requires -l/--log')
+    if options.skip_zero_records and not options.log:
+        sys.exit('Error: Option -z/--skip-zero-records requires -l/--log')
     try:
         # verify that we were passed a valid regex up front
         re.compile(options.fields)
tools/kvm/kvm_stat/kvm_stat.txt +4 -0
index a97ded2aedad..24296dccc00a 100644
@@ -104,6 +104,10 @@ OPTIONS
 --tracepoints::
         retrieve statistics from tracepoints
 
+*z*::
+--skip-zero-records::
+        omit records with all zeros in logging mode
+
 SEE ALSO
 --------
 'perf'(1), 'trace-cmd'(1)
Signature · 1 line
2.17.1
#2 lore raw

PATCH v2 2/3 tools/kvm_stat: Add command line switch '-L' to log to file

In reply to Stefan Raspl

From: Stefan Raspl <[email protected]>

To integrate with logrotate, we have a signal handler that will re-open the logfile.
Assuming we have a systemd unit file with
ExecStart=kvm_stat -dtc -s 10 -L /var/log/kvm_stat.csv ExecReload=/bin/kill -HUP $MAINPID
and a logrotate config featuring
postrotate
/bin/systemctl reload kvm_stat.service
endscript
Then the overall flow will look like this:
(1) systemd starts kvm_stat, logging to A.
(2) At some point, logrotate runs, moving A to B.
kvm_stat continues to write to B at this point.
(3) After rotating, logrotate restarts the kvm_stat unit via systemctl.
(4) The kvm_stat unit sends a SIGHUP to kvm_stat, finally making it switch over to writing to A again.
Note that in order to keep the structure of the cvs output in tact, we make sure to, in contrast to the standard log format, only write the header once at the beginning of a file. This implies that the header is suppressed when appending to an existing file. Unlike with the standard format, where we append to an existing file by starting out with a header.

---
 tools/kvm/kvm_stat/kvm_stat     | 70 +++++++++++++++++++++++++++------
 tools/kvm/kvm_stat/kvm_stat.txt | 11 +++++-
 2 files changed, 68 insertions(+), 13 deletions(-)
tools/kvm/kvm_stat/kvm_stat +59 -11
index d6cced4e1ef4..d199a3694be8 100755
@@ -32,6 +32,7 @@ import resource
 import struct
 import re
 import subprocess
+import signal
 from collections import defaultdict, namedtuple
 from functools import reduce
 from datetime import datetime
@@ -228,6 +229,8 @@ IOCTL_NUMBERS = {
     'RESET':       0x00002403,
 }
 
+signal_received = False
+
 ENCODING = locale.getpreferredencoding(False)
 TRACE_FILTER = re.compile(r'^[^\(]*$')
 
@@ -1523,26 +1526,64 @@ class CSVFormat(object):
 
 def log(stats, opts, frmt, keys):
     """Prints statistics as reiterating key block, multiple value blocks."""
+    global signal_received
     line = 0
     banner_repeat = 20
-    banner_printed = False
-
+    f = None
+
+    def do_banner(opts):
+        nonlocal f
+        if opts.log_to_file:
+            if not f:
+                try:
+                     f = open(opts.log_to_file, 'a')
+                except (IOError, OSError):
+                    sys.exit("Error: Could not open file: %s" %
+                             opts.log_to_file)
+                if isinstance(frmt, CSVFormat) and f.tell() != 0:
+                    return
+        print(frmt.get_banner(), file=f or sys.stdout)
+
+    def do_statline(opts, values):
+        statline = datetime.now().strftime("%Y-%m-%d %H:%M:%S") + \
+                   frmt.get_statline(keys, values)
+        print(statline, file=f or sys.stdout)
+
+    do_banner(opts)
+    banner_printed = True
     while True:
         try:
             time.sleep(opts.set_delay)
-            if line % banner_repeat == 0 and not banner_printed:
-                print(frmt.get_banner())
+            if signal_received:
+                banner_printed = True
+                line = 0
+                f.close()
+                do_banner(opts)
+                signal_received = False
+            if (line % banner_repeat == 0 and not banner_printed and
+                not (opts.log_to_file and isinstance(frmt, CSVFormat))):
+                do_banner(opts)
                 banner_printed = True
             values = stats.get()
             if (not opts.skip_zero_records or
                 any(values[k].delta != 0 for k in keys)):
-                print(datetime.now().strftime("%Y-%m-%d %H:%M:%S") +
-                      frmt.get_statline(keys, values))
+                do_statline(opts, values)
                 line += 1
                 banner_printed = False
         except KeyboardInterrupt:
             break
 
+    if opts.log_to_file:
+        f.close()
+
+
+def handle_signal(sig, frame):
+    global signal_received
+
+    signal_received = True
+
+    return
+
 
 def is_delay_valid(delay):
     """Verify delay is in valid value range."""
@@ -1615,7 +1656,7 @@ 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/-L',
                            )
     argparser.add_argument('-d', '--debugfs',
                            action='store_true',
@@ -1643,6 +1684,11 @@ Press any other key to refresh statistics immediately.
                            default=False,
                            help='run in logging mode (like vmstat)',
                            )
+    argparser.add_argument('-L', '--log-to-file',
+                           type=str,
+                           metavar='FILE',
+                           help="like '--log', but logging to a file"
+                           )
     argparser.add_argument('-p', '--pid',
                            type=int,
                            default=0,
@@ -1666,10 +1712,10 @@ Press any other key to refresh statistics immediately.
                            help='omit records with all zeros in logging mode',
                            )
     options = argparser.parse_args()
-    if options.csv and not options.log:
+    if options.csv and not (options.log or options.log_to_file):
         sys.exit('Error: Option -c/--csv requires -l/--log')
-    if options.skip_zero_records and not options.log:
-        sys.exit('Error: Option -z/--skip-zero-records requires -l/--log')
+    if options.skip_zero_records and not (options.log or options.log_to_file):
+        sys.exit('Error: Option -z/--skip-zero-records requires -l/-L')
     try:
         # verify that we were passed a valid regex up front
         re.compile(options.fields)
@@ -1749,7 +1795,9 @@ def main():
         sys.stdout.write('  ' + '\n  '.join(sorted(set(event_list))) + '\n')
         sys.exit(0)
 
-    if options.log:
+    if options.log or options.log_to_file:
+        if options.log_to_file:
+            signal.signal(signal.SIGHUP, handle_signal)
         keys = sorted(stats.get().keys())
         if options.csv:
             frmt = CSVFormat(keys)
tools/kvm/kvm_stat/kvm_stat.txt +9 -2
index 24296dccc00a..feaf46451e83 100644
@@ -65,8 +65,10 @@ OPTIONS
 	run in batch mode for one second
 
 -c::
---csv=<file>::
-        log in csv format - requires option -l/--log
+--csv::
+        log in csv format. Requires option -l/--log or -L/--log-to-file.
+        When used with option -L/--log-to-file, the header is only ever
+        written to start of file to preserve the format.
 
 -d::
 --debugfs::
@@ -92,6 +94,11 @@ OPTIONS
 --log::
         run in logging mode (like vmstat)
 
+
+-L<file>::
+--log-to-file=<file>::
+        like -l/--log, but logging to a file. Appends to existing files.
+
 -p<pid>::
 --pid=<pid>::
 	limit statistics to one virtual machine (pid)
Signature · 1 line
2.17.1
#3 lore raw

PATCH v2 3/3 tools/kvm_stat: add sample systemd unit file

In reply to Stefan Raspl

From: Stefan Raspl <[email protected]>

Add a sample unit file as a basis for systemd integration of kvm_stat logs.

---
 tools/kvm/kvm_stat/kvm_stat.service | 16 ++++++++++++++++
 1 file changed, 16 insertions(+)
 create mode 100644 tools/kvm/kvm_stat/kvm_stat.service
tools/kvm/kvm_stat/kvm_stat.service new file +16 -0
new file mode 100644
index 000000000000..71aabaffe779
@@ -0,0 +1,16 @@
+# 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=/usr/bin/kvm_stat -dtcz -s 10 -L /var/log/kvm_stat.csv
+ExecReload=/bin/kill -HUP $MAINPID
+Restart=always
+SyslogIdentifier=kvm_stat
+SyslogLevel=debug
+
+[Install]
+WantedBy=multi-user.target
Signature · 1 line
2.17.1
#4 lore raw
In reply to Stefan Raspl
Quoted 16 lines · Stefan Raspl

Next attempt to come up with support for logfiles that can be combined with a solution for rotating logs.
Adding another patch to skip records with all zeros to preserve space.

Changes in v2:
- Addressed feedback from patch review
- Beefed up man page descriptions of --csv and --log-to-file (fixing a glitch in the former)
- Use a metavar for -L in the --help output

Stefan Raspl (3):
tools/kvm_stat: add command line switch '-z' to skip zero records tools/kvm_stat: Add command line switch '-L' to log to file tools/kvm_stat: add sample systemd unit file

Quoted 5 lines
 tools/kvm/kvm_stat/kvm_stat         | 84 ++++++++++++++++++++++++-----
 tools/kvm/kvm_stat/kvm_stat.service | 16 ++++++
 tools/kvm/kvm_stat/kvm_stat.txt     | 15 +++++-
 3 files changed, 101 insertions(+), 14 deletions(-)
 create mode 100644 tools/kvm/kvm_stat/kvm_stat.service

*ping*

#5 lore raw
Quoted 17 lines · Stefan Raspl
Quoted 16 lines · Stefan Raspl

Next attempt to come up with support for logfiles that can be combined with a solution for rotating logs.
Adding another patch to skip records with all zeros to preserve space.

Changes in v2:
- Addressed feedback from patch review
- Beefed up man page descriptions of --csv and --log-to-file (fixing a glitch in the former)
- Use a metavar for -L in the --help output

Stefan Raspl (3):
tools/kvm_stat: add command line switch '-z' to skip zero records tools/kvm_stat: Add command line switch '-L' to log to file tools/kvm_stat: add sample systemd unit file

Quoted 7 lines
Quoted 5 lines
 tools/kvm/kvm_stat/kvm_stat         | 84 ++++++++++++++++++++++++-----
 tools/kvm/kvm_stat/kvm_stat.service | 16 ++++++
 tools/kvm/kvm_stat/kvm_stat.txt     | 15 +++++-
 3 files changed, 101 insertions(+), 14 deletions(-)
 create mode 100644 tools/kvm/kvm_stat/kvm_stat.service

*ping*

So...any consideration?

Ciao,
Stefan

maintainer Applied
#6 lore raw
Quoted 24 lines · Stefan Raspl
Quoted 23 lines · Stefan Raspl
Quoted 21 lines · Stefan Raspl

Next attempt to come up with support for logfiles that can be combined with a solution for rotating logs.
Adding another patch to skip records with all zeros to preserve space.

Changes in v2:
- Addressed feedback from patch review
- Beefed up man page descriptions of --csv and --log-to-file (fixing a glitch in the former)
- Use a metavar for -L in the --help output

Stefan Raspl (3):
tools/kvm_stat: add command line switch '-z' to skip zero records tools/kvm_stat: Add command line switch '-L' to log to file tools/kvm_stat: add sample systemd unit file

 tools/kvm/kvm_stat/kvm_stat         | 84 ++++++++++++++++++++++++-----
 tools/kvm/kvm_stat/kvm_stat.service | 16 ++++++
 tools/kvm/kvm_stat/kvm_stat.txt     | 15 +++++-
 3 files changed, 101 insertions(+), 14 deletions(-)
 create mode 100644 tools/kvm/kvm_stat/kvm_stat.service
Quoted 3 lines
Quoted 1 line

*ping*

So...any consideration?

Queued, thanks. (Patches sent during the merge window are delayed and this tends to result in LIFO order...)

Paolo