Add 'vardir' disk utilization collecting

Added for 'vardir' path disk disk utilization collecting routine which
parses file:

  /proc/diskstats

for the value milliseconds spent doing I/Os from the given device
and counts 'busy' value in percents, like iostat tool does for its
'%util' field. Check for more information linux kernel documentation
[1]. We use from the 'diskstats' file Field 10 which is in real at
the 12th position:

  Field  9 -- # of I/Os currently in progress
    The only field that should go to zero. Incremented as requests are
    given to appropriate struct request_queue and decremented as they
    finish.

  Field 10 -- # of milliseconds spent doing I/Os
    This field increases so long as field 9 is nonzero.

Decided to collect 'vardir' disk utilization per each run test in
standalone file and print to stdout after testing completed, up to
10 most biggest of it.

To count 'vardir' disk utilization for each test we need to know what
was the value of the disk bound on the test start and time when test
started to count later the utilization. On test finish we check the
test finish time and current disk bound and count disk utilization.
All of these checks and counts implemented as the new routine
'get_disk_bound_stat_busy()' in 'lib/utils.py' file.

To collect disk bounds and durations on test start/finish events used
'StatisticsWatcher' listener which has the following usable routines
for it:

  process_result()
    Using 'WorkerCurrentTask' queue message receive event to save the
    disk bounds values at the start of the tests.

    Using 'WorkerTaskResult' queue message receive event to save final
    disk bounds values for finished tests.

  print_statistics() - statistics printing to stdout after testing.
    Prints disk bounds for failed tests and up to 10 most used it tests.
    We use standalone 'statistics' directory in 'vardir' path to save
    'durations.log' file in it with disk bounds for each tested task
    in format:

      <test task name> <disk bound>

Needed for tarantool/tarantool-qa#97

[1]: https://www.kernel.org/doc/Documentation/iostats.txt

Author: avtikhon

lib/utils.py

@@ -248,6 +248,55 @@ def get_proc_stat_rss(pid):
     return rss
 
 
+def get_vardir_device(vardir):
+    dev = 'unknown'
+    path = os.path.abspath(vardir)
+    while not os.path.ismount(path):
+        path = os.path.dirname(path)
+    try:
+        with open('/proc/mounts', 'r') as f:
+            for line in f:
+                if line.split()[1] == path:
+                    mount = line.split()[0]
+                    dev = mount.split('/')[2]
+    except (OSError, IOError):
+        pass
+    return dev
+
+
+# This routine gets the value milliseconds spent doing I/Os
+# from the given 'vardir' device found at '/proc/diskstats'
+# and counts 'busy' value in percents like iostat tool does
+# for its '%util' field.
+#
+# Check for more information linux kernel documentation:
+#   https://www.kernel.org/doc/Documentation/iostats.txt
+#
+# We use Field 10 which has the 12th position in the file:
+#
+#   Field  9 -- # of I/Os currently in progress
+#     The only field that should go to zero. Incremented as requests are
+#     given to appropriate struct request_queue and decremented as they finish.
+#
+#   Field 10 -- # of milliseconds spent doing I/Os
+#     This field increases so long as field 9 is nonzero.
+def get_disk_bound_stat_busy(devname, previous):
+    busy = 'unknown'
+    times = time.time()
+    try:
+        with open('/proc/diskstats', 'r') as f:
+            for line in f:
+                if line.split()[2] == devname:
+                    value = line.split()[12]
+                    if previous[1] == 'unknown':
+                        previous[1] = value
+                    busy = 100 * (int(value) - int(previous[1])) / \
+                        (1024 * (times - previous[0]))
+    except (OSError, IOError):
+        pass
+    return busy, [times, value]
+
+
 def set_fd_cloexec(socket):
     flags = fcntl.fcntl(socket, fcntl.F_GETFD)
     fcntl.fcntl(socket, fcntl.F_SETFD, flags | fcntl.FD_CLOEXEC)

listeners.py

