Skip to content

Commit 6c25ed4

Browse files
VPolkaVPolka
authored
add lwtracks for dsproxy get requests (#13916) (#16774)
1 parent 8be911b commit 6c25ed4

File tree

5 files changed

+178
-14
lines changed

5 files changed

+178
-14
lines changed

‎ydb/core/blobstorage/dsproxy/dsproxy_get.cpp‎

Lines changed: 30 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -130,6 +130,13 @@ class TBlobStorageGroupGetRequest : public TBlobStorageGroupRequestActor {
130130
DiskCounters.resize(orderNumber + 1);
131131
}
132132
DiskCounters[orderNumber].Sent++;
133+
134+
LWTRACK(
135+
DSProxyVGetSent, Orbit,
136+
vDiskId.ToStringWOGeneration(),
137+
orderNumber,
138+
vGets.size()
139+
);
133140
}
134141
for (size_t i = 0; i < vPuts.size(); ++i) {
135142
if (RootCauseTrack.IsOn) {
@@ -143,6 +150,16 @@ class TBlobStorageGroupGetRequest : public TBlobStorageGroupRequestActor {
143150
DiskCounters.resize(orderNumber + 1);
144151
}
145152
DiskCounters[orderNumber].Sent++;
153+
154+
LWTRACK(
155+
DSProxyVPutSent, Orbit,
156+
vPuts[i]->Type(),
157+
vDiskId.ToStringWOGeneration(),
158+
Info->GetFailDomainOrderNumber(vDiskId),
159+
1,
160+
vPuts[i]->GetBufferBytes(),
161+
true
162+
);
146163
}
147164
for (auto& ev : vGets) {
148165
const ui64 cookie = ev->Record.GetCookie();
@@ -202,7 +219,7 @@ class TBlobStorageGroupGetRequest : public TBlobStorageGroupRequestActor {
202219
const TVDiskID vdisk = VDiskIDFromVDiskID(record.GetVDiskID());
203220
const TVDiskIdShort shortId(vdisk);
204221

205-
LWPROBE(DSProxyVDiskRequestDuration, TEvBlobStorage::EvVGet, totalSize, tabletId, vdisk.GroupID.GetRawId(), channel,
222+
LWTRACK(DSProxyVDiskRequestDuration, Orbit, TEvBlobStorage::EvVGet, totalSize, tabletId, vdisk.GroupID.GetRawId(), channel,
206223
Info->GetFailDomainOrderNumber(shortId),
207224
GetStartTime(record.GetTimestamps()),
208225
GetTotalTimeMs(record.GetTimestamps()),
@@ -285,7 +302,7 @@ class TBlobStorageGroupGetRequest : public TBlobStorageGroupRequestActor {
285302

286303
const TLogoBlobID blob = GetFirstBlobId(ev);
287304
ui64 sumBlobSize = SumBlobSize(ev);
288-
LWPROBE(DSProxyVDiskRequestDuration, TEvBlobStorage::EvVPut, sumBlobSize, blob.TabletID(),
305+
LWTRACK(DSProxyVDiskRequestDuration, Orbit, TEvBlobStorage::EvVPut, sumBlobSize, blob.TabletID(),
289306
Info->GroupID.GetRawId(), blob.Channel(), Info->GetFailDomainOrderNumber(shortId),
290307
GetStartTime(record.GetTimestamps()),
291308
GetTotalTimeMs(record.GetTimestamps()),
@@ -333,8 +350,9 @@ class TBlobStorageGroupGetRequest : public TBlobStorageGroupRequestActor {
333350
TDuration timeToAccelerate = TDuration::MicroSeconds(timeToAccelerateUs);
334351
TMonotonic now = TActivationContext::Monotonic();
335352
TMonotonic nextAcceleration = RequestStartTime + timeToAccelerate;
353+
LWTRACK(DSProxyScheduleAccelerate, Orbit, nextAcceleration > now ? (nextAcceleration - now).MicroSeconds() / 1000.0 : 0.0, "Get");
336354
if (nextAcceleration > now) {
337-
ui64 causeIdx = RootCauseTrack.RegisterAccelerate();
355+
ui64 causeIdx = RootCauseTrack.RegisterAccelerate("Get");
338356
Schedule(nextAcceleration - now, new TEvAccelerateGet(causeIdx));
339357
IsGetAccelerateScheduled = true;
340358
} else {
@@ -352,8 +370,9 @@ class TBlobStorageGroupGetRequest : public TBlobStorageGroupRequestActor {
352370
TDuration timeToAccelerate = TDuration::MicroSeconds(timeToAccelerateUs);
353371
TMonotonic now = TActivationContext::Monotonic();
354372
TMonotonic nextAcceleration = RequestStartTime + timeToAccelerate;
373+
LWTRACK(DSProxyScheduleAccelerate, Orbit, nextAcceleration > now ? (nextAcceleration - now).MicroSeconds() / 1000.0 : 0.0, "Put");
355374
if (nextAcceleration > now) {
356-
ui64 causeIdx = RootCauseTrack.RegisterAccelerate();
375+
ui64 causeIdx = RootCauseTrack.RegisterAccelerate("Put");
357376
Schedule(nextAcceleration - now, new TEvAcceleratePut(causeIdx));
358377
IsPutAccelerateScheduled = true;
359378
} else {
@@ -461,6 +480,13 @@ class TBlobStorageGroupGetRequest : public TBlobStorageGroupRequestActor {
461480

462481
LWTRACK(DSProxyGetBootstrap, Orbit);
463482

483+
LWTRACK(
484+
DSProxyGetRequest, Orbit,
485+
Info->GroupID.GetRawId(),
486+
DeviceTypeStr(Info->GetDeviceType(), true),
487+
NKikimrBlobStorage::EGetHandleClass_Name(GetImpl.GetHandleClass())
488+
);
489+
464490
TDeque<std::unique_ptr<TEvBlobStorage::TEvVGet>> vGets;
465491
TDeque<std::unique_ptr<TEvBlobStorage::TEvVPut>> vPuts;
466492
GetImpl.GenerateInitialRequests(LogCtx, vGets);

‎ydb/core/blobstorage/dsproxy/dsproxy_put.cpp‎

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -426,9 +426,9 @@ class TBlobStorageGroupPutRequest : public TBlobStorageGroupRequestActor {
426426
TDuration timeToAccelerate = TDuration::MicroSeconds(timeToAccelerateUs);
427427
TMonotonic now = TActivationContext::Monotonic();
428428
TMonotonic nextAcceleration = RequestStartTime + timeToAccelerate;
429-
LWTRACK(DSProxyScheduleAccelerate, Orbit, nextAcceleration > now ? (nextAcceleration - now).MicroSeconds() / 1000.0 : 0.0);
429+
LWTRACK(DSProxyScheduleAccelerate, Orbit, nextAcceleration > now ? (nextAcceleration - now).MicroSeconds() / 1000.0 : 0.0, "Put");
430430
if (nextAcceleration > now) {
431-
ui64 causeIdx = RootCauseTrack.RegisterAccelerate();
431+
ui64 causeIdx = RootCauseTrack.RegisterAccelerate("Put");
432432
Schedule(nextAcceleration - now, new TEvAccelerate(causeIdx));
433433
IsAccelerateScheduled = true;
434434
} else {

‎ydb/core/blobstorage/dsproxy/root_cause.h‎

Lines changed: 8 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -16,13 +16,15 @@ struct TRootCause {
1616
ui64 TransferCycles;
1717
ui64 VDiskReplyCycles;
1818
bool IsAccelerate;
19+
TString RequestType;
1920

20-
TRootCauseItem(ui64 causeIdx, ui64 startCycles, bool isAccelerate)
21+
TRootCauseItem(ui64 causeIdx, ui64 startCycles, bool isAccelerate, const TString& requestType)
2122
: CauseIdx(causeIdx)
2223
, StartCycles(startCycles)
2324
, TransferCycles(startCycles)
2425
, VDiskReplyCycles(startCycles)
2526
, IsAccelerate(isAccelerate)
27+
, RequestType(requestType)
2628
{}
2729
};
2830
static constexpr ui64 InvalidCauseIdx = 255;
@@ -48,6 +50,7 @@ struct TRootCause {
4850
}
4951
NLWTrace::TParams params;
5052
if (item.IsAccelerate) {
53+
params.Param[1].CopyConstruct<TString>(item.RequestType);
5154
orbit.AddProbe(&LWTRACE_GET_NAME(DSProxyScheduleAccelerate).Probe, params, item.StartCycles);
5255
} else {
5356
orbit.AddProbe(&LWTRACE_GET_NAME(DSProxyStartTransfer).Probe, params, item.StartCycles);
@@ -59,18 +62,18 @@ struct TRootCause {
5962
#endif //LWTRACE_DISABLE
6063
}
6164

62-
ui64 RegisterCause() {
65+
ui64 RegisterCause(const TString& requestType = "") {
6366
if (IsOn && Items.size() < InvalidCauseIdx - 1) {
64-
Items.emplace_back(CurrentCauseIdx, GetCycleCountFast(), false);
67+
Items.emplace_back(CurrentCauseIdx, GetCycleCountFast(), false, requestType);
6568
return Items.size() - 1;
6669
} else {
6770
return InvalidCauseIdx;
6871
}
6972
}
7073

71-
ui64 RegisterAccelerate() {
74+
ui64 RegisterAccelerate(const TString& requestType) {
7275
if (IsOn && Items.size() < InvalidCauseIdx - 1) {
73-
Items.emplace_back(CurrentCauseIdx, GetCycleCountFast(), true);
76+
Items.emplace_back(CurrentCauseIdx, GetCycleCountFast(), true, requestType);
7477
return Items.size() - 1;
7578
} else {
7679
return InvalidCauseIdx;

‎ydb/core/blobstorage/dsproxy/ut/dsproxy_sequence_ut.cpp‎

Lines changed: 135 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -651,7 +651,6 @@ Y_UNIT_TEST(TestGivenMirror3DCGetWithFirstSlowDisk) {
651651

652652
TTestState testState(runtime, type, DSProxyEnv.Info);
653653

654-
655654
TEvBlobStorage::TEvGet::TPtr ev = testState.CreateGetRequest({blobId}, false);
656655
TActorId getActorId = runtime.Register(DSProxyEnv.CreateGetRequestActor(ev, NKikimrBlobStorage::TabletLog).release());
657656
runtime.EnableScheduleForActor(getActorId);
@@ -704,7 +703,6 @@ Y_UNIT_TEST(TestGivenBlock42GetThenVGetResponseParts2523Nodata4ThenGetOk) {
704703
UNIT_ASSERT(getResult->Responses[0].Status == NKikimrProto::OK);
705704
}
706705

707-
708706
struct TBlobPack {
709707
ui32 Count;
710708
ui32 DataLength;
@@ -1285,6 +1283,141 @@ Y_UNIT_TEST(TestGivenBlock42Put6PartsOnOneVDiskWhenDiscoverThenRecoverFirst) {
12851283
}
12861284
}
12871285

1286+
Y_UNIT_TEST(TestBlock42CheckLwtrack) {
1287+
NLWTrace::TManager mngr(*Singleton<NLWTrace::TProbeRegistry>(), true);
1288+
NLWTrace::TOrbit orbit;
1289+
NLWTrace::TTraceRequest req;
1290+
req.SetIsTraced(true);
1291+
mngr.HandleTraceRequest(req, orbit);
1292+
1293+
1294+
TTestBasicRuntime runtime(1, false);
1295+
TBlobStorageGroupType type = {TErasureType::Erasure4Plus2Block};
1296+
Setup(runtime, type);
1297+
runtime.SetLogPriority(NKikimrServices::BS_PROXY_GET, NLog::PRI_DEBUG);
1298+
1299+
TActorId proxy = MakeBlobStorageProxyID(GROUP_ID);
1300+
TActorId sender = runtime.AllocateEdgeActor(0);
1301+
1302+
TString data("xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx");
1303+
TLogoBlobID logoblobid(1, 0, 0, 0, (ui32)data.size(), 0);
1304+
1305+
TVector<TVDiskState> subgroup;
1306+
PrepareBlobSubgroup(logoblobid, data, subgroup, runtime, type);
1307+
1308+
auto ev = new TEvBlobStorage::TEvGet(logoblobid, 0, 0, TInstant::Max(),
1309+
NKikimrBlobStorage::EGetHandleClass::FastRead);
1310+
ev->Orbit = std::move(orbit);
1311+
1312+
runtime.Send(new IEventHandle(proxy, sender, ev));
1313+
for (ui32 i = 0; i < 6; ++i) {
1314+
TAutoPtr<IEventHandle> handle;
1315+
auto vget = runtime.GrabEdgeEventRethrow<TEvBlobStorage::TEvVGet>(handle);
1316+
UNIT_ASSERT(vget);
1317+
for (size_t idx = 0; idx < subgroup.size(); ++idx) {
1318+
if (subgroup[idx].ActorId == handle->Recipient) {
1319+
subgroup[idx].SetCookiesAndSenderFrom(handle.Get(), vget);
1320+
}
1321+
}
1322+
}
1323+
1324+
SendVGetResult(6, NKikimrProto::OK, 2, subgroup, runtime);
1325+
SendVGetResult(4, NKikimrProto::OK, 5, subgroup, runtime);
1326+
SendVGetResult(1, NKikimrProto::OK, 2, subgroup, runtime);
1327+
SendVGetResult(2, NKikimrProto::OK, 3, subgroup, runtime);
1328+
SendVGetResult(7, NKikimrProto::NODATA, 1, subgroup, runtime);
1329+
SendVGetResult(3, NKikimrProto::OK, 4, subgroup, runtime);
1330+
SendVGetResult(5, NKikimrProto::OK, 6, subgroup, runtime);
1331+
SendVGetResult(0, NKikimrProto::OK, 1, subgroup, runtime);
1332+
1333+
TAutoPtr<IEventHandle> handle;
1334+
auto getResult = runtime.GrabEdgeEventRethrow<TEvBlobStorage::TEvGetResult>(handle);
1335+
UNIT_ASSERT(getResult);
1336+
UNIT_ASSERT(getResult->Status == NKikimrProto::OK);
1337+
UNIT_ASSERT(getResult->ResponseSz == 1);
1338+
UNIT_ASSERT(getResult->Responses[0].Status == NKikimrProto::OK);
1339+
1340+
NLWTrace::TTraceResponse resp;
1341+
getResult->Orbit.Serialize(0, *resp.MutableTrace());
1342+
auto& r = resp.GetTrace();
1343+
UNIT_ASSERT_VALUES_EQUAL(21, r.EventsSize());
1344+
1345+
{
1346+
const auto& p = r.GetEvents(0);
1347+
UNIT_ASSERT_VALUES_EQUAL("BLOBSTORAGE_PROVIDER", p.GetProvider());
1348+
UNIT_ASSERT_VALUES_EQUAL("DSProxyGetHandle", p.GetName());
1349+
UNIT_ASSERT_VALUES_EQUAL(0 , p.ParamsSize());
1350+
}
1351+
1352+
{
1353+
const auto& p = r.GetEvents(1);
1354+
UNIT_ASSERT_VALUES_EQUAL("DSProxyGetBootstrap", p.GetName());
1355+
UNIT_ASSERT_VALUES_EQUAL(0 , p.ParamsSize());
1356+
}
1357+
1358+
{
1359+
const auto& p = r.GetEvents(2);
1360+
UNIT_ASSERT_VALUES_EQUAL("DSProxyGetRequest", p.GetName());
1361+
// check groupId
1362+
UNIT_ASSERT_VALUES_EQUAL(0, p.GetParams(0).GetUintValue());
1363+
// check deviceType
1364+
UNIT_ASSERT_VALUES_EQUAL("DEVICE_TYPE_UNKNOWN(255)", p.GetParams(1).GetStrValue());
1365+
// check handleClass
1366+
UNIT_ASSERT_VALUES_EQUAL("FastRead", p.GetParams(2).GetStrValue());
1367+
}
1368+
1369+
TVector<ui32> vdiskOrderNum = {0, 1, 4, 5, 6, 7};
1370+
for (auto i = 3; i < 9; ++i) {
1371+
const auto& p = r.GetEvents(i);
1372+
UNIT_ASSERT_VALUES_EQUAL("DSProxyVGetSent", p.GetName());
1373+
// check vdiskId
1374+
UNIT_ASSERT_VALUES_EQUAL("[0:_:0:" + ToString(vdiskOrderNum[i-3]) + ":0]", p.GetParams(0).GetStrValue());
1375+
// check vdiskOrderNum
1376+
UNIT_ASSERT_VALUES_EQUAL(vdiskOrderNum[i-3], p.GetParams(1).GetUintValue());
1377+
// check vgets count
1378+
UNIT_ASSERT_VALUES_EQUAL(6, p.GetParams(2).GetUintValue());
1379+
}
1380+
1381+
for (auto i = 9; i < 13; ++i) {
1382+
const auto& p = r.GetEvents(i);
1383+
UNIT_ASSERT_VALUES_EQUAL("DSProxyVDiskRequestDuration", p.GetName());
1384+
}
1385+
1386+
for (auto i = 13; i < 15; ++i) {
1387+
const auto& p = r.GetEvents(i);
1388+
UNIT_ASSERT_VALUES_EQUAL("DSProxyScheduleAccelerate", p.GetName());
1389+
UNIT_ASSERT_VALUES_EQUAL("Get", p.GetParams(1).GetStrValue());
1390+
}
1391+
1392+
for (auto i = 15; i < 17; ++i) {
1393+
const auto& p = r.GetEvents(i);
1394+
UNIT_ASSERT_VALUES_EQUAL("DSProxyVDiskRequestDuration", p.GetName());
1395+
}
1396+
1397+
{
1398+
const auto& p = r.GetEvents(17);
1399+
UNIT_ASSERT_VALUES_EQUAL("DSProxyStartTransfer", p.GetName());
1400+
UNIT_ASSERT_VALUES_EQUAL(0 , p.ParamsSize());
1401+
}
1402+
1403+
{
1404+
const auto& p = r.GetEvents(18);
1405+
UNIT_ASSERT_VALUES_EQUAL("VDiskStartProcessing", p.GetName());
1406+
UNIT_ASSERT_VALUES_EQUAL(0 , p.ParamsSize());
1407+
}
1408+
1409+
{
1410+
const auto& p = r.GetEvents(19);
1411+
UNIT_ASSERT_VALUES_EQUAL("VDiskReply", p.GetName());
1412+
UNIT_ASSERT_VALUES_EQUAL(0 , p.ParamsSize());
1413+
}
1414+
1415+
{
1416+
const auto& p = r.GetEvents(20);
1417+
UNIT_ASSERT_VALUES_EQUAL("DSProxyGetReply", p.GetName());
1418+
UNIT_ASSERT_VALUES_EQUAL(0 , p.ParamsSize());
1419+
}
1420+
}
12881421

12891422
} // Y_UNIT_TEST_SUITE TBlobStorageProxySequenceTest
12901423
} // namespace NBlobStorageProxySequenceTest

‎ydb/core/blobstorage/lwtrace_probes/blobstorage_probes.h‎

Lines changed: 3 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -284,6 +284,8 @@ struct TEventTypeField {
284284
PROBE(DSProxyGetBootstrap, GROUPS("DSProxy"), TYPES(), NAMES()) \
285285
PROBE(DSProxyGetHandle, GROUPS("DSProxy", "LWTrackStart"), TYPES(), NAMES()) \
286286
PROBE(DSProxyGetReply, GROUPS("DSProxy"), TYPES(), NAMES()) \
287+
PROBE(DSProxyVGetSent, GROUPS("DSProxy"), TYPES(TString, ui32, ui32), NAMES("vDiskId", "vdiskOrderNum", "count")) \
288+
PROBE(DSProxyGetRequest, GROUPS("DSProxy", "LWTrackStart"), TYPES(ui32, TString, TString), NAMES("groupId", "deviceType", "handleClass")) \
287289
PROBE(DSProxyPutEnqueue, GROUPS("DSProxy", "LWTrackStart"), TYPES(), NAMES()) \
288290
PROBE(DSProxyPutHandle, GROUPS("DSProxyRequest", "DSProxy", "LWTrackStart"), TYPES(), NAMES()) \
289291
PROBE(DSProxyPutBootstrapStart, GROUPS("DSProxy"), TYPES(), NAMES()) \
@@ -293,7 +295,7 @@ struct TEventTypeField {
293295
PROBE(DSProxyPutReply, GROUPS("DSProxy"), TYPES(TString, TString, TString), NAMES("blobId", "status", "errorReason")) \
294296
PROBE(DSProxyPutResumeBootstrap, GROUPS("DSProxy"), TYPES(), NAMES()) \
295297
PROBE(DSProxyPutPauseBootstrap, GROUPS("DSProxy"), TYPES(), NAMES()) \
296-
PROBE(DSProxyScheduleAccelerate, GROUPS("DSProxy"), TYPES(double), NAMES("timeBeforeAccelerationMs")) \
298+
PROBE(DSProxyScheduleAccelerate, GROUPS("DSProxy"), TYPES(double, TString), NAMES("timeBeforeAccelerationMs", "reqType")) \
297299
PROBE(DSProxyStartTransfer, GROUPS("DSProxy"), TYPES(), NAMES()) \
298300
PROBE(VDiskStartProcessing, GROUPS("DSProxy"), TYPES(), NAMES()) \
299301
PROBE(VDiskReply, GROUPS("DSProxy"), TYPES(), NAMES()) \

0 commit comments

Comments
 (0)