Add client timeout histogram for grpc call metrics. (#16065)

In case of investigation problems with unexpected timeout response It is helpful to know actual timeout for grpc call from the server perspective

Author: dcherednik

ydb/core/client/server/grpc_server.cpp

@@ -303,7 +303,7 @@ class TSimpleRequest
         if (Server->IncRequest()) {
 
             RequestSize = Request.ByteSize();
-            Counters->StartProcessing(RequestSize);
+            Counters->StartProcessing(RequestSize, TInstant::Max());
             RequestTimer.Reset();
             InProgress_ = true;
 

ydb/core/grpc_services/counters/counters.cpp

@@ -117,6 +117,7 @@ class TYdbCounterBlock : public NYdbGrpc::ICounterBlock {
     ::NMonitoring::TDynamicCounters::TCounterPtr RequestsWithoutToken;
     ::NMonitoring::TDynamicCounters::TCounterPtr RequestsWithoutTls;
     ::NMonitoring::THistogramPtr Histo;
+    ::NMonitoring::THistogramPtr ClientTimeoutHisto;
 
 
     std::function<void()> InitFn;
@@ -190,7 +191,7 @@ class TYdbCounterBlock : public NYdbGrpc::ICounterBlock {
         *YdbCounters.ResponseBytes += responseSize;
     }
 
-    void StartProcessing(ui32 requestSize) override {
+    void StartProcessing(ui32 requestSize, TInstant deadline) override {
         InitOnce();
         TotalCounter->Inc();
         InflyCounter->Inc();
@@ -201,6 +202,15 @@ class TYdbCounterBlock : public NYdbGrpc::ICounterBlock {
         YdbCounters.RequestInflight->Inc();
         *YdbCounters.RequestBytes += requestSize;
         *YdbCounters.RequestInflightBytes += requestSize;
+        if (deadline != TInstant::Zero() && deadline != TInstant::Max()) {
+            auto now = TInstant::Now();
+            if (deadline > now) {
+                auto timeout = deadline - now;
+                ClientTimeoutHisto->Collect(timeout.MilliSeconds());
+            } else {
+                ClientTimeoutHisto->Collect(0);
+            }
+        }
     }
 
     void FinishProcessing(ui32 requestSize, ui32 responseSize, bool ok, ui32 status,
@@ -330,14 +340,24 @@ TYdbCounterBlock::TYdbCounterBlock(const ::NMonitoring::TDynamicCounterPtr& coun
         TotalCounter = subgroup->GetCounter("total", true);
         InflyCounter = subgroup->GetCounter("infly", false);
 
-        auto h = NMonitoring::ExplicitHistogram(
-            NMonitoring::TBucketBounds{
-                0.5, 1, 2, 3, 4, 5, 6, 7, 8, 9, 10,
-                16, 20, 24, 28, 32, 36,
-                40, 50, 60, 70, 80, 90,
-                100, 200, 300, 400, 500,
-                1000, 5000, 10000, 20000, 60000});
-        Histo = subgroup->GetHistogram("LatencyMs", std::move(h));
+        {
+            auto h = NMonitoring::ExplicitHistogram(
+                NMonitoring::TBucketBounds{
+                    0.5, 1, 2, 3, 4, 5, 6, 7, 8, 9, 10,
+                    16, 20, 24, 28, 32, 36,
+                    40, 50, 60, 70, 80, 90,
+                    100, 200, 300, 400, 500,
+                    1000, 5000, 10000, 20000, 60000});
+            Histo = subgroup->GetHistogram("LatencyMs", std::move(h));
+        }
+
+        {
+            auto h = NMonitoring::ExplicitHistogram(
+                NMonitoring::TBucketBounds{
+                    0, 5, 10, 50, 100, 250, 500,
+                    1000, 5000, 10000, 20000, 60000});
+            ClientTimeoutHisto = subgroup->GetHistogram("TimeoutMs", std::move(h));
+        }
     };
 }
 
@@ -615,9 +635,9 @@ class TYdbCounterBlockWrapper : public NYdbGrpc::ICounterBlock {
         Db->CountResponseBytes(responseSize);
     }
 
-    void StartProcessing(ui32 requestSize) override {
-        Common->StartProcessing(requestSize);
-        Db->StartProcessing(requestSize);
+    void StartProcessing(ui32 requestSize, TInstant deadline) override {
+        Common->StartProcessing(requestSize, deadline);
+        Db->StartProcessing(requestSize, deadline);
     }
 
     void FinishProcessing(ui32 requestSize, ui32 responseSize, bool ok, ui32 status,

ydb/core/grpc_streaming/grpc_streaming.h

@@ -247,7 +247,7 @@ class TGRpcStreamingRequest final
 
         if (IncRequest()) {
             if (Counters) {
-                Counters->StartProcessing(0);
+                Counters->StartProcessing(0, TInstant::Max());
             }
             Flags |= FlagStarted;
 

ydb/library/grpc/server/grpc_counters.cpp

@@ -23,7 +23,7 @@ class TFakeCounterBlock final: public ICounterBlock {
     void CountResponseBytes(ui32 /*responseSize*/) override {
     }
 
-    void StartProcessing(ui32 /*requestSize*/) override {
+    void StartProcessing(ui32 /*requestSize*/, TInstant /*deadline*/) override {
     }
 
     void FinishProcessing(

ydb/library/grpc/server/grpc_counters.h

@@ -13,7 +13,7 @@ struct ICounterBlock : public TThrRefBase {
     virtual void CountResourceExhausted() = 0;
     virtual void CountRequestBytes(ui32 requestSize) = 0;
     virtual void CountResponseBytes(ui32 responseSize) = 0;
-    virtual void StartProcessing(ui32 requestSize) = 0;
+    virtual void StartProcessing(ui32 requestSize, TInstant deadline) = 0;
     virtual void FinishProcessing(ui32 requestSize, ui32 responseSize, bool ok, ui32 status, TDuration requestDuration) = 0;
     virtual void CountRequestsWithoutDatabase() {}
     virtual void CountRequestsWithoutToken() {}
@@ -90,7 +90,7 @@ class TCounterBlock final : public ICounterBlock {
         *ResponseBytes += responseSize;
     }
 
-    void StartProcessing(ui32 requestSize) override {
+    void StartProcessing(ui32 requestSize, TInstant /*deadline*/) override {
         TotalCounter->Inc();
         InflyCounter->Inc();
         *RequestBytes += requestSize;

ydb/library/grpc/server/grpc_request.h

@@ -422,7 +422,7 @@ class TGRpcRequestImpl
         if (IncRequest()) {
             // Adjust counters.
             RequestSize = Request_->ByteSize();
-            Counters_->StartProcessing(RequestSize);
+            Counters_->StartProcessing(RequestSize, Deadline());
             RequestTimer.Reset();
 
             if (!SslServer()) {