Instrument GitLab Shell and log metrics data to a file

CHANGELOG

@@ -1,5 +1,6 @@
 v3.6.5
   - Test against ruby 2.3
+  - Instrument GitLab Shell and log metrics data to a file
 
 v3.6.4
   - Fix rsync with ionice command building

bin/create-hooks

@@ -6,13 +6,16 @@
 
 require_relative '../lib/gitlab_init'
 require File.join(ROOT_PATH, 'lib', 'gitlab_projects')
+require File.join(ROOT_PATH, 'lib', 'gitlab_metrics')
 
 repository_storage_paths = ARGV
 
 repository_storage_paths.each do |repo_path|
   Dir["#{repo_path.chomp('/')}/*/*.git"].each do |repo|
     begin
-      GitlabProjects.create_hooks(repo)
+      GitlabMetrics.measure('command-create-hooks') do
+        GitlabProjects.create_hooks(repo)
+      end
     rescue Errno::ENOENT
       # The user must have deleted their repository. Ignore.
     end

lib/gitlab_config.rb

@@ -54,4 +54,8 @@ def git_annex_enabled?
   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

lib/gitlab_keys.rb

@@ -2,6 +2,7 @@
 
 require_relative 'gitlab_config'
 require_relative 'gitlab_logger'
+require_relative 'gitlab_metrics'
 
 class GitlabKeys
   class KeyError < StandardError ; end
@@ -28,17 +29,25 @@ def initialize
   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}") 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
 

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

lib/gitlab_projects.rb

@@ -4,6 +4,7 @@
 
 require_relative 'gitlab_config'
 require_relative 'gitlab_logger'
+require_relative 'gitlab_metrics'
 require_relative 'gitlab_reference_counter'
 
 class GitlabProjects
@@ -50,24 +51,39 @@ def initialize
   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}") 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
 

lib/gitlab_shell.rb

@@ -2,6 +2,7 @@
 require 'pathname'
 
 require_relative 'gitlab_net'
+require_relative 'gitlab_metrics'
 
 class GitlabShell
   class AccessDeniedError < StandardError; end
@@ -32,7 +33,9 @@ def exec(origin_cmd)
     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 @@ def process_cmd(args)
 
       $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)

spec/gitlab_keys_spec.rb

@@ -53,7 +53,7 @@
     end
 
     context "without file writing" do
-      before { gitlab_keys.stub(:open) }
+      before { allow(gitlab_keys).to receive(:open) }
       before { create_authorized_keys_fixture }
 
       it "should log an add-key event" do
@@ -106,7 +106,7 @@
 
     context "without file writing" do
       before do
-        gitlab_keys.should_receive(:open).and_yield(mock(:file, puts: nil, chmod: nil))
+        gitlab_keys.should_receive(:open).and_yield(double(:file, puts: nil, chmod: nil))
       end
 
       it "should log an add-key event" do

spec/gitlab_metrics_spec.rb

@@ -0,0 +1,30 @@
+require_relative 'spec_helper'
+require_relative '../lib/gitlab_metrics'
+
+describe GitlabMetrics do
+  describe '::measure' do
+    it 'returns the return value of the block' do
+      val = described_class.measure('foo') { 10 }
+
+      expect(val).to eq(10)
+    end
+
+    it 'write in a file metrics data' do
+      result = nil
+      expect(described_class.logger).to receive(:debug) do |&b|
+        result = b.call
+      end
+
+      described_class.measure('foo') { 10 }
+
+      expect(result).to match(/name=\"foo\" wall_time=\d+ cpu_time=\d+/)
+    end
+
+    it 'calls proper measure methods' do
+      expect(described_class::System).to receive(:monotonic_time).twice.and_call_original
+      expect(described_class::System).to receive(:cpu_time).twice.and_call_original
+
+      described_class.measure('foo') { 10 }
+    end
+  end
+end