Merge pull request #16 from aws/issue-15

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

Author: gimki

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):