added histogram latency information to Hystrix dashboard stream by trabetti · Pull Request #3986 · envoyproxy/envoy

trabetti · 2018-07-30T07:45:25Z

Signed-off-by: trabetti talis@il.ibm.com

Description: Adding the latency information from existing histogram to Hystrix event stream that was added in #3425
Risk Level: Low
Testing:
Docs Changes: admin.rst
Release Notes: No addition to release note of original Hystrix stream PR, which is still pending for 1.8.0
Fixes #3753

Signed-off-by: trabetti <talis@il.ibm.com>

trabetti · 2018-07-30T07:53:51Z

Adding timing information from upstream_rq_time histogram.
This may not be the most elegant implementation, Please let me know if I am missing a better way to access the histograms.
some issues/questions:

I am missing information about mean request latency. Is there such information anywhere?
The histograms holds values from last flush or cumulative since the beginning of the cluster activity. I used the cumulative, although the Hystrix dashboard expect last minute data (I think). Not sure if it is a correct decision. Will it mask problems? I didn't want to get into calculations of intermediate values (if possible at all).
Envoy holds percentile 99.9 while Hystrix dashboard expects 99.5. I don't think it really matters so I used the 99.9 for 99.5. Alternatively, could approximate by an average of 99 and 99.9.

trabetti · 2018-07-30T08:12:08Z

preview

mattklein123 · 2018-07-30T18:25:23Z

@mrice32 @jmarantz you mind taking a pass?

mrice32

Awesome! Thanks for working on this!! Some general comments. In general, we seem to be creating a bunch of temporary strings in the concatenation process. It would be nice to refactor to try and concatenate everything directly to the underlying stringstream if you think that's doable. But it might make sense to save this refactor for a later PR.

mrice32 · 2018-07-31T18:38:43Z

source/extensions/stat_sinks/hystrix/hystrix.cc

  out_str << std::endl;
 }

