Skip to content

Commit 9ee90d6

Browse files
domwstdomwst
authored
KIKIMR-20042 KeyValue tablet toplevel tracing (#526)
* KIKIMR-20042 KeyValue tablet toplevel tracing * Get rid of TWilson::Tablet * Remove useless explicit parent constructor
1 parent 5c2b998 commit 9ee90d6

15 files changed

+78
-46
lines changed

‎ydb/core/keyvalue/keyvalue_flat_impl.h‎

Lines changed: 3 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -15,6 +15,7 @@
1515

1616
#include <ydb/library/actors/core/hfunc.h>
1717
#include <ydb/library/actors/core/log.h>
18+
#include <ydb/library/wilson_ids/wilson.h>
1819
#include <library/cpp/json/json_writer.h>
1920
#include <ydb/core/base/appdata.h>
2021
#include <ydb/core/base/blobstorage.h>
@@ -388,7 +389,8 @@ class TKeyValueFlat : public TActor<TKeyValueFlat>, public NTabletFlatExecutor::
388389
CheckYellowChannels(ev->Get()->Intermediate->Stat);
389390

390391
State.OnEvIntermediate(*(ev->Get()->Intermediate), ctx);
391-
Execute(new TTxRequest(std::move(ev->Get()->Intermediate), this), ctx);
392+
auto traceId = ev->Get()->Intermediate->Span.GetTraceId();
393+
Execute(new TTxRequest(std::move(ev->Get()->Intermediate), this), ctx, std::move(traceId));
392394
}
393395

394396
void Handle(TEvKeyValue::TEvNotify::TPtr &ev, const TActorContext &ctx) {

‎ydb/core/keyvalue/keyvalue_intermediate.cpp‎

Lines changed: 3 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1,5 +1,6 @@
11
#include "keyvalue_intermediate.h"
22
#include <ydb/core/base/appdata.h>
3+
#include <ydb/library/wilson_ids/wilson.h>
34
#include <library/cpp/time_provider/time_provider.h>
45

56
namespace NKikimr {
@@ -61,7 +62,7 @@ TRope TIntermediate::TRead::BuildRope() {
6162
}
6263

6364
TIntermediate::TIntermediate(TActorId respondTo, TActorId keyValueActorId, ui64 channelGeneration, ui64 channelStep,
64-
TRequestType::EType requestType)
65+
TRequestType::EType requestType, NWilson::TTraceId traceId)
6566
: Cookie(0)
6667
, Generation(0)
6768
, Deadline(TInstant::Max())
@@ -79,6 +80,7 @@ TIntermediate::TIntermediate(TActorId respondTo, TActorId keyValueActorId, ui64
7980
, CreatedAtGeneration(channelGeneration)
8081
, CreatedAtStep(channelStep)
8182
, IsReplied(false)
83+
, Span(TWilsonTablet::Tablet, std::move(traceId), "KeyValue.Intermediate", NWilson::EFlags::AUTO_END)
8284
{
8385
Stat.IntermediateCreatedAt = TAppData::TimeProvider->Now();
8486
Stat.RequestType = requestType;

‎ydb/core/keyvalue/keyvalue_intermediate.h‎

Lines changed: 4 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -9,6 +9,7 @@
99
#include <ydb/core/protos/msgbus.pb.h>
1010
#include <ydb/core/util/fragmented_buffer.h>
1111
#include <ydb/core/keyvalue/protos/events.pb.h>
12+
#include <ydb/library/actors/wilson/wilson_span.h>
1213

1314
namespace NKikimr {
1415
namespace NKeyValue {
@@ -163,8 +164,10 @@ struct TIntermediate {
163164

164165
ui32 EvType = 0;
165166

167+
NWilson::TSpan Span;
168+
166169
TIntermediate(TActorId respondTo, TActorId keyValueActorId, ui64 channelGeneration, ui64 channelStep,
167-
TRequestType::EType requestType);
170+
TRequestType::EType requestType, NWilson::TTraceId traceId);
168171

169172
void UpdateStat();
170173
};

‎ydb/core/keyvalue/keyvalue_state.cpp‎

Lines changed: 7 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -11,6 +11,7 @@
1111
#include <ydb/core/tablet/tablet_counters_protobuf.h>
1212
#include <ydb/core/tablet/tablet_metrics.h>
1313
#include <ydb/core/util/stlog.h>
14+
#include <ydb/library/wilson_ids/wilson.h>
1415
#include <library/cpp/monlib/service/pages/templates.h>
1516
#include <library/cpp/json/writer/json_value.h>
1617
#include <util/string/escape.h>
@@ -2653,7 +2654,7 @@ bool TKeyValueState::PrepareReadRequest(const TActorContext &ctx, TEvKeyValue::T
26532654
StoredState.SetChannelStep(NextLogoBlobStep - 1);
26542655

26552656
intermediate.Reset(new TIntermediate(ev->Sender, ctx.SelfID,
2656-
StoredState.GetChannelGeneration(), StoredState.GetChannelStep(), TRequestType::ReadOnly));
2657+
StoredState.GetChannelGeneration(), StoredState.GetChannelStep(), TRequestType::ReadOnly, std::move(ev->TraceId)));
26572658

26582659
intermediate->HasCookie = true;
26592660
intermediate->Cookie = request.cookie();
@@ -2707,7 +2708,7 @@ bool TKeyValueState::PrepareReadRangeRequest(const TActorContext &ctx, TEvKeyVal
27072708

27082709
TRequestType::EType requestType = TRequestType::ReadOnly;
27092710
intermediate.Reset(new TIntermediate(ev->Sender, ctx.SelfID,
2710-
StoredState.GetChannelGeneration(), StoredState.GetChannelStep(), requestType));
2711+
StoredState.GetChannelGeneration(), StoredState.GetChannelStep(), requestType, std::move(ev->TraceId)));
27112712

27122713
intermediate->HasCookie = true;
27132714
intermediate->Cookie = request.cookie();
@@ -2774,7 +2775,7 @@ bool TKeyValueState::PrepareExecuteTransactionRequest(const TActorContext &ctx,
27742775

27752776
TRequestType::EType requestType = TRequestType::WriteOnly;
27762777
intermediate.Reset(new TIntermediate(ev->Sender, ctx.SelfID,
2777-
StoredState.GetChannelGeneration(), StoredState.GetChannelStep(), requestType));
2778+
StoredState.GetChannelGeneration(), StoredState.GetChannelStep(), requestType, std::move(ev->TraceId)));
27782779

27792780
intermediate->HasCookie = true;
27802781
intermediate->Cookie = request.cookie();
@@ -2834,7 +2835,7 @@ bool TKeyValueState::PrepareGetStorageChannelStatusRequest(const TActorContext &
28342835

28352836
TRequestType::EType requestType = TRequestType::ReadOnly;
28362837
intermediate.Reset(new TIntermediate(ev->Sender, ctx.SelfID,
2837-
StoredState.GetChannelGeneration(), StoredState.GetChannelStep(), requestType));
2838+
StoredState.GetChannelGeneration(), StoredState.GetChannelStep(), requestType, std::move(ev->TraceId)));
28382839

