11#include " dsproxy.h"
22#include " dsproxy_mon.h"
33#include " root_cause.h"
4+ #include < ydb/core/blobstorage/dsproxy/dsproxy_request_reporting.h>
45#include < ydb/core/blobstorage/vdisk/common/vdisk_events.h>
56#include < ydb/core/blobstorage/lwtrace_probes/blobstorage_probes.h>
7+ #include < ydb/core/util/stlog.h>
68#include < library/cpp/containers/stack_vector/stack_vec.h>
79#include < library/cpp/digest/crc32c/crc32c.h>
810#include < util/generic/set.h>
@@ -36,8 +38,7 @@ class TBlobStorageGroupGetRequest : public TBlobStorageGroupRequestActor<TBlobSt
3638 TRootCause RootCauseTrack;
3739 NLWTrace::TOrbit Orbit;
3840 const TInstant Deadline;
39- TInstant StartTime;
40- TInstant StartTimePut;
41+ TMonotonic StartTimePut;
4142 ui32 RequestsSent = 0 ;
4243 ui32 ResponsesReceived = 0 ;
4344 ui32 GroupSize;
@@ -57,6 +58,8 @@ class TBlobStorageGroupGetRequest : public TBlobStorageGroupRequestActor<TBlobSt
5758 ui32 PutsAccelerated = 0 ;
5859 bool IsPutAccelerateScheduled = false ;
5960
61+ TDuration LongRequestThreshold;
62+
6063 void Handle (TEvAccelerateGet::TPtr &ev) {
6164 IsGetAccelerateScheduled = false ;
6265 RootCauseTrack.OnAccelerate (ev->Get ()->CauseIdx );
@@ -75,6 +78,7 @@ class TBlobStorageGroupGetRequest : public TBlobStorageGroupRequestActor<TBlobSt
7578 }
7679 GetsAccelerated++;
7780
81+ GetImpl.History .AddAcceleration (false );
7882 TDeque<std::unique_ptr<TEvBlobStorage::TEvVGet>> vGets;
7983 TDeque<std::unique_ptr<TEvBlobStorage::TEvVPut>> vPuts;
8084 GetImpl.AccelerateGet (LogCtx, GetUnresponsiveDisksMask (), vGets, vPuts);
@@ -90,6 +94,7 @@ class TBlobStorageGroupGetRequest : public TBlobStorageGroupRequestActor<TBlobSt
9094 }
9195 PutsAccelerated++;
9296
97+ GetImpl.History .AddAcceleration (true );
9398 TDeque<std::unique_ptr<TEvBlobStorage::TEvVGet>> vGets;
9499 TDeque<std::unique_ptr<TEvBlobStorage::TEvVPut>> vPuts;
95100 GetImpl.AcceleratePut (LogCtx, GetUnresponsiveDisksMask (), vGets, vPuts);
@@ -107,7 +112,7 @@ class TBlobStorageGroupGetRequest : public TBlobStorageGroupRequestActor<TBlobSt
107112 if (vPuts.size ()) {
108113 if (!IsPutStarted) {
109114 IsPutStarted = true ;
110- StartTimePut = TActivationContext::Now ();
115+ StartTimePut = TActivationContext::Monotonic ();
111116 }
112117 }
113118 for (size_t i = 0 ; i < vGets.size (); ++i) {
@@ -138,6 +143,7 @@ class TBlobStorageGroupGetRequest : public TBlobStorageGroupRequestActor<TBlobSt
138143 }
139144 SendToQueues (vGets, false );
140145 SendToQueues (vPuts, false );
146+ GetImpl.History .AddAllWaiting ();
141147 }
142148
143149 ui32 CountDisksWithActiveRequests () {
@@ -316,8 +322,8 @@ class TBlobStorageGroupGetRequest : public TBlobStorageGroupRequestActor<TBlobSt
316322 // Count VDisks that have requests in flight, if there is no more than 2 such VDisks, Accelerate
317323 if (CountDisksWithActiveRequests () <= 2 ) {
318324 ui64 timeToAccelerateUs = GetImpl.GetTimeToAccelerateGetNs (LogCtx, GetsAccelerated) / 1000 ;
319- TInstant now = TActivationContext::Now ();
320- TDuration timeSinceStart = (now > StartTime ) ? (now - StartTime ) : TDuration::MilliSeconds (0 );
325+ TMonotonic now = TActivationContext::Monotonic ();
326+ TDuration timeSinceStart = (now > RequestStartTime ) ? (now - RequestStartTime ) : TDuration::MilliSeconds (0 );
321327 if (timeSinceStart.MicroSeconds () < timeToAccelerateUs) {
322328 ui64 causeIdx = RootCauseTrack.RegisterAccelerate ();
323329 Schedule (TDuration::MicroSeconds (timeToAccelerateUs - timeSinceStart.MicroSeconds ()),
@@ -335,7 +341,7 @@ class TBlobStorageGroupGetRequest : public TBlobStorageGroupRequestActor<TBlobSt
335341 // Count VDisks that have requests in flight, if there is no more than 2 such VDisks, Accelerate
336342 if (CountDisksWithActiveRequests () <= 2 ) {
337343 ui64 timeToAccelerateUs = GetImpl.GetTimeToAcceleratePutNs (LogCtx, PutsAccelerated) / 1000 ;
338- TInstant now = TActivationContext::Now ();
344+ TMonotonic now = TActivationContext::Monotonic ();
339345 TDuration timeSinceStart = (now > StartTimePut) ? (now - StartTimePut) : TDuration::MilliSeconds (0 );
340346 if (timeSinceStart.MicroSeconds () < timeToAccelerateUs) {
341347 ui64 causeIdx = RootCauseTrack.RegisterAccelerate ();
@@ -350,9 +356,10 @@ class TBlobStorageGroupGetRequest : public TBlobStorageGroupRequestActor<TBlobSt
350356 }
351357
352358 void SendReplyAndDie (TAutoPtr<TEvBlobStorage::TEvGetResult> &evResult) {
353- const TInstant now = TActivationContext::Now ();
354- const TDuration duration = (now > StartTime) ? (now - StartTime) : TDuration::MilliSeconds (0 );
355- Mon->CountGetResponseTime (Info->GetDeviceType (), GetImpl.GetHandleClass (), evResult->PayloadSizeBytes (), duration);
359+ const TMonotonic now = TActivationContext::Monotonic ();
360+ const TDuration duration = now - RequestStartTime;
361+ NKikimrBlobStorage::EGetHandleClass handleClass = GetImpl.GetHandleClass ();
362+ Mon->CountGetResponseTime (Info->GetDeviceType (), handleClass, evResult->PayloadSizeBytes (), duration);
356363 *Mon->ActiveGetCapacity -= ReportedBytes;
357364 ReportedBytes = 0 ;
358365 bool success = evResult->Status == NKikimrProto::OK;
@@ -368,9 +375,22 @@ class TBlobStorageGroupGetRequest : public TBlobStorageGroupRequestActor<TBlobSt
368375 LWTRACK (DSProxyGetReply, Orbit);
369376 evResult->Orbit = std::move (Orbit);
370377 LWPROBE (DSProxyRequestDuration, TEvBlobStorage::EvGet, requestSize, duration.SecondsFloat () * 1000.0 , tabletId,
371- evResult->GroupId , channel, NKikimrBlobStorage::EGetHandleClass_Name (GetImpl. GetHandleClass () ),
378+ evResult->GroupId , channel, NKikimrBlobStorage::EGetHandleClass_Name (handleClass ),
372379 success);
373380 A_LOG_LOG_S (true , success ? NLog::PRI_INFO : NLog::PRI_NOTICE, " BPG68" , " Result# " << evResult->Print (false ));
381+
382+ if (TActivationContext::Monotonic () - RequestStartTime >= LongRequestThreshold) {
383+ if (AllowToReport (GetImpl.GetHandleClass ())) {
384+ STLOG (PRI_WARN, BS_PROXY_GET, BPG71, " Long TEvGet request detected" , \
385+ (LongRequestThreshold, LongRequestThreshold), \
386+ (GroupId, Info->GroupID ), \
387+ (SubrequestsCount, evResult->ResponseSz ), \
388+ (RequestTotalSize, requestSize), \
389+ (HandleClass, NKikimrBlobStorage::EGetHandleClass_Name (handleClass)), \
390+ (RestartCounter, RestartCounter), \
391+ (History, GetImpl.PrintHistory ()));
392+ }
393+ }
374394 return SendResponseAndDie (std::unique_ptr<TEvBlobStorage::TEvGetResult>(evResult.Release ()));
375395 }
376396
@@ -398,10 +418,10 @@ class TBlobStorageGroupGetRequest : public TBlobStorageGroupRequestActor<TBlobSt
398418 LogCtx.RequestPrefix)
399419 , Orbit(std::move(params.Common.Event->Orbit))
400420 , Deadline(params.Common.Event->Deadline)
401- , StartTime(params.Common.Now)
402- , StartTimePut(StartTime)
421+ , StartTimePut(RequestStartTime)
403422 , GroupSize(Info->Type.BlobSubgroupSize())
404423 , ReportedBytes(0 )
424+ , LongRequestThreshold(params.LongRequestThreshold)
405425 {
406426 ReportBytes (sizeof (*this ));
407427 MaxSaneRequests = params.Common .Event ->QuerySize * Info->Type .TotalPartCount () *
0 commit comments