Skip to content

Commit ddd2f2a

Browse files
VPolkaVPolka
authored
add lwtracks for dsproxy get requests (#13916) (#16777)
1 parent ab1371c commit ddd2f2a

File tree

5 files changed

+178
-14
lines changed

5 files changed

+178
-14
lines changed

Diff for: ‎ydb/core/blobstorage/dsproxy/dsproxy_get.cpp

+30-4
Original file line numberDiff line numberDiff line change
@@ -128,6 +128,13 @@ class TBlobStorageGroupGetRequest : public TBlobStorageGroupRequestActor<TBlobSt
128128
DiskCounters.resize(orderNumber + 1);
129129
}
130130
DiskCounters[orderNumber].Sent++;
131+
132+
LWTRACK(
133+
DSProxyVGetSent, Orbit,
134+
vDiskId.ToStringWOGeneration(),
135+
orderNumber,
136+
vGets.size()
137+
);
131138
}
132139
for (size_t i = 0; i < vPuts.size(); ++i) {
133140
if (RootCauseTrack.IsOn) {
@@ -141,6 +148,16 @@ class TBlobStorageGroupGetRequest : public TBlobStorageGroupRequestActor<TBlobSt
141148
DiskCounters.resize(orderNumber + 1);
142149
}
143150
DiskCounters[orderNumber].Sent++;
151+
152+
LWTRACK(
153+
DSProxyVPutSent, Orbit,
154+
vPuts[i]->Type(),
155+
vDiskId.ToStringWOGeneration(),
156+
Info->GetFailDomainOrderNumber(vDiskId),
157+
1,
158+
vPuts[i]->GetBufferBytes(),
159+
true
160+
);
144161
}
145162
SendToQueues(vGets, false);
146163
SendToQueues(vPuts, false);
@@ -195,7 +212,7 @@ class TBlobStorageGroupGetRequest : public TBlobStorageGroupRequestActor<TBlobSt
195212
const TVDiskID vdisk = VDiskIDFromVDiskID(record.GetVDiskID());
196213
const TVDiskIdShort shortId(vdisk);
197214

