[PROF-4084] Send profile duration and start in pprof to enable UX to show duration

lib/ddtrace/profiling/encoding/profile.rb

@@ -37,7 +37,7 @@ def encode(flush)
             end
 
             # Build the profile and encode it
-            template.to_pprof
+            template.to_pprof(start: flush.start, finish: flush.finish)
           end
         end
       end

lib/ddtrace/profiling/pprof/builder.rb

@@ -4,6 +4,7 @@
 require 'ddtrace/profiling/flush'
 require 'ddtrace/profiling/pprof/message_set'
 require 'ddtrace/profiling/pprof/string_table'
+require 'ddtrace/utils/time'
 
 module Datadog
   module Profiling
@@ -47,14 +48,19 @@ def encode_profile(profile)
           Perftools::Profiles::Profile.encode(profile).force_encoding(DEFAULT_ENCODING)
         end
 
-        def build_profile
+        def build_profile(start:, finish:)
+          start_ns = Datadog::Utils::Time.as_utc_epoch_ns(start)
+          finish_ns = Datadog::Utils::Time.as_utc_epoch_ns(finish)
+
           Perftools::Profiles::Profile.new(
             sample_type: @sample_types.messages,
             sample: @samples,
             mapping: @mappings.messages,
             location: @locations.values,
             function: @functions.messages,
-            string_table: @string_table.strings
+            string_table: @string_table.strings,
+            time_nanos: start_ns,
+            duration_nanos: finish_ns - start_ns,
           )
         end
 

lib/ddtrace/profiling/pprof/template.rb

@@ -80,8 +80,8 @@ def debug_statistics
           converters.values.map(&:debug_statistics).join(', ')
         end
 
-        def to_pprof
-          profile = builder.build_profile
+        def to_pprof(start:, finish:)
+          profile = builder.build_profile(start: start, finish: finish)
           data = builder.encode_profile(profile)
           types = sample_type_mappings.keys
 

lib/ddtrace/utils/time.rb

@@ -40,6 +40,12 @@ def measure
         after = get_time
         after - before
       end
+
+      def as_utc_epoch_ns(time)
+        # we use #to_r instead of #to_f because Float doesn't have enough precision to represent exact nanoseconds, see
+        # https://rubyapi.org/3.0/o/time#method-i-to_f
+        (time.to_r * 1_000_000_000).to_i
+      end
     end
   end
 end

spec/ddtrace/profiling/encoding/profile_spec.rb

@@ -8,7 +8,9 @@
   describe '::encode' do
     subject(:encode) { described_class.encode(flush) }
 
-    let(:flush) { instance_double(Datadog::Profiling::Flush, event_groups: event_groups) }
+    let(:flush) do
+      instance_double(Datadog::Profiling::Flush, event_groups: event_groups, start: start_time, finish: finish_time)
+    end
     let(:event_groups) { [event_group] }
     let(:event_group) { instance_double(Datadog::Profiling::EventGroup, event_class: event_class, events: events) }
     let(:event_class) { double('event class') }
@@ -17,6 +19,8 @@
     let(:template) { instance_double(Datadog::Profiling::Pprof::Template) }
     let(:profile) { instance_double(Perftools::Profiles::Profile) }
     let(:payload) { instance_double(Datadog::Profiling::Pprof::Payload) }
+    let(:start_time) { Time.utc(2020) }
+    let(:finish_time) { Time.utc(2021) }
 
     before do
       expect(Datadog::Profiling::Pprof::Template)
@@ -31,21 +35,16 @@
 
       expect(template)
         .to receive(:to_pprof)
+        .with(start: start_time, finish: finish_time)
         .and_return(payload)
         .ordered
     end
 
     it { is_expected.to be payload }
 
     context 'debug logging' do
-      let(:flush) do
-        instance_double(
-          Datadog::Profiling::Flush,
-          event_groups: event_groups,
-          start: Time.utc(2020),
-          finish: Time.utc(2021),
-          event_count: 42
-        )
+      before do
+        allow(flush).to receive(:event_count).and_return(42)
       end
 
       let(:template) { instance_double(Datadog::Profiling::Pprof::Template, debug_statistics: 'template_debug_statistics') }

spec/ddtrace/profiling/integration_spec.rb

@@ -3,6 +3,7 @@
 require 'ddtrace/profiling/spec_helper'
 
 require 'ddtrace'
