Record and publish application boot time

This change captures and emits the time it takes
for the primary Rails process to start up.

- Log it to application JSON log
- Emit it to prometheus
- Print it to the console message

This is only active for Puma, Sidekiq and Rails console.

Changelog: added

config/application.rb

@@ -508,5 +508,15 @@ module Gitlab
         end
       end
     end
+
+    # DO NOT PLACE ANY INITIALIZERS AFTER THIS.
+    config.after_initialize do
+      # on_master_start yields immediately in unclustered environments and runs
+      # when the primary process is done initializing otherwise.
+      Gitlab::Cluster::LifecycleEvents.on_master_start do
+        Gitlab::Metrics::BootTimeTracker.instance.track_boot_time!
+        Gitlab::Console.welcome!
+      end
+    end
   end
 end

config/feature_flags/development/track_application_boot_time.yml

+---
+name: track_application_boot_time
+introduced_by_url: https://gitlab.com/gitlab-org/gitlab/-/merge_requests/79139
+rollout_issue_url: https://gitlab.com/gitlab-org/gitlab/-/issues/351769
+milestone: '14.8'
+type: development
+group: group::memory
+default_enabled: true

config/initializers/console_message.rb

 # frozen_string_literal: true
 
-# rubocop:disable Rails/Output
 if Gitlab::Runtime.console?
-  # note that this will not print out when using `spring`
-  justify = 15
-
-  puts '-' * 80
-  puts " Ruby:".ljust(justify) + RUBY_DESCRIPTION
-  puts " GitLab:".ljust(justify) + "#{Gitlab::VERSION} (#{Gitlab.revision}) #{Gitlab.ee? ? 'EE' : 'FOSS'}"
-  puts " GitLab Shell:".ljust(justify) + "#{Gitlab::VersionInfo.parse(Gitlab::Shell.version)}"
-
-  if ApplicationRecord.database.exists?
-    puts " #{ApplicationRecord.database.human_adapter_name}:".ljust(justify) + ApplicationRecord.database.version
-
-    Gitlab.ee do
-      if Gitlab::Geo.connected? && Gitlab::Geo.enabled?
-        puts " Geo enabled:".ljust(justify) + 'yes'
-        puts " Geo server:".ljust(justify) + EE::GeoHelper.current_node_human_status
-      end
-    end
-  end
-
-  puts '-' * 80
-
   # Stop irb from writing a history file by default.
   module IrbNoHistory
     def init_config(*)

doc/administration/monitoring/prometheus/gitlab_metrics.md

@@ -48,6 +48,7 @@ The following metrics are available:
 | `gitlab_database_transaction_seconds`                            | Histogram   | 12.1    | Time spent in database transactions, in seconds                                                                       |                                                           |
 | `gitlab_method_call_duration_seconds`                            | Histogram   | 10.2    | Method calls real duration                                                                                            | `controller`, `action`, `module`, `method`                |
 | `gitlab_page_out_of_bounds`                                      | Counter     | 12.8    | Counter for the PageLimiter pagination limit being hit                                                                | `controller`, `action`, `bot`                             |
+| `gitlab_rails_boot_time_seconds`                                 | Gauge       | 14.8    | Time elapsed for Rails primary process to finish startup                                               |                                                           |
 | `gitlab_rails_queue_duration_seconds`                            | Histogram   | 9.4     | Measures latency between GitLab Workhorse forwarding a request to Rails                                               |                                                           |
 | `gitlab_sql_duration_seconds`                                    | Histogram   | 10.2    | SQL execution time, excluding `SCHEMA` operations and `BEGIN` / `COMMIT`                                              |                                                           |
 | `gitlab_sql_<role>_duration_seconds`                             | Histogram   | 13.10   | SQL execution time, excluding `SCHEMA` operations and `BEGIN` / `COMMIT`, grouped by database roles (primary/replica) |                                                           |

