debug:增加DEBUG日志统计router以及loadbalance执行时间 (#49)

chuntaojun · web-flow · commit 2627c5cfbe4b · 2023-06-13T17:59:56.000+08:00
diff --git a/examples/quickstart/consumer.cpp b/examples/quickstart/consumer.cpp
@@ -28,6 +28,7 @@
 #include <thread>
 
 #include "polaris/consumer.h"
+#include "polaris/log.h"
 
 class ConsumerServer {
  public:
@@ -90,7 +91,9 @@ int main(int argc, char** argv) {
 
 ConsumerServer::ConsumerServer(const std::string& host, int port, const polaris::ServiceKey& provider_service)
     : host_(host), port_(port), provider_service_(provider_service), stop_(false) {
-  consumer_ = std::unique_ptr<polaris::ConsumerApi>(polaris::ConsumerApi::CreateWithDefaultFile());
+  polaris::GetLogger()->SetLogLevel(polaris::kDebugLogLevel);
+  auto consumer_api_ = polaris::ConsumerApi::CreateWithDefaultFile();
+  consumer_ = std::unique_ptr<polaris::ConsumerApi>(consumer_api_);
 }
 
 ConsumerServer::~ConsumerServer() {}
diff --git a/examples/quickstart/polaris.yaml b/examples/quickstart/polaris.yaml
@@ -1,4 +1,16 @@
+# 配置模板，不要直接使用，只需要配置需要修改的值，未配置的部分会使用默认值
+# 不传配置文件或传空的配置文件，SDK会使用默认配置初始化，根据需要传入配置覆盖默认配置项
+# 描述:全局配置
 global:
+  # 描述:对接polaris discover server的相关配置
   serverConnector:
     addresses:
-      - 127.0.0.1:8091
+      - 119.91.66.223:8091
+# 描述:主调端配置    
+consumer:
+  # 描述:负载均衡相关配置      
+  loadBalancer:
+    # 描述:负载均衡类型
+    # 范围:已注册的负载均衡插件名
+    # 默认值：权重随机负载均衡
+    type: ringHash
diff --git a/polaris/api/consumer_api.cpp b/polaris/api/consumer_api.cpp
@@ -331,7 +331,12 @@ ReturnCode ConsumerApiImpl::GetOneInstance(ServiceContext* service_context, Rout
   if (load_balancer == nullptr) {
     return kReturnPluginError;
   }
+  auto begin_time = std::chrono::steady_clock::now();
   ret = load_balancer->ChooseInstance(service_instances, req_impl.criteria_, instance);
+  auto end_time = std::chrono::steady_clock::now();
+  auto delay = std::chrono::duration_cast<std::chrono::milliseconds>(end_time - begin_time).count();
+  POLARIS_LOG(LOG_DEBUG, "LoadBalance(%s) ns(%s) svc(%s) do choose cost(%ld ms)", req_impl.load_balance_type_.c_str(),
+              route_info.GetServiceKey().namespace_.c_str(), route_info.GetServiceKey().name_.c_str(), delay);
   if (ret != kReturnOk) {
     const ServiceKey& service_key = route_info.GetServiceKey();
     POLARIS_LOG(LOG_ERROR, "get one instance for service[%s/%s] with load balancer retrun error:%s",
@@ -386,7 +391,7 @@ void ConsumerApiImpl::GetBackupInstances(ServiceInstances* service_instances, Lo
                   target_num);
       target_num = available_num;  // 修正目标值
     }
-    int cycle_times = available_num;  //循环次数上限
+    int cycle_times = available_num;  // 循环次数上限
     Criteria criteria_tmp = criteria;
 
     for (int i = 1; i <= cycle_times; ++i) {
@@ -928,6 +933,4 @@ void ConsumerApiImpl::UpdateServerResult(Context* context, const ServiceKey& ser
   }
 }
 
-
-
 }  // namespace polaris
diff --git a/polaris/plugin/load_balancer/ringhash/ringhash.cpp b/polaris/plugin/load_balancer/ringhash/ringhash.cpp
@@ -15,11 +15,13 @@
 
 #include <stdlib.h>
 
+#include <inttypes.h>
 #include <map>
 #include <string>
 #include <vector>
 
 #include "context/context_impl.h"
+#include "logger.h"
 #include "model/instance.h"
 #include "model/model_impl.h"
 #include "plugin/plugin_manager.h"
@@ -88,6 +90,12 @@ ReturnCode KetamaLoadBalancer::ChooseInstance(ServiceInstances* service_instance
 
   if (lb_value == nullptr) {
     lb_value = data_cache_->CreateOrGet(cache_key, [&] {
+      // 出现 ringhash cache 需要执行 create 时进行打印相关辅助信息日志
+      POLARIS_LOG(LOG_DEBUG, "ringhash_cache run create action ns(%s) svc(%s) hash_str(%s) hash_key(%" PRIu64 ")",
+                  service_instances->GetService()->GetServiceKey().namespace_.c_str(),
+                  service_instances->GetService()->GetServiceKey().name_.c_str(), criteria.hash_string_.c_str(),
+                  criteria.hash_key_);
+
       RingHashCacheValue* new_lb_value = new RingHashCacheValue();
       new_lb_value->prior_date_ = instances_set;
       new_lb_value->prior_date_->IncrementRef();
diff --git a/polaris/plugin/service_router/canary_router.cpp b/polaris/plugin/service_router/canary_router.cpp
@@ -41,6 +41,8 @@ CanaryServiceRouter::~CanaryServiceRouter() {
   }
 }
 
+std::string CanaryServiceRouter::Name() { return "CanaryServiceRouter"; }
+
 ReturnCode CanaryServiceRouter::Init(Config* /*config*/, Context* context) {
   context_ = context;
   router_cache_ = new ServiceCache<CanaryCacheKey, RouterSubsetCache>();
diff --git a/polaris/plugin/service_router/canary_router.h b/polaris/plugin/service_router/canary_router.h
@@ -36,6 +36,8 @@ class CanaryServiceRouter : public ServiceRouter {
 
   virtual RouterStatData* CollectStat();
 
+  virtual std::string Name();
+
  private:
   bool CalculateResult(const std::vector<Instance*>& instances, const std::set<Instance*>& unhealthy_set,
                        std::vector<Instance*>& result);
diff --git a/polaris/plugin/service_router/metadata_router.cpp b/polaris/plugin/service_router/metadata_router.cpp
@@ -14,6 +14,8 @@
 #include "metadata_router.h"
 
 #include <stddef.h>
+#include <map>
+#include <string>
 
 #include <utility>
 
@@ -49,6 +51,8 @@ ReturnCode MetadataServiceRouter::Init(Config* /*config*/, Context* context) {
   return kReturnOk;
 }
 
+std::string MetadataServiceRouter::Name() { return "MetadataServiceRouter"; }
+
 static bool MetadataMatch(const std::map<std::string, std::string>& metadata,
                           const std::map<std::string, std::string>& instance_metadata) {
   if (metadata.size() > instance_metadata.size()) {
@@ -170,6 +174,17 @@ ReturnCode MetadataServiceRouter::DoRoute(RouteInfo& route_info, RouteResult* ro
   RouterSubsetCache* cache_value = router_cache_->GetWithRcuTime(cache_key);
   if (cache_value == nullptr) {
     cache_value = router_cache_->CreateOrGet(cache_key, [&] {
+      // 出现 metadata cache 需要执行 create 时进行打印相关辅助信息日志
+      std::string metadata_str_ = "";
+      for (std::map<std::string, std::string>::iterator it = cache_key.metadata_.begin();
+           it != cache_key.metadata_.end(); it++) {
+        metadata_str_ += it->first + ":" + it->second + ",";
+      }
+      POLARIS_LOG(LOG_DEBUG,
+                  "ns(%s) svc(%s) metadata(%s) failover_type(%d) circuitbreaker_version(%" PRIu64
+                  ") router_cache run create action",
+                  route_info.GetServiceKey().namespace_.c_str(), route_info.GetServiceKey().name_.c_str(),
+                  metadata_str_.c_str(), cache_key.failover_type_, cache_key.circuit_breaker_version_);
       InstancesSet* prior_result = cache_key.prior_data_;
       std::set<Instance*> unhealthy_set;
       route_info.CalculateUnhealthySet(unhealthy_set);
diff --git a/polaris/plugin/service_router/metadata_router.h b/polaris/plugin/service_router/metadata_router.h
@@ -37,6 +37,8 @@ class MetadataServiceRouter : public ServiceRouter {
 
   virtual RouterStatData* CollectStat();
 
+  virtual std::string Name();
+
  private:
   bool CalculateResult(const std::vector<Instance*>& instances, const std::set<Instance*>& unhealthy_set,
                        const std::map<std::string, std::string>& metadata, MetadataFailoverType failover_type,
diff --git a/polaris/plugin/service_router/nearby_router.cpp b/polaris/plugin/service_router/nearby_router.cpp
@@ -242,6 +242,8 @@ ReturnCode NearbyServiceRouter::Init(Config* config, Context* context) {
   return kReturnOk;
 }
 
+std::string NearbyServiceRouter::Name() { return "NearbyServiceRouter"; }
+
 bool NearbyServiceRouter::CheckLocation() {
   ContextImpl* context_impl = context_->GetContextImpl();
   Location location;
diff --git a/polaris/plugin/service_router/nearby_router.h b/polaris/plugin/service_router/nearby_router.h
@@ -115,6 +115,8 @@ class NearbyServiceRouter : public ServiceRouter {
 
   virtual RouterStatData* CollectStat();
 
+  virtual std::string Name();
+
  private:
   bool CheckLocation();
 
diff --git a/polaris/plugin/service_router/router_chain.cpp b/polaris/plugin/service_router/router_chain.cpp
@@ -125,7 +125,14 @@ ReturnCode ServiceRouterChain::DoRoute(RouteInfo& route_info, RouteResult* route
   POLARIS_CHECK_ARGUMENT(route_info.GetServiceInstances() != nullptr);
   ReturnCode ret;
   for (std::size_t index = 0; index < service_router_list_.size(); index++) {
-    if ((ret = service_router_list_[index]->DoRoute(route_info, route_result)) != kReturnOk) {
+    auto begin_time = std::chrono::steady_clock::now();
+    ServiceRouter* router = service_router_list_[index];
+    ret = router->DoRoute(route_info, route_result);
+    auto end_time = std::chrono::steady_clock::now();
+    auto delay = std::chrono::duration_cast<std::chrono::milliseconds>(end_time - begin_time).count();
+    POLARIS_LOG(LOG_DEBUG, "router(%s) ns(%s) svc(%s) do route cost(%ld ms)", router->Name().c_str(),
+                route_info.GetServiceKey().namespace_.c_str(), route_info.GetServiceKey().name_.c_str(), delay);
+    if (ret != kReturnOk) {
       POLARIS_LOG(LOG_ERROR, "run service router plugin[%s] for service[%s/%s] return error[%s]",
                   plugin_name_list_[index].c_str(), service_key_.namespace_.c_str(), service_key_.name_.c_str(),
                   ReturnCodeToMsg(ret).c_str());
diff --git a/polaris/plugin/service_router/service_router.h b/polaris/plugin/service_router/service_router.h
@@ -45,6 +45,9 @@ class ServiceRouter : public Plugin {
 
   /// @brief 收集路由统计数据
   virtual RouterStatData* CollectStat() = 0;
+
+  /// @brief  返回路由插件的名称
+  virtual std::string Name() = 0;
 };
 
 }  // namespace polaris

Original file line number	Diff line number	Diff line change
`@@ -41,6 +41,8 @@ CanaryServiceRouter::~CanaryServiceRouter() {`
`41`	`41`	`}`
`42`	`42`	`}`
`43`	`43`
	`44`	`+std::string CanaryServiceRouter::Name() { return "CanaryServiceRouter"; }`
	`45`	`+`
`44`	`46`	`ReturnCode CanaryServiceRouter::Init(Config* /config/, Context* context) {`
`45`	`47`	`context_ = context;`
`46`	`48`	`router_cache_ = new ServiceCache<CanaryCacheKey, RouterSubsetCache>();`
Original file line number	Diff line number	Diff line change
`@@ -242,6 +242,8 @@ ReturnCode NearbyServiceRouter::Init(Config* config, Context* context) {`
`242`	`242`	`return kReturnOk;`
`243`	`243`	`}`
`244`	`244`
	`245`	`+std::string NearbyServiceRouter::Name() { return "NearbyServiceRouter"; }`
	`246`	`+`
`245`	`247`	`bool NearbyServiceRouter::CheckLocation() {`
`246`	`248`	`ContextImpl* context_impl = context_->GetContextImpl();`
`247`	`249`	`Location location;`