198-
LWPROBE(DSProxyVDiskRequestDuration, TEvBlobStorage::EvVGet, totalSize, tabletId, vdisk.GroupID.GetRawId(), channel,
215+
LWTRACK(DSProxyVDiskRequestDuration, Orbit, TEvBlobStorage::EvVGet, totalSize, tabletId, vdisk.GroupID.GetRawId(), channel,
199216
Info->GetFailDomainOrderNumber(shortId),
200217
GetStartTime(record.GetTimestamps()),
201218
GetTotalTimeMs(record.GetTimestamps()),
@@ -278,7 +295,7 @@ class TBlobStorageGroupGetRequest : public TBlobStorageGroupRequestActor<TBlobSt
278295

279296
const TLogoBlobID blob = GetFirstBlobId(ev);
280297
ui64 sumBlobSize = SumBlobSize(ev);
281-
LWPROBE(DSProxyVDiskRequestDuration, TEvBlobStorage::EvVPut, sumBlobSize, blob.TabletID(),
298+
LWTRACK(DSProxyVDiskRequestDuration, Orbit, TEvBlobStorage::EvVPut, sumBlobSize, blob.TabletID(),
282299
Info->GroupID.GetRawId(), blob.Channel(), Info->GetFailDomainOrderNumber(shortId),
283300
GetStartTime(record.GetTimestamps()),
284301
GetTotalTimeMs(record.GetTimestamps()),
@@ -326,8 +343,9 @@ class TBlobStorageGroupGetRequest : public TBlobStorageGroupRequestActor<TBlobSt
326343
TDuration timeToAccelerate = TDuration::MicroSeconds(timeToAccelerateUs);
327344
TMonotonic now = TActivationContext::Monotonic();
328345
TMonotonic nextAcceleration = RequestStartTime + timeToAccelerate;
346+
LWTRACK(DSProxyScheduleAccelerate, Orbit, nextAcceleration > now ? (nextAcceleration - now).MicroSeconds() / 1000.0 : 0.0, "Get");
329347
if (nextAcceleration > now) {
330-
ui64 causeIdx = RootCauseTrack.RegisterAccelerate();
348+
ui64 causeIdx = RootCauseTrack.RegisterAccelerate("Get");
331349
Schedule(nextAcceleration - now, new TEvAccelerateGet(causeIdx));
332350
IsGetAccelerateScheduled = true;
333351
} else {
@@ -345,8 +363,9 @@ class TBlobStorageGroupGetRequest : public TBlobStorageGroupRequestActor<TBlobSt
345363
TDuration timeToAccelerate = TDuration::MicroSeconds(timeToAccelerateUs);
346364
TMonotonic now = TActivationContext::Monotonic();
347365
TMonotonic nextAcceleration = RequestStartTime + timeToAccelerate;
366+
LWTRACK(DSProxyScheduleAccelerate, Orbit, nextAcceleration > now ? (nextAcceleration - now).MicroSeconds() / 1000.0 : 0.0, "Put");
348367
if (nextAcceleration > now) {
349-
ui64 causeIdx = RootCauseTrack.RegisterAccelerate();
368+
ui64 causeIdx = RootCauseTrack.RegisterAccelerate("Put");
350369
Schedule(nextAcceleration - now, new TEvAcceleratePut(causeIdx));
351370
IsPutAccelerateScheduled = true;
352371
} else {
@@ -457,6 +476,13 @@ class TBlobStorageGroupGetRequest : public TBlobStorageGroupRequestActor<TBlobSt
457476

458477
LWTRACK(DSProxyGetBootstrap, Orbit);
459478

479+
LWTRACK(
480+
DSProxyGetRequest, Orbit,
481+
Info->GroupID.GetRawId(),
482+
DeviceTypeStr(Info->GetDeviceType(), true),
483+
NKikimrBlobStorage::EGetHandleClass_Name(GetImpl.GetHandleClass())
484+
);
485+
460486
TDeque<std::unique_ptr<TEvBlobStorage::TEvVGet>> vGets;
461487
TDeque<std::unique_ptr<TEvBlobStorage::TEvVPut>> vPuts;
462488
GetImpl.GenerateInitialRequests(LogCtx, vGets);

Diff for: ‎ydb/core/blobstorage/dsproxy/dsproxy_put.cpp

+2-2
Original file line numberDiff line numberDiff line change
@@ -417,9 +417,9 @@ class TBlobStorageGroupPutRequest : public TBlobStorageGroupRequestActor<TBlobSt
417417

418418
TMonotonic now = TActivationContext::Monotonic();
419419
TMonotonic nextAcceleration = RequestStartTime + timeToAccelerate;
420-
LWTRACK(DSProxyScheduleAccelerate, Orbit, nextAcceleration > now ? (nextAcceleration - now).MicroSeconds() / 1000.0 : 0.0);
420+
LWTRACK(DSProxyScheduleAccelerate, Orbit, nextAcceleration > now ? (nextAcceleration - now).MicroSeconds() / 1000.0 : 0.0, "Put");
421421
if (nextAcceleration > now) {
422-
ui64 causeIdx = RootCauseTrack.RegisterAccelerate();
422+
ui64 causeIdx = RootCauseTrack.RegisterAccelerate("Put");
423423
Schedule(nextAcceleration - now, new TEvAccelerate(causeIdx));
424424
IsAccelerateScheduled = true;
425425
} else {

Diff for: ‎ydb/core/blobstorage/dsproxy/root_cause.h

+8-5
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;

Diff for: ‎ydb/core/blobstorage/dsproxy/ut/dsproxy_sequence_ut.cpp

+135-2
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

Diff for: ‎ydb/core/blobstorage/lwtrace_probes/blobstorage_probes.h

+3-1
Original file line numberDiff line numberDiff line change
@@ -270,6 +270,8 @@ struct TEventTypeField {
270270
PROBE(DSProxyGetBootstrap, GROUPS("DSProxy"), TYPES(), NAMES()) \
271271
PROBE(DSProxyGetHandle, GROUPS("DSProxy", "LWTrackStart"), TYPES(), NAMES()) \
272272
PROBE(DSProxyGetReply, GROUPS("DSProxy"), TYPES(), NAMES()) \
273+
PROBE(DSProxyVGetSent, GROUPS("DSProxy"), TYPES(TString, ui32, ui32), NAMES("vDiskId", "vdiskOrderNum", "count")) \
274+
PROBE(DSProxyGetRequest, GROUPS("DSProxy", "LWTrackStart"), TYPES(ui32, TString, TString), NAMES("groupId", "deviceType", "handleClass")) \
273275
PROBE(DSProxyPutEnqueue, GROUPS("DSProxy", "LWTrackStart"), TYPES(), NAMES()) \
274276
PROBE(DSProxyPutHandle, GROUPS("DSProxyRequest", "DSProxy", "LWTrackStart"), TYPES(), NAMES()) \
275277
PROBE(DSProxyPutBootstrapStart, GROUPS("DSProxy"), TYPES(), NAMES()) \
@@ -279,7 +281,7 @@ struct TEventTypeField {
279281
PROBE(DSProxyPutReply, GROUPS("DSProxy"), TYPES(TString, TString, TString), NAMES("blobId", "status", "errorReason")) \
280282
PROBE(DSProxyPutResumeBootstrap, GROUPS("DSProxy"), TYPES(), NAMES()) \
281283
PROBE(DSProxyPutPauseBootstrap, GROUPS("DSProxy"), TYPES(), NAMES()) \
282-
PROBE(DSProxyScheduleAccelerate, GROUPS("DSProxy"), TYPES(double), NAMES("timeBeforeAccelerationMs")) \
284+
PROBE(DSProxyScheduleAccelerate, GROUPS("DSProxy"), TYPES(double, TString), NAMES("timeBeforeAccelerationMs", "reqType")) \
283285
PROBE(DSProxyStartTransfer, GROUPS("DSProxy"), TYPES(), NAMES()) \
284286
PROBE(VDiskStartProcessing, GROUPS("DSProxy"), TYPES(), NAMES()) \
285287
PROBE(VDiskReply, GROUPS("DSProxy"), TYPES(), NAMES()) \

0 commit comments

Comments
 (0)