perf: add annotations for non-concurrent cross-scoped duration measurements #13960

rojkov · 2020-11-10T09:37:42Z

Commit Message: perf: add annotations for non-concurrent cross-scoped duration measurements
Additional Description:
Risk Level: Low
Testing: updated unit tests
Docs Changes: N/A
Release Notes: N/A
Platform Specific Features: N/A
Fixes #13860

Signed-off-by: Dmitry Rozhkov <dmitry.rozhkov@intel.com>

antoniovicente · 2020-11-10T22:10:31Z

source/common/common/perf_annotation.cc

@@ -32,6 +32,23 @@ void PerfOperation::record(absl::string_view category, absl::string_view descrip
 // because the constructor is non-trivial due to the contained unordered_map.
 PerfAnnotationContext::PerfAnnotationContext() = default;

+void PerfAnnotationContext::begin(absl::string_view category, absl::string_view description) {
+  const CategoryDescription key = {std::string(category), std::string(description)};
+  RELEASE_ASSERT(!timestamps_map_.contains(key),


RELEASE_ASSERT use seems risky. Are these begin/end annotations meant to be used across event loop events or only within a single call stack?

Within a single call stack only unfortunately. Would be nice to have uniquely identifiable events in the event loop though. Is it possible?

I think it's OK to use RELEASE_ASSERT as this code will only be activated when the binary is compiled with perf annotation enabled.

And it wouldn't do any good to use ASSERT because you generally would want opt-builds for measuring performance.

There's a better way to do all of this: have an RAII object that is kept around for the duration of the perf operation and keeps the necessary state instead of keeping the state on a global as a string in a map.

It nicely solves the issue of concurrent performance measurements and works across call stacks.

Yeah for cases where RAII is OK, that works today with PERF_OPERATION which is just a wrapper that has all the code compile to nothing when perf annotations are not compiled in. I think that should be preferred when feasible to use.

I assume that PERF_BEGIN and PERF_END are where the plumbing needed to hold an object seems not worth it, and correlating by string seems worth it. It doesn't look to me like this adds any overhead when not used, so that's why I'm OK with this if it makes annotations easier to implement.

The cleanest way though is just for begin() to return an object that you store in your filter undef ifdef

A-ha, now I see. In this case the owning object (e.g. filter) needs to be annotated too. And it has to be the same for a pair of begin() and end(). Right?

Yeah though I think the logical next step of what I suggested is that rather than calling begin() you just instantiate an RAII object yourself, throwing it in an ifdef'd member variable in (say) the filter; maybe via unique_ptr, and destructing it works like end().

Understood, thanks!

Yes, exactly, ^ is what I'm proposing. I think we can make it so it compiles to nothing if annotations are not enabled.

Updated. Turned out it's enough to add a few new macros to achieve the same result.

jmarantz

nice. Just some trivial comments.

jmarantz · 2020-11-11T13:16:06Z

source/common/common/perf_annotation.cc

@@ -32,6 +32,23 @@ void PerfOperation::record(absl::string_view category, absl::string_view descrip
 // because the constructor is non-trivial due to the contained unordered_map.
 PerfAnnotationContext::PerfAnnotationContext() = default;

+void PerfAnnotationContext::begin(absl::string_view category, absl::string_view description) {
+  const CategoryDescription key = {std::string(category), std::string(description)};
+  RELEASE_ASSERT(!timestamps_map_.contains(key),


I think it's OK to use RELEASE_ASSERT as this code will only be activated when the binary is compiled with perf annotation enabled.

And it wouldn't do any good to use ASSERT because you generally would want opt-builds for measuring performance.

jmarantz · 2020-11-11T13:16:43Z

source/common/common/perf_annotation.cc

+  const CategoryDescription key = {std::string(category), std::string(description)};
+  const MonotonicTime end_time = currentTime();
+  const auto result = timestamps_map_.extract(key);
+  RELEASE_ASSERT(!result.empty(), "double perf measurement ending is disallowed!");


might as well include the category & description in this message and the RELEASE_ASSERT above.

jmarantz · 2020-11-11T13:19:07Z

source/common/common/perf_annotation.h

@@ -42,6 +42,31 @@
    perf.record(category, description);                                                            \
  } while (false)

+/**
+ * Initiates a duration measurement which can be finished in a different scope.
+ * Please note that this kind of measurements makes sense only in a strictly


s/this/these/
s/makes/make/

jmarantz · 2020-11-11T13:20:00Z

source/common/common/perf_annotation.h

+ * Initiates a duration measurement which can be finished in a different scope.
+ * Please note that this kind of measurements makes sense only in a strictly
+ * sequential flow, i.e. when a new stream isn't created until the current one
+ * is destroyed.


This in reference only to a particular combination of category and description, right?

jmarantz · 2020-11-11T13:21:54Z

test/common/common/perf_annotation_test.cc

+  { PERF_BEGIN("gamma", "4"); }
+  { PERF_BEGIN("sigma", "5"); }
+  { PERF_END("gamma", "4"); }
+  { PERF_END("sigma", "5"); }


Can you also add begin/end checking with same-category different-description and vice versa?

jmarantz · 2020-11-11T13:23:52Z

source/common/common/perf_annotation.h

+   * shown as separate columns in the generated output table. Before ending the
+   * measurement must be started first with a begin() call. The measurement can
+   * be started and ended in different scopes, but the flow of these start and
+   * stop points for the same category and description must be strictly sequential.


seems like you don't need to repeat all of this paragraph from above, but could just reference the doc in begin().

Signed-off-by: Dmitry Rozhkov <dmitry.rozhkov@intel.com>

jmarantz

@envoyproxy/senior-maintainers

This reverts commit c678883. Signed-off-by: Dmitry Rozhkov <dmitry.rozhkov@intel.com>

…asurements" This reverts commit 518b693. Signed-off-by: Dmitry Rozhkov <dmitry.rozhkov@intel.com>

Signed-off-by: Dmitry Rozhkov <dmitry.rozhkov@intel.com>

jmarantz

nice!

mattklein123 · 2020-11-20T18:33:20Z

Can you check coverage?

/wait

rojkov · 2020-11-23T09:27:38Z

/retest

repokitteh-read-only · 2020-11-23T09:27:43Z

Retrying Azure Pipelines:
Retried failed jobs in: envoy-presubmit

🐱

Caused by: a #13960 (comment) was created by @rojkov.

see: more, trace.

rojkov · 2020-11-23T10:43:58Z

Can you check coverage?

@mattklein123 Looks it was a CI glitch. Everything is Ok now.

mattklein123

Awesome!

…ements (envoyproxy#13960) Signed-off-by: Dmitry Rozhkov <dmitry.rozhkov@intel.com> Signed-off-by: Qin Qin <qqin@google.com>

perf: add annotations for sequential cross-scoped duration measurements

518b693

Signed-off-by: Dmitry Rozhkov <dmitry.rozhkov@intel.com>

antoniovicente requested a review from jmarantz November 10, 2020 22:10

antoniovicente assigned jmarantz Nov 10, 2020

antoniovicente reviewed Nov 10, 2020

View reviewed changes

antoniovicente requested a review from asraa November 10, 2020 22:14

antoniovicente assigned jmarantz and asraa and unassigned jmarantz Nov 10, 2020

jmarantz reviewed Nov 11, 2020

View reviewed changes

address review comments

c678883

Signed-off-by: Dmitry Rozhkov <dmitry.rozhkov@intel.com>

jmarantz previously approved these changes Nov 12, 2020

View reviewed changes

repokitteh-read-only bot added waiting:any and removed waiting:any labels Nov 12, 2020

mattklein123 added the waiting label Nov 12, 2020

mattklein123 self-assigned this Nov 12, 2020

rojkov added 2 commits November 19, 2020 15:46

Revert "address review comments"

d541df8

This reverts commit c678883. Signed-off-by: Dmitry Rozhkov <dmitry.rozhkov@intel.com>

Revert "perf: add annotations for sequential cross-scoped duration me…

74f9ff6

…asurements" This reverts commit 518b693. Signed-off-by: Dmitry Rozhkov <dmitry.rozhkov@intel.com>

rojkov dismissed jmarantz’s stale review via 15131ca November 20, 2020 08:22

repokitteh-read-only bot removed the waiting label Nov 20, 2020

rojkov added 3 commits November 20, 2020 10:24

add macros for owned perf operations

15131ca

Signed-off-by: Dmitry Rozhkov <dmitry.rozhkov@intel.com>

clarify macro description

964fbfe

Signed-off-by: Dmitry Rozhkov <dmitry.rozhkov@intel.com>

Merge remote-tracking branch 'upstream/master' into perf-annotations

9568a40

Signed-off-by: Dmitry Rozhkov <dmitry.rozhkov@intel.com>

jmarantz approved these changes Nov 20, 2020

View reviewed changes

repokitteh-read-only bot added the waiting label Nov 20, 2020

mattklein123 approved these changes Nov 23, 2020

View reviewed changes

mattklein123 merged commit ea10523 into envoyproxy:master Nov 23, 2020

qqustc pushed a commit to qqustc/envoy that referenced this pull request Nov 24, 2020

perf: add annotations for non-concurrent cross-scoped duration measur…

c6bc86a

…ements (envoyproxy#13960) Signed-off-by: Dmitry Rozhkov <dmitry.rozhkov@intel.com> Signed-off-by: Qin Qin <qqin@google.com>

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

perf: add annotations for non-concurrent cross-scoped duration measurements #13960

perf: add annotations for non-concurrent cross-scoped duration measurements #13960

rojkov commented Nov 10, 2020

antoniovicente Nov 10, 2020

rojkov Nov 11, 2020

jmarantz Nov 11, 2020

antoniovicente Nov 11, 2020

jmarantz Nov 11, 2020

rojkov Nov 16, 2020

jmarantz Nov 16, 2020

rojkov Nov 16, 2020

mattklein123 Nov 16, 2020

rojkov Nov 20, 2020

jmarantz left a comment

jmarantz Nov 11, 2020

jmarantz Nov 11, 2020

jmarantz Nov 11, 2020

jmarantz Nov 11, 2020

jmarantz Nov 11, 2020

jmarantz Nov 11, 2020

jmarantz left a comment

jmarantz left a comment

mattklein123 commented Nov 20, 2020

rojkov commented Nov 23, 2020

repokitteh-read-only bot commented Nov 23, 2020

rojkov commented Nov 23, 2020

mattklein123 left a comment

perf: add annotations for non-concurrent cross-scoped duration measurements #13960

perf: add annotations for non-concurrent cross-scoped duration measurements #13960

Conversation

rojkov commented Nov 10, 2020

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

jmarantz left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

jmarantz left a comment

Choose a reason for hiding this comment

jmarantz left a comment

Choose a reason for hiding this comment

mattklein123 commented Nov 20, 2020

rojkov commented Nov 23, 2020

repokitteh-read-only bot commented Nov 23, 2020

rojkov commented Nov 23, 2020

mattklein123 left a comment

Choose a reason for hiding this comment