test/core/channel/channel_trace_test.cc

   1 /*
   2  *
   3  * Copyright 2017 gRPC authors.
   4  *
   5  * Licensed under the Apache License, Version 2.0 (the "License");
   6  * you may not use this file except in compliance with the License.
   7  * You may obtain a copy of the License at
   8  *
   9  *     http://www.apache.org/licenses/LICENSE-2.0
  10  *
  11  * Unless required by applicable law or agreed to in writing, software
  12  * distributed under the License is distributed on an "AS IS" BASIS,
  13  * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
  14  * See the License for the specific language governing permissions and
  15  * limitations under the License.
  16  *
  17  */
  18
  19 #include <stdlib.h>
  20 #include <string.h>
  21
  22 #include <gtest/gtest.h>
  23
  24 #include <grpc/support/alloc.h>
  25 #include <grpc/support/log.h>
  26 #include <grpc/support/string_util.h>
  27
  28 #include "src/core/lib/channel/channel_trace.h"
  29 #include "src/core/lib/channel/channelz.h"
  30 #include "src/core/lib/channel/channelz_registry.h"
  31 #include "src/core/lib/gpr/useful.h"
  32 #include "src/core/lib/iomgr/exec_ctx.h"
  33 #include "src/core/lib/json/json.h"
  34 #include "src/core/lib/surface/channel.h"
  35
  36 #include "test/core/util/test_config.h"
  37 #include "test/cpp/util/channel_trace_proto_helper.h"
  38
  39 #include <stdlib.h>
  40 #include <string.h>
  41
  42 namespace grpc_core {
  43 namespace channelz {
  44 namespace testing {
  45
  46 // testing peer to access channel internals
  47 class ChannelNodePeer {
  48  public:
  49   explicit ChannelNodePeer(ChannelNode* node) : node_(node) {}
  50   ChannelTrace* trace() const { return &node_->trace_; }
  51
  52  private:
  53   ChannelNode* node_;
  54 };
  55
  56 size_t GetSizeofTraceEvent() { return sizeof(ChannelTrace::TraceEvent); }
  57
  58 namespace {
  59
  60 grpc_json* GetJsonChild(grpc_json* parent, const char* key) {
  61   EXPECT_NE(parent, nullptr);
  62   for (grpc_json* child = parent->child; child != nullptr;
  63        child = child->next) {
  64     if (child->key != nullptr && strcmp(child->key, key) == 0) return child;
  65   }
  66   return nullptr;
  67 }
  68
  69 void ValidateJsonArraySize(grpc_json* json, const char* key,
  70                            size_t expected_size) {
  71   grpc_json* arr = GetJsonChild(json, key);
  72   // the events array should not be present if there are no events.
  73   if (expected_size == 0) {
  74     EXPECT_EQ(arr, nullptr);
  75     return;
  76   }
  77   ASSERT_NE(arr, nullptr);
  78   ASSERT_EQ(arr->type, GRPC_JSON_ARRAY);
  79   size_t count = 0;
  80   for (grpc_json* child = arr->child; child != nullptr; child = child->next) {
  81     ++count;
  82   }
  83   ASSERT_EQ(count, expected_size);
  84 }
  85
  86 void ValidateChannelTraceData(grpc_json* json,
  87                               size_t num_events_logged_expected,
  88                               size_t actual_num_events_expected) {
  89   ASSERT_NE(json, nullptr);
  90   grpc_json* num_events_logged_json = GetJsonChild(json, "numEventsLogged");
  91   ASSERT_NE(num_events_logged_json, nullptr);
  92   grpc_json* start_time = GetJsonChild(json, "creationTimestamp");
  93   ASSERT_NE(start_time, nullptr);
  94   size_t num_events_logged =
  95       (size_t)strtol(num_events_logged_json->value, nullptr, 0);
  96   ASSERT_EQ(num_events_logged, num_events_logged_expected);
  97   ValidateJsonArraySize(json, "events", actual_num_events_expected);
  98 }
  99
 100 void AddSimpleTrace(ChannelTrace* tracer) {
 101   tracer->AddTraceEvent(ChannelTrace::Severity::Info,
 102                         grpc_slice_from_static_string("simple trace"));
 103 }
 104
 105 // checks for the existence of all the required members of the tracer.
 106 void ValidateChannelTraceCustom(ChannelTrace* tracer, size_t num_events_logged,
 107                                 size_t num_events_expected) {
 108   grpc_json* json = tracer->RenderJson();
 109   EXPECT_NE(json, nullptr);
 110   char* json_str = grpc_json_dump_to_string(json, 0);
 111   grpc_json_destroy(json);
 112   grpc::testing::ValidateChannelTraceProtoJsonTranslation(json_str);
 113   grpc_json* parsed_json = grpc_json_parse_string(json_str);
 114   ValidateChannelTraceData(parsed_json, num_events_logged, num_events_expected);
 115   grpc_json_destroy(parsed_json);
 116   gpr_free(json_str);
 117 }
 118
 119 void ValidateChannelTrace(ChannelTrace* tracer, size_t num_events_logged) {
 120   ValidateChannelTraceCustom(tracer, num_events_logged, num_events_logged);
 121 }
 122
 123 class ChannelFixture {
 124  public:
 125   ChannelFixture(int max_tracer_event_memory) {
 126     grpc_arg client_a = grpc_channel_arg_integer_create(
 127         const_cast<char*>(GRPC_ARG_MAX_CHANNEL_TRACE_EVENT_MEMORY_PER_NODE),
 128         max_tracer_event_memory);
 129     grpc_channel_args client_args = {1, &client_a};
 130     channel_ =
 131         grpc_insecure_channel_create("fake_target", &client_args, nullptr);
 132   }
 133
 134   ~ChannelFixture() { grpc_channel_destroy(channel_); }
 135
 136   grpc_channel* channel() { return channel_; }
 137
 138  private:
 139   grpc_channel* channel_;
 140 };
 141
 142 }  // anonymous namespace
 143
 144 const int kEventListMemoryLimit = 1024 * 1024;
 145
 146 // Tests basic ChannelTrace functionality like construction, adding trace, and
 147 // lookups by uuid.
 148 TEST(ChannelTracerTest, BasicTest) {
 149   grpc_core::ExecCtx exec_ctx;
 150   ChannelTrace tracer(kEventListMemoryLimit);
 151   AddSimpleTrace(&tracer);
 152   AddSimpleTrace(&tracer);
 153   tracer.AddTraceEvent(ChannelTrace::Severity::Info,
 154                        grpc_slice_from_static_string("trace three"));
 155   tracer.AddTraceEvent(ChannelTrace::Severity::Error,
 156                        grpc_slice_from_static_string("trace four error"));
 157   ValidateChannelTrace(&tracer, 4);
 158   AddSimpleTrace(&tracer);
 159   AddSimpleTrace(&tracer);
 160   ValidateChannelTrace(&tracer, 6);
 161   AddSimpleTrace(&tracer);
 162   AddSimpleTrace(&tracer);
 163   AddSimpleTrace(&tracer);
 164   AddSimpleTrace(&tracer);
 165   ValidateChannelTrace(&tracer, 10);
 166 }
 167
 168 // Tests more complex functionality, like a parent channel tracking
 169 // subchannles. This exercises the ref/unref patterns since the parent tracer
 170 // and this function will both hold refs to the subchannel.
 171 TEST(ChannelTracerTest, ComplexTest) {
 172   grpc_core::ExecCtx exec_ctx;
 173   ChannelTrace tracer(kEventListMemoryLimit);
 174   AddSimpleTrace(&tracer);
 175   AddSimpleTrace(&tracer);
 176   ChannelFixture channel1(kEventListMemoryLimit);
 177   RefCountedPtr<ChannelNode> sc1 = MakeRefCounted<ChannelNode>(
 178       UniquePtr<char>(gpr_strdup("fake_target")), kEventListMemoryLimit, 0);
 179   ChannelNodePeer sc1_peer(sc1.get());
 180   tracer.AddTraceEventWithReference(
 181       ChannelTrace::Severity::Info,
 182       grpc_slice_from_static_string("subchannel one created"), sc1);
 183   ValidateChannelTrace(&tracer, 3);
 184   AddSimpleTrace(sc1_peer.trace());
 185   AddSimpleTrace(sc1_peer.trace());
 186   AddSimpleTrace(sc1_peer.trace());
 187   ValidateChannelTrace(sc1_peer.trace(), 3);
 188   AddSimpleTrace(sc1_peer.trace());
 189   AddSimpleTrace(sc1_peer.trace());
 190   AddSimpleTrace(sc1_peer.trace());
 191   ValidateChannelTrace(sc1_peer.trace(), 6);
 192   AddSimpleTrace(&tracer);
 193   AddSimpleTrace(&tracer);
 194   ValidateChannelTrace(&tracer, 5);
 195   ChannelFixture channel2(kEventListMemoryLimit);
 196   RefCountedPtr<ChannelNode> sc2 = MakeRefCounted<ChannelNode>(
 197       UniquePtr<char>(gpr_strdup("fake_target")), kEventListMemoryLimit, 0);
 198   tracer.AddTraceEventWithReference(
 199       ChannelTrace::Severity::Info,
 200       grpc_slice_from_static_string("LB channel two created"), sc2);
 201   tracer.AddTraceEventWithReference(
 202       ChannelTrace::Severity::Warning,
 203       grpc_slice_from_static_string("subchannel one inactive"), sc1);
 204   ValidateChannelTrace(&tracer, 7);
 205   AddSimpleTrace(&tracer);
 206   AddSimpleTrace(&tracer);
 207   AddSimpleTrace(&tracer);
 208   AddSimpleTrace(&tracer);
 209   AddSimpleTrace(&tracer);
 210   AddSimpleTrace(&tracer);
 211   sc1.reset();
 212   sc2.reset();
 213 }
 214
 215 // Test a case in which the parent channel has subchannels and the subchannels
 216 // have connections. Ensures that everything lives as long as it should then
 217 // gets deleted.
 218 TEST(ChannelTracerTest, TestNesting) {
 219   grpc_core::ExecCtx exec_ctx;
 220   ChannelTrace tracer(kEventListMemoryLimit);
 221   AddSimpleTrace(&tracer);
 222   AddSimpleTrace(&tracer);
 223   ValidateChannelTrace(&tracer, 2);
 224   ChannelFixture channel1(kEventListMemoryLimit);
 225   RefCountedPtr<ChannelNode> sc1 = MakeRefCounted<ChannelNode>(
 226       UniquePtr<char>(gpr_strdup("fake_target")), kEventListMemoryLimit, 0);
 227   ChannelNodePeer sc1_peer(sc1.get());
 228   tracer.AddTraceEventWithReference(
 229       ChannelTrace::Severity::Info,
 230       grpc_slice_from_static_string("subchannel one created"), sc1);
 231   ValidateChannelTrace(&tracer, 3);
 232   AddSimpleTrace(sc1_peer.trace());
 233   ChannelFixture channel2(kEventListMemoryLimit);
 234   RefCountedPtr<ChannelNode> conn1 = MakeRefCounted<ChannelNode>(
 235       UniquePtr<char>(gpr_strdup("fake_target")), kEventListMemoryLimit, 0);
 236   ChannelNodePeer conn1_peer(conn1.get());
 237   // nesting one level deeper.
 238   sc1_peer.trace()->AddTraceEventWithReference(
 239       ChannelTrace::Severity::Info,
 240       grpc_slice_from_static_string("connection one created"), conn1);
 241   ValidateChannelTrace(&tracer, 3);
 242   AddSimpleTrace(conn1_peer.trace());
 243   AddSimpleTrace(&tracer);
 244   AddSimpleTrace(&tracer);
 245   ValidateChannelTrace(&tracer, 5);
 246   ValidateChannelTrace(conn1_peer.trace(), 1);
 247   ChannelFixture channel3(kEventListMemoryLimit);
 248   RefCountedPtr<ChannelNode> sc2 = MakeRefCounted<ChannelNode>(
 249       UniquePtr<char>(gpr_strdup("fake_target")), kEventListMemoryLimit, 0);
 250   tracer.AddTraceEventWithReference(
 251       ChannelTrace::Severity::Info,
 252       grpc_slice_from_static_string("subchannel two created"), sc2);
 253   // this trace should not get added to the parents children since it is already
 254   // present in the tracer.
 255   tracer.AddTraceEventWithReference(
 256       ChannelTrace::Severity::Warning,
 257       grpc_slice_from_static_string("subchannel one inactive"), sc1);
 258   AddSimpleTrace(&tracer);
 259   ValidateChannelTrace(&tracer, 8);
 260   sc1.reset();
 261   sc2.reset();
 262   conn1.reset();
 263 }
 264
 265 TEST(ChannelTracerTest, TestSmallMemoryLimit) {
 266   grpc_core::ExecCtx exec_ctx;
 267   // doesn't make sense, but serves a testing purpose for the channel tracing
 268   // bookkeeping. All tracing events added should will get immediately garbage
 269   // collected.
 270   const int kSmallMemoryLimit = 1;
 271   ChannelTrace tracer(kSmallMemoryLimit);
 272   AddSimpleTrace(&tracer);
 273   AddSimpleTrace(&tracer);
 274   tracer.AddTraceEvent(ChannelTrace::Severity::Info,
 275                        grpc_slice_from_static_string("trace three"));
 276   tracer.AddTraceEvent(ChannelTrace::Severity::Error,
 277                        grpc_slice_from_static_string("trace four error"));
 278   ValidateChannelTraceCustom(&tracer, 4, 0);
 279   AddSimpleTrace(&tracer);
 280   AddSimpleTrace(&tracer);
 281   ValidateChannelTraceCustom(&tracer, 6, 0);
 282   AddSimpleTrace(&tracer);
 283   AddSimpleTrace(&tracer);
 284   AddSimpleTrace(&tracer);
 285   AddSimpleTrace(&tracer);
 286   ValidateChannelTraceCustom(&tracer, 10, 0);
 287 }
 288
 289 TEST(ChannelTracerTest, TestEviction) {
 290   grpc_core::ExecCtx exec_ctx;
 291   const int kTraceEventSize = GetSizeofTraceEvent();
 292   const int kNumEvents = 5;
 293   ChannelTrace tracer(kTraceEventSize * kNumEvents);
 294   for (int i = 1; i <= kNumEvents; ++i) {
 295     AddSimpleTrace(&tracer);
 296     ValidateChannelTrace(&tracer, i);
 297   }
 298   // at this point the list is full, and each subsequent enntry will cause an
 299   // eviction.
 300   for (int i = 1; i <= kNumEvents; ++i) {
 301     AddSimpleTrace(&tracer);
 302     ValidateChannelTraceCustom(&tracer, kNumEvents + i, kNumEvents);
 303   }
 304 }
 305
 306 TEST(ChannelTracerTest, TestMultipleEviction) {
 307   grpc_core::ExecCtx exec_ctx;
 308   const int kTraceEventSize = GetSizeofTraceEvent();
 309   const int kNumEvents = 5;
 310   ChannelTrace tracer(kTraceEventSize * kNumEvents);
 311   for (int i = 1; i <= kNumEvents; ++i) {
 312     AddSimpleTrace(&tracer);
 313     ValidateChannelTrace(&tracer, i);
 314   }
 315   // at this point the list is full, and each subsequent enntry will cause an
 316   // eviction. We will now add in a trace event that has a copied string. This
 317   // uses more memory, so it will cause a double eviciction
 318   tracer.AddTraceEvent(
 319       ChannelTrace::Severity::Info,
 320       grpc_slice_from_copied_string(
 321           "long enough string to trigger a multiple eviction"));
 322   ValidateChannelTraceCustom(&tracer, kNumEvents + 1, kNumEvents - 1);
 323 }
 324
 325 TEST(ChannelTracerTest, TestTotalEviction) {
 326   grpc_core::ExecCtx exec_ctx;
 327   const int kTraceEventSize = GetSizeofTraceEvent();
 328   const int kNumEvents = 5;
 329   ChannelTrace tracer(kTraceEventSize * kNumEvents);
 330   for (int i = 1; i <= kNumEvents; ++i) {
 331     AddSimpleTrace(&tracer);
 332     ValidateChannelTrace(&tracer, i);
 333   }
 334   // at this point the list is full. Now we add such a big slice that
 335   // everything gets evicted.
 336   grpc_slice huge_slice = grpc_slice_malloc(kTraceEventSize * (kNumEvents + 1));
 337   tracer.AddTraceEvent(ChannelTrace::Severity::Info, huge_slice);
 338   ValidateChannelTraceCustom(&tracer, kNumEvents + 1, 0);
 339 }
 340
 341 }  // namespace testing
 342 }  // namespace channelz
 343 }  // namespace grpc_core
 344
 345 int main(int argc, char** argv) {
 346   grpc::testing::TestEnvironment env(argc, argv);
 347   grpc_init();
 348   ::testing::InitGoogleTest(&argc, argv);
 349   int ret = RUN_ALL_TESTS();
 350   grpc_shutdown();
 351   return ret;
 352 }