KIKIMR-20042 KeyValue tablet toplevel tracing

ydb/core/keyvalue/keyvalue_flat_impl.h

@@ -15,6 +15,7 @@
 
 #include <ydb/library/actors/core/hfunc.h>
 #include <ydb/library/actors/core/log.h>
+#include <ydb/library/wilson_ids/wilson.h>
 #include <library/cpp/json/json_writer.h>
 #include <ydb/core/base/appdata.h>
 #include <ydb/core/base/blobstorage.h>
@@ -388,7 +389,8 @@ class TKeyValueFlat : public TActor<TKeyValueFlat>, public NTabletFlatExecutor::
         CheckYellowChannels(ev->Get()->Intermediate->Stat);
 
         State.OnEvIntermediate(*(ev->Get()->Intermediate), ctx);
-        Execute(new TTxRequest(std::move(ev->Get()->Intermediate), this), ctx);
+        auto traceId = ev->Get()->Intermediate->Span.GetTraceId();
+        Execute(new TTxRequest(std::move(ev->Get()->Intermediate), this), ctx, std::move(traceId));
     }
 
     void Handle(TEvKeyValue::TEvNotify::TPtr &ev, const TActorContext &ctx) {

ydb/core/keyvalue/keyvalue_intermediate.cpp

@@ -1,5 +1,6 @@
 #include "keyvalue_intermediate.h"
 #include <ydb/core/base/appdata.h>
+#include <ydb/library/wilson_ids/wilson.h>
 #include <library/cpp/time_provider/time_provider.h>
 
 namespace NKikimr {
@@ -61,7 +62,7 @@ TRope TIntermediate::TRead::BuildRope() {
 }
 
 TIntermediate::TIntermediate(TActorId respondTo, TActorId keyValueActorId, ui64 channelGeneration, ui64 channelStep,
-        TRequestType::EType requestType)
+        TRequestType::EType requestType, NWilson::TTraceId traceId)
     : Cookie(0)
     , Generation(0)
     , Deadline(TInstant::Max())
@@ -79,6 +80,7 @@ TIntermediate::TIntermediate(TActorId respondTo, TActorId keyValueActorId, ui64
     , CreatedAtGeneration(channelGeneration)
     , CreatedAtStep(channelStep)
     , IsReplied(false)
+    , Span(TWilsonTablet::Tablet, std::move(traceId), "KeyValue.Intermediate", NWilson::EFlags::AUTO_END)
 {
     Stat.IntermediateCreatedAt = TAppData::TimeProvider->Now();
     Stat.RequestType = requestType;

ydb/core/keyvalue/keyvalue_intermediate.h

@@ -9,6 +9,7 @@
 #include <ydb/core/protos/msgbus.pb.h>
 #include <ydb/core/util/fragmented_buffer.h>
 #include <ydb/core/keyvalue/protos/events.pb.h>
+#include <ydb/library/actors/wilson/wilson_span.h>
 
 namespace NKikimr {
 namespace NKeyValue {
@@ -163,8 +164,10 @@ struct TIntermediate {
 
     ui32 EvType = 0;
 
+    NWilson::TSpan Span;
+
     TIntermediate(TActorId respondTo, TActorId keyValueActorId, ui64 channelGeneration, ui64 channelStep,
-            TRequestType::EType requestType);
+            TRequestType::EType requestType, NWilson::TTraceId traceId);
 
     void UpdateStat();
 };

ydb/core/keyvalue/keyvalue_state.cpp

@@ -11,6 +11,7 @@
 #include <ydb/core/tablet/tablet_counters_protobuf.h>
 #include <ydb/core/tablet/tablet_metrics.h>
 #include <ydb/core/util/stlog.h>
+#include <ydb/library/wilson_ids/wilson.h>
 #include <library/cpp/monlib/service/pages/templates.h>
 #include <library/cpp/json/writer/json_value.h>
 #include <util/string/escape.h>
@@ -2653,7 +2654,7 @@ bool TKeyValueState::PrepareReadRequest(const TActorContext &ctx, TEvKeyValue::T
     StoredState.SetChannelStep(NextLogoBlobStep - 1);
 
     intermediate.Reset(new TIntermediate(ev->Sender, ctx.SelfID,
-            StoredState.GetChannelGeneration(), StoredState.GetChannelStep(), TRequestType::ReadOnly));
+            StoredState.GetChannelGeneration(), StoredState.GetChannelStep(), TRequestType::ReadOnly, std::move(ev->TraceId)));
 
     intermediate->HasCookie = true;
     intermediate->Cookie = request.cookie();
@@ -2707,7 +2708,7 @@ bool TKeyValueState::PrepareReadRangeRequest(const TActorContext &ctx, TEvKeyVal
 
     TRequestType::EType requestType = TRequestType::ReadOnly;
     intermediate.Reset(new TIntermediate(ev->Sender, ctx.SelfID,
-        StoredState.GetChannelGeneration(), StoredState.GetChannelStep(), requestType));
+        StoredState.GetChannelGeneration(), StoredState.GetChannelStep(), requestType, std::move(ev->TraceId)));
 
     intermediate->HasCookie = true;
     intermediate->Cookie = request.cookie();
@@ -2774,7 +2775,7 @@ bool TKeyValueState::PrepareExecuteTransactionRequest(const TActorContext &ctx,
 
     TRequestType::EType requestType = TRequestType::WriteOnly;
     intermediate.Reset(new TIntermediate(ev->Sender, ctx.SelfID,
-        StoredState.GetChannelGeneration(), StoredState.GetChannelStep(), requestType));
+        StoredState.GetChannelGeneration(), StoredState.GetChannelStep(), requestType, std::move(ev->TraceId)));
 
     intermediate->HasCookie = true;
     intermediate->Cookie = request.cookie();
@@ -2834,7 +2835,7 @@ bool TKeyValueState::PrepareGetStorageChannelStatusRequest(const TActorContext &
 
     TRequestType::EType requestType = TRequestType::ReadOnly;
     intermediate.Reset(new TIntermediate(ev->Sender, ctx.SelfID,
-        StoredState.GetChannelGeneration(), StoredState.GetChannelStep(), requestType));
+        StoredState.GetChannelGeneration(), StoredState.GetChannelStep(), requestType, std::move(ev->TraceId)));
 
     intermediate->RequestUid = NextRequestUid;
     ++NextRequestUid;
