diff --git a/ydb/core/blobstorage/dsproxy/dsproxy_get.cpp b/ydb/core/blobstorage/dsproxy/dsproxy_get.cpp index c08f72d87efb..8c65537b2e1d 100644 --- a/ydb/core/blobstorage/dsproxy/dsproxy_get.cpp +++ b/ydb/core/blobstorage/dsproxy/dsproxy_get.cpp @@ -130,6 +130,13 @@ class TBlobStorageGroupGetRequest : public TBlobStorageGroupRequestActor { DiskCounters.resize(orderNumber + 1); } DiskCounters[orderNumber].Sent++; + + LWTRACK( + DSProxyVGetSent, Orbit, + vDiskId.ToStringWOGeneration(), + orderNumber, + vGets.size() + ); } for (size_t i = 0; i < vPuts.size(); ++i) { if (RootCauseTrack.IsOn) { @@ -143,6 +150,16 @@ class TBlobStorageGroupGetRequest : public TBlobStorageGroupRequestActor { DiskCounters.resize(orderNumber + 1); } DiskCounters[orderNumber].Sent++; + + LWTRACK( + DSProxyVPutSent, Orbit, + vPuts[i]->Type(), + vDiskId.ToStringWOGeneration(), + Info->GetFailDomainOrderNumber(vDiskId), + 1, + vPuts[i]->GetBufferBytes(), + true + ); } for (auto& ev : vGets) { const ui64 cookie = ev->Record.GetCookie(); @@ -202,7 +219,7 @@ class TBlobStorageGroupGetRequest : public TBlobStorageGroupRequestActor { const TVDiskID vdisk = VDiskIDFromVDiskID(record.GetVDiskID()); const TVDiskIdShort shortId(vdisk); - LWPROBE(DSProxyVDiskRequestDuration, TEvBlobStorage::EvVGet, totalSize, tabletId, vdisk.GroupID.GetRawId(), channel, + LWTRACK(DSProxyVDiskRequestDuration, Orbit, TEvBlobStorage::EvVGet, totalSize, tabletId, vdisk.GroupID.GetRawId(), channel, Info->GetFailDomainOrderNumber(shortId), GetStartTime(record.GetTimestamps()), GetTotalTimeMs(record.GetTimestamps()), @@ -285,7 +302,7 @@ class TBlobStorageGroupGetRequest : public TBlobStorageGroupRequestActor { const TLogoBlobID blob = GetFirstBlobId(ev); ui64 sumBlobSize = SumBlobSize(ev); - LWPROBE(DSProxyVDiskRequestDuration, TEvBlobStorage::EvVPut, sumBlobSize, blob.TabletID(), + LWTRACK(DSProxyVDiskRequestDuration, Orbit, TEvBlobStorage::EvVPut, sumBlobSize, blob.TabletID(), Info->GroupID.GetRawId(), blob.Channel(), Info->GetFailDomainOrderNumber(shortId), GetStartTime(record.GetTimestamps()), GetTotalTimeMs(record.GetTimestamps()), @@ -333,8 +350,9 @@ class TBlobStorageGroupGetRequest : public TBlobStorageGroupRequestActor { TDuration timeToAccelerate = TDuration::MicroSeconds(timeToAccelerateUs); TMonotonic now = TActivationContext::Monotonic(); TMonotonic nextAcceleration = RequestStartTime + timeToAccelerate; + LWTRACK(DSProxyScheduleAccelerate, Orbit, nextAcceleration > now ? (nextAcceleration - now).MicroSeconds() / 1000.0 : 0.0, "Get"); if (nextAcceleration > now) { - ui64 causeIdx = RootCauseTrack.RegisterAccelerate(); + ui64 causeIdx = RootCauseTrack.RegisterAccelerate("Get"); Schedule(nextAcceleration - now, new TEvAccelerateGet(causeIdx)); IsGetAccelerateScheduled = true; } else { @@ -352,8 +370,9 @@ class TBlobStorageGroupGetRequest : public TBlobStorageGroupRequestActor { TDuration timeToAccelerate = TDuration::MicroSeconds(timeToAccelerateUs); TMonotonic now = TActivationContext::Monotonic(); TMonotonic nextAcceleration = RequestStartTime + timeToAccelerate; + LWTRACK(DSProxyScheduleAccelerate, Orbit, nextAcceleration > now ? (nextAcceleration - now).MicroSeconds() / 1000.0 : 0.0, "Put"); if (nextAcceleration > now) { - ui64 causeIdx = RootCauseTrack.RegisterAccelerate(); + ui64 causeIdx = RootCauseTrack.RegisterAccelerate("Put"); Schedule(nextAcceleration - now, new TEvAcceleratePut(causeIdx)); IsPutAccelerateScheduled = true; } else { @@ -461,6 +480,13 @@ class TBlobStorageGroupGetRequest : public TBlobStorageGroupRequestActor { LWTRACK(DSProxyGetBootstrap, Orbit); + LWTRACK( + DSProxyGetRequest, Orbit, + Info->GroupID.GetRawId(), + DeviceTypeStr(Info->GetDeviceType(), true), + NKikimrBlobStorage::EGetHandleClass_Name(GetImpl.GetHandleClass()) + ); + TDeque> vGets; TDeque> vPuts; GetImpl.GenerateInitialRequests(LogCtx, vGets); diff --git a/ydb/core/blobstorage/dsproxy/dsproxy_put.cpp b/ydb/core/blobstorage/dsproxy/dsproxy_put.cpp index 3426728b1a00..9153e4a5f493 100644 --- a/ydb/core/blobstorage/dsproxy/dsproxy_put.cpp +++ b/ydb/core/blobstorage/dsproxy/dsproxy_put.cpp @@ -426,9 +426,9 @@ class TBlobStorageGroupPutRequest : public TBlobStorageGroupRequestActor { TDuration timeToAccelerate = TDuration::MicroSeconds(timeToAccelerateUs); TMonotonic now = TActivationContext::Monotonic(); TMonotonic nextAcceleration = RequestStartTime + timeToAccelerate; - LWTRACK(DSProxyScheduleAccelerate, Orbit, nextAcceleration > now ? (nextAcceleration - now).MicroSeconds() / 1000.0 : 0.0); + LWTRACK(DSProxyScheduleAccelerate, Orbit, nextAcceleration > now ? (nextAcceleration - now).MicroSeconds() / 1000.0 : 0.0, "Put"); if (nextAcceleration > now) { - ui64 causeIdx = RootCauseTrack.RegisterAccelerate(); + ui64 causeIdx = RootCauseTrack.RegisterAccelerate("Put"); Schedule(nextAcceleration - now, new TEvAccelerate(causeIdx)); IsAccelerateScheduled = true; } else { diff --git a/ydb/core/blobstorage/dsproxy/root_cause.h b/ydb/core/blobstorage/dsproxy/root_cause.h index fcb2b89f496a..eaf66668aba7 100644 --- a/ydb/core/blobstorage/dsproxy/root_cause.h +++ b/ydb/core/blobstorage/dsproxy/root_cause.h @@ -16,13 +16,15 @@ struct TRootCause { ui64 TransferCycles; ui64 VDiskReplyCycles; bool IsAccelerate; + TString RequestType; - TRootCauseItem(ui64 causeIdx, ui64 startCycles, bool isAccelerate) + TRootCauseItem(ui64 causeIdx, ui64 startCycles, bool isAccelerate, const TString& requestType) : CauseIdx(causeIdx) , StartCycles(startCycles) , TransferCycles(startCycles) , VDiskReplyCycles(startCycles) , IsAccelerate(isAccelerate) + , RequestType(requestType) {} }; static constexpr ui64 InvalidCauseIdx = 255; @@ -48,6 +50,7 @@ struct TRootCause { } NLWTrace::TParams params; if (item.IsAccelerate) { + params.Param[1].CopyConstruct(item.RequestType); orbit.AddProbe(&LWTRACE_GET_NAME(DSProxyScheduleAccelerate).Probe, params, item.StartCycles); } else { orbit.AddProbe(&LWTRACE_GET_NAME(DSProxyStartTransfer).Probe, params, item.StartCycles); @@ -59,18 +62,18 @@ struct TRootCause { #endif //LWTRACE_DISABLE } - ui64 RegisterCause() { + ui64 RegisterCause(const TString& requestType = "") { if (IsOn && Items.size() < InvalidCauseIdx - 1) { - Items.emplace_back(CurrentCauseIdx, GetCycleCountFast(), false); + Items.emplace_back(CurrentCauseIdx, GetCycleCountFast(), false, requestType); return Items.size() - 1; } else { return InvalidCauseIdx; } } - ui64 RegisterAccelerate() { + ui64 RegisterAccelerate(const TString& requestType) { if (IsOn && Items.size() < InvalidCauseIdx - 1) { - Items.emplace_back(CurrentCauseIdx, GetCycleCountFast(), true); + Items.emplace_back(CurrentCauseIdx, GetCycleCountFast(), true, requestType); return Items.size() - 1; } else { return InvalidCauseIdx; diff --git a/ydb/core/blobstorage/dsproxy/ut/dsproxy_sequence_ut.cpp b/ydb/core/blobstorage/dsproxy/ut/dsproxy_sequence_ut.cpp index 41f36cb8ceb7..bc3041983d07 100644 --- a/ydb/core/blobstorage/dsproxy/ut/dsproxy_sequence_ut.cpp +++ b/ydb/core/blobstorage/dsproxy/ut/dsproxy_sequence_ut.cpp @@ -651,7 +651,6 @@ Y_UNIT_TEST(TestGivenMirror3DCGetWithFirstSlowDisk) { TTestState testState(runtime, type, DSProxyEnv.Info); - TEvBlobStorage::TEvGet::TPtr ev = testState.CreateGetRequest({blobId}, false); TActorId getActorId = runtime.Register(DSProxyEnv.CreateGetRequestActor(ev, NKikimrBlobStorage::TabletLog).release()); runtime.EnableScheduleForActor(getActorId); @@ -704,7 +703,6 @@ Y_UNIT_TEST(TestGivenBlock42GetThenVGetResponseParts2523Nodata4ThenGetOk) { UNIT_ASSERT(getResult->Responses[0].Status == NKikimrProto::OK); } - struct TBlobPack { ui32 Count; ui32 DataLength; @@ -1285,6 +1283,141 @@ Y_UNIT_TEST(TestGivenBlock42Put6PartsOnOneVDiskWhenDiscoverThenRecoverFirst) { } } +Y_UNIT_TEST(TestBlock42CheckLwtrack) { + NLWTrace::TManager mngr(*Singleton(), true); + NLWTrace::TOrbit orbit; + NLWTrace::TTraceRequest req; + req.SetIsTraced(true); + mngr.HandleTraceRequest(req, orbit); + + + TTestBasicRuntime runtime(1, false); + TBlobStorageGroupType type = {TErasureType::Erasure4Plus2Block}; + Setup(runtime, type); + runtime.SetLogPriority(NKikimrServices::BS_PROXY_GET, NLog::PRI_DEBUG); + + TActorId proxy = MakeBlobStorageProxyID(GROUP_ID); + TActorId sender = runtime.AllocateEdgeActor(0); + + TString data("xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx"); + TLogoBlobID logoblobid(1, 0, 0, 0, (ui32)data.size(), 0); + + TVector subgroup; + PrepareBlobSubgroup(logoblobid, data, subgroup, runtime, type); + + auto ev = new TEvBlobStorage::TEvGet(logoblobid, 0, 0, TInstant::Max(), + NKikimrBlobStorage::EGetHandleClass::FastRead); + ev->Orbit = std::move(orbit); + + runtime.Send(new IEventHandle(proxy, sender, ev)); + for (ui32 i = 0; i < 6; ++i) { + TAutoPtr handle; + auto vget = runtime.GrabEdgeEventRethrow(handle); + UNIT_ASSERT(vget); + for (size_t idx = 0; idx < subgroup.size(); ++idx) { + if (subgroup[idx].ActorId == handle->Recipient) { + subgroup[idx].SetCookiesAndSenderFrom(handle.Get(), vget); + } + } + } + + SendVGetResult(6, NKikimrProto::OK, 2, subgroup, runtime); + SendVGetResult(4, NKikimrProto::OK, 5, subgroup, runtime); + SendVGetResult(1, NKikimrProto::OK, 2, subgroup, runtime); + SendVGetResult(2, NKikimrProto::OK, 3, subgroup, runtime); + SendVGetResult(7, NKikimrProto::NODATA, 1, subgroup, runtime); + SendVGetResult(3, NKikimrProto::OK, 4, subgroup, runtime); + SendVGetResult(5, NKikimrProto::OK, 6, subgroup, runtime); + SendVGetResult(0, NKikimrProto::OK, 1, subgroup, runtime); + + TAutoPtr handle; + auto getResult = runtime.GrabEdgeEventRethrow(handle); + UNIT_ASSERT(getResult); + UNIT_ASSERT(getResult->Status == NKikimrProto::OK); + UNIT_ASSERT(getResult->ResponseSz == 1); + UNIT_ASSERT(getResult->Responses[0].Status == NKikimrProto::OK); + + NLWTrace::TTraceResponse resp; + getResult->Orbit.Serialize(0, *resp.MutableTrace()); + auto& r = resp.GetTrace(); + UNIT_ASSERT_VALUES_EQUAL(21, r.EventsSize()); + + { + const auto& p = r.GetEvents(0); + UNIT_ASSERT_VALUES_EQUAL("BLOBSTORAGE_PROVIDER", p.GetProvider()); + UNIT_ASSERT_VALUES_EQUAL("DSProxyGetHandle", p.GetName()); + UNIT_ASSERT_VALUES_EQUAL(0 , p.ParamsSize()); + } + + { + const auto& p = r.GetEvents(1); + UNIT_ASSERT_VALUES_EQUAL("DSProxyGetBootstrap", p.GetName()); + UNIT_ASSERT_VALUES_EQUAL(0 , p.ParamsSize()); + } + + { + const auto& p = r.GetEvents(2); + UNIT_ASSERT_VALUES_EQUAL("DSProxyGetRequest", p.GetName()); + // check groupId + UNIT_ASSERT_VALUES_EQUAL(0, p.GetParams(0).GetUintValue()); + // check deviceType + UNIT_ASSERT_VALUES_EQUAL("DEVICE_TYPE_UNKNOWN(255)", p.GetParams(1).GetStrValue()); + // check handleClass + UNIT_ASSERT_VALUES_EQUAL("FastRead", p.GetParams(2).GetStrValue()); + } + + TVector vdiskOrderNum = {0, 1, 4, 5, 6, 7}; + for (auto i = 3; i < 9; ++i) { + const auto& p = r.GetEvents(i); + UNIT_ASSERT_VALUES_EQUAL("DSProxyVGetSent", p.GetName()); + // check vdiskId + UNIT_ASSERT_VALUES_EQUAL("[0:_:0:" + ToString(vdiskOrderNum[i-3]) + ":0]", p.GetParams(0).GetStrValue()); + // check vdiskOrderNum + UNIT_ASSERT_VALUES_EQUAL(vdiskOrderNum[i-3], p.GetParams(1).GetUintValue()); + // check vgets count + UNIT_ASSERT_VALUES_EQUAL(6, p.GetParams(2).GetUintValue()); + } + + for (auto i = 9; i < 13; ++i) { + const auto& p = r.GetEvents(i); + UNIT_ASSERT_VALUES_EQUAL("DSProxyVDiskRequestDuration", p.GetName()); + } + + for (auto i = 13; i < 15; ++i) { + const auto& p = r.GetEvents(i); + UNIT_ASSERT_VALUES_EQUAL("DSProxyScheduleAccelerate", p.GetName()); + UNIT_ASSERT_VALUES_EQUAL("Get", p.GetParams(1).GetStrValue()); + } + + for (auto i = 15; i < 17; ++i) { + const auto& p = r.GetEvents(i); + UNIT_ASSERT_VALUES_EQUAL("DSProxyVDiskRequestDuration", p.GetName()); + } + + { + const auto& p = r.GetEvents(17); + UNIT_ASSERT_VALUES_EQUAL("DSProxyStartTransfer", p.GetName()); + UNIT_ASSERT_VALUES_EQUAL(0 , p.ParamsSize()); + } + + { + const auto& p = r.GetEvents(18); + UNIT_ASSERT_VALUES_EQUAL("VDiskStartProcessing", p.GetName()); + UNIT_ASSERT_VALUES_EQUAL(0 , p.ParamsSize()); + } + + { + const auto& p = r.GetEvents(19); + UNIT_ASSERT_VALUES_EQUAL("VDiskReply", p.GetName()); + UNIT_ASSERT_VALUES_EQUAL(0 , p.ParamsSize()); + } + + { + const auto& p = r.GetEvents(20); + UNIT_ASSERT_VALUES_EQUAL("DSProxyGetReply", p.GetName()); + UNIT_ASSERT_VALUES_EQUAL(0 , p.ParamsSize()); + } +} } // Y_UNIT_TEST_SUITE TBlobStorageProxySequenceTest } // namespace NBlobStorageProxySequenceTest diff --git a/ydb/core/blobstorage/lwtrace_probes/blobstorage_probes.h b/ydb/core/blobstorage/lwtrace_probes/blobstorage_probes.h index fa03fd03e7ee..17626ab65ae2 100644 --- a/ydb/core/blobstorage/lwtrace_probes/blobstorage_probes.h +++ b/ydb/core/blobstorage/lwtrace_probes/blobstorage_probes.h @@ -284,6 +284,8 @@ struct TEventTypeField { PROBE(DSProxyGetBootstrap, GROUPS("DSProxy"), TYPES(), NAMES()) \ PROBE(DSProxyGetHandle, GROUPS("DSProxy", "LWTrackStart"), TYPES(), NAMES()) \ PROBE(DSProxyGetReply, GROUPS("DSProxy"), TYPES(), NAMES()) \ + PROBE(DSProxyVGetSent, GROUPS("DSProxy"), TYPES(TString, ui32, ui32), NAMES("vDiskId", "vdiskOrderNum", "count")) \ + PROBE(DSProxyGetRequest, GROUPS("DSProxy", "LWTrackStart"), TYPES(ui32, TString, TString), NAMES("groupId", "deviceType", "handleClass")) \ PROBE(DSProxyPutEnqueue, GROUPS("DSProxy", "LWTrackStart"), TYPES(), NAMES()) \ PROBE(DSProxyPutHandle, GROUPS("DSProxyRequest", "DSProxy", "LWTrackStart"), TYPES(), NAMES()) \ PROBE(DSProxyPutBootstrapStart, GROUPS("DSProxy"), TYPES(), NAMES()) \ @@ -293,7 +295,7 @@ struct TEventTypeField { PROBE(DSProxyPutReply, GROUPS("DSProxy"), TYPES(TString, TString, TString), NAMES("blobId", "status", "errorReason")) \ PROBE(DSProxyPutResumeBootstrap, GROUPS("DSProxy"), TYPES(), NAMES()) \ PROBE(DSProxyPutPauseBootstrap, GROUPS("DSProxy"), TYPES(), NAMES()) \ - PROBE(DSProxyScheduleAccelerate, GROUPS("DSProxy"), TYPES(double), NAMES("timeBeforeAccelerationMs")) \ + PROBE(DSProxyScheduleAccelerate, GROUPS("DSProxy"), TYPES(double, TString), NAMES("timeBeforeAccelerationMs", "reqType")) \ PROBE(DSProxyStartTransfer, GROUPS("DSProxy"), TYPES(), NAMES()) \ PROBE(VDiskStartProcessing, GROUPS("DSProxy"), TYPES(), NAMES()) \ PROBE(VDiskReply, GROUPS("DSProxy"), TYPES(), NAMES()) \