@@ -2,6 +2,7 @@
 import sys
 import yaml
 import shutil
+import time
 
 from lib import Options
 from lib.colorer import color_stdout
@@ -16,6 +17,8 @@
 from lib.utils import safe_makedirs
 from lib.utils import print_tail_n
 from lib.utils import print_unidiff
+from lib.utils import get_vardir_device
+from lib.utils import get_disk_bound_stat_busy
 
 
 class BaseWatcher(object):
@@ -36,11 +39,20 @@ def __init__(self, get_logfile):
         self.stats = dict()
         self.rss_summary = sampler.rss_summary()
         self.tasks_durations = dict()
+        self.vardir_devname = get_vardir_device(Options().args.vardir)
+        self.vardir_bounds = dict()
+        self.vardir_data = dict()
         self.failed_tasks = []
         self.get_logfile = get_logfile
         self.long_tasks = []
 
     def process_result(self, obj):
+        # Called only once on task run initiated.
+        if isinstance(obj, WorkerCurrentTask):
+            task_name = obj.task_name + ((':' + obj.task_param) if obj.task_param else '')
+            self.vardir_bounds[task_name], self.vardir_data[task_name] = get_disk_bound_stat_busy(
+                    self.vardir_devname, [time.time(), 'unknown'])
+
         if not isinstance(obj, WorkerTaskResult):
             return
 
@@ -59,6 +71,8 @@ def process_result(self, obj):
                                       obj.show_reproduce_content))
 
         self.tasks_durations[task_name] = obj.duration
+        self.vardir_bounds[task_name], self.vardir_data[task_name] = get_disk_bound_stat_busy(
+                self.vardir_devname, self.vardir_data[task_name])
 
     def get_failed_task_name(self, task):
         return task[0][0] + ((':' + task[0][1]) if task[0][1] else '')
@@ -70,6 +84,7 @@ def print_statistics(self):
         field_size = 60
         top_rss = 10
         top_durations = 10
+        top_bounds = 10
 
         # Prepare standalone subpath '<vardir>/statistics' for statistics files.
         stats_dir = os.path.join(Options().args.vardir, 'statistics')
@@ -130,6 +145,34 @@ def print_statistics(self):
             fd.write("{} {}\n".format(task_name, self.tasks_durations[task_name]))
         fd.close()
 
+        # Disk usage.
+
+        # Print to stdout disk usage statistics for all failed tasks.
+        if self.failed_tasks:
+            color_stdout('Disk bounds of the failed tasks:\n', schema='test_var')
+            for task in self.failed_tasks:
+                task_name = self.get_failed_task_name(task)
+                if task_name in self.vardir_bounds:
+                    color_stdout('* %3d %s %s\n' % (self.vardir_bounds[task_name],
+                                 task_name.ljust(field_size), self.get_long_mark(task_name)),
+                                 schema='test_var')
+
+        # Print to stdout disk bounds statistics for some number of most it used tasks.
+        color_stdout('Up to {} most disk bounds used by tasks:\n'.format(top_bounds),
+                     schema='test_var')
+        results_sorted = sorted(self.vardir_bounds.items(), key=lambda x: x[1], reverse=True)
+        for task_name, bounds in results_sorted[:top_bounds]:
+            color_stdout('* %3d %s %s\n' % (bounds, task_name.ljust(field_size),
+                         self.get_long_mark(task_name)), schema='test_var')
+        color_stdout('-' * 41, "\n", schema='separator')
+
+        # Print disk bounds statistics to '<vardir>/statistics/diskbounds.log' file.
+        filepath = os.path.join(stats_dir, 'diskbounds.log')
+        fd = open(filepath, 'w')
+        for task_name in self.vardir_bounds:
+            fd.write("{} {}\n".format(task_name, self.vardir_bounds[task_name]))
+        fd.close()
+
         """Returns are there failed tasks."""
         if self.stats:
             color_stdout('Statistics:\n', schema='test_var')