ee/spec/lib/gitlab/console_spec.rb

+# frozen_string_literal: true
+
+require 'fast_spec_helper'
+
+RSpec.describe Gitlab::Console do
+  describe '.welcome!' do
+    context 'when running in the Rails console' do
+      before do
+        allow(Gitlab::Runtime).to receive(:console?).and_return(true)
+        allow(Gitlab::Geo).to receive(:enabled?).and_return(true)
+        allow(Gitlab::Metrics::BootTimeTracker.instance).to receive(:startup_time).and_return(42)
+      end
+
+      it 'prints a welcome message' do
+        expect($stdout).to receive(:puts).ordered.with(include("--"))
+        expect($stdout).to receive(:puts).ordered.with(include("Ruby:"))
+        expect($stdout).to receive(:puts).ordered.with(include("GitLab:"))
+        expect($stdout).to receive(:puts).ordered.with(include("GitLab Shell:"))
+        expect($stdout).to receive(:puts).ordered.with(include("PostgreSQL:"))
+        expect($stdout).to receive(:puts).ordered.with(include("Geo enabled:"))
+        expect($stdout).to receive(:puts).ordered.with(include("Geo server:"))
+        expect($stdout).to receive(:puts).ordered.with(include("--"))
+        expect($stdout).not_to receive(:puts).ordered
+
+        described_class.welcome!
+      end
+    end
+  end
+end

lib/gitlab/console.rb

+# frozen_string_literal: true
+
+# rubocop:disable Rails/Output
+module Gitlab
+  module Console
+    class << self
+      def welcome!
+        return unless Gitlab::Runtime.console?
+
+        # note that this will not print out when using `spring`
+        justify = 15
+
+        puts '-' * 80
+        puts " Ruby:".ljust(justify) + RUBY_DESCRIPTION
+        puts " GitLab:".ljust(justify) + "#{Gitlab::VERSION} (#{Gitlab.revision}) #{Gitlab.ee? ? 'EE' : 'FOSS'}"
+        puts " GitLab Shell:".ljust(justify) + "#{Gitlab::VersionInfo.parse(Gitlab::Shell.version)}"
+
+        if ApplicationRecord.database.exists?
+          puts " #{ApplicationRecord.database.human_adapter_name}:".ljust(justify) + ApplicationRecord.database.version
+
+          Gitlab.ee do
+            if Gitlab::Geo.connected? && Gitlab::Geo.enabled?
+              puts " Geo enabled:".ljust(justify) + 'yes'
+              puts " Geo server:".ljust(justify) + EE::GeoHelper.current_node_human_status
+            end
+          end
+        end
+
+        if RUBY_PLATFORM.include?('darwin')
+          # Sorry, macOS users. The current implementation requires procfs.
+          puts '-' * 80
+        else
+          boot_time_seconds = Gitlab::Metrics::BootTimeTracker.instance.startup_time
+          booted_in = "[ booted in %.2fs ]" % [boot_time_seconds]
+          puts '-' * (80 - booted_in.length) + booted_in
+        end
+      end
+    end
+  end
+end
+# rubocop:enable Rails/Output

lib/gitlab/metrics/boot_time_tracker.rb

+# frozen_string_literal: true
+
+module Gitlab
+  module Metrics
+    class BootTimeTracker
+      include Singleton
+
+      SUPPORTED_RUNTIMES = [:puma, :sidekiq, :console].freeze
+
+      def startup_time
+        @startup_time || 0
+      end
+
+      def track_boot_time!(logger: Gitlab::AppJsonLogger)
+        return if @startup_time
+
+        runtime = Gitlab::Runtime.safe_identify
+        return unless SUPPORTED_RUNTIMES.include?(runtime) && Feature.enabled?(:track_application_boot_time, default_enabled: :yaml)
+
+        @startup_time = Gitlab::Metrics::System.process_runtime_elapsed_seconds
+
+        Gitlab::Metrics.gauge(
+          :gitlab_rails_boot_time_seconds, 'Time elapsed for Rails primary process to finish startup'
+        ).set({}, @startup_time)
+
+        logger.info(message: 'Application boot finished', runtime: runtime.to_s, duration_s: @startup_time)
+      end
+
+      def reset!
+        @startup_time = nil
+      end
+    end
+  end
+end