@@ -2869,7 +2870,7 @@ bool TKeyValueState::PrepareAcquireLockRequest(const TActorContext &ctx, TEvKeyV
 
     TRequestType::EType requestType = TRequestType::ReadOnlyInline;
     intermediate.Reset(new TIntermediate(ev->Sender, ctx.SelfID,
-        StoredState.GetChannelGeneration(), StoredState.GetChannelStep(), requestType));
+        StoredState.GetChannelGeneration(), StoredState.GetChannelStep(), requestType, std::move(ev->TraceId)));
 
     intermediate->RequestUid = NextRequestUid;
     ++NextRequestUid;
@@ -3160,7 +3161,7 @@ bool TKeyValueState::PrepareIntermediate(TEvKeyValue::TEvRequest::TPtr &ev, THol
     StoredState.SetChannelStep(NextLogoBlobStep - 1);
 
     intermediate.Reset(new TIntermediate(ev->Sender, ctx.SelfID,
-        StoredState.GetChannelGeneration(), StoredState.GetChannelStep(), inOutRequestType));
+        StoredState.GetChannelGeneration(), StoredState.GetChannelStep(), inOutRequestType, std::move(ev->TraceId)));
     intermediate->RequestUid = NextRequestUid;
     ++NextRequestUid;
     RequestInputTime[intermediate->RequestUid] = TAppData::TimeProvider->Now();

ydb/core/keyvalue/keyvalue_state.h

@@ -392,7 +392,7 @@ class TKeyValueState {
 
     template<class Cmd>
     bool CheckCmds(THolder<TIntermediate>& intermediate, const TDeque<Cmd>& cmds, const TActorContext& ctx,
-        TKeySet& keys, const TTabletStorageInfo* info);        
+        TKeySet& keys, const TTabletStorageInfo* info);
     bool CheckCmds(THolder<TIntermediate>& intermediate, const TActorContext& /*ctx*/, TKeySet& keys,
             const TTabletStorageInfo* /*info*/);
 

