Instrument GitLab Shell and log metrics data to a file62-instrument-gitlab-shell

5 files changed, 121 insertions, 34 deletions

diff --git a/lib/gitlab_config.rb b/lib/gitlab_config.rb
index 781c706..f8a10cf 100644
--- a/lib/gitlab_config.rb
+++ b/lib/gitlab_config.rb
@@ -54,4 +54,8 @@ class GitlabConfig
   def git_trace_log_file
     @config['git_trace_log_file']
   end
+
+  def metrics_log_file
+    @config['metrics_log_file'] ||= File.join(ROOT_PATH, 'gitlab-shell-metrics.log')
+  end
 end
diff --git a/lib/gitlab_keys.rb b/lib/gitlab_keys.rb
index 0eb04eb..7a93b09 100644
--- a/lib/gitlab_keys.rb
+++ b/lib/gitlab_keys.rb
@@ -2,6 +2,7 @@ require 'timeout'
 
 require_relative 'gitlab_config'
 require_relative 'gitlab_logger'
+require_relative 'gitlab_metrics'
 
 class GitlabKeys
   class KeyError < StandardError ; end
@@ -28,17 +29,25 @@ class GitlabKeys
   end
 
   def exec
-    case @command
-    when 'add-key'; add_key
-    when 'batch-add-keys'; batch_add_keys
-    when 'rm-key';  rm_key
-    when 'list-keys'; puts list_keys
-    when 'clear';  clear
-    when 'check-permissions'; check_permissions
-    else
-      $logger.warn "Attempt to execute invalid gitlab-keys command #{@command.inspect}."
-      puts 'not allowed'
-      false
+    GitlabMetrics.measure("command-#{@command.inspect}") do
+      case @command
+      when 'add-key';
+        add_key
+      when 'batch-add-keys';
+        batch_add_keys
+      when 'rm-key';
+        rm_key
+      when 'list-keys';
+        list_keys
+      when 'clear';
+        clear
+      when 'check-permissions';
+        check_permissions
+      else
+        $logger.warn "Attempt to execute invalid gitlab-keys command #{@command.inspect}."
+        puts 'not allowed'
+        false
+      end
     end
   end
 
diff --git a/lib/gitlab_metrics.rb b/lib/gitlab_metrics.rb
new file mode 100644
index 0000000..7bf07a5
--- /dev/null
+++ b/lib/gitlab_metrics.rb
@@ -0,0 +1,55 @@
+require 'logger'
+require_relative 'gitlab_config'
+
+module GitlabMetrics
+  module System
+    # THREAD_CPUTIME is not supported on OS X
+    if Process.const_defined?(:CLOCK_THREAD_CPUTIME_ID)
+      def self.cpu_time
+        Process.
+          clock_gettime(Process::CLOCK_THREAD_CPUTIME_ID, :millisecond)
+      end
+    else
+      def self.cpu_time
+        Process.
+          clock_gettime(Process::CLOCK_PROCESS_CPUTIME_ID, :millisecond)
+      end
+    end
+
+    # Returns the current monotonic clock time in a given precision.
+    #
+    # Returns the time as a Fixnum.
+    def self.monotonic_time
+      Process.clock_gettime(Process::CLOCK_MONOTONIC, :millisecond)
+    end
+  end
+
+  def self.logger
+    @logger ||= Logger.new(GitlabConfig.new.metrics_log_file)
+  end
+
+  # Measures the execution time of a block.
+  #
+  # Example:
+  #
+  #     GitlabMetrics.measure(:find_by_username_duration) do
+  #       User.find_by_username(some_username)
+  #     end
+  #
+  # name - The name of the field to store the execution time in.
+  #
+  # Returns the value yielded by the supplied block.
+  def self.measure(name)
+    start_real = System.monotonic_time
+    start_cpu = System.cpu_time
+
+    retval = yield
+
+    real_time = System.monotonic_time - start_real
+    cpu_time = System.cpu_time - start_cpu
+
+    logger.debug { "name=#{name.inspect} wall_time=#{real_time.inspect} cpu_time=#{cpu_time.inspect}" }
+
+    retval
+  end
+end
diff --git a/lib/gitlab_projects.rb b/lib/gitlab_projects.rb
index 58dea50..054feed 100644
--- a/lib/gitlab_projects.rb
+++ b/lib/gitlab_projects.rb
@@ -4,6 +4,7 @@ require 'open3'
 
 require_relative 'gitlab_config'
 require_relative 'gitlab_logger'
