On Wed, Jan 27, 2021 at 10:14:36AM +0100, Jan Tluka wrote:
Wed, Jan 27, 2021 at 10:00:04AM CET, olichtne(a)redhat.com wrote:
>On Wed, Jan 27, 2021 at 09:11:05AM +0100, Jan Tluka wrote:
>> Tue, Jan 26, 2021 at 03:09:17PM CET, olichtne(a)redhat.com wrote:
>> >From: Ondrej Lichtner <olichtne(a)redhat.com>
>> >
>> >Extending the PerfResult object api with the following
>> >methods/properties:
>> >
>> >* start_timestamp
>> >* end_timestamp
>> >* time_slice(start, end)
>> >
>> >These unify the api for PerfInterval, SequentialPerfResult and
>> >ParallelPerfResult.
>> >
>> >This also means that "timestamp" itself in PerfInterval is renamed
to
>> >"start_timestamp" to avoid duplication.
>> >
>> >The "time_slice" method returns an object of the same type
>> >(PerfInterval, SequentialPerfResult, ParallelPerfResult or other class
>> >derived from PerfResult) that is "sliced" to only contain
measurement
>> >data from the selected timestamp period restricted by the "start"
and
>> >"end" parameters.
>> >
>> >The implementation depends on the specific class:
>> >* PerfInterval serves as the smalles unit and creates a new PerfInterval
>> > object that has a shorter *duration* (intersection of current
>> > start-end and requested start-end), and has the *value*, adjusted by
>> > the ration of new_duration/old_duration. This ensures that the
>> > "average" calculated from this PerfInterval is consistent after
the
>> > time_slice
>> >* PerfList derivatives (SequentialPerfResult and ParallelPerfResult),
>> > recursively call "time_slice" in all the individual items of
the
>> > sequence.
>> >
>> >In case an empty slice would be created (mismatch of start-end
>> >intervals), an EmptySlice exception is thrown.
>> >
>> >This commit also adjusts the PerfRecipe "align_data" related code
to use
>> >this new refactored code.
>> >
>> >Signed-off-by: Ondrej Lichtner <olichtne(a)redhat.com>
>> >---
>> > .../Perf/Measurements/BaseFlowMeasurement.py | 48 ++++++------
>> > .../Perf/Measurements/StatCPUMeasurement.py | 14 +---
>> > lnst/RecipeCommon/Perf/Recipe.py | 2 +-
>> > lnst/RecipeCommon/Perf/Results.py | 74 ++++++++++++++++++-
>> > 4 files changed, 96 insertions(+), 42 deletions(-)
>> >
>> >diff --git a/lnst/RecipeCommon/Perf/Measurements/BaseFlowMeasurement.py
b/lnst/RecipeCommon/Perf/Measurements/BaseFlowMeasurement.py
>> >index dcb0d2a..a8e9328 100644
>> >--- a/lnst/RecipeCommon/Perf/Measurements/BaseFlowMeasurement.py
>> >+++ b/lnst/RecipeCommon/Perf/Measurements/BaseFlowMeasurement.py
>> >@@ -165,40 +165,34 @@ def receiver_cpu_stats(self, value):
>> >
>> > @property
>> > def start_timestamp(self):
>> >- return max([seq_result[0].timestamp for seq_result in
self.generator_results])
>> >+ return min(
>> >+ [
>> >+ self.generator_results.start_timestamp,
>> >+ self.generator_cpu_stats.start_timestamp,
>> >+ self.receiver_results.start_timestamp,
>> >+ self.receiver_cpu_stats.start_timestamp,
>> >+ ]
>> >+ )
>> >
>> > @property
>> > def end_timestamp(self):
>> >- return min([seq_result[-1].timestamp for seq_result in
self.generator_results])
>> >+ return max(
>> >+ [
>> >+ self.generator_results.end_timestamp,
>> >+ self.generator_cpu_stats.end_timestamp,
>> >+ self.receiver_results.end_timestamp,
>> >+ self.receiver_cpu_stats.end_timestamp,
>> >+ ]
>> >+ )
>> >
>> >- def align_data(self, start, end):
>> >+ def time_slice(self, start, end):
>> > result_copy = FlowMeasurementResults(self.measurement, self.flow)
>> >
>> >- # NOTE: iperf reports the cpu utilization for the whole test
>> >- # period, not each second, so the CPU samples cannot be aligned
>> >- result_copy.generator_cpu_stats = self.generator_cpu_stats
>> >- result_copy.receiver_cpu_stats = self.receiver_cpu_stats
>> >-
>> >- result_copy.generator_results = ParallelPerfResult()
>> >- result_copy.receiver_results = ParallelPerfResult()
>> >-
>> >- for stream in self.generator_results:
>> >- aligned_intervals = [
>> >- interval
>> >- for interval in stream
>> >- if interval.timestamp >= start and
interval.timestamp <= end
>> >- ]
>> >-
>> >-
result_copy.generator_results.append(SequentialPerfResult(aligned_intervals))
>> >-
>> >- for stream in self.receiver_results:
>> >- aligned_intervals = [
>> >- interval
>> >- for interval in stream
>> >- if interval.timestamp >= start and
interval.timestamp <= end
>> >- ]
>> >+ result_copy.generator_cpu_stats =
self.generator_cpu_stats.time_slice(start, end)
>> >+ result_copy.receiver_cpu_stats =
self.receiver_cpu_stats.time_slice(start, end)
>> >
>> >-
result_copy.receiver_results.append(SequentialPerfResult(aligned_intervals))
>> >+ result_copy.generator_results =
self.generator_results.time_slice(start, end)
>> >+ result_copy.receiver_results =
self.generator_results.time_slice(start, end)
>> >
>> > return result_copy
>> >
>> >diff --git a/lnst/RecipeCommon/Perf/Measurements/StatCPUMeasurement.py
b/lnst/RecipeCommon/Perf/Measurements/StatCPUMeasurement.py
>> >index 49aa262..c5b50fe 100644
>> >--- a/lnst/RecipeCommon/Perf/Measurements/StatCPUMeasurement.py
>> >+++ b/lnst/RecipeCommon/Perf/Measurements/StatCPUMeasurement.py
>> >@@ -28,26 +28,20 @@ def utilization(self):
>> >
>> > @property
>> > def start_timestamp(self):
>> >- return self._data["user"][0].timestamp
>> >+ return min([item.start_timestamp for item in self._data.values()])
>>
>> Although this seems to be a correct way to get the timestamp, the way
>> how StatCPUMeasurement is implemented does not require this.
>>
>> The timestamps are the same for all 'user', 'system',
'irq' etc for one
>> sample. That's why used the optimization before. I think you can do the
>> same.
>
>agreed, but if StatCPUMeasurement ever changes this may need to be
>updated and we could miss that, I'll do some profiling on this method to
>see how much of an optimization it really is and if it's worth it.
>
>-Ondrej
>
I completely agree. I'm ok with keeping this as-is. Let's see how the
profiling goes.
profiling outputs:
unoptimized version:
time_slice called 230 times -> 2969070 function calls in 1.011 seconds
end_timestamp called 230 times -> 8050 function calls in 0.003 seconds
start_timestamp called 230 times -> 5750 function calls in 0.002 seconds
optimized version:
time_slice called 240 times -> 3098160 function calls in 1.105 seconds
end_timestamp called 240 times -> 960 function calls in 0.000 seconds
start_timestamp called 240 times -> 720 function calls in 0.000 seconds
the 230 vs 240 times calls is probably influenced by some artifact in
the length of my tests (was using local vms and "faking" higher number
of cpu cores), but it should be close enough to create a relevant
comparison.
The important numbers are the function calls caused by calling each
function.
The "time_slice" call stays roughly the same - there's no code change or
optimization done on it.
Both end_timestamp and start_timestamp can be ~8 times faster when
looking at the number of function calls that each causes, however,
looking at the time spent on the execution, this is still a very minimal
difference.
As such I think we're ok with not optimizing this for now.
-Ondrej