adding kv_engine profiling using linux perf profiling

Change-Id: I582bf31264a542dd87137659aec1fe448205c831
Reviewed-on: http://review.couchbase.org/c/perfrunner/+/145759
Reviewed-by: Bo-Chun Wang <[email protected]>
Reviewed-by: <[email protected]>
Tested-by: <[email protected]>

Author: sharujayaram

perfrunner/helpers/cluster.py

@@ -519,3 +519,23 @@ def set_min_tls_version(self):
             )
             check_tls_version = self.rest.get_minimum_tls_version(self.master_node)
             logger.info('new tls version: {}'.format(check_tls_version))
+
+    def get_debug_rpm_url(self):
+        release, build_number = self.build.split('-')
+        build = tuple(map(int, release.split('.'))) + (int(build_number),)
+        if build > (7, 0, 0, 0):
+            release = 'cheshire-cat'
+        elif build > (6, 5, 0, 0) and build < (7, 0, 0, 0):
+            release = 'mad-hatter'
+        elif build < (6, 5, 0, 0):
+            release = 'alice'
+        centos_version = self.remote.detect_centos_release()
+
+        rpm_url = 'http://latestbuilds.service.couchbase.com/builds/' \
+                  'latestbuilds/couchbase-server/{}/{}/' \
+                  'couchbase-server-enterprise-debuginfo-{}-centos{}.x86_64.rpm' \
+                  ''.format(release, build_number, self.build, centos_version)
+        return rpm_url
+
+    def install_cb_debug_rpm(self):
+        self.remote.install_cb_debug_rpm(url=self.get_debug_rpm_url())

perfrunner/helpers/profiler.py

@@ -1,6 +1,7 @@
 import threading
 from typing import Callable
 
+import paramiko
 import requests
 from decorator import decorator
 from sshtunnel import SSHTunnelForwarder
@@ -41,7 +42,8 @@ class Profiler:
     DEBUG_PORTS = {
         'fts':   8094,
         'index': 9102,
-        'kv':    9998,  # goxdcr
+        'goxdcr':    9998,
+        'kv': 9998,           # will be deprecated in future
         'n1ql':  8093,
     }
 
@@ -60,6 +62,12 @@ def __init__(self, cluster_spec: ClusterSpec, test_config: TestConfig):
 
         self.ssh_username, self.ssh_password = cluster_spec.ssh_credentials
 
