diff --git a/ydb/core/kqp/executer_actor/kqp_executer_impl.h b/ydb/core/kqp/executer_actor/kqp_executer_impl.h index d2abfd352f01..e9597f7ba942 100644 --- a/ydb/core/kqp/executer_actor/kqp_executer_impl.h +++ b/ydb/core/kqp/executer_actor/kqp_executer_impl.h @@ -684,7 +684,7 @@ class TKqpExecuterBase : public TActorBootstrapped { if (statusCode == Ydb::StatusIds::INTERNAL_ERROR) { InternalError(issues); } else if (statusCode == Ydb::StatusIds::TIMEOUT) { - TimeoutError(ev->Sender); + TimeoutError(ev->Sender, issues); } else { RuntimeError(NYql::NDq::DqStatusToYdbStatus(msg.GetStatusCode()), issues); } @@ -1706,29 +1706,32 @@ class TKqpExecuterBase : public TActorBootstrapped { ReplyErrorAndDie(status, &issues); } - void TimeoutError(TActorId abortSender) { + void TimeoutError(TActorId abortSender, NYql::TIssues issues) { if (AlreadyReplied) { LOG_E("Timeout when we already replied - not good" << Endl << TBackTrace().PrintToString() << Endl); return; } const auto status = NYql::NDqProto::StatusIds::TIMEOUT; - const TString message = "Request timeout exceeded"; + if (issues.Empty()) { + issues.AddIssue("Request timeout exceeded"); + } - TerminateComputeActors(Ydb::StatusIds::TIMEOUT, message); + TerminateComputeActors(Ydb::StatusIds::TIMEOUT, issues); AlreadyReplied = true; - LOG_E("Abort execution: " << NYql::NDqProto::StatusIds_StatusCode_Name(status) << "," << message); + LOG_E("Abort execution: " << NYql::NDqProto::StatusIds_StatusCode_Name(status) << ", " << issues.ToOneLineString()); if (ExecuterSpan) { ExecuterSpan.EndError(TStringBuilder() << NYql::NDqProto::StatusIds_StatusCode_Name(status)); } ResponseEv->Record.MutableResponse()->SetStatus(Ydb::StatusIds::TIMEOUT); + NYql::IssuesToMessage(issues, ResponseEv->Record.MutableResponse()->MutableIssues()); // TEvAbortExecution can come from either ComputeActor or SessionActor (== Target). if (abortSender != Target) { - auto abortEv = MakeHolder(status, message); + auto abortEv = MakeHolder(status, issues); this->Send(Target, abortEv.Release()); } diff --git a/ydb/core/kqp/proxy_service/kqp_proxy_service.cpp b/ydb/core/kqp/proxy_service/kqp_proxy_service.cpp index 07c4a3478733..c6793fc65208 100644 --- a/ydb/core/kqp/proxy_service/kqp_proxy_service.cpp +++ b/ydb/core/kqp/proxy_service/kqp_proxy_service.cpp @@ -148,12 +148,14 @@ class TKqpProxyService : public TActorBootstrapped { struct TEvOnRequestTimeout: public TEventLocal { ui64 RequestId; TDuration Timeout; + TDuration InitialTimeout; NYql::NDqProto::StatusIds::StatusCode Status; int Round; TEvOnRequestTimeout(ui64 requestId, TDuration timeout, NYql::NDqProto::StatusIds::StatusCode status, int round) : RequestId(requestId) , Timeout(timeout) + , InitialTimeout(timeout) , Status(status) , Round(round) {} @@ -1283,9 +1285,9 @@ class TKqpProxyService : public TActorBootstrapped { const TKqpSessionInfo* info = LocalSessions->FindPtr(reqInfo->SessionId); if (msg->Round == 0 && info) { - TString message = TStringBuilder() - << "request's " << (msg->Status == NYql::NDqProto::StatusIds::TIMEOUT ? "timeout" : "cancelAfter") - << " exceeded"; + TString message = msg->Status == NYql::NDqProto::StatusIds::TIMEOUT + ? (TStringBuilder() << "Request timeout " << msg->Timeout.MilliSeconds() << "ms exceeded") + : (TStringBuilder() << "Request canceled after " << msg->Timeout.MilliSeconds() << "ms"); Send(info->WorkerId, new TEvKqp::TEvAbortExecution(msg->Status, message)); @@ -1297,7 +1299,7 @@ class TKqpProxyService : public TActorBootstrapped { } } else { TString message = TStringBuilder() - << "Query did not complete within specified timeout, session id " << reqInfo->SessionId; + << "Query did not complete within specified timeout " << msg->InitialTimeout.MilliSeconds() << "ms, session id " << reqInfo->SessionId; ReplyProcessError(NYql::NDq::DqStatusToYdbStatus(msg->Status), message, requestId); } } diff --git a/ydb/core/kqp/run_script_actor/kqp_run_script_actor.cpp b/ydb/core/kqp/run_script_actor/kqp_run_script_actor.cpp index 04fd7ea59ecd..3f93bda5465e 100644 --- a/ydb/core/kqp/run_script_actor/kqp_run_script_actor.cpp +++ b/ydb/core/kqp/run_script_actor/kqp_run_script_actor.cpp @@ -3,6 +3,7 @@ #include #include #include +#include #include #include #include @@ -216,6 +217,12 @@ class TRunScriptActor : public NActors::TActorBootstrapped { WaitFinalizationRequest = true; RunState = IsExecuting() ? ERunState::Finishing : RunState; + if (RunState == ERunState::Cancelling) { + NYql::TIssue cancelIssue("Request was canceled by user"); + cancelIssue.SetCode(NYql::DEFAULT_ERROR, NYql::TSeverityIds::S_INFO); + Issues.AddIssue(std::move(cancelIssue)); + } + auto scriptFinalizeRequest = std::make_unique( GetFinalizationStatusFromRunState(), ExecutionId, Database, Status, GetExecStatusFromStatusCode(Status), Issues, std::move(QueryStats), std::move(QueryPlan), std::move(QueryAst), LeaseGeneration @@ -424,6 +431,13 @@ class TRunScriptActor : public NActors::TActorBootstrapped { const auto& issueMessage = record.GetResponse().GetQueryIssues(); NYql::IssuesFromMessage(issueMessage, Issues); + if (record.GetYdbStatus() == Ydb::StatusIds::TIMEOUT) { + const TDuration timeout = GetQueryTimeout(NKikimrKqp::QUERY_TYPE_SQL_GENERIC_SCRIPT, Request.GetRequest().GetTimeoutMs(), {}, QueryServiceConfig); + NYql::TIssue timeoutIssue(TStringBuilder() << "Current request timeout is " << timeout.MilliSeconds() << "ms"); + timeoutIssue.SetCode(NYql::DEFAULT_ERROR, NYql::TSeverityIds::S_INFO); + Issues.AddIssue(std::move(timeoutIssue)); + } + if (record.GetResponse().HasQueryPlan()) { QueryPlan = record.GetResponse().GetQueryPlan(); } diff --git a/ydb/core/kqp/session_actor/kqp_query_state.cpp b/ydb/core/kqp/session_actor/kqp_query_state.cpp index b61237ea2d4b..7aa59a3909e2 100644 --- a/ydb/core/kqp/session_actor/kqp_query_state.cpp +++ b/ydb/core/kqp/session_actor/kqp_query_state.cpp @@ -138,6 +138,7 @@ std::unique_ptr TKqpQueryState::BuildN bool TKqpQueryState::SaveAndCheckCompileResult(TEvKqp::TEvCompileResponse* ev) { + CompilationRunning = false; CompileResult = ev->CompileResult; YQL_ENSURE(CompileResult); MaxReadType = CompileResult->MaxReadType; diff --git a/ydb/core/kqp/session_actor/kqp_query_state.h b/ydb/core/kqp/session_actor/kqp_query_state.h index 1637495dd19c..0a614cf8c7e0 100644 --- a/ydb/core/kqp/session_actor/kqp_query_state.h +++ b/ydb/core/kqp/session_actor/kqp_query_state.h @@ -128,6 +128,7 @@ class TKqpQueryState : public TNonCopyable { bool KeepSession = false; TIntrusiveConstPtr UserToken; NActors::TMonotonic StartedAt; + bool CompilationRunning = false; THashMap TableVersions; diff --git a/ydb/core/kqp/session_actor/kqp_session_actor.cpp b/ydb/core/kqp/session_actor/kqp_session_actor.cpp index 93f04a624a08..977506b55c2a 100644 --- a/ydb/core/kqp/session_actor/kqp_session_actor.cpp +++ b/ydb/core/kqp/session_actor/kqp_session_actor.cpp @@ -524,6 +524,7 @@ class TKqpSessionActor : public TActorBootstrapped { void CompileQuery() { YQL_ENSURE(QueryState); + QueryState->CompilationRunning = true; auto ev = QueryState->BuildCompileRequest(CompilationCookie, GUCSettings); LOG_D("Sending CompileQuery request"); @@ -1528,16 +1529,22 @@ class TKqpSessionActor : public TActorBootstrapped { TString logMsg = TStringBuilder() << "got TEvAbortExecution in " << CurrentStateFuncName(); LOG_I(logMsg << ", status: " << NYql::NDqProto::StatusIds_StatusCode_Name(msg.GetStatusCode()) << " send to: " << ExecuterId); - TString reason = TStringBuilder() << "Request timeout exceeded, cancelling after " - << (AppData()->MonotonicTimeProvider->Now() - QueryState->StartedAt).MilliSeconds() - << " milliseconds."; + auto issues = ev->Get()->GetIssues(); + TStringBuilder reason = TStringBuilder() << "Cancelling after " << (AppData()->MonotonicTimeProvider->Now() - QueryState->StartedAt).MilliSeconds() << "ms"; + if (QueryState->CompilationRunning) { + reason << " during compilation"; + } else if (ExecuterId) { + reason << " during execution"; + } else { + reason << " in " << CurrentStateFuncName(); + } + issues.AddIssue(reason); if (ExecuterId) { - auto abortEv = MakeHolder(msg.GetStatusCode(), reason); + auto abortEv = MakeHolder(msg.GetStatusCode(), issues); Send(ExecuterId, abortEv.Release(), IEventHandle::FlagTrackDelivery); } else { - const auto& issues = ev->Get()->GetIssues(); - ReplyQueryError(NYql::NDq::DqStatusToYdbStatus(msg.GetStatusCode()), logMsg, MessageFromIssues(issues)); + ReplyQueryError(NYql::NDq::DqStatusToYdbStatus(msg.GetStatusCode()), "", MessageFromIssues(issues)); } } @@ -2279,9 +2286,7 @@ class TKqpSessionActor : public TActorBootstrapped { void Handle(TEvKqp::TEvCancelQueryRequest::TPtr& ev) { { - auto abort = MakeHolder(); - abort->Record.SetStatusCode(NYql::NDqProto::StatusIds::CANCELLED); - abort->Record.AddIssues()->set_message("Canceled"); + auto abort = MakeHolder(NYql::NDqProto::StatusIds::CANCELLED, "Request was canceled"); Send(SelfId(), abort.Release()); } diff --git a/ydb/core/kqp/workload_service/ut/common/kqp_workload_service_ut_common.h b/ydb/core/kqp/workload_service/ut/common/kqp_workload_service_ut_common.h index b433e86d337f..85b1b17af3fd 100644 --- a/ydb/core/kqp/workload_service/ut/common/kqp_workload_service_ut_common.h +++ b/ydb/core/kqp/workload_service/ut/common/kqp_workload_service_ut_common.h @@ -124,7 +124,7 @@ struct TSampleQueries { template static void CheckCancelled(const TResult& result) { UNIT_ASSERT_VALUES_EQUAL_C(result.GetStatus(), NYdb::EStatus::CANCELLED, result.GetIssues().ToString()); - UNIT_ASSERT_STRING_CONTAINS(result.GetIssues().ToString(), "Request timeout exceeded, cancelling after"); + UNIT_ASSERT_STRING_CONTAINS(result.GetIssues().ToString(), "Request was canceled"); } struct TSelect42 { diff --git a/ydb/library/yql/dq/actors/compute/dq_compute_actor_impl.h b/ydb/library/yql/dq/actors/compute/dq_compute_actor_impl.h index 2b8a5dae1de3..1b6bd9f063fd 100644 --- a/ydb/library/yql/dq/actors/compute/dq_compute_actor_impl.h +++ b/ydb/library/yql/dq/actors/compute/dq_compute_actor_impl.h @@ -109,6 +109,7 @@ class TDqComputeActorBase : public NActors::TActorBootstrapped public: void Bootstrap() { try { + StartTime = TInstant::Now(); { TStringBuilder prefixBuilder; prefixBuilder << "SelfId: " << this->SelfId() << ", TxId: " << TxId << ", task: " << Task.GetId() << ". "; @@ -1049,8 +1050,14 @@ class TDqComputeActorBase : public NActors::TActorBootstrapped ); } + TStringBuilder reason = TStringBuilder() << "Task execution timeout "; + if (RuntimeSettings.Timeout) { + reason << RuntimeSettings.Timeout->MilliSeconds() << "ms "; + } + reason << "exceeded, terminating after " << (TInstant::Now() - StartTime).MilliSeconds() << "ms"; + State = NDqProto::COMPUTE_STATE_FAILURE; - ReportStateAndMaybeDie(NYql::NDqProto::StatusIds::TIMEOUT, {TIssue("timeout exceeded")}, true); + ReportStateAndMaybeDie(NYql::NDqProto::StatusIds::TIMEOUT, {TIssue(reason)}, true); break; } case EEvWakeupTag::PeriodicStatsTag: { @@ -1928,6 +1935,7 @@ class TDqComputeActorBase : public NActors::TActorBootstrapped NWilson::TSpan ComputeActorSpan; TDuration SourceCpuTime; private: + TInstant StartTime; bool Running = true; TInstant LastSendStatsTime; bool PassExceptions = false;