From 0797e8c99e593b9a9ad54837cb85fe84d3d8725e Mon Sep 17 00:00:00 2001 From: MrPresent-Han Date: Fri, 11 Aug 2023 12:36:22 +0800 Subject: [PATCH] refine log in segcore to print out traceID --- internal/core/src/common/Tracer.cpp | 9 +++++++++ internal/core/src/common/Tracer.h | 3 +++ internal/core/src/segcore/segment_c.cpp | 7 ++----- internal/proxy/task_insert.go | 4 ++-- internal/querynodev2/segments/segment.go | 3 --- 5 files changed, 16 insertions(+), 10 deletions(-) diff --git a/internal/core/src/common/Tracer.cpp b/internal/core/src/common/Tracer.cpp index de467cc1f84d6..fd3d6fcf1be37 100644 --- 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 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{&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 index 0acb9287f3e0d..0457325e8aa1e 100644 --- a/internal/core/src/common/Tracer.h +++ b/internal/core/src/common/Tracer.h @@ -42,4 +42,7 @@ GetTracer(); std::shared_ptr 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 index fdd6d321a0986..b511c48276e64 100644 --- 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 index aa571baed75fe..3e519b3fc1d73 100644 --- 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 index c67142c5f1766..cf81cc2d0f414 100644 --- 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