+        self.cluster_spec = cluster_spec
+
+        self.profiling_settings = test_config.profiling_settings
+
+        self.linux_perf_path = '/opt/couchbase/var/lib/couchbase/logs/'
+
     def new_tunnel(self, host: str, port: int) -> SSHTunnelForwarder:
         return SSHTunnelForwarder(
             ssh_address_or_host=host,
@@ -74,12 +82,59 @@ def save(self, host: str, service: str, profile: str, content: bytes):
         with open(fname, 'wb') as fh:
             fh.write(content)
 
+    def linux_perf_profile(self, host: str, fname: str, path: str):
+
+        client = paramiko.SSHClient()
+        client.set_missing_host_key_policy(paramiko.AutoAddPolicy())
+
+        try:
+            client.connect(hostname=host, username=self.ssh_username,
+                           password=self.ssh_password)
+
+        except Exception:
+            logger.info('Cannot connect to the "{}" via SSH Server'.format(host))
+            exit()
+
+        logger.info('Capturing linux profile using linux perf record ')
+
+        cmd = 'perf record -a -F {} -g --call-graph {} ' \
+              '-p $(pgrep memcached) -o {}{} ' \
+              '-- sleep {}'.format(self.profiling_settings.linux_perf_frequency,
+                                   self.profiling_settings.linux_perf_callgraph,
+                                   path,
+                                   fname,
+                                   self.profiling_settings.linux_perf_profile_duration)
+        stdin, stdout, stderr = client.exec_command(cmd)
+        exit_status = stdout.channel.recv_exit_status()
+
+        if exit_status == 0:
+            logger.info("linux perf record: linux perf profile capture completed")
+        else:
+            logger.info("perf record failed , exit_status :  ", exit_status)
+
+        client.close()
+
     def profile(self, host: str, service: str, profile: str):
         logger.info('Collecting {} profile on {}'.format(profile, host))
 
         endpoint = self.ENDPOINTS[profile]
         port = self.DEBUG_PORTS[service]
 
+        if self.profiling_settings.linux_perf_profile_flag:
+            logger.info('Collecting {} profile on {} using linux perf '
+                        'reccord'.format(profile, host))
+
+            fname = 'linux_{}_{}_{}_perf.data'.format(host, profile, uhex()[:4])
+            self.linux_perf_profile(host=host, fname=fname, path=self.linux_perf_path)
+
+        else:
+            logger.info('Collecting {} profile on {}'.format(profile, host))
+
+            with self.new_tunnel(host, port) as tunnel:
+                url = endpoint.format(tunnel.local_bind_port)
+                response = requests.get(url=url, auth=self.rest.auth)
+                self.save(host, service, profile, response.content)
+
         with self.new_tunnel(host, port) as tunnel:
             url = endpoint.format(tunnel.local_bind_port)
             response = requests.get(url=url, auth=self.rest.auth)

perfrunner/remote/linux.py

@@ -1,11 +1,11 @@
 import os
+import time
 from collections import defaultdict
 from typing import Dict, List
 from urllib.parse import urlparse
 
 from fabric.api import cd, get, put, quiet, run, settings
 from fabric.exceptions import CommandTimeout, NetworkError
-
 from logger import logger
 from perfrunner.helpers.misc import uhex
 from perfrunner.remote import Remote
@@ -29,6 +29,10 @@ class RemoteLinux(Remote):
 
     PROCESS_PATTERNS = ('cbas', )
 
+    LINUX_PERF_PROFILES_PATH = '/opt/couchbase/var/lib/couchbase/logs/'
+
+    LINUX_PERF_DELAY = 30
+
     @property
     def package(self):
         if self.os.upper() in ('UBUNTU', 'DEBIAN'):
@@ -812,3 +816,47 @@ def cbbackupmgr_restore(self, master_node: str, cluster_spec: ClusterSpec,
 
             logger.info('Running: {}'.format(cmd))
             run(cmd)
+
+    @all_servers
+    def install_cb_debug_rpm(self, url):
+        logger.info('Installing Couchbase Debug rpm on all servers')
+        run('rpm -iv {}'.format(url), quiet=True)
+
+    @all_servers
+    def generate_linux_perf_script(self):
+
+        files_list = 'for i in {}*_perf.data; do echo $i; ' \
+                     'done'.format(self.LINUX_PERF_PROFILES_PATH)
+        files = run(files_list).replace("\r", "").split("\n")
+
+        for filename in files:
+            fname = filename.split('/')[-1]
+            if fname != '*_perf.data':
+                cmd_perf_script = 'perf script -i {}' \
+                                ' --no-inline > {}.txt'.format(filename, filename)
+
+                logger.info('Generating linux script data : {}'.format(cmd_perf_script))
+                try:
+
+                    with settings(warn_only=True):
+                        run(cmd_perf_script, timeout=600, pty=False)
+                        time.sleep(self.LINUX_PERF_DELAY)
+
+                except CommandTimeout:
+                    logger.error('linux perf script timed out')
+
+                cmd_zip = 'cd {}; zip -q {}.zip {}.txt'.format(self.LINUX_PERF_PROFILES_PATH,
+                                                               fname,
+                                                               fname)
+
+                with settings(warn_only=True):
+                    run(cmd_zip, pty=False)
+
+    @all_servers
+    def get_linuxperf_files(self):
+
+        logger.info('Collecting linux perf files from kv nodes')
+        with cd(self.LINUX_PERF_PROFILES_PATH):
+            r = run('stat *.zip', quiet=True, warn_only=True)
+            if not r.return_code:
+                get('*.zip', local_path='.')

perfrunner/settings.py

@@ -290,6 +290,14 @@ class ProfilingSettings:
 
     SERVICES = ''
 
+    LINUX_PERF_PROFILE_DURATION = 10  # seconds
+
+    LINUX_PERF_FREQUENCY = 99
+
+    LINUX_PERF_CALLGRAPH = 'lbr'     # optional lbr, dwarf
+
+    LINUX_PERF_DELAY_MULTIPLIER = 2
+
     def __init__(self, options: dict):
         self.services = options.get('services',
                                     self.SERVICES).split()
@@ -299,6 +307,19 @@ def __init__(self, options: dict):
                                             self.NUM_PROFILES))
         self.profiles = options.get('profiles',
                                     self.PROFILES).split(',')