lib/gitlab/metrics/system.rb

@@ -7,6 +7,9 @@ module Gitlab
     # This module relies on the /proc filesystem being available. If /proc is
     # not available the methods of this module will be stubbed.
     module System
+      extend self
+
+      PROC_STAT_PATH = '/proc/self/stat'
       PROC_STATUS_PATH = '/proc/self/status'
       PROC_SMAPS_ROLLUP_PATH = '/proc/self/smaps_rollup'
       PROC_LIMITS_PATH = '/proc/self/limits'
@@ -17,7 +20,7 @@ module Gitlab
       RSS_PATTERN = /VmRSS:\s+(?<value>\d+)/.freeze
       MAX_OPEN_FILES_PATTERN = /Max open files\s*(?<value>\d+)/.freeze
 
-      def self.summary
+      def summary
         proportional_mem = memory_usage_uss_pss
         {
           version: RUBY_DESCRIPTION,
@@ -32,43 +35,43 @@ module Gitlab
       end
 
       # Returns the current process' RSS (resident set size) in bytes.
-      def self.memory_usage_rss
+      def memory_usage_rss
         sum_matches(PROC_STATUS_PATH, rss: RSS_PATTERN)[:rss].kilobytes
       end
 
       # Returns the current process' USS/PSS (unique/proportional set size) in bytes.
-      def self.memory_usage_uss_pss
+      def memory_usage_uss_pss
         sum_matches(PROC_SMAPS_ROLLUP_PATH, uss: PRIVATE_PAGES_PATTERN, pss: PSS_PATTERN)
           .transform_values(&:kilobytes)
       end
 
-      def self.file_descriptor_count
+      def file_descriptor_count
         Dir.glob(PROC_FD_GLOB).length
       end
 
-      def self.max_open_file_descriptors
+      def max_open_file_descriptors
         sum_matches(PROC_LIMITS_PATH, max_fds: MAX_OPEN_FILES_PATTERN)[:max_fds]
       end
 
-      def self.cpu_time
+      def cpu_time
         Process.clock_gettime(Process::CLOCK_PROCESS_CPUTIME_ID, :float_second)
       end
 
       # Returns the current real time in a given precision.
       #
       # Returns the time as a Float for precision = :float_second.
-      def self.real_time(precision = :float_second)
+      def real_time(precision = :float_second)
         Process.clock_gettime(Process::CLOCK_REALTIME, precision)
       end
 
       # Returns the current monotonic clock time as seconds with microseconds precision.
       #
       # Returns the time as a Float.
-      def self.monotonic_time
+      def monotonic_time
         Process.clock_gettime(Process::CLOCK_MONOTONIC, :float_second)
       end
 
-      def self.thread_cpu_time
+      def thread_cpu_time
         # Not all OS kernels are supporting `Process::CLOCK_THREAD_CPUTIME_ID`
         # Refer: https://gitlab.com/gitlab-org/gitlab/issues/30567#note_221765627
         return unless defined?(Process::CLOCK_THREAD_CPUTIME_ID)
@@ -76,33 +79,67 @@ module Gitlab
         Process.clock_gettime(Process::CLOCK_THREAD_CPUTIME_ID, :float_second)
       end
 
-      def self.thread_cpu_duration(start_time)
+      def thread_cpu_duration(start_time)
         end_time = thread_cpu_time
         return unless start_time && end_time
 
         end_time - start_time
       end
 
+      # Returns the total time the current process has been running in seconds.
+      def process_runtime_elapsed_seconds
+        # Entry 22 (1-indexed) contains the process `starttime`, see:
+        # https://man7.org/linux/man-pages/man5/proc.5.html
+        #
+        # This value is a fixed timestamp in clock ticks.
+        # To obtain an elapsed time in seconds, we divide by the number
+        # of ticks per second and subtract from the system uptime.
+        start_time_ticks = proc_stat_entries[21].to_f
+        clock_ticks_per_second = Etc.sysconf(Etc::SC_CLK_TCK)
+        uptime - (start_time_ticks / clock_ticks_per_second)
+      end
+
+      private
+
       # Given a path to a file in /proc and a hash of (metric, pattern) pairs,
       # sums up all values found for those patterns under the respective metric.
-      def self.sum_matches(proc_file, **patterns)
+      def sum_matches(proc_file, **patterns)
         results = patterns.transform_values { 0 }
 
-        begin
-          File.foreach(proc_file) do |line|
+        safe_yield_procfile(proc_file) do |io|
+          io.each_line do |line|
             patterns.each do |metric, pattern|
               match = line.match(pattern)
               value = match&.named_captures&.fetch('value', 0)
               results[metric] += value.to_i
             end
           end
-        rescue Errno::ENOENT
-          # This means the procfile we're reading from did not exist;
-          # this is safe to ignore, since we initialize each metric to 0
         end
 
         results
       end
+
+      def proc_stat_entries
+        safe_yield_procfile(PROC_STAT_PATH) do |io|
+          io.read.split(' ')
+        end || []
+      end
+
+      def safe_yield_procfile(path, &block)
+        File.open(path, &block)
+      rescue Errno::ENOENT
+        # This means the procfile we're reading from did not exist;
+        # most likely we're on Darwin.
+      end
+
+      # Equivalent to reading /proc/uptime on Linux 2.6+.
+      #
+      # Returns 0 if not supported, e.g. on Darwin.
+      def uptime
+        Process.clock_gettime(Process::CLOCK_BOOTTIME)
+      rescue NameError
+        0
+      end
     end
   end
 end

lib/gitlab/runtime.rb

@@ -31,6 +31,12 @@ module Gitlab
         end
       end
 
+      def safe_identify
+        identify
+      rescue UnknownProcessError, AmbiguousProcessError
+        nil
+      end
+
       def puma?
         !!defined?(::Puma)
       end

spec/lib/gitlab/console_spec.rb

+# frozen_string_literal: true
+
+require 'fast_spec_helper'
+
+RSpec.describe Gitlab::Console do
+  describe '.welcome!' do
+    context 'when running in the Rails console' do
+      before do
+        allow(Gitlab::Runtime).to receive(:console?).and_return(true)
+        allow(Gitlab::Metrics::BootTimeTracker.instance).to receive(:startup_time).and_return(42)
+      end
+
+      shared_examples 'console messages' do
+        it 'prints system info' do
+          expect($stdout).to receive(:puts).ordered.with(include("--"))
+          expect($stdout).to receive(:puts).ordered.with(include("Ruby:"))
+          expect($stdout).to receive(:puts).ordered.with(include("GitLab:"))
+          expect($stdout).to receive(:puts).ordered.with(include("GitLab Shell:"))
+          expect($stdout).to receive(:puts).ordered.with(include("PostgreSQL:"))
+          expect($stdout).to receive(:puts).ordered.with(include("--"))
+          expect($stdout).not_to receive(:puts).ordered
+
+          described_class.welcome!
+        end
+      end
+
+      # This is to add line coverage, not to actually verify behavior on macOS.
+      context 'on darwin' do
+        before do
+          stub_const('RUBY_PLATFORM', 'x86_64-darwin-19')
+        end
+
+        it_behaves_like 'console messages'
+      end
+
+      it_behaves_like 'console messages'
+    end
+
+    context 'when not running in the Rails console' do
+      before do
+        allow(Gitlab::Runtime).to receive(:console?).and_return(false)
+      end
+
+      it 'does not print anything' do
+        expect($stdout).not_to receive(:puts)
+
+        described_class.welcome!
+      end
+    end
+  end
+end

spec/lib/gitlab/metrics/boot_time_tracker_spec.rb

+# frozen_string_literal: true
+
+require 'spec_helper'
+
+RSpec.describe Gitlab::Metrics::BootTimeTracker do
+  let(:logger) { double('logger') }
+  let(:gauge) { double('gauge') }
+
+  subject(:tracker) { described_class.instance }
+
+  before do
+    described_class.instance.reset!
+
+    allow(logger).to receive(:info)
+    allow(gauge).to receive(:set)
+    allow(Gitlab::Metrics).to receive(:gauge).and_return(gauge)
+  end
+
+  describe '#track_boot_time!' do
+    described_class::SUPPORTED_RUNTIMES.each do |runtime|
+      context "when called on #{runtime} for the first time" do
+        before do
+          expect(Gitlab::Runtime).to receive(:safe_identify).and_return(runtime)
+        end
+
+        it 'set the startup_time' do
+          tracker.track_boot_time!(logger: logger)
+
+          expect(tracker.startup_time).to be > 0
+        end
+
+        it 'records the current process runtime' do
+          expect(Gitlab::Metrics::System).to receive(:process_runtime_elapsed_seconds).once
+
+          tracker.track_boot_time!(logger: logger)
+        end
+
+        it 'logs the application boot time' do
+          expect(Gitlab::Metrics::System).to receive(:process_runtime_elapsed_seconds).and_return(42)
+          expect(logger).to receive(:info).with(message: 'Application boot finished', runtime: runtime.to_s, duration_s: 42)
+
+          tracker.track_boot_time!(logger: logger)
+        end
+
+        it 'tracks boot time in a prometheus gauge' do
+          expect(Gitlab::Metrics::System).to receive(:process_runtime_elapsed_seconds).and_return(42)
+          expect(gauge).to receive(:set).with({}, 42)
+
+          tracker.track_boot_time!(logger: logger)
+        end
+
+        context 'on subsequent calls' do
+          it 'does nothing' do
+            tracker.track_boot_time!(logger: logger)
+
+            expect(Gitlab::Metrics::System).not_to receive(:process_runtime_elapsed_seconds)
+            expect(logger).not_to receive(:info)
+            expect(gauge).not_to receive(:set)
+
+            tracker.track_boot_time!(logger: logger)
+          end
+        end
+      end
+    end
+
+    context 'when called on other runtimes' do
+      it 'does nothing' do
+        tracker.track_boot_time!(logger: logger)
+
+        expect(Gitlab::Metrics::System).not_to receive(:process_runtime_elapsed_seconds)
+        expect(logger).not_to receive(:info)
+        expect(gauge).not_to receive(:set)
+
+        tracker.track_boot_time!(logger: logger)
+      end
+    end
+
+    # TODO: When https://gitlab.com/gitlab-org/gitlab/-/issues/351769 is closed,
+    #       revert to using fast_spec_helper again.
+    context 'when feature flag is off' do
+      it 'does nothing' do
+        stub_feature_flags(track_application_boot_time: false)
+
+        expect(Gitlab::Metrics::System).not_to receive(:process_runtime_elapsed_seconds)
+        expect(logger).not_to receive(:info)
+        expect(gauge).not_to receive(:set)
+
+        tracker.track_boot_time!(logger: logger)
+      end
+    end
+  end
+
+  describe '#startup_time' do
+    it 'returns 0 when boot time not tracked' do
+      expect(tracker.startup_time).to eq(0)
+    end
+  end
+end

spec/lib/gitlab/metrics/system_spec.rb

@@ -4,6 +4,13 @@ require 'spec_helper'
 
 RSpec.describe Gitlab::Metrics::System do
   context 'when /proc files exist' do
+    # Modified column 22 to be 1000 (starttime ticks)
+    let(:proc_stat) do
+      <<~SNIP
+      2095 (ruby) R 0 2095 2095 34818 2095 4194560 211267 7897 2 0 287 51 10 1 20 0 5 0 1000 566210560 80885 18446744073709551615 94736211292160 94736211292813 140720919612064 0 0 0 0 0 1107394127 0 0 0 17 3 0 0 0 0 0 94736211303768 94736211304544 94736226689024 140720919619473 140720919619513 140720919619513 140720919621604 0
+      SNIP
+    end
+
     # Fixtures pulled from:
     # Linux carbon 5.3.0-7648-generic #41~1586789791~19.10~9593806-Ubuntu SMP Mon Apr 13 17:50:40 UTC  x86_64 x86_64 x86_64 GNU/Linux
     let(:proc_status) do
@@ -97,6 +104,29 @@ RSpec.describe Gitlab::Metrics::System do
       end
     end
 
+    describe '.process_runtime_elapsed_seconds' do
+      it 'returns the seconds elapsed since the process was started' do
+        # sets process starttime ticks to 1000
+        mock_existing_proc_file('/proc/self/stat', proc_stat)
+        # system clock ticks/sec
+        expect(Etc).to receive(:sysconf).with(Etc::SC_CLK_TCK).and_return(100)
+        # system uptime in seconds
+        expect(::Process).to receive(:clock_gettime).and_return(15)
+
+        # uptime - (starttime_ticks / ticks_per_sec)
+        expect(described_class.process_runtime_elapsed_seconds).to eq(5)
+      end
+
+      context 'when inputs are not available' do
+        it 'returns 0' do
+          mock_missing_proc_file
+          expect(::Process).to receive(:clock_gettime).and_raise(NameError)
+
+          expect(described_class.process_runtime_elapsed_seconds).to eq(0)
+        end
+      end
+    end
+
     describe '.summary' do
       it 'contains a selection of the available fields' do
         stub_const('RUBY_DESCRIPTION', 'ruby-3.0-patch1')
@@ -223,10 +253,10 @@ RSpec.describe Gitlab::Metrics::System do
   end
 
   def mock_existing_proc_file(path, content)
-    allow(File).to receive(:foreach).with(path) { |_path, &block| content.each_line(&block) }
+    allow(File).to receive(:open).with(path) { |_path, &block| block.call(StringIO.new(content)) }
   end
 
   def mock_missing_proc_file
-    allow(File).to receive(:foreach).and_raise(Errno::ENOENT)
+    allow(File).to receive(:open).and_raise(Errno::ENOENT)
   end
 end

spec/lib/gitlab/runtime_spec.rb

@@ -26,8 +26,16 @@ RSpec.describe Gitlab::Runtime do
   end
 
   context "when unknown" do
-    it "raises an exception when trying to identify" do
-      expect { subject.identify }.to raise_error(subject::UnknownProcessError)
+    describe '.identify' do
+      it "raises an exception when trying to identify" do
+        expect { subject.identify }.to raise_error(subject::UnknownProcessError)
+      end
+    end
+
+    describe '.safe_identify' do
+      it "returns nil" do
+        expect(subject.safe_identify).to be_nil
+      end
     end
   end
 
@@ -37,8 +45,16 @@ RSpec.describe Gitlab::Runtime do
       stub_const('::Rails::Console', double)
     end
 
-    it "raises an exception when trying to identify" do
-      expect { subject.identify }.to raise_error(subject::AmbiguousProcessError)
+    describe '.identify' do
+      it "raises an exception when trying to identify" do
+        expect { subject.identify }.to raise_error(subject::AmbiguousProcessError)
+      end
+    end
+
+    describe '.safe_identify' do
+      it "returns nil" do
+        expect(subject.safe_identify).to be_nil
+      end
     end
   end