28392840
intermediate->RequestUid = NextRequestUid;
28402841
++NextRequestUid;
@@ -2869,7 +2870,7 @@ bool TKeyValueState::PrepareAcquireLockRequest(const TActorContext &ctx, TEvKeyV
28692870

28702871
TRequestType::EType requestType = TRequestType::ReadOnlyInline;
28712872
intermediate.Reset(new TIntermediate(ev->Sender, ctx.SelfID,
2872-
StoredState.GetChannelGeneration(), StoredState.GetChannelStep(), requestType));
2873+
StoredState.GetChannelGeneration(), StoredState.GetChannelStep(), requestType, std::move(ev->TraceId)));
28732874

28742875
intermediate->RequestUid = NextRequestUid;
28752876
++NextRequestUid;
@@ -3160,7 +3161,7 @@ bool TKeyValueState::PrepareIntermediate(TEvKeyValue::TEvRequest::TPtr &ev, THol
31603161
StoredState.SetChannelStep(NextLogoBlobStep - 1);
31613162

31623163
intermediate.Reset(new TIntermediate(ev->Sender, ctx.SelfID,
3163-
StoredState.GetChannelGeneration(), StoredState.GetChannelStep(), inOutRequestType));
3164+
StoredState.GetChannelGeneration(), StoredState.GetChannelStep(), inOutRequestType, std::move(ev->TraceId)));
31643165
intermediate->RequestUid = NextRequestUid;
31653166
++NextRequestUid;
31663167
RequestInputTime[intermediate->RequestUid] = TAppData::TimeProvider->Now();

