refine log in segcore to print out traceID

MrPresent-Han · Aug 11, 2023 · 0797e8c · 0797e8c
1 parent 98bd074
commit 0797e8c
Show file tree

Hide file tree

Showing 5 changed files with 16 additions and 10 deletions.
diff --git a/internal/core/src/common/Tracer.cpp b/internal/core/src/common/Tracer.cpp
@@ -34,6 +34,8 @@ namespace jaeger = opentelemetry::exporter::jaeger;
 namespace ostream = opentelemetry::exporter::trace;
 namespace otlp = opentelemetry::exporter::otlp;
 
+static const int trace_id_size = 2 * opentelemetry::trace::TraceId::kSize;
+
 void
 initTelementry(TraceConfig* config) {
     std::unique_ptr<opentelemetry::sdk::trace::SpanExporter> exporter;
@@ -84,4 +86,11 @@ StartSpan(std::string name, TraceContext* parentCtx) {
     return GetTracer()->StartSpan(name, opts);
 }
 
+void
+logTraceContext(const std::string& extended_info, const trace::SpanContext& ctx) {
+    char traceID[trace_id_size];
+    ctx.trace_id().ToLowerBase16(nostd::span<char, 2 * opentelemetry::trace::TraceId::kSize>{&traceID[0], trace_id_size});
+    LOG_SEGCORE_INFO_ << extended_info << ":" << traceID;
+}
+
 }  // namespace milvus::tracer
diff --git a/internal/core/src/common/Tracer.h b/internal/core/src/common/Tracer.h
@@ -42,4 +42,7 @@ GetTracer();
 std::shared_ptr<trace::Span>
 StartSpan(std::string name, TraceContext* ctx = nullptr);
 
+void
+logTraceContext(const std::string& extended_info,  const trace::SpanContext& ctx);
+
 }  // namespace milvus::tracer
diff --git a/internal/core/src/segcore/segment_c.cpp b/internal/core/src/segcore/segment_c.cpp
@@ -79,12 +79,9 @@ Search(CSegmentInterface c_segment,
             c_placeholder_group);
         auto ctx = milvus::tracer::TraceContext{
             c_trace.traceID, c_trace.spanID, c_trace.flag};
-        auto span = milvus::tracer::StartSpan("SegcoreSearch", &ctx);
-        LOG_SEGCORE_INFO_ << "before-search, traceID:" << *ctx.traceID << ", ts:" << timestamp
-            << ", segmentID:" << segment->get_segment_id();
+        auto span = milvus::tracer::StartSpan("SegCoreSearch", &ctx);
+        milvus::tracer::logTraceContext("SegCore_SegmentSearch_SegmentID:" + std::to_string(segment->get_segment_id()), span->GetContext());
         auto search_result = segment->Search(plan, phg_ptr, timestamp);
-        LOG_SEGCORE_INFO_ << "after-search, traceID:" << *ctx.traceID << ", ts:" << timestamp
-            << ", segmentID:" << segment->get_segment_id();
         if (!milvus::PositivelyRelated(
                 plan->plan_node_->search_info_.metric_type_)) {
             for (auto& dis : search_result->distances_) {

diff --git a/internal/proxy/task_insert.go b/internal/proxy/task_insert.go
@@ -95,7 +95,7 @@ func (it *insertTask) OnEnqueue() error {
 }
 
 func (it *insertTask) PreExecute(ctx context.Context) error {
-	ctx, sp := otel.Tracer(typeutil.ProxyRole).Start(ctx, "Insert-PreExecute")
+	ctx, sp := otel.Tracer(typeutil.ProxyRole).Start(ctx, "Proxy-Insert-PreExecute")
 	defer sp.End()
 
 	it.result = &milvuspb.MutationResult{
@@ -212,7 +212,7 @@ func (it *insertTask) PreExecute(ctx context.Context) error {
 }
 
 func (it *insertTask) Execute(ctx context.Context) error {
-	ctx, sp := otel.Tracer(typeutil.ProxyRole).Start(ctx, "Proxy-Insert-PreExecute")
+	ctx, sp := otel.Tracer(typeutil.ProxyRole).Start(ctx, "Proxy-Insert-Execute")
 	defer sp.End()
 
 	tr := timerecord.NewTimeRecorder(fmt.Sprintf("proxy execute insert %d", it.ID()))

diff --git a/internal/querynodev2/segments/segment.go b/internal/querynodev2/segments/segment.go
@@ -363,7 +363,6 @@ func (s *LocalSegment) Search(ctx context.Context, searchReq *SearchRequest) (*S
 	)
 	s.mut.RLock("Search")
 	defer s.mut.RUnlock("Search") //hc--may block here
-	log.Debug("obtained segment rlock before searching segment")
 
 	if s.ptr == nil {
 		return nil, merr.WrapErrSegmentNotLoaded(s.segmentID, "segment released")
@@ -381,8 +380,6 @@ func (s *LocalSegment) Search(ctx context.Context, searchReq *SearchRequest) (*S
 
 	hasIndex := s.ExistIndex(searchReq.searchFieldID)
 	log = log.With(zap.Bool("withIndex", hasIndex))
-	log.Debug("search segment...", zap.Int("SQPool_Cap", GetSQPool().Cap()),
-		zap.Int("SQPool_Working", GetSQPool().Running()))
 
 	var searchResult SearchResult
 	var status C.CStatus