+std::string ClusterStatsCache::printTimingHistogram() {


Can we make this addHistogramToStream and let it take in a stringstream?

mrice32 · 2018-07-31T18:42:44Z

source/extensions/stat_sinks/hystrix/hystrix.cc

+      std::unordered_map<std::string, double> hist_map;
+      for (size_t i = 0; i < histogram->cumulativeStatistics().supportedQuantiles().size(); ++i) {
+        if (histogram->cumulativeStatistics().supportedQuantiles()[i] == 0.999) {
+          // Envoy provide 99.9 percentile, while Hystrix shows 99.5, so there is a small


Why can't we just add that to the supported quantiles? It seems like a reasonable percentile to care about.

I guess we can? I have no idea if this will effect anything else.. I'll try and see if any test fails.

mrice32 · 2018-07-31T18:49:19Z

source/extensions/stat_sinks/hystrix/hystrix.cc

+    // i.e. "cluster.service1.upstream_rq_time".
+    std::vector<std::string> split_name = absl::StrSplit(histogram->name(), ".");
+    if (split_name[0] == "clusters" && split_name[2] == "upstream_rq_time") {
+      std::unordered_map<std::string, double> hist_map;


Can we avoid the copy later by doing the following:

std::unordered_map<std::string, double>& hist_map = time_histograms[split_name[1]];

mrice32 · 2018-07-31T18:51:50Z

source/extensions/stat_sinks/hystrix/hystrix.cc

+  for (const Stats::ParentHistogramSharedPtr histogram : server_.stats().histograms()) {
+    // histogram->name() on clusters of the format "cluster.cluster_name.histogram_name"
+    // i.e. "cluster.service1.upstream_rq_time".
+    std::vector<std::string> split_name = absl::StrSplit(histogram->name(), ".");


If you set the return type to std::vector<absl::string_view> (weird StrSplit return type allows casting to a bunch of different types), this won't require us to do a bunch of string copies.

Also, I think it's slightly better to pass in the the delimiter as a char ('.') rather than a string (really it's a char*) if it's only a single character because it will allow the library to choose a non-multi character overload.

mrice32 · 2018-07-31T19:36:47Z

source/extensions/stat_sinks/hystrix/hystrix.h

  RollingWindow timeouts_;
  RollingWindow rejected_;
+
+  std::unordered_map<std::string, double> timing_;


Why do we need this to be cached if we're just going to regenerate the map each time?

Also, why not make this a double to double instead by storing the quantile as a double rather than a string?

Why do we need this to be cached if we're just going to regenerate the map each time?

I still have an open question if it worth to do any kind of calculation over the percentile values, instead of giving the values since the beginning of the cluster's operation. Otherwise, I can pass it directly without using the cache.

why not make this a double to double instead by storing the quantile as a double rather than a string?

Just to overcome the inconsistent representation - "99.5" vs. all other values which are integers (25, 50, 99, etc..), and if I pass them as doubles, dashboard do not accept. It was convenient to handle this here.

This is just mapping "99.5" to 99.5? and "25" to 25.0?

Unless there's a big efficiency issue I'd vote for doing this type coercion closer to where it's consumed. Otherwise commenting why you are doing this would be really helpful.

It is mapping the string representation of the quantile to its current value from the histogram

I don't mean in the PR; comments; I mean adding comments in the code. Document both what it's doing and also why you think this is helpful from a code-structure or performance perspective.

Signed-off-by: trabetti <talis@il.ibm.com>

jmarantz · 2018-08-02T12:30:54Z

docs/root/operations/admin.rst

    load balancer pool, but requests are not rejected as a result. Therefore, this counter is always 
    set to '0'.
-  * Latency information is currently unavailable.
+  * Latency information represent cumulative data from start of the clusters operation. 


s/represent/represents/
s/start/the start/

jmarantz · 2018-08-02T12:40:10Z

source/extensions/stat_sinks/hystrix/hystrix.h

  RollingWindow timeouts_;
  RollingWindow rejected_;
+
+  std::unordered_map<std::string, double> timing_;


This is just mapping "99.5" to 99.5? and "25" to 25.0?

Unless there's a big efficiency issue I'd vote for doing this type coercion closer to where it's consumed. Otherwise commenting why you are doing this would be really helpful.

jmarantz · 2018-08-02T12:41:20Z

source/extensions/stat_sinks/hystrix/hystrix.cc


+void ClusterStatsCache::addHistogramToStream(std::stringstream& ss) {
+  bool is_first = true;
+  for (std::pair<std::string, double> element : timing_) {


const std::pair<std::string, double>&

jmarantz · 2018-08-02T12:42:48Z

source/extensions/stat_sinks/hystrix/hystrix.cc

 void HystrixSink::updateRollingWindowMap(const Upstream::ClusterInfo& cluster_info,
-                                         ClusterStatsCache& cluster_stats_cache) {
+                                         ClusterStatsCache& cluster_stats_cache,
+                                         std::unordered_map<std::string, double>& histogram) {


can we have a 'using' shortcut for this map type, declared in the HystrixSink scope, I think.

jmarantz · 2018-08-02T12:43:55Z

source/extensions/stat_sinks/hystrix/hystrix.cc

+  ss << ", \"latencyExecute\": {";
+  cluster_stats_cache.addHistogramToStream(ss);
+  ss << "}";
+  // addInfoToStream("latencyExecute", "{" + cluster_stats_cache.printTimingHistogram() + "}", ss);


remove this line?

jmarantz · 2018-08-02T12:45:42Z

source/extensions/stat_sinks/hystrix/hystrix.cc

+    // histogram->name() on clusters of the format "cluster.cluster_name.histogram_name"
+    // i.e. "cluster.service1.upstream_rq_time".
+    const std::vector<absl::string_view> split_name = absl::StrSplit(histogram->name(), '.');
+    if (split_name[0] == "cluster" && split_name[2] == "upstream_rq_time") {


check split_name.size()>2 first

Do you mean there could be a case where the histogram name is made up of more parts?

more parts would be OK. less parts would crash. I would prefer to be locally paranoid and have an assertion rather than a SEGV if that occurs.

jmarantz · 2018-08-02T12:48:51Z

source/extensions/stat_sinks/hystrix/hystrix.cc

+                      histogram->cumulativeStatistics().supportedQuantiles()[i]) !=
+            hystrix_quantiles.end()) {
+          if (histogram->cumulativeStatistics().supportedQuantiles()[i] == 0.995) {
+            hist_map["99.5"] = histogram->cumulativeStatistics().computedQuantiles()[i];


why does this require special-casing? add comment in code.

jmarantz · 2018-08-02T12:49:48Z

source/extensions/stat_sinks/hystrix/hystrix.cc

+      std::unordered_map<std::string, double>& hist_map = time_histograms[split_name[1]];
+      for (size_t i = 0; i < histogram->cumulativeStatistics().supportedQuantiles().size(); ++i) {
+        if (std::find(hystrix_quantiles.begin(), hystrix_quantiles.end(),
+                      histogram->cumulativeStatistics().supportedQuantiles()[i]) !=


Can you make a temp ref for supportedQuartiles()? Would make this long std::find call easier to read.

jmarantz · 2018-08-02T12:51:02Z

source/extensions/stat_sinks/hystrix/hystrix.cc

+      for (size_t i = 0; i < histogram->cumulativeStatistics().supportedQuantiles().size(); ++i) {
+        if (std::find(hystrix_quantiles.begin(), hystrix_quantiles.end(),
+                      histogram->cumulativeStatistics().supportedQuantiles()[i]) !=
+            hystrix_quantiles.end()) {


Should there be handling for a case where the find() fails?

doesn't it suppose to return hystrix_quantiles.end() if it fails?

Of course, but is that expected? Should you handle that case?

mrice32 · 2018-08-02T19:47:58Z

source/extensions/stat_sinks/hystrix/hystrix.cc

-      "latencyExecute",
-      "{\"0\":0,\"25\":0,\"50\":0,\"75\":0,\"90\":0,\"95\":0,\"99\":0,\"99.5\":0,\"100\":0}", ss);
+  ss << ", \"latencyExecute\": {";
+  cluster_stats_cache.addHistogramToStream(ss);


Why not pass the key into the method as a string_view as you do for the others? This would allow the method to handle the brackets, etc. You can still concatenate them directly to the underlying stringstream directly IIUC.

Signed-off-by: trabetti <talis@il.ibm.com>

mrice32 · 2018-08-03T20:10:36Z

source/extensions/stat_sinks/hystrix/hystrix.cc

+            hystrix_quantiles.end()) {
+          if (supported_quantiles[i] == 0.995) {
+            // The only non int quantile value
+            hist_map["99.5"] = histogram->cumulativeStatistics().computedQuantiles()[i];


What's the Hystrix formatting requirement for these strings? Could we possibly take advantage of sprintf formatting options to format all of them the same way instead of using an if statement?

only the 99.5 is not an int. all others are integers and it didn't work when i tried sending these as double.
{"95": 12.500000, "100": 16000.000000, "99": 15300.000000, "90": 7.100000, "0": 1.000000, "99.5": 15650.000000, "25": 1.060345, "50": 2.040000, "75": 3.070833}

What are the requirements? Would "95.0" be okay? Or does it have to be exactly "95"? There are some float formatting options in sprintf that allow you to limit the number of decimals on floats, which might allow you to get what you want without the if statement.

sprintf with %g might do what you want. But are you using that? Or fmt::format?

Also you might want to consider using integers scaled by 10.

amazing, you have the solution for everything 😀 it worked. I am keeping it as a double to make it more clear, does it improve a lot to scale by 10 and use integer?

mrice32 · 2018-08-03T20:41:16Z

source/extensions/stat_sinks/hystrix/hystrix.cc

  Upstream::ClusterManager::ClusterInfoMap clusters = server_.clusterManager().clusters();
+
+  // Save a map of the relevant histograms per cluster in a convenient format.
+  std::unordered_map<absl::string_view, std::unordered_map<std::string, double>, StringViewHash>


Using a string_view as the key for a map is a little dangerous. You need to be sure that the string that's being used to generate the string_view lasts longer than that element in the map. This is mostly true here, but I think there's a small edge case where it might be possible to cause a segfault. You're grabbing a vector of histogram shared pointers, but that goes away at the end of the scope, which means it's possible for one of the histograms that's holding one of the referenced strings to be destroyed by the time you do the lookup in the map. I'd suggest just using a regular string as the key.

Also, can't we use QuantileLatencyMap here instead of typing out the entire type?

mrice32 · 2018-08-03T21:20:53Z

source/extensions/stat_sinks/hystrix/hystrix.cc

+  // Save a map of the relevant histograms per cluster in a convenient format.
+  std::unordered_map<absl::string_view, std::unordered_map<std::string, double>, StringViewHash>
+      time_histograms;
+  for (const Stats::ParentHistogramSharedPtr histogram : server_.stats().histograms()) {


nit: I think we should be using the Stats::Source::cachedHistograms() method on the Source that's being passed in (

envoy/include/envoy/stats/stats.h

Line 301 in 3460595

virtual const std::vector<ParentHistogramSharedPtr>& cachedHistograms() PURE;

) to get the histograms.

…lative extreme values stay forever, real problems can't be distinguihsed from temporary Signed-off-by: trabetti <talis@il.ibm.com>

mrice32

This looks good! LGTM once the comments below are resolved.

mrice32 · 2018-08-06T15:12:51Z

source/extensions/stat_sinks/hystrix/hystrix.cc

  Upstream::ClusterManager::ClusterInfoMap clusters = server_.clusterManager().clusters();
+
+  // Save a map of the relevant histograms per cluster in a convenient format.
+  std::unordered_map<std::string, QuantileLatencyMap, StringViewHash> time_histograms;


Why do you need the StringViewHash template argument?

Leftover from when it was absl::string_view..

mrice32 · 2018-08-06T15:18:21Z

source/extensions/stat_sinks/hystrix/hystrix.h

  RollingWindow rejected_;
+
+  // Map string representation of the quantile to its recently read value from the histogram
+  QuantileLatencyMap timing_;


Have we decided whether we need to store this between flushes? My vote would be to not store it until we implement the use-case for it.

… out of cache Signed-off-by: trabetti <talis@il.ibm.com>

mrice32

Are we testing this new feature?

mrice32 · 2018-08-07T21:43:56Z

source/extensions/stat_sinks/hystrix/hystrix.cc

+    // histogram->name() on clusters of the format "cluster.cluster_name.histogram_name"
+    // i.e. "cluster.service1.upstream_rq_time".
+    const std::vector<std::string> split_name = absl::StrSplit(histogram->name(), '.');
+    if (split_name.size() >= 2 && split_name[0] == "cluster" &&


I just realized that you're essentially repeating work already done by Envoy. Rather than manually parsing the string, you could check the tag and tag_extracted_name since Envoy parses those for you. It may be a bit more code, but I think it's a bit safer since the regexes are a little more specific than splitting on .. It's up to you if you'd rather use it or not, but I figured I'd present the alternative. For example (this may not compile since I haven't tried, but the rough idea is there :) ):

if (histogram->tag_extracted_name() == "cluster.upstream_rq_time") { // TODO(mrice32): add an Envoy utility function to look up and return a tag for a metric. auto it = std::find_if(histogram->tags().begin(), histogram->tags().end(), [](const Stats::Tag& tag) { return tag.name_ == Config::TagNames::get().CLUSTER_NAME; }); // Should always be true, so we probably want to log or something if not. if (it == histogram.tags().end()) { // We didn't find the cluster name despite finding the correct stat. } else { QuantileLatencyMap& hist_map = time_histograms[it->value_]; ... } }

I don't know if we should log if a cluster_name tag is not found. What could be the reason? Anything the user can do about it? If not, I think we can just verify it is not histogram.tags().end().

I think it would imply that something is broken since we expect that this should never happen. I wouldn't say it's a catastrophic failure, so it's not a crashable event, but logging an error to the console might catch someone's attention so that they could file a bug against Envoy. I'm not super opinionated, so it's ultimately up to you.

IMO this is what ASSERT is for. It should stop tests from passing so you can investigate. I suspect a log would just slow things down and no one would notice.

+1 for ASSERT

mrice32 · 2018-08-07T21:46:58Z

source/extensions/stat_sinks/hystrix/hystrix.cc

+  for (const Stats::ParentHistogramSharedPtr histogram : source.cachedHistograms()) {
+    // histogram->name() on clusters of the format "cluster.cluster_name.histogram_name"
+    // i.e. "cluster.service1.upstream_rq_time".
+    const std::vector<std::string> split_name = absl::StrSplit(histogram->name(), '.');


This can still be a vector of string_views. If we need to put them into a map, it's easy to convert them when needed. This means we only need to store them as strings if we need them to be permanent.

took your suggestion to use tags, removed this vector.

mrice32 · 2018-08-07T21:52:31Z

source/extensions/stat_sinks/hystrix/hystrix.cc

+    const std::vector<std::string> split_name = absl::StrSplit(histogram->name(), '.');
+    if (split_name.size() >= 2 && split_name[0] == "cluster" &&
+        split_name[2] == "upstream_rq_time") {
+      QuantileLatencyMap& hist_map = time_histograms[split_name[1]];


Don't we only expect to do this emplacement once per flush? What happens if you get multiple histograms that happen to satisfy your format checks and produce the same cluster name on the same flush (because of the dynamic nature of stats strings, things like this are always possible :) )? Won't the second overwrite the first? How do you want to handle that case?

If you want to do something other than overwrite, this case can be checked pretty easily by using time_histograms.emplace() and checking the return value. See http://www.cplusplus.com/reference/unordered_map/unordered_map/emplace/.

I think there's no problem with overwriting. We want to show latency information in dashboard, it doesn't have to be exact data. If there is an extreme value (very high latency) it could be either a temporary situation that has already recovered, or a consistent problem the user wants to find and fix. In the case it was temporary, if we missed it because of the overwrite, it doesn't matter. If it is consistent, user will see it on next flush.

That makes sense. I think overwriting is fine. However, it seems like the code assumes that each cluster should only have one histogram that matches this filter (a pretty good assumption IMO). If there's another histogram that somehow gets inside the if statement, it might be worthwhile to log an error because it means that something is probably broken here. WDYT?

no problem, I can log in both cases, can you point me to a similar example?

assert here too?

mrice32 · 2018-08-07T21:53:21Z

source/extensions/stat_sinks/hystrix/hystrix.h

  void printToStream(std::stringstream& out_str);
  void printRollingWindow(absl::string_view name, RollingWindow rolling_window,
                          std::stringstream& out_str);
+


blank line?

jmarantz

Generally looks good; just a few nits remaining.

jmarantz · 2018-08-08T13:32:11Z

source/extensions/stat_sinks/hystrix/hystrix.cc

+    // histogram->name() on clusters of the format "cluster.cluster_name.histogram_name"
+    // i.e. "cluster.service1.upstream_rq_time".
+    const std::vector<std::string> split_name = absl::StrSplit(histogram->name(), '.');
+    if (split_name.size() >= 2 && split_name[0] == "cluster" &&


split_name.size() > 2

You are looking at split_name[2] so if size==2 that's a crasher.

changed the code to use tags instead of this split, following @mrice32's suggestion

jmarantz · 2018-08-08T13:35:59Z

source/extensions/stat_sinks/hystrix/hystrix.cc

+      const std::vector<double>& supported_quantiles =
+          histogram->cumulativeStatistics().supportedQuantiles();
+      for (size_t i = 0; i < supported_quantiles.size(); ++i) {
+        if (std::find(hystrix_quantiles.begin(), hystrix_quantiles.end(), supported_quantiles[i]) !=


is hystrix_quantiles sorted? If so, binary-search (via std::lower_bound and an equality-test) might be faster, but it's probably a small enough N that it isn't a big deal I guess. Still it's worth a comment that this is a deliberate choice. E.g.

// binary-search here is likely not worth it, as hystrix_quantiles has <10 elements.

jmarantz · 2018-08-08T13:38:31Z

source/extensions/stat_sinks/hystrix/hystrix.h

+  static void addIntToStream(absl::string_view key, uint64_t value, std::stringstream& info,
+                             bool is_first = false);
+
+  static void addHistogramToStream(QuantileLatencyMap latency_map, absl::string_view key,


const QuantileLatencyMap&

jmarantz · 2018-08-08T13:38:44Z

source/extensions/stat_sinks/hystrix/hystrix.cc

  out_str << std::endl;
 }

+void HystrixSink::addHistogramToStream(QuantileLatencyMap latency_map, absl::string_view key,


const QuantileLatencyMap&

jmarantz · 2018-08-08T13:39:20Z

source/extensions/stat_sinks/hystrix/hystrix.cc

+                                       std::stringstream& ss) {
+  ss << ", \"" << key << "\": {";
+  bool is_first = true;
+  for (const std::pair<double, double> element : latency_map) {


const std::pair<double, double>&

Signed-off-by: trabetti <talis@il.ibm.com>

trabetti · 2018-08-08T20:43:58Z

Pushed a new version with fixes. Will look at testing tomorrow.

mrice32

LGTM other than a few small comments and missing tests.

mrice32 · 2018-08-09T14:23:56Z

source/extensions/stat_sinks/hystrix/hystrix.h

                               uint64_t reporting_hosts,
-                               std::chrono::milliseconds rolling_window_ms, std::stringstream& ss);
+                               std::chrono::milliseconds rolling_window_ms,
+                               QuantileLatencyMap& histogram, std::stringstream& ss);


nit: can we make this const?

mrice32 · 2018-08-09T14:25:14Z

source/extensions/stat_sinks/hystrix/hystrix.cc

                                          uint64_t reporting_hosts,
                                          std::chrono::milliseconds rolling_window_ms,
-                                          std::stringstream& ss) {
+                                          QuantileLatencyMap& histogram, std::stringstream& ss) {


nit: can we make this const?

mrice32 · 2018-08-09T14:25:42Z

source/extensions/stat_sinks/hystrix/hystrix.cc

                                    uint64_t max_concurrent_requests, uint64_t reporting_hosts,
                                    std::chrono::milliseconds rolling_window_ms,
-                                    std::stringstream& ss) {
+                                    QuantileLatencyMap& histogram, std::stringstream& ss) {


nit: const?

mrice32 · 2018-08-09T14:26:27Z

source/extensions/stat_sinks/hystrix/hystrix.h

  void addHystrixCommand(ClusterStatsCache& cluster_stats_cache, absl::string_view cluster_name,
                         uint64_t max_concurrent_requests, uint64_t reporting_hosts,
-                         std::chrono::milliseconds rolling_window_ms, std::stringstream& ss);
+                         std::chrono::milliseconds rolling_window_ms, QuantileLatencyMap& histogram,


nit: const QuantileLatencyMap&?

mrice32 · 2018-08-09T14:42:15Z

source/extensions/stat_sinks/hystrix/hystrix.cc

+      // Make sure we found the cluster name tag
+      ASSERT(it != histogram->tags().end());
+      // Make sure histogram with this name was not already added
+      ASSERT(time_histograms.find(it->value_) == time_histograms.end());


I think we can refactor to remove the double lookup:

auto it_bool_pair = time_histograms.emplace(std::make_pair(it->value_, QuantileLatencyMap())); // Make sure histogram with this name was not already added ASSERT(it_bool_pair.second); QuantileLatencyMap& hist_map = it_bool_pair.first->second;

Is it safe to do it->value_ in the std::make_pair without the assert first?

Should be, depending on your definition of 'safe' :). A false return in it_bool_pair.second just means an entry was already in the map for the specified key. In that case, the assert will fire and you'll crash. Is that safe?

Are we sure that duplicates are not possible?

Signed-off-by: trabetti <talis@il.ibm.com>

trabetti · 2018-08-16T06:07:21Z

Any updates? Thanks!

mrice32

A few nits. LGTM. Passing it to @jmarantz and a maintainer for final review.

mrice32 · 2018-08-16T16:40:10Z

source/extensions/stat_sinks/hystrix/hystrix.cc

+                             });
+
+      // Make sure we found the cluster name tag
+      ASSERT(it != histogram->tags().end()); // Can remove this??


Why the "Can remove this??" comment?

to ask you if that's what you meant

mrice32 · 2018-08-16T16:44:51Z

test/extensions/stats_sinks/hystrix/hystrix_test.cc

+  // Data was added such that the value equals the quantile:
+  // "latencyExecute": {"99.5": 99.500000, "95": 95.000000, "90": 90.000000, "100": 100.000000, "0":
+  // 0.000000, "25": 25.000000, "99": 99.000000, "50": 50.000000, "75": 75.000000}.
+  for (auto it = begin(hystrix_quantiles); it != end(hystrix_quantiles); ++it) {


nit: why not a simpler range-based loop:

for (const double quantile : hystrix_quantiles) { ...

jmarantz

lgtm modulo Matt's comments.

Signed-off-by: trabetti <talis@il.ibm.com>

trabetti · 2018-08-23T06:26:46Z

Any idea why the intervalStatistics histogram latency data for lower quantiles is almost always '0' or nan?

curl -v 172.18.0.3:8001/stats | grep -v external | grep upstream_rq_time 
cluster.service1.upstream_rq_time: P0(0,0) P25(0,0) P50(0,0) P75(0,0) P90(0,0) P95(1.02355,1.02746) P99(1.09313,1.09932) P99.5(3.03475,3.0282) P99.9(15.339,13.623) P100(16,29)
cluster.service2.upstream_rq_time: P0(0,0) P25(0,0) P50(0,0) P75(0,0) P90(1.005,1.0693) P95(1.065,1.09984) P99(15520,15045) P99.5(15760,15522.5) P99.9(15952,15904.5) P100(16000,16000)
cluster.service3.upstream_rq_time: P0(nan,1) P25(nan,1.05) P50(nan,1.1) P75(nan,2.074) P90(nan,14150) P95(nan,15075) P99(nan,15815) P99.5(nan,15907.5) P99.9(nan,15981.5) P100(nan,16000)
cluster.service_slow.upstream_rq_time: P0(nan,1) P25(nan,1.1) P50(nan,3.1) P75(nan,5.1) P90(nan,14200) P95(nan,14600) P99(nan,14920) P99.5(nan,14960) P99.9(nan,14992) P100(nan,15000)

@ramaraochavali maybe you know?

…rd freezes with stale values + sync to upstream and resolved conflicts Signed-off-by: trabetti <talis@il.ibm.com>

Signed-off-by: trabetti <talis@il.ibm.com>

ramaraochavali · 2018-08-23T10:02:58Z

@trabetti Nan indicates that the value has not been updated during the interval. 0 probably is because the value is so low - that is how histogram has evaluated the value for that quantile. Do you know the raw values?

trabetti · 2018-08-23T10:14:55Z

thanks @ramaraochavali , i don't have raw values but that makes sense. By the way, is there any reasonable way for me to calculate histogram of accumulated latency values across several flush intervals (e.g. i want to accumulate and show accumulated data of the last 10 intervals)?

ramaraochavali · 2018-08-23T10:36:44Z

No. There is no way currently that gives the accumulated value of last n flush cycles. It has only values computed in that the interval or from envoy start.

trabetti · 2018-08-23T10:55:35Z

@ramaraochavali I thought so.. thanks for confirming.

Signed-off-by: trabetti <talis@il.ibm.com>

trabetti · 2018-08-28T09:04:40Z

Hi, can we finish with this one? (or are you all on vacations..?) Thanks!

dnoe · 2018-08-28T11:53:10Z

Sorry, this dropped off my radar. Thanks for all the hard work - assigning @htuch for senior review.

htuch

Looks good, mostly a nits pass.

htuch · 2018-08-28T16:34:54Z

source/extensions/stat_sinks/hystrix/hystrix.cc

+void HystrixSink::addHistogramToStream(const QuantileLatencyMap& latency_map, absl::string_view key,
+                                       std::stringstream& ss) {
+  ss << ", \"" << key << "\": {";
+  bool is_first = true;


This seems a place where a join operation would make sense, but I can see that there is already a stylized approach to building these strings in this code.

Do you want me to consider changing the code to use join?

Up to you, TODO is fine as well.

htuch · 2018-08-28T16:38:13Z

source/extensions/stat_sinks/hystrix/hystrix.cc

+
+  // Save a map of the relevant histograms per cluster in a convenient format.
+  std::unordered_map<std::string, QuantileLatencyMap> time_histograms;
+  for (const Stats::ParentHistogramSharedPtr histogram : source.cachedHistograms()) {


Nit: should this be const Stats::ParentHistogramSharedPtr&, since we don't want to take an additional refcount in the body below?

htuch · 2018-08-28T16:38:50Z

source/extensions/stat_sinks/hystrix/hystrix.cc

+  // Save a map of the relevant histograms per cluster in a convenient format.
+  std::unordered_map<std::string, QuantileLatencyMap> time_histograms;
+  for (const Stats::ParentHistogramSharedPtr histogram : source.cachedHistograms()) {
+    if (histogram->tagExtractedName() == "cluster.upstream_rq_time") {


Should we be hardcoding strings like this? @mrice32 do we have a better way of handling this?

Did not find anything searching the code

htuch · 2018-08-28T16:39:30Z

source/extensions/stat_sinks/hystrix/hystrix.cc

+                             });
+
+      // Make sure we found the cluster name tag
+      ASSERT(it != histogram->tags().end());


Is this guaranteed? I.e. is this truly an invariant, or should we have error handling behavior?

we discussed it here #3986 (comment)

htuch · 2018-08-28T16:40:00Z

source/extensions/stat_sinks/hystrix/hystrix.cc

+        // binary-search here is likely not worth it, as hystrix_quantiles has <10 elements.
+        if (std::find(hystrix_quantiles.begin(), hystrix_quantiles.end(), supported_quantiles[i]) !=
+            hystrix_quantiles.end()) {
+          double value = histogram->intervalStatistics().computedQuantiles()[i];


Nit: const double

htuch · 2018-08-28T16:40:11Z

source/extensions/stat_sinks/hystrix/hystrix.cc

+  ss << ", \"" << key << "\": {";
+  bool is_first = true;
+  for (const std::pair<double, double>& element : latency_map) {
+    std::string quantile = fmt::sprintf("%g", element.first * 100);


Nit: const std::string

htuch · 2018-08-28T16:41:14Z

test/extensions/stats_sinks/hystrix/hystrix_test.cc

  }

+  histogram_t* makeHistogram(const std::vector<uint64_t>& values) {
+    histogram_t* histogram = hist_alloc(); // The histogram needs to be freed later


Should we have a RAII wrapper for this?

is it something like

class HistogramWrapper { public: HistogramWrapper() { histogram = hist_alloc(); } ~HistogramWrapper() { hist_free(histogram); } histogram_t* histogram; };

and

HistogramWrapper hist1_interval;

Yes; if you use hist_alloc() in other places in your source, I recommend the same pattern.

I don't, but I am tempted to use it in the test I borrowed from, thread_local_store_test.

Signed-off-by: trabetti <talis@il.ibm.com>

trabetti · 2018-08-28T21:53:43Z

@htuch pushed a new version with fixes to your comments.

htuch

LGTM modulo tiny nits.

htuch · 2018-08-29T02:08:49Z

test/common/stats/thread_local_store_test.cc

+  }
+
+private:
+  histogram_t* histogram;


Tiny nit: s/histogram/histogram_/

htuch · 2018-08-29T02:09:08Z

test/common/stats/thread_local_store_test.cc


+class HistogramWrapper {
+public:
+  HistogramWrapper() { histogram = hist_alloc(); }


Tiny nit: HIstogramWrapper() : histogram_(hist_alloc()) {}

htuch · 2018-08-29T02:09:48Z

test/extensions/stats_sinks/hystrix/hystrix_test.cc

+
+  const histogram_t* getHistogram() { return histogram; }
+
+  void initHistogram(const std::vector<uint64_t>& values) {


Why not in constructor?

Just since it can be called several times to set different values (IIUC). Although we don't do that in code. So maybe I'll change the name to setHistogramValues

Signed-off-by: trabetti <talis@il.ibm.com>

trabetti · 2018-08-29T18:56:33Z

fixed comments in 3d6395a

htuch

Thanks!

Pulling the following changes from github.com/envoyproxy/envoy: f936fc6 ssl: serialize accesses to SSL socket factory contexts (envoyproxy#4345) e34dcd6 Fix crash in tcp_proxy (envoyproxy#4323) ae6a252 router: fix matching when all domains have wildcards (envoyproxy#4326) aa06142 test: Stop fake_upstream methods from accidentally succeeding (envoyproxy#4232) 5d73187 rbac: update the authenticated.user to a StringMatcher. (envoyproxy#4250) c6bfc7d time: Event::TimeSystem abstraction to make it feasible to inject time with simulated timers (envoyproxy#4257) 752483e Fixing the fix (envoyproxy#4333) 83487f6 tls: update BoringSSL to ab36a84b (3497). (envoyproxy#4338) 7bc210e test: fixing interactions between waitFor and ignore_spurious_events (envoyproxy#4309) 69474b3 admin: order stats in clusters json admin (envoyproxy#4306) 2d155f9 ppc64le build (envoyproxy#4183) 07efc6d fix static initialization fiasco problem (envoyproxy#4314) 0b7e3b5 test: Remove declared but undefined class methods (envoyproxy#4297) 1485a13 lua: make sure resetting dynamic metadata wrapper when request info is marked dead d243cd6 test: set to zero when start_time exceeds limit (envoyproxy#4328) 0a1e92a test: fix heap use-after-free in ~IntegrationTestServer. (envoyproxy#4319) cddc732 CONTRIBUTING: Document 'kick-ci' trick. (envoyproxy#4335) f13ef24 docs: remove reference to deprecated value field (envoyproxy#4322) e947a27 router: minor doc fixes in stream idle timeout (envoyproxy#4329) 0c2e998 tcp-proxy: fixing a TCP proxy bug where we attempted to readDisable a closed connection (envoyproxy#4296) 00ffe44 utility: fix strftime overflow handling. (envoyproxy#4321) af1183c Re-enable TcpProxySslIntegrationTest and make the tests pass again. (envoyproxy#4318) 3553461 fuzz: fix H2 codec fuzzer post envoyproxy#4262. (envoyproxy#4311) 42f6048 Proto string issue fix (envoyproxy#4320) 9c492a0 Support Envoy to fetch secrets using SDS service. (envoyproxy#4256) a857219 ratelimit: revert `revert rate limit failure mode config` and add tests (envoyproxy#4303) 1d34172 dns: fix exception unsafe behavior in c-ares callbacks. (envoyproxy#4307) 1212423 alts: add gRPC TSI socket (envoyproxy#4153) f0363ae fuzz: detect client-side resets in H2 codec fuzzer. (envoyproxy#4300) 01aa3f8 test: hopefully deflaking echo integration test (envoyproxy#4304) 1fc0f4b ratelimit: link legacy proto when message is being used (envoyproxy#4308) aa4481e fix rare List::remove(&target) segfault (envoyproxy#4244) 89e0f23 headers: fixing fast fail of size-validation (envoyproxy#4269) 97eba59 build: bump googletest version. (envoyproxy#4293) 0057e22 fuzz: avoid false positives in HCM fuzzer. (envoyproxy#4262) 9d094e5 Revert ac0bd74 (envoyproxy#4295) ddb28a4 Add validation context provider (envoyproxy#4264) 3b47cba added histogram latency information to Hystrix dashboard stream (envoyproxy#3986) cf87d50 docs: update SNI FAQ. (envoyproxy#4285) f952033 config: fix update empty stat for eds (envoyproxy#4276) 329e591 router: Add ability of custom headers to rely on per-request data (envoyproxy#4219) 68d20b4 thrift: refactor build files and imports (envoyproxy#4271) 5fa8192 access_log: log requested_server_name in tcp proxy (envoyproxy#4144) fa45bb4 fuzz: libc++ clocks don't like nanos. (envoyproxy#4282) 53f8944 stats: add symbol table for future stat name encoding (envoyproxy#3927) c987b42 test infra: Remove timeSource() from the ClusterManager api (envoyproxy#4247) cd171d9 websocket: tunneling websockets (and upgrades in general) over H2 (envoyproxy#4188) b9dc5d9 router: disallow :path/host rewriting in request_headers_to_add. (envoyproxy#4220) 0c91011 network: skip socket options and source address for UDS client connections (envoyproxy#4252) da1857d build: fixing a downstream compile error by noting explicit fallthrough (envoyproxy#4265) 9857cfe fuzz: cleanup per-test environment after each fuzz case. (envoyproxy#4253) 52beb06 test: Wrap proto string in std::string before comparison (envoyproxy#4238) f5e219e extensions/thrift_proxy: Add header matching to thrift router (envoyproxy#4239) c9ce5d2 fuzz: track read_disable_count bidirectionally in codec_impl_fuzz_test. (envoyproxy#4260) 35103b3 fuzz: use nanoseconds for SystemTime in RequestInfo. (envoyproxy#4255) ba6ba98 fuzz: make runtime root hermetic in server_fuzz_test. (envoyproxy#4258) b0a9014 time: Add 'format' test to ensure no one directly instantiates Prod*Time from source. (envoyproxy#4248) 8567460 access_log: support beginning of epoch in START_TIME. (envoyproxy#4254) 28d5f41 proto: unify envoy_proto_library/api_proto_library. (envoyproxy#4233) f7d3cb6 http: fix allocation bug introduced in envoyproxy#4211. (envoyproxy#4245) Fixes istio/istio#8310 (once pulled into istio/istio). Signed-off-by: Piotr Sikora <piotrsikora@google.com>

added histogram latency information to Hystrix dashboard stream

92f2a12

Signed-off-by: trabetti <talis@il.ibm.com>

mattklein123 assigned mrice32 and jmarantz Jul 30, 2018

mrice32 reviewed Jul 31, 2018

View reviewed changes

trabetti added 4 commits August 1, 2018 12:55

use absl::string_view and add 99.5 percentile

5aec25a

Signed-off-by: trabetti <talis@il.ibm.com>

fixed admin_test to include added percentile

a37a9a5

Signed-off-by: trabetti <talis@il.ibm.com>

fixed thread_local_store_test to include added percentile

1e8b632

Signed-off-by: trabetti <talis@il.ibm.com>

merge and fix conflicts

7b03da0

Signed-off-by: trabetti <talis@il.ibm.com>

jmarantz reviewed Aug 2, 2018

View reviewed changes

mrice32 reviewed Aug 2, 2018

View reviewed changes

fix review coments

87b2d37

Signed-off-by: trabetti <talis@il.ibm.com>

mrice32 reviewed Aug 3, 2018

View reviewed changes

review comments + use interval latency instead of cumulative. in cumu…

af829b3

…lative extreme values stay forever, real problems can't be distinguihsed from temporary Signed-off-by: trabetti <talis@il.ibm.com>

trabetti mentioned this pull request Aug 5, 2018

Add missing timing information to Hystrix event stream output #3753

Closed

mrice32 reviewed Aug 6, 2018

View reviewed changes

use %g instead of if statement to print quantiles. move histogram map…

9bb6ba2

… out of cache Signed-off-by: trabetti <talis@il.ibm.com>

mrice32 reviewed Aug 7, 2018

View reviewed changes

jmarantz reviewed Aug 8, 2018

View reviewed changes

use tags to find histogram and cluster name. added assertions

bd40d1a

Signed-off-by: trabetti <talis@il.ibm.com>

mrice32 reviewed Aug 9, 2018

View reviewed changes

trabetti added 3 commits August 12, 2018 11:33

on work. commiting so I can merge upstream

b929103

Signed-off-by: trabetti <talis@il.ibm.com>

merge upstream

04fae8a

Signed-off-by: trabetti <talis@il.ibm.com>

adding histogram test and fix review comments

94929e5

Signed-off-by: trabetti <talis@il.ibm.com>

mrice32 previously approved these changes Aug 16, 2018

View reviewed changes

jmarantz previously approved these changes Aug 16, 2018

View reviewed changes

simplified for loop, removed comment

eb95fdf

Signed-off-by: trabetti <talis@il.ibm.com>

trabetti dismissed stale reviews from jmarantz and mrice32 via eb95fdf August 17, 2018 20:42

merge upstream

34afb7b

Signed-off-by: trabetti <talis@il.ibm.com>

trabetti added 2 commits August 23, 2018 12:13

added isnan check to the histogram values - otherwise hystrix dashboa…

e780519

…rd freezes with stale values + sync to upstream and resolved conflicts Signed-off-by: trabetti <talis@il.ibm.com>

accidently changed unrelated test. reverting

e30818c

Signed-off-by: trabetti <talis@il.ibm.com>

add comment

9bbc77c

Signed-off-by: trabetti <talis@il.ibm.com>

dnoe assigned htuch Aug 28, 2018

mrice32 previously approved these changes Aug 28, 2018

View reviewed changes

htuch suggested changes Aug 28, 2018

View reviewed changes

added RAII wrapper to histograms + minor changes

cf3adc9

Signed-off-by: trabetti <talis@il.ibm.com>

trabetti dismissed mrice32’s stale review via cf3adc9 August 28, 2018 21:52

htuch reviewed Aug 29, 2018

View reviewed changes

review fixes

3d6395a

Signed-off-by: trabetti <talis@il.ibm.com>

htuch approved these changes Aug 29, 2018

View reviewed changes

htuch merged commit 3b47cba into envoyproxy:master Aug 29, 2018


		const histogram_t* getHistogram() { return histogram; }

		void initHistogram(const std::vector<uint64_t>& values) {

Conversation

trabetti commented Jul 30, 2018 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

trabetti commented Jul 30, 2018

Uh oh!

trabetti commented Jul 30, 2018

Uh oh!

mattklein123 commented Jul 30, 2018

Uh oh!

mrice32 left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

trabetti Aug 1, 2018 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

mrice32 left a comment

trabetti commented Jul 30, 2018 •

edited

Loading

trabetti Aug 1, 2018 •

edited

Loading