‎ydb/core/keyvalue/keyvalue_state.h‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -392,7 +392,7 @@ class TKeyValueState {
392392

393393
template<class Cmd>
394394
bool CheckCmds(THolder<TIntermediate>& intermediate, const TDeque<Cmd>& cmds, const TActorContext& ctx,
395-
TKeySet& keys, const TTabletStorageInfo* info);
395+
TKeySet& keys, const TTabletStorageInfo* info);
396396
bool CheckCmds(THolder<TIntermediate>& intermediate, const TActorContext& /*ctx*/, TKeySet& keys,
397397
const TTabletStorageInfo* /*info*/);
398398

‎ydb/core/keyvalue/keyvalue_storage_read_request.cpp‎

Lines changed: 8 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -3,6 +3,8 @@
33

44
#include <ydb/core/util/stlog.h>
55
#include <ydb/library/actors/protos/services_common.pb.h>
6+
#include <ydb/library/actors/wilson/wilson_span.h>
7+
#include <ydb/library/wilson_ids/wilson.h>
68
#include <util/generic/overloaded.h>
79

810

@@ -50,6 +52,8 @@ class TKeyValueStorageReadRequest : public TActorBootstrapped<TKeyValueStorageRe
5052

5153
TStackVec<TReadItemInfo, 1> ReadItems;
5254

55+
NWilson::TSpan Span;
56+
5357
public:
5458
static constexpr NKikimrServices::TActivity::EType ActorActivityType() {
5559
return NKikimrServices::TActivity::KEYVALUE_ACTOR;
@@ -189,7 +193,7 @@ class TKeyValueStorageReadRequest : public TActorBootstrapped<TKeyValueStorageRe
189193
ev->ReaderTabletData = {TabletInfo->TabletID, TabletGeneration};
190194

191195
SendToBSProxy(TActivationContext::AsActorContext(), batch.GroupId, ev.release(),
192-
batch.Cookie);
196+
batch.Cookie, Span.GetTraceId());
193197
batch.SentTime = TActivationContext::Now();
194198
}
195199
}
@@ -378,6 +382,7 @@ class TKeyValueStorageReadRequest : public TActorBootstrapped<TKeyValueStorageRe
378382
Send(IntermediateResult->RespondTo, response.release());
379383
IntermediateResult->IsReplied = true;
380384
SendNotify(status);
385+
Span.EndError(TStringBuilder() << NKikimrKeyValue::Statuses::ReplyStatus_Name(status));
381386
PassAway();
382387
}
383388

@@ -489,6 +494,7 @@ class TKeyValueStorageReadRequest : public TActorBootstrapped<TKeyValueStorageRe
489494
Send(IntermediateResult->RespondTo, response.release());
490495
IntermediateResult->IsReplied = true;
491496
SendNotify(status);
497+
Span.EndOk();
492498
PassAway();
493499
}
494500

@@ -505,6 +511,7 @@ class TKeyValueStorageReadRequest : public TActorBootstrapped<TKeyValueStorageRe
505511
: IntermediateResult(std::move(intermediate))
506512
, TabletInfo(const_cast<TTabletStorageInfo*>(tabletInfo))
507513
, TabletGeneration(tabletGeneration)
514+
, Span(TWilsonTablet::Tablet, IntermediateResult->Span.GetTraceId(), "KeyValue.StorageReadRequest")
508515
{}
509516
};
510517

