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

Commit Message

Stefan Raspl March 31, 2020, 8 p.m. UTC

From: Stefan Raspl <[e-mail]>

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 restart 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 the standard
format, where we append to an existing file by starting out with a
header.

Signed-off-by: Stefan Raspl <[e-mail]>
---
 tools/kvm/kvm_stat/kvm_stat     | 75 +++++++++++++++++++++++++++++----
 tools/kvm/kvm_stat/kvm_stat.txt |  5 +++
 2 files changed, 71 insertions(+), 9 deletions(-)

Comments

Paolo Bonzini March 31, 2020, 9:02 p.m. UTC | #1

On 31/03/20 22:00, Stefan Raspl wrote:
> From: Stefan Raspl <[e-mail]>
> 
> 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 restart kvm_stat.service

Does reload work too?

Regarding the code, I only have a few nits.


> +            f.write(frmt.get_banner())
> +            f.write('\n')
> +        else:
> +            print(frmt.get_banner())

What about

      print(frmt.get_banner(), file=f or sys.stdout)

> +
> +    def do_statline(opts):
> +        statline = frmt.get_statline(keys, stats.get())
> +        if len(statline) == 0:
> +            return False
> +        statline = datetime.now().strftime("%Y-%m-%d %H:%M:%S") + statline
> +        if opts.log_to_file:
> +            f.write(statline)
> +            f.write('\n')
> +        else:
> +            print(statline)

... and likewise here?  (

>  
> +        return True
> +
> +    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
> -            statline = frmt.get_statline(keys, stats.get())
> -            if len(statline) == 0:
> +            if not do_statline(opts):
>                  continue
> -            print(datetime.now().strftime("%Y-%m-%d %H:%M:%S") + statline)
>              line += 1
>              banner_printed = False
>          except KeyboardInterrupt:
>              break
>  
> +    if opts.log_to_file:
> +        f.close()

"if f:"?

> +
> +
> +def handle_signal(sig, frame):
> +    global signal_received
> +
> +    signal_received = True
> +
> +    return
> +
>  
>  def is_delay_valid(delay):
>      """Verify delay is in valid value range."""
> @@ -1652,6 +1703,10 @@ 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,
> +                           help="like '--log', but logging to a file"
> +                           )
>      argparser.add_argument('-p', '--pid',
>                             type=int,
>                             default=0,
> @@ -1675,9 +1730,9 @@ 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')

"requires -l/-L"?

> -    if options.skip_zero_records and not options.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/--log')

Likewise.

>      try:
>          # verify that we were passed a valid regex up front
> @@ -1758,7 +1813,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, options.skip_zero_records)
> diff --git a/tools/kvm/kvm_stat/kvm_stat.txt b/tools/kvm/kvm_stat/kvm_stat.txt
> index 24296dccc00a..de7c4a2497f9 100644
> --- a/tools/kvm/kvm_stat/kvm_stat.txt
> +++ b/tools/kvm/kvm_stat/kvm_stat.txt
> @@ -92,6 +92,11 @@ OPTIONS
>  --log::
>          run in logging mode (like vmstat)
>  
> +
> +-L::
> +--log-to-file::
> +        like '--log', but logging to a file

-L<file>:: / --log-to-file=<file>

> +
>  -p<pid>::
>  --pid=<pid>::
>  	limit statistics to one virtual machine (pid)
>

Stefan Raspl April 1, 2020, 12:59 p.m. UTC | #2

On 2020-03-31 23:02, Paolo Bonzini wrote:
> On 31/03/20 22:00, Stefan Raspl wrote:
>> From: Stefan Raspl <[e-mail]>
>>
>> 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 restart kvm_stat.service
> 
> Does reload work too?

Reload and restart work fine - any specific concerns or areas to look for?


> Regarding the code, I only have a few nits.
> 
> 
>> +            f.write(frmt.get_banner())
>> +            f.write('\n')
>> +        else:
>> +            print(frmt.get_banner())
> 
> What about
> 
>       print(frmt.get_banner(), file=f or sys.stdout)

Yup, thx!


