Add ability to collect direct reclaim latency trace with ftrace (#15)

* Add ability to collect direct reclaim latency trace with ftrace
* Fix various issues in utility functions

Author: ethercflow

insight.py

@@ -31,9 +31,11 @@
 from measurement.files import logfiles
 from measurement.process import meta as proc_meta
 from measurement.tidb import pdctl
+from measurement.ftrace import ftrace
 
 
 class Insight():
+    cwd = util.cwd()
     # data output dir
     outdir = "data"
     full_outdir = ""
@@ -43,14 +45,18 @@ class Insight():
     insight_logfiles = None
     insight_configfiles = None
     insight_pdctl = None
+    insight_trace = None
 
     def __init__(self, args):
-        if args.output:
-            self.outdir = args.output
         if not args.alias:
             self.alias = util.get_hostname()
-        self.full_outdir = fileutils.create_dir(
-            os.path.join(self.outdir, self.alias))
+        if args.output and util.is_abs_path(args.output):
+            self.outdir = args.output
+            self.full_outdir = fileutils.create_dir(
+                os.path.join(self.outdir, self.alias))
+        else:
+            self.full_outdir = fileutils.create_dir(
+                os.path.join(self.cwd, self.outdir, self.alias))
         logging.debug("Output directory is: %s" % self.full_outdir)
 
     # data collected by `collector`
@@ -126,6 +132,22 @@ def run_perf(self, args):
             self.insight_perf = perf.InsightPerf(options=args)
         self.insight_perf.run(self.full_outdir)
 
+    def run_ftrace(self, args):
+        if not args.ftrace:
+            logging.debug("Ignoring collecting of ftrace data.")
+            return
+        # perf requires root priviledge
+        if not util.is_root_privilege():
+            logging.fatal("It's required to run ftrace with root priviledge.")
+            return
+
+        if args.ftracepoint:
+            self.insight_ftrace = ftrace.InsightFtrace(self.cwd, args)
+            self.insight_ftrace.run(self.full_outdir)
+        else:
+            logging.debug("Ignoring collecting of ftrace data, no tracepoint is chose.")
+
+
     def get_datadir_size(self):
         # du requires root priviledge to check data-dir
         if not util.is_root_privilege():
@@ -242,6 +264,9 @@ def read_pdctl(self, args):
         # read and save `pd-ctl` info
         insight.read_pdctl(args)
 
+    # save ftrace data
+    insight.run_ftrace(args)
+
     # compress all output to tarball
     if args.compress:
         fileutils.compress_tarball(insight.full_outdir, insight.alias)

measurement/files/fileutils.py

@@ -3,14 +3,9 @@
 
 import logging
 import os
-import sys
 
 from measurement import util
 
-# get a numeric Python version
-python_version = sys.version_info[0] + sys.version_info[1] / 10
-
-
 # read data from file
 def read_file(filename):
     data = None
@@ -54,7 +49,7 @@ def create_dir(path):
 def list_dir(path):
     file_list = []
     try:
-        if python_version >= 3.5:
+        if util.python_version() >= 3.5:
             for entry in os.scandir(path):
                 file_list.append("%s/%s" % (path, entry.name))
         else:

measurement/ftrace/__init__.py

@@ -0,0 +1 @@
+# -*- coding: utf-8 -*-

measurement/ftrace/ftrace.py

@@ -0,0 +1,32 @@
+# -*- coding: utf-8 -*-
+# Collect stack trace with `ftrace`
+
+from measurement.ftrace.mem import drtracer
+from measurement.files import fileutils
+
+
+class InsightFtrace():
+    # options about tracer
+    ftrace_options = {}
+    cwd = ""
+
+    # output dir
+    data_dir = "ftracedata"
+
+    def __init__(self, cwd, options):
+        self.cwd = cwd
+        self.ftrace_options = vars(options)
+
+    def run(self, outputdir=None):
+        ftrace_outputdir = fileutils.build_full_output_dir(
+            basedir=outputdir, subdir=self.data_dir)
+
+        if not ftrace_outputdir:
+            return
+
+        tracepoint = self.ftrace_options["ftracepoint"]
+        if tracepoint == "dr":
+            tracer = drtracer.DirectReclaimTracer(self.ftrace_options)
+            tracer.save_trace(self.cwd, ftrace_outputdir)
+        else:
+            logging.debug("Tracepiont %s is not supported." % tracepoint)

measurement/ftrace/mem/__init__.py

@@ -0,0 +1 @@
+# -*- coding: utf-8 -*-

measurement/ftrace/mem/drtracer.py

@@ -0,0 +1,75 @@
+# -*- coding: utf-8 -*-
+# Trace direct reclaim latency.
+
+import os
+import logging
+
+from measurement import util
+from measurement.files import fileutils
+
+
+class DirectReclaimTracer():
+    # options about tracer
+    ftrace_options = {}
+
+    # output dir
+    data_file = "mem/drtrace"
+
+    # tracefs mount point
+    tracefs = "/sys/kernel/debug/tracing"
+    direct_reclaim_begin = "events/vmscan/mm_vmscan_direct_reclaim_begin/enable"
+    direct_reclaim_end = "events/vmscan/mm_vmscan_direct_reclaim_end/enable"
+
+    def __init__(self, options={}):
+        self.ftrace_options = options
+
+    def save_trace(self, cwd, outputdir=None):
+        _, stderr = util.run_cmd(["cd", self.tracefs])
+        if stderr:
+            logging.fatal("""ERROR: accessing tracing. Root user? Kernel has FTRACE?
+            debugfs mounted? (mount -t debugfs debugfs /sys/kernel/debug)""")
+            return
+
+        if not outputdir:
+            logging.fatal("ERROR: please give a dir to save trace data")
+            return
+
+        util.chdir(self.tracefs)
+
+        # setup trace, set opt
+        _, stderr = util.run_cmd(["echo nop > current_tracer"], shell=True)
+        if stderr:
+            logging.fatal("ERROR: reset current_tracer failed")
+            os.chdir(cwd)
+            return
+
+        bufsize_kb = self.ftrace_options["ftrace_bufsize"] if "ftrace_bufsize" in \
+            self.ftrace_options and self.ftrace_options["ftrace_bufsize"] else "4096"
+        _, stderr = util.run_cmd(["echo %s > buffer_size_kb" % bufsize_kb], shell=True)
+        if stderr:
+            logging.fatal("ERROR: set bufsize_kb failed")
+            os.chdir(cwd)
+            return
+
+        # begin tracing
+        for event in [self.direct_reclaim_begin, self.direct_reclaim_end]:
+            _, stderr = util.run_cmd(["echo 1 > %s" % event], shell=True)
+            if stderr:
+                logging.fatal("ERROR: enable %s tracepoint failed" % event)
+                os.chdir(cwd)
+                return
+
+        # collect trace
+        time = self.ftrace_options["ftrace_time"] if "ftrace_time" in \
+            self.ftrace_options and self.ftrace_options["ftrace_time"] else 60
+        util.run_cmd_for_a_while(["cat trace_pipe > %s/%s" %(outputdir, self.data_file)], time, shell=True)
+
+        # End tracing
+        for event in [self.direct_reclaim_begin, self.direct_reclaim_end]:
+            _, stderr = util.run_cmd(["echo 0 > %s" % event], shell=True)
+            if stderr:
+                logging.fatal("ERROR: disable %s tracepoint failed" % event)
+                os.chdir(cwd)
+                return
+
+        os.chdir(cwd)

measurement/util.py

@@ -4,6 +4,8 @@
 import argparse
 import logging
 import os
+import sys
+import time
 
 from subprocess import Popen, PIPE
 try:
@@ -30,11 +32,24 @@ def cwd():
     return os.getcwd()
 
 
-def run_cmd(cmd):
-    p = Popen(cmd, stdout=PIPE, stderr=PIPE)
+def chdir(nwd):
+    return os.chdir(nwd)
+
+
+def is_abs_path(path):
+    return os.path.isabs(path)
+
+def run_cmd(cmd, shell=False):
+    p = Popen(cmd, shell=shell, stdout=PIPE, stderr=PIPE)
     return p.communicate()
 
 
+def run_cmd_for_a_while(cmd, duration, shell=False):
+    p = Popen(cmd, shell=shell)
+    time.sleep(duration)
+    p.kill()
+
+
 def parse_cmdline(cmdline):
     result = {}
     try:
@@ -114,6 +129,15 @@ def parse_insight_opts():
     parser.add_argument("-v", "--verbose", action="store_true", default=False,
                         help="Print verbose output.")
 
+    parser.add_argument("-f", "--ftrace", action="store_true", default=False,
+                        help="Collect trace info using ftrace. Disabled by default.")
+    parser.add_argument("--ftracepoint",  action="store", default=None,
+                        help="Tracepoint to be traced (only support to trace direct reclaim latency).")
+    parser.add_argument("--ftrace-time", type=int, action="store", default=None,
+                        help="Time period of ftrace recording, in seconds (default 60s).")
+    parser.add_argument("--ftrace-bufsize", action="store", default=None,
+                        help="Ftrace ring buffer size in kb (default 4096 kb).")
+
     return parser.parse_args()
 
 
@@ -146,3 +170,7 @@ def get_hostname():
     # This function is merely used, so only import socket package when necessary
     import socket
     return socket.gethostname()
+
+def python_version():
+    # get a numeric Python version
+    return sys.version_info[0] + sys.version_info[1] * 0.1