Add debug log for slow config updates for GRPC subscriptions

docs/root/configuration/upstream/cluster_manager/cluster_stats.rst

@@ -94,6 +94,7 @@ Every cluster has a statistics tree rooted at *cluster.<name>.* with the followi
   update_attempt, Counter, Total attempted cluster membership updates by service discovery
   update_success, Counter, Total successful cluster membership updates by service discovery
   update_failure, Counter, Total failed cluster membership updates by service discovery
+  update_duration, Histogram, Amount of time spent updating configs
   update_empty, Counter, Total cluster membership updates ending with empty cluster load assignment and continuing with previous config
   update_no_rebuild, Counter, Total successful cluster membership updates that didn't result in any cluster load balancing structure rebuilds
   version, Gauge, Hash of the contents from the last successful API fetch

include/envoy/config/subscription.h

@@ -204,22 +204,23 @@ using SubscriptionPtr = std::unique_ptr<Subscription>;
 /**
  * Per subscription stats. @see stats_macros.h
  */
-#define ALL_SUBSCRIPTION_STATS(COUNTER, GAUGE, TEXT_READOUT)                                       \
+#define ALL_SUBSCRIPTION_STATS(COUNTER, GAUGE, TEXT_READOUT, HISTOGRAM)                            \
   COUNTER(init_fetch_timeout)                                                                      \
   COUNTER(update_attempt)                                                                          \
   COUNTER(update_failure)                                                                          \
   COUNTER(update_rejected)                                                                         \
   COUNTER(update_success)                                                                          \
   GAUGE(update_time, NeverImport)                                                                  \
   GAUGE(version, NeverImport)                                                                      \
+  HISTOGRAM(update_duration, Milliseconds)                                                         \
   TEXT_READOUT(version_text)
 
 /**
  * Struct definition for per subscription stats. @see stats_macros.h
  */
 struct SubscriptionStats {
   ALL_SUBSCRIPTION_STATS(GENERATE_COUNTER_STRUCT, GENERATE_GAUGE_STRUCT,
-                         GENERATE_TEXT_READOUT_STRUCT)
+                         GENERATE_TEXT_READOUT_STRUCT, GENERATE_HISTOGRAM_STRUCT)
 };
 
 } // namespace Config

source/common/config/grpc_subscription_impl.cc

@@ -1,5 +1,7 @@
 #include "common/config/grpc_subscription_impl.h"
 
+#include <chrono>
+
 #include "common/common/assert.h"
 #include "common/common/logger.h"
 #include "common/common/utility.h"
@@ -63,14 +65,37 @@ void GrpcSubscriptionImpl::onConfigUpdate(const std::vector<Config::DecodedResou
   // supply those versions to onConfigUpdate() along with the xDS response ("system")
   // version_info. This way, both types of versions can be tracked and exposed for debugging by
   // the configuration update targets.
+  auto start = dispatcher_.timeSource().monotonicTime();
   callbacks_.onConfigUpdate(resources, version_info);
+  std::chrono::milliseconds update_duration = std::chrono::duration_cast<std::chrono::milliseconds>(
+      dispatcher_.timeSource().monotonicTime() - start);
   stats_.update_success_.inc();
   stats_.update_attempt_.inc();
   stats_.update_time_.set(DateUtil::nowToMilliseconds(dispatcher_.timeSource()));
   stats_.version_.set(HashUtil::xxHash64(version_info));
   stats_.version_text_.set(version_info);
+  stats_.update_duration_.recordValue(update_duration.count());
   ENVOY_LOG(debug, "gRPC config for {} accepted with {} resources with version {}", type_url_,
             resources.size(), version_info);
+
+  if (update_duration > updateDurationLogThreshold()) {
+    // Figure out the total size of all resource names plus delimiters
+    int name_size = 0;
+    std::for_each(resources.begin(), resources.end(),
+                  [&name_size](const Config::DecodedResource& resource) {
+                    name_size += resource.name().size() + 2;
+                  });
+    std::string resource_names;
+    resource_names.reserve(name_size);
+    for (const auto& resource : resources) {
+      resource_names.append(resource.get().name());
+      if (&resource != &resources.back()) {
+        resource_names.append(", ");
+      }
+    }
+    ENVOY_LOG(debug, "gRPC config update took {} ms! Resources names: {}", update_duration.count(),
+              resource_names);
+  }
 }
 
 void GrpcSubscriptionImpl::onConfigUpdate(
@@ -79,11 +104,15 @@ void GrpcSubscriptionImpl::onConfigUpdate(
     const std::string& system_version_info) {
   disableInitFetchTimeoutTimer();
   stats_.update_attempt_.inc();
+  auto start = dispatcher_.timeSource().monotonicTime();
   callbacks_.onConfigUpdate(added_resources, removed_resources, system_version_info);
+  std::chrono::milliseconds update_duration = std::chrono::duration_cast<std::chrono::milliseconds>(
+      dispatcher_.timeSource().monotonicTime() - start);
   stats_.update_success_.inc();
   stats_.update_time_.set(DateUtil::nowToMilliseconds(dispatcher_.timeSource()));
   stats_.version_.set(HashUtil::xxHash64(system_version_info));
   stats_.version_text_.set(system_version_info);
+  stats_.update_duration_.recordValue(update_duration.count());
 }
 
 void GrpcSubscriptionImpl::onConfigUpdateFailed(ConfigUpdateFailureReason reason,
@@ -121,5 +150,12 @@ void GrpcSubscriptionImpl::disableInitFetchTimeoutTimer() {
   }
 }
 
+// Returns the threshold used to trigger logging of long config updates.
+// TODO(adamsjob): make the threshold configurable, either through runtime or bootstrap
+std::chrono::milliseconds& GrpcSubscriptionImpl::updateDurationLogThreshold() {
+  static std::chrono::milliseconds* threshold_ms = new std::chrono::milliseconds(50);
+  return *threshold_ms;
+}
+
 } // namespace Config
 } // namespace Envoy

source/common/config/grpc_subscription_impl.h

@@ -1,5 +1,6 @@
 #pragma once
 
+#include <chrono>
 #include <memory>
 
 #include "envoy/config/grpc_mux.h"
@@ -42,6 +43,7 @@ class GrpcSubscriptionImpl : public Subscription,
 
 private:
   void disableInitFetchTimeoutTimer();
+  std::chrono::milliseconds& updateDurationLogThreshold();
 
   GrpcMuxSharedPtr grpc_mux_;
   SubscriptionCallbacks& callbacks_;

source/common/config/utility.h

@@ -14,6 +14,7 @@
 #include "envoy/server/filter_config.h"
 #include "envoy/stats/histogram.h"
 #include "envoy/stats/scope.h"
+#include "envoy/stats/stats_macros.h"
 #include "envoy/stats/stats_matcher.h"
 #include "envoy/stats/tag_producer.h"
 #include "envoy/upstream/cluster_manager.h"
@@ -205,8 +206,8 @@ class Utility {
    * @return SubscriptionStats for scope.
    */
   static SubscriptionStats generateStats(Stats::Scope& scope) {
-    return {
-        ALL_SUBSCRIPTION_STATS(POOL_COUNTER(scope), POOL_GAUGE(scope), POOL_TEXT_READOUT(scope))};
+    return {ALL_SUBSCRIPTION_STATS(POOL_COUNTER(scope), POOL_GAUGE(scope), POOL_TEXT_READOUT(scope),
+                                   POOL_HISTOGRAM(scope))};
   }
 
   /**