ydb/core/keyvalue/keyvalue_storage_read_request.cpp

@@ -3,6 +3,8 @@
 
 #include <ydb/core/util/stlog.h>
 #include <ydb/library/actors/protos/services_common.pb.h>
+#include <ydb/library/actors/wilson/wilson_span.h>
+#include <ydb/library/wilson_ids/wilson.h>
 #include <util/generic/overloaded.h>
 
 
@@ -50,6 +52,8 @@ class TKeyValueStorageReadRequest : public TActorBootstrapped<TKeyValueStorageRe
 
     TStackVec<TReadItemInfo, 1> ReadItems;
 
+    NWilson::TSpan Span;
+
 public:
     static constexpr NKikimrServices::TActivity::EType ActorActivityType() {
         return NKikimrServices::TActivity::KEYVALUE_ACTOR;
@@ -189,7 +193,7 @@ class TKeyValueStorageReadRequest : public TActorBootstrapped<TKeyValueStorageRe
             ev->ReaderTabletData = {TabletInfo->TabletID, TabletGeneration};
 
             SendToBSProxy(TActivationContext::AsActorContext(), batch.GroupId, ev.release(),
-                    batch.Cookie);
+                    batch.Cookie, Span.GetTraceId());
             batch.SentTime = TActivationContext::Now();
         }
     }
@@ -378,6 +382,7 @@ class TKeyValueStorageReadRequest : public TActorBootstrapped<TKeyValueStorageRe
         Send(IntermediateResult->RespondTo, response.release());
         IntermediateResult->IsReplied = true;
         SendNotify(status);
+        Span.EndError(TStringBuilder() << NKikimrKeyValue::Statuses::ReplyStatus_Name(status));
         PassAway();
     }
 
@@ -489,6 +494,7 @@ class TKeyValueStorageReadRequest : public TActorBootstrapped<TKeyValueStorageRe
         Send(IntermediateResult->RespondTo, response.release());
         IntermediateResult->IsReplied = true;
         SendNotify(status);
+        Span.EndOk();
         PassAway();
     }
 
@@ -505,6 +511,7 @@ class TKeyValueStorageReadRequest : public TActorBootstrapped<TKeyValueStorageRe
         : IntermediateResult(std::move(intermediate))
         , TabletInfo(const_cast<TTabletStorageInfo*>(tabletInfo))
         , TabletGeneration(tabletGeneration)
+        , Span(TWilsonTablet::Tablet, IntermediateResult->Span.GetTraceId(), "KeyValue.StorageReadRequest")
     {}
 };
 

ydb/core/keyvalue/keyvalue_storage_read_request_ut.cpp