‎ydb/core/keyvalue/keyvalue_storage_read_request_ut.cpp‎

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -186,7 +186,7 @@ struct TReadRequestBuilder {
186186
TBuilderResult Build(TActorId respondTo, TActorId keyValueActorId, ui32 channelGeneration = 1, ui32 channelStep = 1)
187187
{
188188
std::unique_ptr<TIntermediate> intermediate = std::make_unique<TIntermediate>(respondTo, keyValueActorId,
189-
channelGeneration, channelStep, TRequestType::ReadOnly);
189+
channelGeneration, channelStep, TRequestType::ReadOnly, NWilson::TTraceId());
190190
TStringBuilder valueBuilder;
191191
for (auto &[value, blobId, offset, size] : Items) {
192192
valueBuilder << value;
@@ -231,7 +231,7 @@ struct TRangeReadRequestBuilder {
231231
TBuilderResult Build(TActorId respondTo, TActorId keyValueActorId, ui32 channelGeneration = 1, ui32 channelStep = 1)
232232
{
233233
std::unique_ptr<TIntermediate> intermediate = std::make_unique<TIntermediate>(respondTo, keyValueActorId,
234-
channelGeneration, channelStep, TRequestType::ReadOnly);
234+
channelGeneration, channelStep, TRequestType::ReadOnly, NWilson::TTraceId());
235235

236236
TBuilderResult res;
237237
intermediate->ReadCommand = TIntermediate::TRangeRead();

‎ydb/core/keyvalue/keyvalue_storage_request.cpp‎

Lines changed: 15 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -1,10 +1,12 @@
11
#include "keyvalue_flat_impl.h"
22

3-
#include <ydb/library/actors/core/actor_bootstrapped.h>
4-
#include <ydb/public/lib/base/msgbus.h>
53
#include <ydb/core/base/tablet_pipe.h>
64
#include <ydb/core/base/hive.h>
75
#include <ydb/core/util/log_priority_mute_checker.h>
6+
#include <ydb/library/actors/core/actor_bootstrapped.h>
7+
#include <ydb/library/actors/wilson/wilson_span.h>
8+
#include <ydb/library/wilson_ids/wilson.h>
9+
#include <ydb/public/lib/base/msgbus.h>
810

911
namespace NKikimr {
1012
namespace NKeyValue {
@@ -62,6 +64,8 @@ class TKeyValueStorageRequest : public TActorBootstrapped<TKeyValueStorageReques
6264
TStackVec<ui32, 16> YellowMoveChannels;
6365
TStackVec<ui32, 16> YellowStopChannels;
6466

67+
NWilson::TSpan Span;
68+
6569
public:
6670
static constexpr NKikimrServices::TActivity::EType ActorActivityType() {
6771
return NKikimrServices::TActivity::KEYVALUE_ACTOR;
@@ -84,6 +88,7 @@ class TKeyValueStorageRequest : public TActorBootstrapped<TKeyValueStorageReques
8488
, TabletGeneration(tabletGeneration)
8589
, IntermediateResults(std::move(intermediate))
8690
, TabletInfo(const_cast<TTabletStorageInfo*>(tabletInfo))
91+
, Span(TWilsonTablet::Tablet, IntermediateResults->Span.GetTraceId(), "KeyValue.StorageRequest")
8792
{
8893
IntermediateResults->Stat.KeyvalueStorageRequestSentAt = TAppData::TimeProvider->Now();
8994
}
@@ -377,6 +382,7 @@ class TKeyValueStorageRequest : public TActorBootstrapped<TKeyValueStorageReques
377382
YellowMoveChannels.begin(), YellowMoveChannels.end());
378383
TActorId keyValueActorId = IntermediateResults->KeyValueActorId;
379384
ctx.Send(keyValueActorId, new TEvKeyValue::TEvIntermediate(std::move(IntermediateResults)));
385+
Span.EndOk();
380386
Die(ctx);
381387
return true;
382388
}
@@ -482,7 +488,9 @@ class TKeyValueStorageRequest : public TActorBootstrapped<TKeyValueStorageReques
482488
ctx.Send(keyValueActorId, new TEvKeyValue::TEvNotify(
483489
IntermediateResults->RequestUid,
484490
IntermediateResults->CreatedAtGeneration, IntermediateResults->CreatedAtStep,
485-
IntermediateResults->Stat, status, std::move(IntermediateResults->RefCountsIncr)));
491+
IntermediateResults->Stat, status, std::move(IntermediateResults->RefCountsIncr)), 0, 0, Span.GetTraceId());
492+
493+
Span.EndError(TStringBuilder() << status << ": " << errorDescription);
486494
Die(ctx);
487495
}
488496

@@ -588,7 +596,7 @@ class TKeyValueStorageRequest : public TActorBootstrapped<TKeyValueStorageReques
588596

589597
auto ev = std::make_unique<TEvBlobStorage::TEvGet>(readQueries, readQueryCount, IntermediateResults->Deadline, handleClass, false);
590598
ev->ReaderTabletData = {TabletInfo->TabletID, TabletGeneration};
591-
SendToBSProxy(ctx, prevGroup, ev.release(), cookie);
599+
SendToBSProxy(ctx, prevGroup, ev.release(), cookie, Span.GetTraceId());
592600
return true;
593601
}
594602