+require_relative 'gitlab_metrics'
 require_relative 'gitlab_reference_counter'
 
 class GitlabProjects
@@ -50,24 +51,39 @@ class GitlabProjects
   end
 
   def exec
-    case @command
-    when 'create-tag'; create_tag
-    when 'add-project'; add_project
-    when 'list-projects'; puts list_projects
-    when 'rm-project'; rm_project
-    when 'mv-project'; mv_project
-    when 'mv-storage'; mv_storage
-    when 'import-project'; import_project
-    when 'fork-project'; fork_project
-    when 'fetch-remote'; fetch_remote
-    when 'push-branches'; push_branches
-    when 'delete-remote-branches'; delete_remote_branches
-    when 'list-remote-tags'; list_remote_tags
-    when 'gc'; gc
-    else
-      $logger.warn "Attempt to execute invalid gitlab-projects command #{@command.inspect}."
-      puts 'not allowed'
-      false
+    GitlabMetrics.measure("command-#{@command.inspect}") do
+      case @command
+      when 'create-tag';
+        create_tag
+      when 'add-project';
+        add_project
+      when 'list-projects';
+        puts list_projects
+      when 'rm-project';
+        rm_project
+      when 'mv-project';
+        mv_project
+      when 'mv-storage';
+        mv_storage
+      when 'import-project';
+        import_project
+      when 'fork-project';
+        fork_project
+      when 'fetch-remote';
+        fetch_remote
+      when 'push-branches';
+        push_branches
+      when 'delete-remote-branches';
+        delete_remote_branches
+      when 'list-remote-tags';
+        list_remote_tags
+      when 'gc';
+        gc
+      else
+        $logger.warn "Attempt to execute invalid gitlab-projects command #{@command.inspect}."
+        puts 'not allowed'
+        false
+      end
     end
   end
 
diff --git a/lib/gitlab_shell.rb b/lib/gitlab_shell.rb
index f72ce74..ad2cc50 100644
--- a/lib/gitlab_shell.rb
+++ b/lib/gitlab_shell.rb
@@ -2,6 +2,7 @@ require 'shellwords'
 require 'pathname'
 
 require_relative 'gitlab_net'
+require_relative 'gitlab_metrics'
 
 class GitlabShell
   class AccessDeniedError < StandardError; end
@@ -32,7 +33,9 @@ class GitlabShell
     args = Shellwords.shellwords(origin_cmd)
     parse_cmd(args)
 
-    verify_access if GIT_COMMANDS.include?(args.first)
+    if GIT_COMMANDS.include?(args.first)
+      GitlabMetrics.measure('verify_access') { verify_access }
+    end
 
     process_cmd(args)
 
@@ -118,11 +121,11 @@ class GitlabShell
 
       $logger.info "gitlab-shell: executing git-annex command <#{parsed_args.join(' ')}> for #{log_username}."
       exec_cmd(*parsed_args)
-
     elsif @command == 'git-lfs-authenticate'
-      $logger.info "gitlab-shell: Processing LFS authentication for #{log_username}."
-      lfs_authenticate
-
+      GitlabMetrics.measure('lfs_authenticate') do
+        $logger.info "gitlab-shell: Processing LFS authentication for #{log_username}."
+        lfs_authenticate
+      end
     else
       $logger.info "gitlab-shell: executing git command <#{@command} #{repo_path}> for #{log_username}."
       exec_cmd(@command, repo_path)