@@ -186,7 +186,7 @@ struct TReadRequestBuilder {
     TBuilderResult Build(TActorId respondTo, TActorId keyValueActorId, ui32 channelGeneration = 1, ui32 channelStep = 1)
     {
         std::unique_ptr<TIntermediate> intermediate = std::make_unique<TIntermediate>(respondTo, keyValueActorId,
-                channelGeneration, channelStep, TRequestType::ReadOnly);
+                channelGeneration, channelStep, TRequestType::ReadOnly, NWilson::TTraceId());
         TStringBuilder valueBuilder;
         for (auto &[value, blobId, offset, size] : Items) {
                 valueBuilder << value;
@@ -231,7 +231,7 @@ struct TRangeReadRequestBuilder {
     TBuilderResult Build(TActorId respondTo, TActorId keyValueActorId, ui32 channelGeneration = 1, ui32 channelStep = 1)
     {
         std::unique_ptr<TIntermediate> intermediate = std::make_unique<TIntermediate>(respondTo, keyValueActorId,
-                channelGeneration, channelStep, TRequestType::ReadOnly);
+                channelGeneration, channelStep, TRequestType::ReadOnly, NWilson::TTraceId());
 
         TBuilderResult res;
         intermediate->ReadCommand = TIntermediate::TRangeRead();

ydb/core/keyvalue/keyvalue_storage_request.cpp

@@ -1,10 +1,12 @@
 #include "keyvalue_flat_impl.h"
 
-#include <ydb/library/actors/core/actor_bootstrapped.h>
-#include <ydb/public/lib/base/msgbus.h>
 #include <ydb/core/base/tablet_pipe.h>
 #include <ydb/core/base/hive.h>
 #include <ydb/core/util/log_priority_mute_checker.h>
+#include <ydb/library/actors/core/actor_bootstrapped.h>
+#include <ydb/library/actors/wilson/wilson_span.h>
+#include <ydb/library/wilson_ids/wilson.h>
+#include <ydb/public/lib/base/msgbus.h>
 
 namespace NKikimr {
 namespace NKeyValue {
@@ -62,6 +64,8 @@ class TKeyValueStorageRequest : public TActorBootstrapped<TKeyValueStorageReques
     TStackVec<ui32, 16> YellowMoveChannels;
     TStackVec<ui32, 16> YellowStopChannels;
 
+    NWilson::TSpan Span;
+
 public:
     static constexpr NKikimrServices::TActivity::EType ActorActivityType() {
         return NKikimrServices::TActivity::KEYVALUE_ACTOR;
@@ -84,6 +88,7 @@ class TKeyValueStorageRequest : public TActorBootstrapped<TKeyValueStorageReques
         , TabletGeneration(tabletGeneration)
         , IntermediateResults(std::move(intermediate))
         , TabletInfo(const_cast<TTabletStorageInfo*>(tabletInfo))
+        , Span(TWilsonTablet::Tablet, IntermediateResults->Span.GetTraceId(), "KeyValue.StorageRequest")
     {
         IntermediateResults->Stat.KeyvalueStorageRequestSentAt = TAppData::TimeProvider->Now();
     }
@@ -377,6 +382,7 @@ class TKeyValueStorageRequest : public TActorBootstrapped<TKeyValueStorageReques
                     YellowMoveChannels.begin(), YellowMoveChannels.end());
             TActorId keyValueActorId = IntermediateResults->KeyValueActorId;
             ctx.Send(keyValueActorId, new TEvKeyValue::TEvIntermediate(std::move(IntermediateResults)));
+            Span.EndOk();
             Die(ctx);
             return true;
         }
@@ -482,7 +488,9 @@ class TKeyValueStorageRequest : public TActorBootstrapped<TKeyValueStorageReques
         ctx.Send(keyValueActorId, new TEvKeyValue::TEvNotify(
             IntermediateResults->RequestUid,
             IntermediateResults->CreatedAtGeneration, IntermediateResults->CreatedAtStep,
-            IntermediateResults->Stat, status, std::move(IntermediateResults->RefCountsIncr)));
+            IntermediateResults->Stat, status, std::move(IntermediateResults->RefCountsIncr)), 0, 0, Span.GetTraceId());
+
+        Span.EndError(TStringBuilder() << status << ": " << errorDescription);
         Die(ctx);
     }
 
@@ -588,7 +596,7 @@ class TKeyValueStorageRequest : public TActorBootstrapped<TKeyValueStorageReques
 
         auto ev = std::make_unique<TEvBlobStorage::TEvGet>(readQueries, readQueryCount, IntermediateResults->Deadline, handleClass, false);
         ev->ReaderTabletData = {TabletInfo->TabletID, TabletGeneration};
-        SendToBSProxy(ctx, prevGroup, ev.release(), cookie);
+        SendToBSProxy(ctx, prevGroup, ev.release(), cookie, Span.GetTraceId());
         return true;
     }
 
@@ -599,7 +607,7 @@ class TKeyValueStorageRequest : public TActorBootstrapped<TKeyValueStorageReques
                 Y_ABORT_UNLESS(getStatus.Status == NKikimrProto::UNKNOWN);
                 SendToBSProxy(
                         ctx, getStatus.GroupId,
-                        new TEvBlobStorage::TEvStatus(IntermediateResults->Deadline), i);
+                        new TEvBlobStorage::TEvStatus(IntermediateResults->Deadline), i, Span.GetTraceId());
                 ++GetStatusRequestsSent;
             }
         }
