read rows rpc timeout logs

Author: qrort

ydb/core/grpc_services/rpc_read_rows.cpp

@@ -759,8 +759,41 @@ class TReadRowsRPC : public TActorBootstrapped<TReadRowsRPC> {
     }
 
     void HandleTimeout(TEvents::TEvWakeup::TPtr&) {
-        ReplyWithError(Ydb::StatusIds::TIMEOUT, TStringBuilder() << "ReadRows from table " << GetTable()
-            << " timed out, duration: " << (TAppData::TimeProvider->Now() - StartTime).Seconds() << " sec");
+        TString errorMessage = TStringBuilder() << "ReadRows from table " << GetTable()
+            << " timed out, duration: " << (TAppData::TimeProvider->Now() - StartTime).Seconds() << " sec\n";
+
+        auto errorLog = TStringBuilder() <<  "TableName: " << GetTable() << '\n';
+        
+        errorLog << "ShardIdToReadState: {";
+        ui64 rowsRequested = 0;
+        bool first = true;
+        for (const auto& [shardId, readState] : ShardIdToReadState) {
+            if (!first) {
+                errorLog << ", ";
+            }
+            first = false;
+            errorLog << "{"
+                << " ShardId: " << shardId
+                << " Status: " << readState.Status
+                << " ContinuationToken: " << readState.FirstUnprocessedQuery
+            << " }";
+
+            rowsRequested += readState.Keys.size();
+        }
+        errorLog << "}\n";
+
+        ui64 rowsRead = 0;
+        for (auto& result : EvReadResults) {
+            rowsRead += result->GetRowsCount();
+        }
+
+        errorLog << "ReadsInFlight: " << ReadsInFlight << '\n';
+        errorLog << "Retries: " << Retries << '\n';
+        errorLog << "Rows requested: " << rowsRequested << '\n';
+        errorLog << "Rows read: " << rowsRead << '\n';
+        errorLog << "Estimated RuCost: " << RuCost << '\n';
+        ReplyWithError(Ydb::StatusIds::TIMEOUT, errorMessage);
+        LOG_ERROR_S(TlsActivationContext->AsActorContext(), NKikimrServices::RPC_REQUEST, "TReadRowsRPC HandleTimeout actor state: " << errorLog);
     }
 
     void HandleForget(TRpcServices::TEvForgetOperation::TPtr& ev) {

ydb/services/ydb/ydb_read_rows_ut.cpp

@@ -92,8 +92,27 @@ Y_UNIT_TEST_SUITE(ReadRows) {
             UNIT_ASSERT_VALUES_EQUAL(res.status(), ::Ydb::StatusIds::UNAVAILABLE);
         }
 
-    }
+        dsReadResultOberver.Remove();
+        
+
+        // Slow read
+        auto dsReadResultObserver = runtime.AddObserver<TEvDataShard::TEvReadResult>([&](auto&) {
+            SimulateSleep(runtime, TDuration::Seconds(100));
+        });
 
+        // Timeout
+        {
+            Ydb::Table::ReadRowsRequest request = MakeReadRowsRequest("/Root/table-1", {1, 5});
+            auto readRowsFuture = NRpcService::DoLocalRpc<TEvReadRowsRequest>(
+                std::move(request), "/Root", "", runtime.GetActorSystem(0));
+            auto res = runtime.WaitFuture(readRowsFuture, TDuration::Seconds(10));
+            UNIT_ASSERT_VALUES_EQUAL(res.status(), ::Ydb::StatusIds::TIMEOUT);
+            UNIT_ASSERT_VALUES_EQUAL(
+                res.issues().begin()->Getmessage(), 
+                "ReadRows from table /Root/table-1 timed out, duration: 60 sec\n"
+            );
+        }
+    }
 }
 
 } // namespace NKikimr