@@ -599,7 +607,7 @@ class TKeyValueStorageRequest : public TActorBootstrapped<TKeyValueStorageReques
599607
Y_ABORT_UNLESS(getStatus.Status == NKikimrProto::UNKNOWN);
600608
SendToBSProxy(
601609
ctx, getStatus.GroupId,
602-
new TEvBlobStorage::TEvStatus(IntermediateResults->Deadline), i);
610+
new TEvBlobStorage::TEvStatus(IntermediateResults->Deadline), i, Span.GetTraceId());
603611
++GetStatusRequestsSent;
604612
}
605613
}
@@ -616,7 +624,7 @@ class TKeyValueStorageRequest : public TActorBootstrapped<TKeyValueStorageReques
616624
TLogoBlobID from(tabletId, 0, 0, channel, 0, 0);
617625
TLogoBlobID to(tabletId, Max<ui32>(), Max<ui32>(), channel, TLogoBlobID::MaxBlobSize, TLogoBlobID::MaxCookie);
618626
auto request = MakeHolder<TEvBlobStorage::TEvRange>(tabletId, from, to, false, TInstant::Max(), true);
619-
SendToBSProxy(ctx, groupId, request.Release());
627+
SendToBSProxy(ctx, groupId, request.Release(), 0, Span.GetTraceId());
620628
++RangeRequestsSent;
621629
}
622630
}
@@ -647,7 +655,7 @@ class TKeyValueStorageRequest : public TActorBootstrapped<TKeyValueStorageReques
647655
<< " Send TEvPut# " << put->ToString() << " to groupId# " << groupId
648656
<< " now# " << TAppData::TimeProvider->Now().MilliSeconds() << " Marker# KV60");
649657

650-
SendPutToGroup(ctx, groupId, TabletInfo.Get(), std::move(put), i);
658+
SendPutToGroup(ctx, groupId, TabletInfo.Get(), std::move(put), i, Span.GetTraceId());
651659

652660
++WriteRequestsSent;
653661
}

‎ydb/core/kqp/session_actor/kqp_session_actor.cpp‎

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -211,7 +211,7 @@ class TKqpSessionActor : public TActorBootstrapped<TKqpSessionActor> {
211211
NWilson::TTraceId id;
212212
if (false) { // change to enable Wilson tracing
213213
id = NWilson::TTraceId::NewTraceId(15, 4095);
214-
LOG_I("wilson tracing started, id: " + std::to_string(id.GetTraceId()));
214+
LOG_I("wilson tracing started, id: " + id.GetHexTraceId());
215215
}
216216
auto selfId = SelfId();
217217
auto as = TActivationContext::ActorSystem();
@@ -1161,7 +1161,7 @@ class TKqpSessionActor : public TActorBootstrapped<TKqpSessionActor> {
11611161
ev->Get()->Record.SetQueryPlan(SerializeAnalyzePlan(stats));
11621162
}
11631163
}
1164-
1164+
11651165
LOG_D("Forwarded TEvExecuterProgress to " << QueryState->RequestActorId);
11661166
Send(QueryState->RequestActorId, ev->Release().Release(), 0, QueryState->ProxyRequestId);
11671167
}

‎ydb/core/tablet_flat/flat_exec_seat.h‎

Lines changed: 11 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -37,11 +37,19 @@ namespace NTabletFlatExecutor {
3737
void Terminate(ETerminationReason reason, const TActorContext& ctx) noexcept;
3838

3939
void CreateEnqueuedSpan() noexcept {
40-
EnqueuedSpan = NWilson::TSpan(TWilsonTablet::Tablet, TxSpan.GetTraceId(), "Tablet.Transaction.Enqueued");
40+
WaitingSpan = NWilson::TSpan(TWilsonTablet::Tablet, TxSpan.GetTraceId(), "Tablet.Transaction.Enqueued");
4141
}
4242

4343
void FinishEnqueuedSpan() noexcept {
44-
EnqueuedSpan.EndOk();
44+
WaitingSpan.EndOk();
45+
}
46+
47+
void CreatePendingSpan() noexcept {
48+
WaitingSpan = NWilson::TSpan(TWilsonTablet::Tablet, TxSpan.GetTraceId(), "Tablet.Transaction.Pending");
49+
}
50+
51+
void FinishPendingSpan() noexcept {
52+
WaitingSpan.EndOk();
4553
}
4654

4755
NWilson::TTraceId GetTxTraceId() const noexcept {
@@ -51,7 +59,7 @@ namespace NTabletFlatExecutor {
5159
const ui64 UniqID = Max<ui64>();
5260
const TAutoPtr<ITransaction> Self;
5361
NWilson::TSpan TxSpan;
54-
NWilson::TSpan EnqueuedSpan;
62+
NWilson::TSpan WaitingSpan;
5563
ui64 Retries = 0;
5664
TPinned Pinned;
5765

0 commit comments

Comments
 (0)