+        self.linux_perf_profile_duration = int(options.get('linux_perf_profile_duration',
+                                                           self.LINUX_PERF_PROFILE_DURATION))
+
+        self.linux_perf_profile_flag = bool(options.get('linux_perf_profile_flag'))
+
+        self.linux_perf_frequency = int(options.get('linux_perf_frequency',
+                                                    self.LINUX_PERF_FREQUENCY))
+
+        self.linux_perf_callgraph = options.get('linux_perf_callgraph',
+                                                self.LINUX_PERF_CALLGRAPH)
+
+        self.linux_perf_delay_multiplier = int(options.get('linux_perf_delay_multiplier',
+                                                           self.LINUX_PERF_DELAY_MULTIPLIER))
 
 
 class BucketSettings:

perfrunner/tests/__init__.py

@@ -95,6 +95,9 @@ def eventing_nodes(self) -> List[str]:
         return self.rest.get_active_nodes_by_role(self.master_node, 'eventing')
 
     def tear_down(self):
+        if self.test_config.profiling_settings.linux_perf_profile_flag:
+            self.collect_linux_perf_profiles()
+
         if self.test_config.test_case.use_workers:
             self.worker_manager.download_celery_logs()
             self.worker_manager.terminate()
@@ -107,6 +110,10 @@ def tear_down(self):
 
             self.cluster.reset_memory_settings()
 
+    def collect_linux_perf_profiles(self):
+        self.remote.generate_linux_perf_script()
+        self.remote.get_linuxperf_files()
+
     def collect_logs(self):
         self.remote.collect_info()
 

perfrunner/tests/dcp.py

@@ -14,6 +14,7 @@ def _report_kpi(self, time_elapsed: float, clients: int, stream: str):
 
     @with_stats
     @timeit
+    @with_profiles
     def access(self, *args):
         username, password = self.cluster_spec.rest_credentials
 
@@ -64,6 +65,7 @@ def init_java_dcp_client(self):
 
     @with_stats
     @timeit
+    @with_profiles
     def access(self, *args):
         for target in self.target_iterator:
             local.run_java_dcp_client(

perfrunner/tests/kv.py

@@ -2,6 +2,7 @@
 
 from logger import logger
 from perfrunner.helpers.cbmonitor import timeit, with_stats
+from perfrunner.helpers.profiler import with_profiles
 from perfrunner.helpers.worker import (
     pillowfight_data_load_task,
     pillowfight_task,
@@ -552,6 +553,7 @@ class CompressionTest(PillowFightTest):
 
     @with_stats
     @timeit
+    @with_profiles
     def wait_for_compression(self):
         for master in self.cluster_spec.masters:
             for bucket in self.test_config.buckets:
@@ -578,6 +580,7 @@ class CompactionTest(KVTest):
 
     @with_stats
     @timeit
+    @with_profiles
     def compact(self):
         self.compact_bucket()
 

perfrunner/tests/rebalance.py

@@ -99,6 +99,7 @@ def post_rebalance(self):
         time.sleep(self.rebalance_settings.stop_after)
 
     @with_stats
+    @with_profiles
     def rebalance(self, services=None):
         self.pre_rebalance()
         self.rebalance_time = self._rebalance(services)
@@ -137,6 +138,7 @@ class RebalanceDurabilityTest(RebalanceTest):
     COLLECTORS = {'latency': True}
 
     @with_stats
+    @with_profiles
     def rebalance(self, services=None):
         self.access_bg()
         self.rebalance_time = self._rebalance(services)
@@ -177,6 +179,7 @@ def rebalance(self, services=None):
         self.post_rebalance()
 
     @with_stats
+    @with_profiles
     def create_fts_index(self):
         st = time.time()
         self.create_index()

perfrunner/utils/cluster.py

@@ -81,6 +81,9 @@ def main():
     cm.tweak_memory()
     cm.enable_n2n_encryption()
 
+    if cm.test_config.profiling_settings.linux_perf_profile_flag:
+        cm.install_cb_debug_rpm()
+
 
 if __name__ == '__main__':
     main()