Report profile before sample to avoid incorrect profile end time #15

codeguru_profiler_agent/local_aggregator.py

@@ -102,7 +102,6 @@ def refresh_configuration(self):
  def _report_profile(self, now):
  self.last_report_attempted = now
  self._add_overhead_metric_to_profile()
- self.profile.end = now
  logger.info("Attempting to report profile data: " + str(self.profile))
  if self.profile.is_empty():
  logger.info("Report was cancelled because it was empty")

codeguru_profiler_agent/model/profile.py

@@ -43,9 +43,9 @@ def end(self):
  @end.setter
  def end(self, value):
  self._validate_positive_number(value)
- if value <= self.start:
+ if value < self.start:
  raise ValueError(
- "Profile end value must be bigger than {}, got {}".format(self.start, value))
+ "Profile end value must be greater than or equal to {}, got {}".format(self.start, value))
  self._end = value
  # this is the total cpu time spent in this application since start, not just the overhead
  self.cpu_time_seconds = time.process_time() - self._start_process_time
@@ -63,7 +63,7 @@ def get_active_millis_since_start(self):
 
  def add(self, sample):
  """
- Merge Sample into the call graph.
+ Merge Sample into the call graph and update profile end time pointing to the last sample time.
  """
  self.total_attempted_sample_threads_count += \
  sample.attempted_sample_threads_count
@@ -74,6 +74,8 @@ def add(self, sample):
  for stack in sample.stacks:
  self._insert_stack(stack)
 
+ self.end = current_milli_time(clock=self._clock)
+
  def set_overhead_ms(self, duration_timedelta):
  """
  The overhead is the total cpu time spent profiling since start. It is measured by a Timer object and only passed
@@ -138,6 +140,6 @@ def average_thread_weight(self):
  def __str__(self):
  return "Profile(profiling_group_name=" + self.profiling_group_name \
  + ", start=" + to_iso(self.start) \
- + ', end=' + to_iso(self.end) \
+ + ', end=' + "none" if self.end is None else to_iso(self.end) \
  + ', duration_ms=' + str(self.get_active_millis_since_start()) \
  + ')'

codeguru_profiler_agent/profiler_runner.py

@@ -86,10 +86,10 @@ def _run_profiler(self):
 
  # after the refresh we may be working on a profile
  if self.is_profiling_in_progress:
- sample = self.sampler.sample()
- self.collector.add(sample)
  if self.collector.flush():
  self.is_profiling_in_progress = False
+ sample = self.sampler.sample()
+ self.collector.add(sample)
  return True
 
  def is_running(self):

test/unit/model/test_profile.py

@@ -32,6 +32,7 @@ class TestAdd(TestProfile):
  @before
  def before(self):
  super().before()
+ self.turn_clock(1)
 
  @pytest.mark.parametrize("stacks, expected", [
  ([[Frame("method_one"), Frame("method_two"), Frame("method_three")]], {
@@ -254,6 +255,12 @@ def test_add_stack(self, stacks, expected):
 
  assert (_convert_profile_into_dict(self.subject) == expected)
 
+ def test_add_stack_set_profile_end(self):
+ self.subject.add(Sample(stacks=[[Frame("frame1")]], attempted_sample_threads_count=12))
+ test_end_time = self.subject.start + 1000
+ assert self.subject.end == test_end_time
+
+
  def test_it_keeps_the_total_sum_of_the_attempted_sample_threads_count_values(
  self):
  sample1 = Sample(stacks=[[Frame("frame1")]], attempted_sample_threads_count=12)
@@ -454,6 +461,7 @@ class TestGetAverageThreadWeight(TestProfile):
  @before
  def before(self):
  super().before()
+ self.turn_clock(1)
 
  def test_it_returns_the_average_thread_weight_for_the_samples_in_the_profile(
  self):