+require 'ddtrace/utils/time'
 require 'ddtrace/profiling'
 require 'ddtrace/profiling/pprof/template'
 require 'ddtrace/profiling/collectors/stack'
@@ -195,7 +196,7 @@ def stack_two
   end
 
   describe 'building a Perftools::Profiles::Profile using Pprof::Template' do
-    subject(:build_profile) { template.to_pprof }
+    subject(:build_profile) { template.to_pprof(start: start, finish: finish) }
 
     let(:template) { Datadog::Profiling::Pprof::Template.for_event_classes(event_classes) }
     let(:event_classes) { events.keys.uniq }
@@ -204,6 +205,8 @@ def stack_two
         Datadog::Profiling::Events::StackSample => stack_samples
       }
     end
+    let(:start) { Time.now }
+    let(:finish) { start + 60 * 60 }
 
     def rand_int
       rand(1e3)
@@ -238,11 +241,14 @@ def stack_frame_to_function_id(backtrace_location)
       it { is_expected.to be_kind_of(Perftools::Profiles::Profile) }
 
       it 'is well formed' do
+        start_ns = Datadog::Utils::Time.as_utc_epoch_ns(start)
+        finish_ns = Datadog::Utils::Time.as_utc_epoch_ns(finish)
+
         is_expected.to have_attributes(
           drop_frames: 0,
           keep_frames: 0,
-          time_nanos: 0,
-          duration_nanos: 0,
+          time_nanos: start_ns,
+          duration_nanos: finish_ns - start_ns,
           period_type: nil,
           period: 0,
           comment: [],

spec/ddtrace/profiling/pprof/builder_spec.rb

@@ -45,7 +45,10 @@ def string_id_for(string)
   end
 
   describe '#build_profile' do
-    subject(:build_profile) { builder.build_profile }
+    let(:start) { Time.utc(2022) }
+    let(:finish) { Time.utc(2023) }
+
+    subject(:build_profile) { builder.build_profile(start: start, finish: finish) }
 
     before do
       expect(Perftools::Profiles::Profile)
@@ -56,7 +59,9 @@ def string_id_for(string)
           mapping: builder.mappings.messages,
           location: builder.locations.values,
           function: builder.functions.messages,
-          string_table: builder.string_table.strings
+          string_table: builder.string_table.strings,
+          time_nanos: start.to_i * 1_000_000_000,
+          duration_nanos: (finish - start).to_i * 1_000_000_000,
         )
         .and_call_original
     end

spec/ddtrace/profiling/pprof/template_spec.rb

@@ -126,14 +126,17 @@ def string_id_for(string)
   end
 
   describe '#to_pprof' do
-    subject(:to_pprof) { template.to_pprof }
+    subject(:to_pprof) { template.to_pprof(start: start, finish: finish) }
 
     let(:profile) { instance_double(Perftools::Profiles::Profile) }
     let(:data) { instance_double(String) }
+    let(:start) { instance_double(::Time, 'Start time') }
+    let(:finish) { instance_double(::Time, 'Finish time') }
 
     before do
       expect(template.builder)
         .to receive(:build_profile)
+        .with(start: start, finish: finish)
         .and_return(profile)
 
       expect(template.builder)

spec/ddtrace/utils/time_spec.rb

@@ -1,6 +1,7 @@
 # typed: false
 require 'spec_helper'
 
+require 'time'
 require 'ddtrace/utils/time'
 
 RSpec.describe Datadog::Utils::Time do
@@ -40,4 +41,25 @@
       end
     end
   end
+
+  describe '#as_utc_epoch_ns' do
+    let(:time) { Time.iso8601('2021-01-01T01:02:03.405060708Z') }
+
+    subject(:as_utc_epoch_ns) { described_class.as_utc_epoch_ns(time) }
+
+    it 'converts a time object into nanoseconds since UTC epoch' do
+      expect(as_utc_epoch_ns).to be 1609462923405060708
+    end
+
+    it 'can round trip without losing precision' do
+      expect(Time.at(as_utc_epoch_ns.to_r / 1_000_000_000)).to eq time
+    end
+
+    it 'can correctly handle non-UTC time objects' do
+      # same as :time above, but in a different timezone
+      non_utc_time = Time.iso8601('2021-01-01T06:32:03.405060708+05:30')
+
+      expect(as_utc_epoch_ns).to eq described_class.as_utc_epoch_ns(non_utc_time)
+    end
+  end
 end