@@ -616,7 +624,7 @@ class TKeyValueStorageRequest : public TActorBootstrapped<TKeyValueStorageReques
                 TLogoBlobID from(tabletId, 0, 0, channel, 0, 0);
                 TLogoBlobID to(tabletId, Max<ui32>(), Max<ui32>(), channel, TLogoBlobID::MaxBlobSize, TLogoBlobID::MaxCookie);
                 auto request = MakeHolder<TEvBlobStorage::TEvRange>(tabletId, from, to, false, TInstant::Max(), true);
-                SendToBSProxy(ctx, groupId, request.Release());
+                SendToBSProxy(ctx, groupId, request.Release(), 0, Span.GetTraceId());
                 ++RangeRequestsSent;
             }
         }
@@ -647,7 +655,7 @@ class TKeyValueStorageRequest : public TActorBootstrapped<TKeyValueStorageReques
                                 << " Send TEvPut# " << put->ToString() << " to groupId# " << groupId
                                 << " now# " << TAppData::TimeProvider->Now().MilliSeconds() << " Marker# KV60");
 
-                        SendPutToGroup(ctx, groupId, TabletInfo.Get(), std::move(put), i);
+                        SendPutToGroup(ctx, groupId, TabletInfo.Get(), std::move(put), i, Span.GetTraceId());
 
                         ++WriteRequestsSent;
                     }

ydb/core/kqp/session_actor/kqp_session_actor.cpp

@@ -211,7 +211,7 @@ class TKqpSessionActor : public TActorBootstrapped<TKqpSessionActor> {
         NWilson::TTraceId id;
         if (false) { // change to enable Wilson tracing
             id = NWilson::TTraceId::NewTraceId(15, 4095);
-            LOG_I("wilson tracing started, id: " + std::to_string(id.GetTraceId()));
+            LOG_I("wilson tracing started, id: " + id.GetHexTraceId());
         }
         auto selfId = SelfId();
         auto as = TActivationContext::ActorSystem();
@@ -1161,7 +1161,7 @@ class TKqpSessionActor : public TActorBootstrapped<TKqpSessionActor> {
                     ev->Get()->Record.SetQueryPlan(SerializeAnalyzePlan(stats));
                 }
             }
-            
+
             LOG_D("Forwarded TEvExecuterProgress to " << QueryState->RequestActorId);
             Send(QueryState->RequestActorId, ev->Release().Release(), 0, QueryState->ProxyRequestId);
         }

ydb/core/tablet_flat/flat_exec_seat.h

@@ -37,11 +37,19 @@ namespace NTabletFlatExecutor {
         void Terminate(ETerminationReason reason, const TActorContext& ctx) noexcept;
 
         void CreateEnqueuedSpan() noexcept {
-            EnqueuedSpan = NWilson::TSpan(TWilsonTablet::Tablet, TxSpan.GetTraceId(), "Tablet.Transaction.Enqueued");
+            WaitingSpan = NWilson::TSpan(TWilsonTablet::Tablet, TxSpan.GetTraceId(), "Tablet.Transaction.Enqueued");
         }
 
         void FinishEnqueuedSpan() noexcept {
-            EnqueuedSpan.EndOk();
+            WaitingSpan.EndOk();
+        }
+
+        void CreatePendingSpan() noexcept {
+            WaitingSpan = NWilson::TSpan(TWilsonTablet::Tablet, TxSpan.GetTraceId(), "Tablet.Transaction.Pending");
+        }
+
+        void FinishPendingSpan() noexcept {
+            WaitingSpan.EndOk();
         }
 
         NWilson::TTraceId GetTxTraceId() const noexcept {
@@ -51,7 +59,7 @@ namespace NTabletFlatExecutor {
         const ui64 UniqID = Max<ui64>();
         const TAutoPtr<ITransaction> Self;
         NWilson::TSpan TxSpan;
-        NWilson::TSpan EnqueuedSpan;
+        NWilson::TSpan WaitingSpan;
         ui64 Retries = 0;
         TPinned Pinned;