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 {
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;
@@ -58,6 +59,7 @@ class TBlobStorageGroupGetRequest : public TBlobStorageGroupRequestActor {
5859 bool IsPutAccelerateScheduled = false ;
5960
6061 TAccelerationParams AccelerationParams;
62+ TDuration LongRequestThreshold;
6163
6264 void Handle (TEvAccelerateGet::TPtr &ev) {
6365 IsGetAccelerateScheduled = false ;
@@ -77,6 +79,7 @@ class TBlobStorageGroupGetRequest : public TBlobStorageGroupRequestActor {
7779 }
7880 GetsAccelerated++;
7981
82+ GetImpl.History .AddAcceleration (false );
8083 TDeque<std::unique_ptr<TEvBlobStorage::TEvVGet>> vGets;
8184 TDeque<std::unique_ptr<TEvBlobStorage::TEvVPut>> vPuts;
8285 GetImpl.AccelerateGet (LogCtx, GetUnresponsiveDisksMask (), vGets, vPuts);
@@ -92,6 +95,7 @@ class TBlobStorageGroupGetRequest : public TBlobStorageGroupRequestActor {
9295 }
9396 PutsAccelerated++;
9497
98+ GetImpl.History .AddAcceleration (true );
9599 TDeque<std::unique_ptr<TEvBlobStorage::TEvVGet>> vGets;
96100 TDeque<std::unique_ptr<TEvBlobStorage::TEvVPut>> vPuts;
97101 GetImpl.AcceleratePut (LogCtx, GetUnresponsiveDisksMask (), vGets, vPuts);
@@ -111,7 +115,7 @@ class TBlobStorageGroupGetRequest : public TBlobStorageGroupRequestActor {
111115 if (vPuts.size ()) {
112116 if (!IsPutStarted) {
113117 IsPutStarted = true ;
114- StartTimePut = TActivationContext::Now ();
118+ StartTimePut = TActivationContext::Monotonic ();
115119 }
116120 }
117121 for (size_t i = 0 ; i < vGets.size (); ++i) {
@@ -148,6 +152,7 @@ class TBlobStorageGroupGetRequest : public TBlobStorageGroupRequestActor {
148152 const ui64 cookie = ev->Record .GetCookie ();
149153 SendToQueue (std::move (ev), cookie);
150154 }
155+ GetImpl.History .AddAllWaiting ();
151156 }
152157
153158 ui32 CountDisksWithActiveRequests () {
@@ -326,8 +331,8 @@ class TBlobStorageGroupGetRequest : public TBlobStorageGroupRequestActor {
326331 if (CountDisksWithActiveRequests () <= 2 ) {
327332 ui64 timeToAccelerateUs = GetImpl.GetTimeToAccelerateGetNs (LogCtx) / 1000 ;
328333 TDuration timeToAccelerate = TDuration::MicroSeconds (timeToAccelerateUs);
329- TInstant now = TActivationContext::Now ();
330- TInstant nextAcceleration = StartTime + timeToAccelerate;
334+ TMonotonic now = TActivationContext::Monotonic ();
335+ TMonotonic nextAcceleration = RequestStartTime + timeToAccelerate;
331336 if (nextAcceleration > now) {
332337 ui64 causeIdx = RootCauseTrack.RegisterAccelerate ();
333338 Schedule (nextAcceleration - now, new TEvAccelerateGet (causeIdx));
@@ -345,8 +350,8 @@ class TBlobStorageGroupGetRequest : public TBlobStorageGroupRequestActor {
345350 if (CountDisksWithActiveRequests () <= 2 ) {
346351 ui64 timeToAccelerateUs = GetImpl.GetTimeToAcceleratePutNs (LogCtx) / 1000 ;
347352 TDuration timeToAccelerate = TDuration::MicroSeconds (timeToAccelerateUs);
348- TInstant now = TActivationContext::Now ();
349- TInstant nextAcceleration = StartTime + timeToAccelerate;
353+ TMonotonic now = TActivationContext::Monotonic ();
354+ TMonotonic nextAcceleration = RequestStartTime + timeToAccelerate;
350355 if (nextAcceleration > now) {
351356 ui64 causeIdx = RootCauseTrack.RegisterAccelerate ();
352357 Schedule (nextAcceleration - now, new TEvAcceleratePut (causeIdx));
@@ -359,9 +364,10 @@ class TBlobStorageGroupGetRequest : public TBlobStorageGroupRequestActor {
359364 }
360365
361366 void SendReplyAndDie (TAutoPtr<TEvBlobStorage::TEvGetResult> &evResult) {
362- const TInstant now = TActivationContext::Now ();
363- const TDuration duration = (now > StartTime) ? (now - StartTime) : TDuration::MilliSeconds (0 );
364- Mon->CountGetResponseTime (Info->GetDeviceType (), GetImpl.GetHandleClass (), evResult->PayloadSizeBytes (), duration);
367+ const TMonotonic now = TActivationContext::Monotonic ();
368+ const TDuration duration = now - RequestStartTime;
369+ NKikimrBlobStorage::EGetHandleClass handleClass = GetImpl.GetHandleClass ();
370+ Mon->CountGetResponseTime (Info->GetDeviceType (), handleClass, evResult->PayloadSizeBytes (), duration);
365371 *Mon->ActiveGetCapacity -= ReportedBytes;
366372 ReportedBytes = 0 ;
367373 bool success = evResult->Status == NKikimrProto::OK;
@@ -377,9 +383,22 @@ class TBlobStorageGroupGetRequest : public TBlobStorageGroupRequestActor {
377383 LWTRACK (DSProxyGetReply, Orbit);
378384 evResult->Orbit = std::move (Orbit);
379385 LWPROBE (DSProxyRequestDuration, TEvBlobStorage::EvGet, requestSize, duration.SecondsFloat () * 1000.0 , tabletId,
380- evResult->GroupId , channel, NKikimrBlobStorage::EGetHandleClass_Name (GetImpl. GetHandleClass () ),
386+ evResult->GroupId , channel, NKikimrBlobStorage::EGetHandleClass_Name (handleClass ),
381387 success);
382388 DSP_LOG_LOG_S (success ? NLog::PRI_INFO : NLog::PRI_NOTICE, " BPG68" , " Result# " << evResult->Print (false ));
389+
390+ if (TActivationContext::Monotonic () - RequestStartTime >= LongRequestThreshold) {
391+ if (AllowToReport (GetImpl.GetHandleClass ())) {
392+ STLOG (PRI_WARN, BS_PROXY_GET, BPG71, " Long TEvGet request detected" , \
393+ (LongRequestThreshold, LongRequestThreshold), \
394+ (GroupId, Info->GroupID ), \
395+ (SubrequestsCount, evResult->ResponseSz ), \
396+ (RequestTotalSize, requestSize), \
397+ (HandleClass, NKikimrBlobStorage::EGetHandleClass_Name (handleClass)), \
398+ (RestartCounter, RestartCounter), \
399+ (History, GetImpl.PrintHistory ()));
400+ }
401+ }
383402 return SendResponseAndDie (std::unique_ptr<TEvBlobStorage::TEvGetResult>(evResult.Release ()));
384403 }
385404
@@ -404,11 +423,11 @@ class TBlobStorageGroupGetRequest : public TBlobStorageGroupRequestActor {
404423 params.AccelerationParams, LogCtx.RequestPrefix)
405424 , Orbit(std::move(params.Common.Event->Orbit))
406425 , Deadline(params.Common.Event->Deadline)
407- , StartTime(params.Common.Now)
408- , StartTimePut(StartTime)
426+ , StartTimePut(RequestStartTime)
409427 , GroupSize(Info->Type.BlobSubgroupSize())
410428 , ReportedBytes(0 )
411429 , AccelerationParams(params.AccelerationParams)
430+ , LongRequestThreshold(params.LongRequestThreshold)
412431 {
413432 ReportBytes (sizeof (*this ));
414433 MaxSaneRequests = params.Common .Event ->QuerySize * Info->Type .TotalPartCount () *
0 commit comments