From f6c3bb0ae9ba6251da56b714bd7f77b026c26008 Mon Sep 17 00:00:00 2001 From: Colman Yau Date: Fri, 26 Feb 2021 12:22:44 +0000 Subject: [PATCH 1/5] Flush profile before sampling to avoid profile with skewed data https://github.com/aws/amazon-codeguru-profiler-python-agent/issues/15 --- codeguru_profiler_agent/profiler_runner.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/codeguru_profiler_agent/profiler_runner.py b/codeguru_profiler_agent/profiler_runner.py index 4c3e845..c8a83ca 100644 --- a/codeguru_profiler_agent/profiler_runner.py +++ b/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): From 65622c7ff730b83e84288493bbf8f82477224d5b Mon Sep 17 00:00:00 2001 From: Colman Yau Date: Fri, 26 Feb 2021 12:48:04 +0000 Subject: [PATCH 2/5] Set profile end time whenever sample is added --- codeguru_profiler_agent/local_aggregator.py | 1 - codeguru_profiler_agent/model/profile.py | 4 +++- test/unit/model/test_profile.py | 8 ++++++++ 3 files changed, 11 insertions(+), 2 deletions(-) diff --git a/codeguru_profiler_agent/local_aggregator.py b/codeguru_profiler_agent/local_aggregator.py index 76795b2..fff2205 100644 --- a/codeguru_profiler_agent/local_aggregator.py +++ b/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") diff --git a/codeguru_profiler_agent/model/profile.py b/codeguru_profiler_agent/model/profile.py index 8ab43e3..da73f86 100644 --- a/codeguru_profiler_agent/model/profile.py +++ b/codeguru_profiler_agent/model/profile.py @@ -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 diff --git a/test/unit/model/test_profile.py b/test/unit/model/test_profile.py index f197f4d..44926a7 100644 --- a/test/unit/model/test_profile.py +++ b/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): From 0a42f1d4cf82f019e412bdb5202fed718a56ebd2 Mon Sep 17 00:00:00 2001 From: Colman Yau Date: Fri, 26 Feb 2021 15:14:10 +0000 Subject: [PATCH 3/5] Update Profile string representation to handle situation when end is not set --- codeguru_profiler_agent/model/profile.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/codeguru_profiler_agent/model/profile.py b/codeguru_profiler_agent/model/profile.py index da73f86..022dce1 100644 --- a/codeguru_profiler_agent/model/profile.py +++ b/codeguru_profiler_agent/model/profile.py @@ -140,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=' + "not set" if self.end is None else to_iso(self.end) \ + ', duration_ms=' + str(self.get_active_millis_since_start()) \ + ')' From 0d3994467d7f6e5924b76f2e728cb48c3460ca35 Mon Sep 17 00:00:00 2001 From: Colman Yau Date: Fri, 26 Feb 2021 16:31:55 +0000 Subject: [PATCH 4/5] Allow profile start time equals end time As we are using the last sample time as end time, there is chance we have the start time equals to end time. --- codeguru_profiler_agent/model/profile.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/codeguru_profiler_agent/model/profile.py b/codeguru_profiler_agent/model/profile.py index 022dce1..77d1e4c 100644 --- a/codeguru_profiler_agent/model/profile.py +++ b/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 equals 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 From 7e63b3c3242d17a4741f796da3d63bbad4a0047d Mon Sep 17 00:00:00 2001 From: Colman Yau Date: Mon, 1 Mar 2021 12:03:30 +0000 Subject: [PATCH 5/5] Update typo in equals/equal --- codeguru_profiler_agent/model/profile.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/codeguru_profiler_agent/model/profile.py b/codeguru_profiler_agent/model/profile.py index 77d1e4c..7327e74 100644 --- a/codeguru_profiler_agent/model/profile.py +++ b/codeguru_profiler_agent/model/profile.py @@ -45,7 +45,7 @@ def end(self, value): self._validate_positive_number(value) if value < self.start: raise ValueError( - "Profile end value must be greater than or equals to {}, 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 @@ -140,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=' + "not set" if self.end is None else 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()) \ + ')'