>> +
>> +    def do_statline(opts):
>> +        statline = frmt.get_statline(keys, stats.get())
>> +        if len(statline) == 0:
>> +            return False
>> +        statline = datetime.now().strftime("%Y-%m-%d %H:%M:%S") + statline
>> +        if opts.log_to_file:
>> +            f.write(statline)
>> +            f.write('\n')
>> +        else:
>> +            print(statline)
> 
> ... and likewise here?  (

Sure


>>  
>> +        return True
>> +
>> +    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
>> -            statline = frmt.get_statline(keys, stats.get())
>> -            if len(statline) == 0:
>> +            if not do_statline(opts):
>>                  continue
>> -            print(datetime.now().strftime("%Y-%m-%d %H:%M:%S") + statline)
>>              line += 1
>>              banner_printed = False
>>          except KeyboardInterrupt:
>>              break
>>  
>> +    if opts.log_to_file:
>> +        f.close()
> 
> "if f:"?

I'd argue the former is a lot more telling/easier to read - one of the downsides
of using extremely short variable names like 'f'.


>> +
>> +
>> +def handle_signal(sig, frame):
>> +    global signal_received
>> +
>> +    signal_received = True
>> +
>> +    return
>> +
>>  
>>  def is_delay_valid(delay):
>>      """Verify delay is in valid value range."""
>> @@ -1652,6 +1703,10 @@ 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,
>> +                           help="like '--log', but logging to a file"
>> +                           )
>>      argparser.add_argument('-p', '--pid',
>>                             type=int,
>>                             default=0,
>> @@ -1675,9 +1730,9 @@ 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')
> 
> "requires -l/-L"?

Yes!


>> -    if options.skip_zero_records and not options.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/--log')
> 
> Likewise.

Of course.


>>      try:
>>          # verify that we were passed a valid regex up front
>> @@ -1758,7 +1813,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, options.skip_zero_records)
>> diff --git a/tools/kvm/kvm_stat/kvm_stat.txt b/tools/kvm/kvm_stat/kvm_stat.txt
>> index 24296dccc00a..de7c4a2497f9 100644
>> --- a/tools/kvm/kvm_stat/kvm_stat.txt
>> +++ b/tools/kvm/kvm_stat/kvm_stat.txt
>> @@ -92,6 +92,11 @@ OPTIONS
>>  --log::
>>          run in logging mode (like vmstat)
>>  
>> +
>> +-L::
>> +--log-to-file::
>> +        like '--log', but logging to a file
> 
> -L<file>:: / --log-to-file=<file>

Argh...

Ciao,
Stefan

Paolo Bonzini April 1, 2020, 1:24 p.m. UTC | #3

On 01/04/20 14:59, Stefan Raspl wrote:
> On 2020-03-31 23:02, Paolo Bonzini wrote:
>> On 31/03/20 22:00, Stefan Raspl wrote:
>>> From: Stefan Raspl <[e-mail]>
>>>
>>> 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 restart kvm_stat.service
>>
>> Does reload work too?
> 
> Reload and restart work fine - any specific concerns or areas to look for?

No, I would just put reload in the postrotate script.
>>> +    if opts.log_to_file:
>>> +        f.close()
>>
>> "if f:"?
> 
> I'd argue the former is a lot more telling/easier to read - one of the downsides
> of using extremely short variable names like 'f'.

Fair enough.

Paolo

Patch

diff --git a/tools/kvm/kvm_stat/kvm_stat b/tools/kvm/kvm_stat/kvm_stat
index 54000ac508f9..e4f67f0629ee 100755
--- a/tools/kvm/kvm_stat/kvm_stat
+++ b/tools/kvm/kvm_stat/kvm_stat
@@ -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'^[^\(]*$')
 
@@ -1533,25 +1536,73 @@  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
+            f.write(frmt.get_banner())
+            f.write('\n')
+        else:
+            print(frmt.get_banner())
+
+    def do_statline(opts):
+        statline = frmt.get_statline(keys, stats.get())
+        if len(statline) == 0:
+            return False
+        statline = datetime.now().strftime("%Y-%m-%d %H:%M:%S") + statline
+        if opts.log_to_file:
+            f.write(statline)
+            f.write('\n')
+        else:
+            print(statline)
 
+        return True
+
+    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
-            statline = frmt.get_statline(keys, stats.get())
-            if len(statline) == 0:
+            if not do_statline(opts):
                 continue
-            print(datetime.now().strftime("%Y-%m-%d %H:%M:%S") + statline)
             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."""
@@ -1652,6 +1703,10 @@  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,
+                           help="like '--log', but logging to a file"
+                           )
     argparser.add_argument('-p', '--pid',
                            type=int,
                            default=0,
@@ -1675,9 +1730,9 @@  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:
+    if options.skip_zero_records and not (options.log or options.log_to_file):
         sys.exit('Error: Option -z/--skip-zero-records requires -l/--log')
     try:
         # verify that we were passed a valid regex up front
@@ -1758,7 +1813,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, options.skip_zero_records)
diff --git a/tools/kvm/kvm_stat/kvm_stat.txt b/tools/kvm/kvm_stat/kvm_stat.txt
index 24296dccc00a..de7c4a2497f9 100644
--- a/tools/kvm/kvm_stat/kvm_stat.txt
+++ b/tools/kvm/kvm_stat/kvm_stat.txt
@@ -92,6 +92,11 @@  OPTIONS
 --log::
         run in logging mode (like vmstat)
 
+
+-L::
+--log-to-file::
+        like '--log', but logging to a file
+
 -p<pid>::
 --pid=<pid>::
 	limit statistics to one virtual machine (pid)