2024-06-27T20:19:14.865145Z node 1 :KQP_EXECUTER ERROR: kqp_predictor.cpp:134 :user pool is undefined for executer tasks construction 2024-06-27T20:19:14.865501Z node 1 :METADATA_PROVIDER WARN: fline=table_exists.cpp:54;actor=TTableExistsActor;event=undelivered;self_id=[1:7385280251640167694:4098];send_to=[0:7307199536658146131:7762515]; 2024-06-27T20:19:14.865516Z node 1 :KQP_EXECUTER ERROR: kqp_predictor.cpp:134 :user pool is undefined for executer tasks construction 2024-06-27T20:19:14.865675Z node 1 :KQP_EXECUTER ERROR: kqp_predictor.cpp:134 :user pool is undefined for executer tasks construction 2024-06-27T20:19:14.865680Z node 1 :METADATA_PROVIDER ERROR: fline=accessor_snapshot_base.cpp:68;action=cannot detect path existence;path=//Root/.metadata/initialization/migrations;error=scheme_cache_undelivered_message; test_client.cpp: SetPath # /home/runner/.ya/build/build_root/qrxm/00292c/r3tmp/tmpG120Zh/pdisk_1.dat 2024-06-27T20:19:14.923310Z node 1 :IMPORT WARN: Table profiles were not loaded TServer::EnableGrpc on GrpcPort 20450, node 1 2024-06-27T20:19:14.941280Z node 1 :NET_CLASSIFIER WARN: distributable config is empty, broken or outdated, will use file: (empty maybe) 2024-06-27T20:19:14.941293Z node 1 :NET_CLASSIFIER WARN: will try to initialize from file: (empty maybe) 2024-06-27T20:19:14.941295Z node 1 :NET_CLASSIFIER WARN: failed to initialize from file: (empty maybe) 2024-06-27T20:19:14.941327Z node 1 :NET_CLASSIFIER ERROR: got bad distributable configuration TClient is connected to server localhost:61633 WaitRootIsUp 'Root'... TClient::Ls request: Root TClient::Ls response: 2024-06-27T20:19:14.965625Z node 1 :HIVE WARN: HIVE#72057594037968897 Node(1, (0,0,0,0)) VolatileState: Unknown -> Disconnected 2024-06-27T20:19:14.965653Z node 1 :HIVE WARN: HIVE#72057594037968897 Node(1, (0,0,0,0)) VolatileState: Disconnected -> Connecting Status: 1 StatusCode: SUCCESS SchemeStatus: 0 PathDescription { Self { Name: "Root" PathId: 1 SchemeshardId: 72057594046644480 PathType: EPathTypeDir CreateFinished: true CreateTxId: 1 CreateStep: 0 ParentPathId: 1 PathState: EPathStateNoChanges Owner: "root@builtin" ACL: "" EffectiveACL: "" PathVersion: 2 PathSubType: EPathSubTypeEmpty Version { GeneralVersion: 2 ACLVersion: 0 EffectiveACLVersion: 0 UserAttrsVersion: 1 ChildrenVersion: 1 SubDomainVersion: 0 SecurityStateVersion: 0 } } Children { Name: ".sys" PathId: 18446744073709551615 SchemeshardId: 72057594046644480 PathType: EPathTypeDir CreateFinished: true CreateTxId: 0 CreateStep: 0 ParentPathId: 18446744073709551615 } DomainDescription { SchemeShardId_Depricated: 72057594046644480 PathId_Depricated: 1 ProcessingParams { Version: 0 PlanResolution: 7 Coo... (TRUNCATED) WaitRootIsUp 'Root' success. 2024-06-27T20:19:14.971888Z node 1 :HIVE WARN: HIVE#72057594037968897 Node(1, (0,0,0,0)) VolatileState: Connecting -> Connected waiting... 2024-06-27T20:19:14.978852Z node 1 :FLAT_TX_SCHEMESHARD WARN: NotifyTxCompletion, unknown transaction, txId: 281474976715657, at schemeshard: 72057594046644480 2024-06-27T20:19:14.984635Z node 1 :TICKET_PARSER ERROR: Ticket **** (7F399AB7): System domain not available for user usage 2024-06-27T20:19:15.187426Z node 1 :KQP_WORKLOAD_SERVICE INFO: [WorkloadService] [Service] Started workload service initialization 2024-06-27T20:19:15.187512Z node 1 :KQP_WORKLOAD_SERVICE DEBUG: [WorkloadService] [Service] Subscribed for config changes 2024-06-27T20:19:15.187521Z node 1 :KQP_WORKLOAD_SERVICE INFO: [WorkloadService] [Service] Resource pools was enanbled 2024-06-27T20:19:15.187532Z node 1 :KQP_WORKLOAD_SERVICE DEBUG: [WorkloadService] [TCleanupTablesActor] ActorId: [1:7385280255935135532:8258], Start check tables existence, number paths: 2 2024-06-27T20:19:15.187771Z node 1 :KQP_WORKLOAD_SERVICE DEBUG: [WorkloadService] [TCleanupTablesActor] ActorId: [1:7385280255935135532:8258], Describe table Root/.metadata/workload_manager/delayed_requests status PathErrorUnknown 2024-06-27T20:19:15.187774Z node 1 :KQP_WORKLOAD_SERVICE DEBUG: [WorkloadService] [TCleanupTablesActor] ActorId: [1:7385280255935135532:8258], Describe table Root/.metadata/workload_manager/running_requests status PathErrorUnknown 2024-06-27T20:19:15.187777Z node 1 :KQP_WORKLOAD_SERVICE DEBUG: [WorkloadService] [TCleanupTablesActor] ActorId: [1:7385280255935135532:8258], Successfully finished 2024-06-27T20:19:15.187784Z node 1 :KQP_WORKLOAD_SERVICE DEBUG: [WorkloadService] [Service] Cleanup completed, tables exists: 0 2024-06-27T20:19:15.187949Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=Y2Q4YmY5MzUtYzIzYTMxZjctZGRkMmUxYWYtNDYxZmU1ZGQ=, ActorId: [0:0:0], ActorState: unknown state, Create session actor with id Y2Q4YmY5MzUtYzIzYTMxZjctZGRkMmUxYWYtNDYxZmU1ZGQ= 2024-06-27T20:19:15.188024Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=Y2Q4YmY5MzUtYzIzYTMxZjctZGRkMmUxYWYtNDYxZmU1ZGQ=, ActorId: [1:7385280255935135548:4273], ActorState: unknown state, session actor bootstrapped 2024-06-27T20:19:15.192339Z node 1 :KQP_WORKLOAD_SERVICE DEBUG: [WorkloadService] [TPoolCreatorActor] ActorId: [1:7385280255935135550:12335], Database: Root, PoolId: sample_pool_id, Start pool creating 2024-06-27T20:19:15.193178Z node 1 :KQP_WORKLOAD_SERVICE WARN: [WorkloadService] [TPoolCreatorActor] ActorId: [1:7385280255935135550:12335], Database: Root, PoolId: sample_pool_id, Scheduled retry for error: Retry shard unavailable error 2024-06-27T20:19:15.258789Z node 1 :KQP_WORKLOAD_SERVICE DEBUG: [WorkloadService] [TPoolCreatorActor] ActorId: [1:7385280255935135550:12335], Database: Root, PoolId: sample_pool_id, Start pool creating 2024-06-27T20:19:15.259784Z node 1 :KQP_WORKLOAD_SERVICE DEBUG: [WorkloadService] [TPoolCreatorActor] ActorId: [1:7385280255935135550:12335], Database: Root, PoolId: sample_pool_id, Pool successfully created 2024-06-27T20:19:15.260334Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=YzNiMDM5NDQtNWE1MjdlYzktMWQyNDk1ZDctOGUwZTBjMGI=, ActorId: [0:0:0], ActorState: unknown state, Create session actor with id YzNiMDM5NDQtNWE1MjdlYzktMWQyNDk1ZDctOGUwZTBjMGI= 2024-06-27T20:19:15.260418Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=YzNiMDM5NDQtNWE1MjdlYzktMWQyNDk1ZDctOGUwZTBjMGI=, ActorId: [1:7385280255935135587:4294], ActorState: unknown state, session actor bootstrapped 2024-06-27T20:19:15.260560Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=YzNiMDM5NDQtNWE1MjdlYzktMWQyNDk1ZDctOGUwZTBjMGI=, ActorId: [1:7385280255935135587:4294], ActorState: ReadyState, TraceId: 01j1dnmbnwb3znjgdtw3kv6eed, received request, proxyRequestId: 3 prepared: 0 tx_control: 0 action: QUERY_ACTION_EXECUTE type: QUERY_TYPE_SQL_GENERIC_QUERY text: SELECT 42; rpcActor: [1:7385280255935135584:12336] database: Root pool id: sample_pool_id 2024-06-27T20:19:15.260592Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ZmNiMDg3ZmUtODA1OTcyMmMtNDBmZTNlODUtODkzNTI5NTg=, ActorId: [0:0:0], ActorState: unknown state, Create session actor with id ZmNiMDg3ZmUtODA1OTcyMmMtNDBmZTNlODUtODkzNTI5NTg= 2024-06-27T20:19:15.260602Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ZmNiMDg3ZmUtODA1OTcyMmMtNDBmZTNlODUtODkzNTI5NTg=, ActorId: [1:7385280255935135589:4295], ActorState: unknown state, session actor bootstrapped 2024-06-27T20:19:15.260619Z node 1 :KQP_WORKLOAD_SERVICE DEBUG: [WorkloadService] [Service] Recieved new request from [1:7385280255935135587:4294], Database: Root, PoolId: sample_pool_id, SessionId: ydb://session/3?node_id=1&id=YzNiMDM5NDQtNWE1MjdlYzktMWQyNDk1ZDctOGUwZTBjMGI= 2024-06-27T20:19:15.260623Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ZmNiMDg3ZmUtODA1OTcyMmMtNDBmZTNlODUtODkzNTI5NTg=, ActorId: [1:7385280255935135589:4295], ActorState: ReadyState, TraceId: 01j1dnmbnw7se85r900xdda22m, received request, proxyRequestId: 4 prepared: 0 tx_control: 0 action: QUERY_ACTION_EXECUTE type: QUERY_TYPE_SQL_GENERIC_QUERY text: SELECT 42; rpcActor: [1:7385280255935135586:12346] database: Root pool id: sample_pool_id 2024-06-27T20:19:15.260637Z node 1 :KQP_WORKLOAD_SERVICE DEBUG: [WorkloadService] [Service] Recieved new request from [1:7385280255935135589:4295], Database: Root, PoolId: sample_pool_id, SessionId: ydb://session/3?node_id=1&id=ZmNiMDg3ZmUtODA1OTcyMmMtNDBmZTNlODUtODkzNTI5NTg= 2024-06-27T20:19:15.260640Z node 1 :KQP_WORKLOAD_SERVICE DEBUG: [WorkloadService] [TPoolFetcherActor] ActorId: [1:7385280255935135591:8246], Database: Root, PoolId: sample_pool_id, SessionId: ydb://session/3?node_id=1&id=YzNiMDM5NDQtNWE1MjdlYzktMWQyNDk1ZDctOGUwZTBjMGI=Start pool fetching 2024-06-27T20:19:15.260644Z node 1 :KQP_WORKLOAD_SERVICE DEBUG: [WorkloadService] [TPoolFetcherActor] ActorId: [1:7385280255935135592:8264], Database: Root, PoolId: sample_pool_id, SessionId: ydb://session/3?node_id=1&id=ZmNiMDg3ZmUtODA1OTcyMmMtNDBmZTNlODUtODkzNTI5NTg=Start pool fetching 2024-06-27T20:19:15.260869Z node 1 :KQP_WORKLOAD_SERVICE DEBUG: [WorkloadService] [TPoolFetcherActor] ActorId: [1:7385280255935135592:8264], Database: Root, PoolId: sample_pool_id, SessionId: ydb://session/3?node_id=1&id=ZmNiMDg3ZmUtODA1OTcyMmMtNDBmZTNlODUtODkzNTI5NTg=Pool info successfully fetched 2024-06-27T20:19:15.260869Z node 1 :KQP_WORKLOAD_SERVICE DEBUG: [WorkloadService] [TPoolFetcherActor] ActorId: [1:7385280255935135591:8246], Database: Root, PoolId: sample_pool_id, SessionId: ydb://session/3?node_id=1&id=YzNiMDM5NDQtNWE1MjdlYzktMWQyNDk1ZDctOGUwZTBjMGI=Pool info successfully fetched 2024-06-27T20:19:15.260878Z node 1 :KQP_WORKLOAD_SERVICE DEBUG: [WorkloadService] [Service] Successfully fetched pool sample_pool_id, Database: Root, SessionId: ydb://session/3?node_id=1&id=YzNiMDM5NDQtNWE1MjdlYzktMWQyNDk1ZDctOGUwZTBjMGI= 2024-06-27T20:19:15.260880Z node 1 :KQP_WORKLOAD_SERVICE INFO: [WorkloadService] [Service] Creating new handler for pool Root/sample_pool_id 2024-06-27T20:19:15.260915Z node 1 :KQP_WORKLOAD_SERVICE DEBUG: [WorkloadService] [Service] Successfully fetched pool sample_pool_id, Database: Root, SessionId: ydb://session/3?node_id=1&id=ZmNiMDg3ZmUtODA1OTcyMmMtNDBmZTNlODUtODkzNTI5NTg= 2024-06-27T20:19:15.260921Z node 1 :KQP_WORKLOAD_SERVICE DEBUG: [WorkloadService] [TPoolHandlerActorBase] ActorId: [1:7385280255935135602:8276], Database: Root, PoolId: sample_pool_id, Received new request, worker id: [1:7385280255935135587:4294], session id: ydb://session/3?node_id=1&id=YzNiMDM5NDQtNWE1MjdlYzktMWQyNDk1ZDctOGUwZTBjMGI= 2024-06-27T20:19:15.260929Z node 1 :KQP_WORKLOAD_SERVICE DEBUG: [WorkloadService] [TPoolHandlerActorBase] ActorId: [1:7385280255935135602:8276], Database: Root, PoolId: sample_pool_id, Received new request, worker id: [1:7385280255935135589:4295], session id: ydb://session/3?node_id=1&id=ZmNiMDg3ZmUtODA1OTcyMmMtNDBmZTNlODUtODkzNTI5NTg= 2024-06-27T20:19:15.260933Z node 1 :KQP_WORKLOAD_SERVICE TRACE: [WorkloadService] [Service] Got create teables request, Database: Root, PoolId: sample_pool_id 2024-06-27T20:19:15.260936Z node 1 :KQP_WORKLOAD_SERVICE INFO: [WorkloadService] [Service] Started workload service tables creation 2024-06-27T20:19:15.260968Z node 1 :KQP_WORKLOAD_SERVICE TRACE: [WorkloadService] [Service] Got create teables request, Database: Root, PoolId: sample_pool_id 2024-06-27T20:19:15.261001Z node 1 :KQP_WORKLOAD_SERVICE DEBUG: Table delayed_requests updater. Describe result: PathErrorUnknown 2024-06-27T20:19:15.261007Z node 1 :KQP_WORKLOAD_SERVICE NOTICE: Table delayed_requests updater. Creating table 2024-06-27T20:19:15.261012Z node 1 :KQP_WORKLOAD_SERVICE DEBUG: Table delayed_requests updater. Full table path:/Root/.metadata/workload_manager/delayed_requests 2024-06-27T20:19:15.261032Z node 1 :KQP_WORKLOAD_SERVICE DEBUG: Table running_requests updater. Describe result: PathErrorUnknown 2024-06-27T20:19:15.261033Z node 1 :KQP_WORKLOAD_SERVICE NOTICE: Table running_requests updater. Creating table 2024-06-27T20:19:15.261036Z node 1 :KQP_WORKLOAD_SERVICE DEBUG: Table running_requests updater. Full table path:/Root/.metadata/workload_manager/running_requests 2024-06-27T20:19:15.263147Z node 1 :KQP_WORKLOAD_SERVICE DEBUG: Table running_requests updater. TEvProposeTransactionStatus: { Status: 53 TxId: 281474976715661 SchemeShardStatus: 1 SchemeShardTabletId: 72057594046644480 PathId: 6 } 2024-06-27T20:19:15.263157Z node 1 :KQP_WORKLOAD_SERVICE DEBUG: Table running_requests updater. Subscribe on create table tx: 281474976715661 2024-06-27T20:19:15.263449Z node 1 :KQP_WORKLOAD_SERVICE DEBUG: Table delayed_requests updater. TEvProposeTransactionStatus: { Status: 53 TxId: 281474976715660 SchemeShardStatus: 1 SchemeShardTabletId: 72057594046644480 PathId: 7 } 2024-06-27T20:19:15.263452Z node 1 :KQP_WORKLOAD_SERVICE DEBUG: Table delayed_requests updater. Subscribe on create table tx: 281474976715660 2024-06-27T20:19:15.321233Z node 1 :KQP_WORKLOAD_SERVICE DEBUG: Table running_requests updater. Request: create. Transaction completed: 281474976715661. Doublechecking... 2024-06-27T20:19:15.327058Z node 1 :KQP_WORKLOAD_SERVICE DEBUG: Table delayed_requests updater. Request: create. Transaction completed: 281474976715660. Doublechecking... 2024-06-27T20:19:15.409858Z node 1 :KQP_WORKLOAD_SERVICE DEBUG: Table running_requests updater. Column diff is empty, finishing 2024-06-27T20:19:15.418613Z node 1 :KQP_WORKLOAD_SERVICE DEBUG: Table delayed_requests updater. Column diff is empty, finishing 2024-06-27T20:19:15.418653Z node 1 :KQP_WORKLOAD_SERVICE DEBUG: [WorkloadService] [Service] Succefully created tables, send response to handlers 2024-06-27T20:19:15.418688Z node 1 :KQP_WORKLOAD_SERVICE DEBUG: [TQueryBase] [TRefreshPoolStateQuery] TraceId: sample_pool_id, RequestDatabase: Root, RequestSessionId: , Bootstrap. Database: /Root 2024-06-27T20:19:15.420911Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=OWY1YTAyMzQtZGJjMjVlOGQtYTZjYWI3ZDMtODQ5Y2Q0OWU=, ActorId: [0:0:0], ActorState: unknown state, Create session actor with id OWY1YTAyMzQtZGJjMjVlOGQtYTZjYWI3ZDMtODQ5Y2Q0OWU= 2024-06-27T20:19:15.420972Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=OWY1YTAyMzQtZGJjMjVlOGQtYTZjYWI3ZDMtODQ5Y2Q0OWU=, ActorId: [1:7385280255935135769:4307], ActorState: unknown state, session actor bootstrapped 2024-06-27T20:19:15.421106Z node 1 :KQP_WORKLOAD_SERVICE DEBUG: [TQueryBase] [TRefreshPoolStateQuery] TraceId: sample_pool_id, RequestDatabase: Root, RequestSessionId: , RunDataQuery: -- TRefreshPoolStateQuery::OnRunQuery DECLARE $database AS Text; DECLARE $pool_id AS Text; DECLARE $node_id AS Uint32; DECLARE $lease_duration AS Interval; UPDATE `.metadata/workload_manager/delayed_requests` SET lease_deadline = CurrentUtcTimestamp() + $lease_duration WHERE database = $database AND pool_id = $pool_id AND node_id = $node_id AND (wait_deadline IS NULL OR wait_deadline >= CurrentUtcTimestamp()) AND lease_deadline >= CurrentUtcTimestamp(); UPDATE `.metadata/workload_manager/running_requests` SET lease_deadline = CurrentUtcTimestamp() + $lease_duration WHERE database = $database AND pool_id = $pool_id AND node_id = $node_id AND lease_deadline >= CurrentUtcTimestamp(); 2024-06-27T20:19:15.421333Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=OWY1YTAyMzQtZGJjMjVlOGQtYTZjYWI3ZDMtODQ5Y2Q0OWU=, ActorId: [1:7385280255935135769:4307], ActorState: ReadyState, TraceId: 01j1dnmbtx3g0cpy7yhcd54aat, received request, proxyRequestId: 6 prepared: 0 tx_control: 1 action: QUERY_ACTION_EXECUTE type: QUERY_TYPE_SQL_DML text: -- TRefreshPoolStateQuery::OnRunQuery DECLARE $database AS Text; DECLARE $pool_id AS Text; DECLARE $node_id AS Uint32; DECLARE $lease_duration AS Interval; UPDATE `.metadata/workload_manager/delayed_requests` SET lease_deadline = CurrentUtcTimestamp() + $lease_duration WHERE database = $database AND pool_id = $pool_id AND node_id = $node_id AND (wait_deadline IS NULL OR wait_deadline >= CurrentUtcTimestamp()) AND lease_deadline >= CurrentUtcTimestamp(); UPDATE `.metadata/workload_manager/running_requests` SET lease_deadline = CurrentUtcTimestamp() + $lease_duration WHERE database = $database AND pool_id = $pool_id AND node_id = $node_id AND lease_deadline >= CurrentUtcTimestamp(); rpcActor: [1:7385280255935135770:4282] database: /Root pool id: 2024-06-27T20:19:15.421353Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=OWY1YTAyMzQtZGJjMjVlOGQtYTZjYWI3ZDMtODQ5Y2Q0OWU=, ActorId: [1:7385280255935135769:4307], ActorState: ReadyState, TraceId: 01j1dnmbtx3g0cpy7yhcd54aat, Sending CompileQuery request 2024-06-27T20:19:15.479093Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=OWY1YTAyMzQtZGJjMjVlOGQtYTZjYWI3ZDMtODQ5Y2Q0OWU=, ActorId: [1:7385280255935135769:4307], ActorState: ExecuteState, TraceId: 01j1dnmbtx3g0cpy7yhcd54aat, ExecutePhyTx, tx: 0x0000075C7AC19698 literal: 0 commit: 0 txCtx.DeferredEffects.size(): 0 2024-06-27T20:19:15.479117Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=OWY1YTAyMzQtZGJjMjVlOGQtYTZjYWI3ZDMtODQ5Y2Q0OWU=, ActorId: [1:7385280255935135769:4307], ActorState: ExecuteState, TraceId: 01j1dnmbtx3g0cpy7yhcd54aat, Sending to Executer TraceId: 0 8 2024-06-27T20:19:15.479145Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=OWY1YTAyMzQtZGJjMjVlOGQtYTZjYWI3ZDMtODQ5Y2Q0OWU=, ActorId: [1:7385280255935135769:4307], ActorState: ExecuteState, TraceId: 01j1dnmbtx3g0cpy7yhcd54aat, Created new KQP executer: [1:7385280255935135778:4307] isRollback: 0 2024-06-27T20:19:15.483156Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=OWY1YTAyMzQtZGJjMjVlOGQtYTZjYWI3ZDMtODQ5Y2Q0OWU=, ActorId: [1:7385280255935135769:4307], ActorState: ExecuteState, TraceId: 01j1dnmbtx3g0cpy7yhcd54aat, TEvTxResponse, CurrentTx: 1/2 response.status: SUCCESS 2024-06-27T20:19:15.483216Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=OWY1YTAyMzQtZGJjMjVlOGQtYTZjYWI3ZDMtODQ5Y2Q0OWU=, ActorId: [1:7385280255935135769:4307], ActorState: ExecuteState, TraceId: 01j1dnmbtx3g0cpy7yhcd54aat, ExecutePhyTx, tx: 0x0000000000000000 literal: 0 commit: 1 txCtx.DeferredEffects.size(): 1 2024-06-27T20:19:15.483229Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=OWY1YTAyMzQtZGJjMjVlOGQtYTZjYWI3ZDMtODQ5Y2Q0OWU=, ActorId: [1:7385280255935135769:4307], ActorState: ExecuteState, TraceId: 01j1dnmbtx3g0cpy7yhcd54aat, TExecPhysicalRequest, add DeferredEffect to Transaction, current Transactions.size(): 1 2024-06-27T20:19:15.483231Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=OWY1YTAyMzQtZGJjMjVlOGQtYTZjYWI3ZDMtODQ5Y2Q0OWU=, ActorId: [1:7385280255935135769:4307], ActorState: ExecuteState, TraceId: 01j1dnmbtx3g0cpy7yhcd54aat, TExecPhysicalRequest, tx has commit locks 2024-06-27T20:19:15.483237Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=OWY1YTAyMzQtZGJjMjVlOGQtYTZjYWI3ZDMtODQ5Y2Q0OWU=, ActorId: [1:7385280255935135769:4307], ActorState: ExecuteState, TraceId: 01j1dnmbtx3g0cpy7yhcd54aat, Sending to Executer TraceId: 0 8 2024-06-27T20:19:15.483246Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=OWY1YTAyMzQtZGJjMjVlOGQtYTZjYWI3ZDMtODQ5Y2Q0OWU=, ActorId: [1:7385280255935135769:4307], ActorState: ExecuteState, TraceId: 01j1dnmbtx3g0cpy7yhcd54aat, Created new KQP executer: [1:7385280255935135803:4307] isRollback: 0 2024-06-27T20:19:15.488839Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=OWY1YTAyMzQtZGJjMjVlOGQtYTZjYWI3ZDMtODQ5Y2Q0OWU=, ActorId: [1:7385280255935135769:4307], ActorState: ExecuteState, TraceId: 01j1dnmbtx3g0cpy7yhcd54aat, TEvTxResponse, CurrentTx: 2/2 response.status: SUCCESS 2024-06-27T20:19:15.488916Z node 1 :KQP_SESSION INFO: SessionId: ydb://session/3?node_id=1&id=OWY1YTAyMzQtZGJjMjVlOGQtYTZjYWI3ZDMtODQ5Y2Q0OWU=, ActorId: [1:7385280255935135769:4307], ActorState: ExecuteState, TraceId: 01j1dnmbtx3g0cpy7yhcd54aat, txInfo Status: Committed Kind: ReadWrite TotalDuration: 9.897 ServerDuration: 9.846 QueriesCount: 2 2024-06-27T20:19:15.488938Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=OWY1YTAyMzQtZGJjMjVlOGQtYTZjYWI3ZDMtODQ5Y2Q0OWU=, ActorId: [1:7385280255935135769:4307], ActorState: ExecuteState, TraceId: 01j1dnmbtx3g0cpy7yhcd54aat, Create QueryResponse for action: QUERY_ACTION_EXECUTE with SUCCESS status 2024-06-27T20:19:15.488954Z node 1 :KQP_SESSION INFO: SessionId: ydb://session/3?node_id=1&id=OWY1YTAyMzQtZGJjMjVlOGQtYTZjYWI3ZDMtODQ5Y2Q0OWU=, ActorId: [1:7385280255935135769:4307], ActorState: ExecuteState, TraceId: 01j1dnmbtx3g0cpy7yhcd54aat, Cleanup start, isFinal: 0 CleanupCtx: 0 TransactionsToBeAborted.size(): 0 WorkerId: [0:0:0] WorkloadServiceCleanup: 0 2024-06-27T20:19:15.488962Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=OWY1YTAyMzQtZGJjMjVlOGQtYTZjYWI3ZDMtODQ5Y2Q0OWU=, ActorId: [1:7385280255935135769:4307], ActorState: ExecuteState, TraceId: 01j1dnmbtx3g0cpy7yhcd54aat, EndCleanup, isFinal: 0 2024-06-27T20:19:15.488971Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=OWY1YTAyMzQtZGJjMjVlOGQtYTZjYWI3ZDMtODQ5Y2Q0OWU=, ActorId: [1:7385280255935135769:4307], ActorState: ExecuteState, TraceId: 01j1dnmbtx3g0cpy7yhcd54aat, Sent query response back to proxy, proxyRequestId: 6, proxyId: [1:7385280251640167895:12299] 2024-06-27T20:19:15.489083Z node 1 :KQP_WORKLOAD_SERVICE DEBUG: [TQueryBase] [TRefreshPoolStateQuery] TraceId: sample_pool_id, RequestDatabase: Root, RequestSessionId: , State: Update lease, TEvDataQueryResult SUCCESS, Issues: , SessionId: ydb://session/3?node_id=1&id=OWY1YTAyMzQtZGJjMjVlOGQtYTZjYWI3ZDMtODQ5Y2Q0OWU=, TxId: 2024-06-27T20:19:15.489118Z node 1 :KQP_WORKLOAD_SERVICE DEBUG: [TQueryBase] [TRefreshPoolStateQuery] TraceId: sample_pool_id, RequestDatabase: Root, RequestSessionId: , State: Update lease, RunDataQuery: -- TRefreshPoolStateQuery::OnLeaseUpdated DECLARE $database AS Text; DECLARE $pool_id AS Text; SELECT COUNT(*) AS delayed_requests FROM `.metadata/workload_manager/delayed_requests` WHERE database = $database AND pool_id = $pool_id AND (wait_deadline IS NULL OR wait_deadline >= CurrentUtcTimestamp()) AND lease_deadline >= CurrentUtcTimestamp(); SELECT COUNT(*) AS running_requests FROM `.metadata/workload_manager/running_requests` WHERE database = $database AND pool_id = $pool_id AND lease_deadline >= CurrentUtcTimestamp(); 2024-06-27T20:19:15.489309Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=OWY1YTAyMzQtZGJjMjVlOGQtYTZjYWI3ZDMtODQ5Y2Q0OWU=, ActorId: [1:7385280255935135769:4307], ActorState: ReadyState, TraceId: 01j1dnmbx1a4mjdxj1s403vadc, received request, proxyRequestId: 7 prepared: 0 tx_control: 1 action: QUERY_ACTION_EXECUTE type: QUERY_TYPE_SQL_DML text: -- TRefreshPoolStateQuery::OnLeaseUpdated DECLARE $database AS Text; DECLARE $pool_id AS Text; SELECT COUNT(*) AS delayed_requests FROM `.metadata/workload_manager/delayed_requests` WHERE database = $database AND pool_id = $pool_id AND (wait_deadline IS NULL OR wait_deadline >= CurrentUtcTimestamp()) AND lease_deadline >= CurrentUtcTimestamp(); SELECT COUNT(*) AS running_requests FROM `.metadata/workload_manager/running_requests` WHERE database = $database AND pool_id = $pool_id AND lease_deadline >= CurrentUtcTimestamp(); rpcActor: [1:7385280255935135814:4285] database: /Root pool id: 2024-06-27T20:19:15.489326Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=OWY1YTAyMzQtZGJjMjVlOGQtYTZjYWI3ZDMtODQ5Y2Q0OWU=, ActorId: [1:7385280255935135769:4307], ActorState: ReadyState, TraceId: 01j1dnmbx1a4mjdxj1s403vadc, Sending CompileQuery request 2024-06-27T20:19:15.558927Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=OWY1YTAyMzQtZGJjMjVlOGQtYTZjYWI3ZDMtODQ5Y2Q0OWU=, ActorId: [1:7385280255935135769:4307], ActorState: ExecuteState, TraceId: 01j1dnmbx1a4mjdxj1s403vadc, ExecutePhyTx, tx: 0x0000075C7AC24D98 literal: 0 commit: 0 txCtx.DeferredEffects.size(): 0 2024-06-27T20:19:15.558949Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=OWY1YTAyMzQtZGJjMjVlOGQtYTZjYWI3ZDMtODQ5Y2Q0OWU=, ActorId: [1:7385280255935135769:4307], ActorState: ExecuteState, TraceId: 01j1dnmbx1a4mjdxj1s403vadc, Sending to Executer TraceId: 0 8 2024-06-27T20:19:15.558962Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=OWY1YTAyMzQtZGJjMjVlOGQtYTZjYWI3ZDMtODQ5Y2Q0OWU=, ActorId: [1:7385280255935135769:4307], ActorState: ExecuteState, TraceId: 01j1dnmbx1a4mjdxj1s403vadc, Created new KQP executer: [1:7385280255935135823:4307] isRollback: 0 2024-06-27T20:19:15.560979Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=OWY1YTAyMzQtZGJjMjVlOGQtYTZjYWI3ZDMtODQ5Y2Q0OWU=, ActorId: [1:7385280255935135769:4307], ActorState: ExecuteState, TraceId: 01j1dnmbx1a4mjdxj1s403vadc, TEvTxResponse, CurrentTx: 1/2 response.status: SUCCESS 2024-06-27T20:19:15.561018Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=OWY1YTAyMzQtZGJjMjVlOGQtYTZjYWI3ZDMtODQ5Y2Q0OWU=, ActorId: [1:7385280255935135769:4307], ActorState: ExecuteState, TraceId: 01j1dnmbx1a4mjdxj1s403vadc, ExecutePhyTx, tx: 0x0000075C7AC24E18 literal: 0 commit: 1 txCtx.DeferredEffects.size(): 0 2024-06-27T20:19:15.561036Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=OWY1YTAyMzQtZGJjMjVlOGQtYTZjYWI3ZDMtODQ5Y2Q0OWU=, ActorId: [1:7385280255935135769:4307], ActorState: ExecuteState, TraceId: 01j1dnmbx1a4mjdxj1s403vadc, TExecPhysicalRequest, tx has rollback locks 2024-06-27T20:19:15.561047Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=OWY1YTAyMzQtZGJjMjVlOGQtYTZjYWI3ZDMtODQ5Y2Q0OWU=, ActorId: [1:7385280255935135769:4307], ActorState: ExecuteState, TraceId: 01j1dnmbx1a4mjdxj1s403vadc, Sending to Executer TraceId: 0 8 2024-06-27T20:19:15.561054Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=OWY1YTAyMzQtZGJjMjVlOGQtYTZjYWI3ZDMtODQ5Y2Q0OWU=, ActorId: [1:7385280255935135769:4307], ActorState: ExecuteState, TraceId: 01j1dnmbx1a4mjdxj1s403vadc, Created new KQP executer: [1:7385280255935135839:4307] isRollback: 0 2024-06-27T20:19:15.561614Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=OWY1YTAyMzQtZGJjMjVlOGQtYTZjYWI3ZDMtODQ5Y2Q0OWU=, ActorId: [1:7385280255935135769:4307], ActorState: ExecuteState, TraceId: 01j1dnmbx1a4mjdxj1s403vadc, TEvTxResponse, CurrentTx: 2/2 response.status: SUCCESS 2024-06-27T20:19:15.561654Z node 1 :KQP_SESSION INFO: SessionId: ydb://session/3?node_id=1&id=OWY1YTAyMzQtZGJjMjVlOGQtYTZjYWI3ZDMtODQ5Y2Q0OWU=, ActorId: [1:7385280255935135769:4307], ActorState: ExecuteState, TraceId: 01j1dnmbx1a4mjdxj1s403vadc, txInfo Status: Committed Kind: ReadOnly TotalDuration: 2.775 ServerDuration: 2.731 QueriesCount: 2 2024-06-27T20:19:15.561683Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=OWY1YTAyMzQtZGJjMjVlOGQtYTZjYWI3ZDMtODQ5Y2Q0OWU=, ActorId: [1:7385280255935135769:4307], ActorState: ExecuteState, TraceId: 01j1dnmbx1a4mjdxj1s403vadc, Create QueryResponse for action: QUERY_ACTION_EXECUTE with SUCCESS status 2024-06-27T20:19:15.561713Z node 1 :KQP_SESSION INFO: SessionId: ydb://session/3?node_id=1&id=OWY1YTAyMzQtZGJjMjVlOGQtYTZjYWI3ZDMtODQ5Y2Q0OWU=, ActorId: [1:7385280255935135769:4307], ActorState: ExecuteState, TraceId: 01j1dnmbx1a4mjdxj1s403vadc, Cleanup start, isFinal: 0 CleanupCtx: 0 TransactionsToBeAborted.size(): 0 WorkerId: [0:0:0] WorkloadServiceCleanup: 0 2024-06-27T20:19:15.561722Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=OWY1YTAyMzQtZGJjMjVlOGQtYTZjYWI3ZDMtODQ5Y2Q0OWU=, ActorId: [1:7385280255935135769:4307], ActorState: ExecuteState, TraceId: 01j1dnmbx1a4mjdxj1s403vadc, EndCleanup, isFinal: 0 2024-06-27T20:19:15.561736Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=OWY1YTAyMzQtZGJjMjVlOGQtYTZjYWI3ZDMtODQ5Y2Q0OWU=, ActorId: [1:7385280255935135769:4307], ActorState: ExecuteState, TraceId: 01j1dnmbx1a4mjdxj1s403vadc, Sent query response back to proxy, proxyRequestId: 7, proxyId: [1:7385280251640167895:12299] 2024-06-27T20:19:15.561830Z node 1 :KQP_WORKLOAD_SERVICE DEBUG: [TQueryBase] [TRefreshPoolStateQuery] TraceId: sample_pool_id, RequestDatabase: Root, RequestSessionId: , State: Describe pool, TEvDataQueryResult SUCCESS, Issues: , SessionId: ydb://session/3?node_id=1&id=OWY1YTAyMzQtZGJjMjVlOGQtYTZjYWI3ZDMtODQ5Y2Q0OWU=, TxId: 2024-06-27T20:19:15.561880Z node 1 :KQP_WORKLOAD_SERVICE DEBUG: [TQueryBase] [TRefreshPoolStateQuery] TraceId: sample_pool_id, RequestDatabase: Root, RequestSessionId: , State: Describe pool, Finish with SUCCESS, SessionId: ydb://session/3?node_id=1&id=OWY1YTAyMzQtZGJjMjVlOGQtYTZjYWI3ZDMtODQ5Y2Q0OWU=, TxId: 2024-06-27T20:19:15.561925Z node 1 :KQP_WORKLOAD_SERVICE TRACE: [WorkloadService] [TPoolHandlerActorBase] ActorId: [1:7385280255935135602:8276], Database: Root, PoolId: sample_pool_id, succefully refreshed pool state, in flight: 0, delayed: 0 2024-06-27T20:19:15.561948Z node 1 :KQP_SESSION INFO: SessionId: ydb://session/3?node_id=1&id=OWY1YTAyMzQtZGJjMjVlOGQtYTZjYWI3ZDMtODQ5Y2Q0OWU=, ActorId: [1:7385280255935135769:4307], ActorState: ReadyState, Session closed due to explicit close event 2024-06-27T20:19:15.561958Z node 1 :KQP_SESSION INFO: SessionId: ydb://session/3?node_id=1&id=OWY1YTAyMzQtZGJjMjVlOGQtYTZjYWI3ZDMtODQ5Y2Q0OWU=, ActorId: [1:7385280255935135769:4307], ActorState: ReadyState, Cleanup start, isFinal: 1 CleanupCtx: 0 TransactionsToBeAborted.size(): 0 WorkerId: [0:0:0] WorkloadServiceCleanup: 0 2024-06-27T20:19:15.561969Z node 1 :KQP_WORKLOAD_SERVICE DEBUG: [TQueryBase] [TStartRequestQuery] TraceId: sample_pool_id, RequestDatabase: Root, RequestSessionId: ydb://session/3?node_id=1&id=YzNiMDM5NDQtNWE1MjdlYzktMWQyNDk1ZDctOGUwZTBjMGI=, Bootstrap. Database: /Root 2024-06-27T20:19:15.561972Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=OWY1YTAyMzQtZGJjMjVlOGQtYTZjYWI3ZDMtODQ5Y2Q0OWU=, ActorId: [1:7385280255935135769:4307], ActorState: ReadyState, EndCleanup, isFinal: 1 2024-06-27T20:19:15.561975Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=OWY1YTAyMzQtZGJjMjVlOGQtYTZjYWI3ZDMtODQ5Y2Q0OWU=, ActorId: [1:7385280255935135769:4307], ActorState: unknown state, Cleanup temp tables: 0 2024-06-27T20:19:15.561987Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=OWY1YTAyMzQtZGJjMjVlOGQtYTZjYWI3ZDMtODQ5Y2Q0OWU=, ActorId: [1:7385280255935135769:4307], ActorState: unknown state, Session actor destroyed 2024-06-27T20:19:15.562329Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=YTc3NmQwOTUtMzQ3NjQ2OGItNjYyZDI0NTAtM2EzMjVmNWQ=, ActorId: [0:0:0], ActorState: unknown state, Create session actor with id YTc3NmQwOTUtMzQ3NjQ2OGItNjYyZDI0NTAtM2EzMjVmNWQ= 2024-06-27T20:19:15.562374Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=YTc3NmQwOTUtMzQ3NjQ2OGItNjYyZDI0NTAtM2EzMjVmNWQ=, ActorId: [1:7385280255935135852:4300], ActorState: unknown state, session actor bootstrapped 2024-06-27T20:19:15.562395Z node 1 :KQP_WORKLOAD_SERVICE DEBUG: [TQueryBase] [TStartRequestQuery] TraceId: sample_pool_id, RequestDatabase: Root, RequestSessionId: ydb://session/3?node_id=1&id=YzNiMDM5NDQtNWE1MjdlYzktMWQyNDk1ZDctOGUwZTBjMGI=, RunDataQuery: -- TStartRequestQuery::OnRunQuery DECLARE $database AS Text; DECLARE $pool_id AS Text; DECLARE $session_id AS Text; DECLARE $node_id AS Uint32; DECLARE $lease_duration AS Interval; UPSERT INTO `.metadata/workload_manager/running_requests` (database, pool_id, session_id, node_id, lease_deadline) VALUES ( $database, $pool_id, $session_id, $node_id, CurrentUtcTimestamp() + $lease_duration ); 2024-06-27T20:19:15.562479Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=YTc3NmQwOTUtMzQ3NjQ2OGItNjYyZDI0NTAtM2EzMjVmNWQ=, ActorId: [1:7385280255935135852:4300], ActorState: ReadyState, TraceId: 01j1dnmbzadnewwj5x445fmkhy, received request, proxyRequestId: 9 prepared: 0 tx_control: 1 action: QUERY_ACTION_EXECUTE type: QUERY_TYPE_SQL_DML text: -- TStartRequestQuery::OnRunQuery DECLARE $database AS Text; DECLARE $pool_id AS Text; DECLARE $session_id AS Text; DECLARE $node_id AS Uint32; DECLARE $lease_duration AS Interval; UPSERT INTO `.metadata/workload_manager/running_requests` (database, pool_id, session_id, node_id, lease_deadline) VALUES ( $database, $pool_id, $session_id, $node_id, CurrentUtcTimestamp() + $lease_duration ); rpcActor: [1:7385280255935135853:4282] database: /Root pool id: 2024-06-27T20:19:15.562490Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=YTc3NmQwOTUtMzQ3NjQ2OGItNjYyZDI0NTAtM2EzMjVmNWQ=, ActorId: [1:7385280255935135852:4300], ActorState: ReadyState, TraceId: 01j1dnmbzadnewwj5x445fmkhy, Sending CompileQuery request 2024-06-27T20:19:15.572252Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=YTc3NmQwOTUtMzQ3NjQ2OGItNjYyZDI0NTAtM2EzMjVmNWQ=, ActorId: [1:7385280255935135852:4300], ActorState: ExecuteState, TraceId: 01j1dnmbzadnewwj5x445fmkhy, ExecutePhyTx, tx: 0x0000075C7AC24018 literal: 1 commit: 0 txCtx.DeferredEffects.size(): 0 2024-06-27T20:19:15.572574Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=YTc3NmQwOTUtMzQ3NjQ2OGItNjYyZDI0NTAtM2EzMjVmNWQ=, ActorId: [1:7385280255935135852:4300], ActorState: ExecuteState, TraceId: 01j1dnmbzadnewwj5x445fmkhy, TEvTxResponse, CurrentTx: 1/2 response.status: SUCCESS 2024-06-27T20:19:15.572591Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=YTc3NmQwOTUtMzQ3NjQ2OGItNjYyZDI0NTAtM2EzMjVmNWQ=, ActorId: [1:7385280255935135852:4300], ActorState: ExecuteState, TraceId: 01j1dnmbzadnewwj5x445fmkhy, ExecutePhyTx, tx: 0x0000000000000000 literal: 0 commit: 1 txCtx.DeferredEffects.size(): 1 2024-06-27T20:19:15.572593Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=YTc3NmQwOTUtMzQ3NjQ2OGItNjYyZDI0NTAtM2EzMjVmNWQ=, ActorId: [1:7385280255935135852:4300], ActorState: ExecuteState, TraceId: 01j1dnmbzadnewwj5x445fmkhy, TExecPhysicalRequest, add DeferredEffect to Transaction, current Transactions.size(): 1 2024-06-27T20:19:15.572597Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=YTc3NmQwOTUtMzQ3NjQ2OGItNjYyZDI0NTAtM2EzMjVmNWQ=, ActorId: [1:7385280255935135852:4300], ActorState: ExecuteState, TraceId: 01j1dnmbzadnewwj5x445fmkhy, Sending to Executer TraceId: 0 8 2024-06-27T20:19:15.572607Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=YTc3NmQwOTUtMzQ3NjQ2OGItNjYyZDI0NTAtM2EzMjVmNWQ=, ActorId: [1:7385280255935135852:4300], ActorState: ExecuteState, TraceId: 01j1dnmbzadnewwj5x445fmkhy, Created new KQP executer: [1:7385280255935135859:4300] isRollback: 0 2024-06-27T20:19:15.574401Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=YTc3NmQwOTUtMzQ3NjQ2OGItNjYyZDI0NTAtM2EzMjVmNWQ=, ActorId: [1:7385280255935135852:4300], ActorState: ExecuteState, TraceId: 01j1dnmbzadnewwj5x445fmkhy, TEvTxResponse, CurrentTx: 2/2 response.status: SUCCESS 2024-06-27T20:19:15.574441Z node 1 :KQP_SESSION INFO: SessionId: ydb://session/3?node_id=1&id=YTc3NmQwOTUtMzQ3NjQ2OGItNjYyZDI0NTAtM2EzMjVmNWQ=, ActorId: [1:7385280255935135852:4300], ActorState: ExecuteState, TraceId: 01j1dnmbzadnewwj5x445fmkhy, txInfo Status: Committed Kind: WriteOnly TotalDuration: 2.236 ServerDuration: 2.195 QueriesCount: 2 2024-06-27T20:19:15.574461Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=YTc3NmQwOTUtMzQ3NjQ2OGItNjYyZDI0NTAtM2EzMjVmNWQ=, ActorId: [1:7385280255935135852:4300], ActorState: ExecuteState, TraceId: 01j1dnmbzadnewwj5x445fmkhy, Create QueryResponse for action: QUERY_ACTION_EXECUTE with SUCCESS status 2024-06-27T20:19:15.574475Z node 1 :KQP_SESSION INFO: SessionId: ydb://session/3?node_id=1&id=YTc3NmQwOTUtMzQ3NjQ2OGItNjYyZDI0NTAtM2EzMjVmNWQ=, ActorId: [1:7385280255935135852:4300], ActorState: ExecuteState, TraceId: 01j1dnmbzadnewwj5x445fmkhy, Cleanup start, isFinal: 0 CleanupCtx: 0 TransactionsToBeAborted.size(): 0 WorkerId: [0:0:0] WorkloadServiceCleanup: 0 2024-06-27T20:19:15.574477Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=YTc3NmQwOTUtMzQ3NjQ2OGItNjYyZDI0NTAtM2EzMjVmNWQ=, ActorId: [1:7385280255935135852:4300], ActorState: ExecuteState, TraceId: 01j1dnmbzadnewwj5x445fmkhy, EndCleanup, isFinal: 0 2024-06-27T20:19:15.574490Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=YTc3NmQwOTUtMzQ3NjQ2OGItNjYyZDI0NTAtM2EzMjVmNWQ=, ActorId: [1:7385280255935135852:4300], ActorState: ExecuteState, TraceId: 01j1dnmbzadnewwj5x445fmkhy, Sent query response back to proxy, proxyRequestId: 9, proxyId: [1:7385280251640167895:12299] 2024-06-27T20:19:15.574564Z node 1 :KQP_WORKLOAD_SERVICE DEBUG: [TQueryBase] [TStartRequestQuery] TraceId: sample_pool_id, RequestDatabase: Root, RequestSessionId: ydb://session/3?node_id=1&id=YzNiMDM5NDQtNWE1MjdlYzktMWQyNDk1ZDctOGUwZTBjMGI=, TEvDataQueryResult SUCCESS, Issues: , SessionId: ydb://session/3?node_id=1&id=YTc3NmQwOTUtMzQ3NjQ2OGItNjYyZDI0NTAtM2EzMjVmNWQ=, TxId: 2024-06-27T20:19:15.574574Z node 1 :KQP_WORKLOAD_SERVICE DEBUG: [TQueryBase] [TStartRequestQuery] TraceId: sample_pool_id, RequestDatabase: Root, RequestSessionId: ydb://session/3?node_id=1&id=YzNiMDM5NDQtNWE1MjdlYzktMWQyNDk1ZDctOGUwZTBjMGI=, Finish with SUCCESS, SessionId: ydb://session/3?node_id=1&id=YTc3NmQwOTUtMzQ3NjQ2OGItNjYyZDI0NTAtM2EzMjVmNWQ=, TxId: 2024-06-27T20:19:15.574610Z node 1 :KQP_WORKLOAD_SERVICE DEBUG: [WorkloadService] [TPoolHandlerActorBase] ActorId: [1:7385280255935135602:8276], Database: Root, PoolId: sample_pool_id, started request, session id: ydb://session/3?node_id=1&id=YzNiMDM5NDQtNWE1MjdlYzktMWQyNDk1ZDctOGUwZTBjMGI= 2024-06-27T20:19:15.574625Z node 1 :KQP_WORKLOAD_SERVICE DEBUG: [WorkloadService] [TPoolHandlerActorBase] ActorId: [1:7385280255935135602:8276], Database: Root, PoolId: sample_pool_id, Reply continue success to [1:7385280255935135587:4294], session id: ydb://session/3?node_id=1&id=YzNiMDM5NDQtNWE1MjdlYzktMWQyNDk1ZDctOGUwZTBjMGI=, local in flight: 1 2024-06-27T20:19:15.574632Z node 1 :KQP_SESSION INFO: SessionId: ydb://session/3?node_id=1&id=YTc3NmQwOTUtMzQ3NjQ2OGItNjYyZDI0NTAtM2EzMjVmNWQ=, ActorId: [1:7385280255935135852:4300], ActorState: ReadyState, Session closed due to explicit close event 2024-06-27T20:19:15.574636Z node 1 :KQP_SESSION INFO: SessionId: ydb://session/3?node_id=1&id=YTc3NmQwOTUtMzQ3NjQ2OGItNjYyZDI0NTAtM2EzMjVmNWQ=, ActorId: [1:7385280255935135852:4300], ActorState: ReadyState, Cleanup start, isFinal: 1 CleanupCtx: 0 TransactionsToBeAborted.size(): 0 WorkerId: [0:0:0] WorkloadServiceCleanup: 0 2024-06-27T20:19:15.574638Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=YTc3NmQwOTUtMzQ3NjQ2OGItNjYyZDI0NTAtM2EzMjVmNWQ=, ActorId: [1:7385280255935135852:4300], ActorState: ReadyState, EndCleanup, isFinal: 1 2024-06-27T20:19:15.574652Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=YzNiMDM5NDQtNWE1MjdlYzktMWQyNDk1ZDctOGUwZTBjMGI=, ActorId: [1:7385280255935135587:4294], ActorState: ExecuteState, TraceId: 01j1dnmbnwb3znjgdtw3kv6eed, continue request, pool id: sample_pool_id 2024-06-27T20:19:15.574653Z node 1 :KQP_WORKLOAD_SERVICE DEBUG: [TQueryBase] [TRefreshPoolStateQuery] TraceId: sample_pool_id, RequestDatabase: Root, RequestSessionId: , Bootstrap. Database: /Root 2024-06-27T20:19:15.574661Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=YTc3NmQwOTUtMzQ3NjQ2OGItNjYyZDI0NTAtM2EzMjVmNWQ=, ActorId: [1:7385280255935135852:4300], ActorState: unknown state, Cleanup temp tables: 0 2024-06-27T20:19:15.574668Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=YzNiMDM5NDQtNWE1MjdlYzktMWQyNDk1ZDctOGUwZTBjMGI=, ActorId: [1:7385280255935135587:4294], ActorState: ExecuteState, TraceId: 01j1dnmbnwb3znjgdtw3kv6eed, Sending CompileQuery request 2024-06-27T20:19:15.574674Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=YTc3NmQwOTUtMzQ3NjQ2OGItNjYyZDI0NTAtM2EzMjVmNWQ=, ActorId: [1:7385280255935135852:4300], ActorState: unknown state, Session actor destroyed 2024-06-27T20:19:15.574957Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ODk4MzFhNTktMmJiZDc5MjktMmQ4NDgyYTEtZjJlNmI1MTk=, ActorId: [0:0:0], ActorState: unknown state, Create session actor with id ODk4MzFhNTktMmJiZDc5MjktMmQ4NDgyYTEtZjJlNmI1MTk= 2024-06-27T20:19:15.574985Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ODk4MzFhNTktMmJiZDc5MjktMmQ4NDgyYTEtZjJlNmI1MTk=, ActorId: [1:7385280255935135870:4307], ActorState: unknown state, session actor bootstrapped 2024-06-27T20:19:15.575061Z node 1 :KQP_WORKLOAD_SERVICE DEBUG: [TQueryBase] [TRefreshPoolStateQuery] TraceId: sample_pool_id, RequestDatabase: Root, RequestSessionId: , RunDataQuery: -- TRefreshPoolStateQuery::OnRunQuery DECLARE $database AS Text; DECLARE $pool_id AS Text; DECLARE $node_id AS Uint32; DECLARE $lease_duration AS Interval; UPDATE `.metadata/workload_manager/delayed_requests` SET lease_deadline = CurrentUtcTimestamp() + $lease_duration WHERE database = $database AND pool_id = $pool_id AND node_id = $node_id AND (wait_deadline IS NULL OR wait_deadline >= CurrentUtcTimestamp()) AND lease_deadline >= CurrentUtcTimestamp(); UPDATE `.metadata/workload_manager/running_requests` SET lease_deadline = CurrentUtcTimestamp() + $lease_duration WHERE database = $database AND pool_id = $pool_id AND node_id = $node_id AND lease_deadline >= CurrentUtcTimestamp(); 2024-06-27T20:19:15.575226Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ODk4MzFhNTktMmJiZDc5MjktMmQ4NDgyYTEtZjJlNmI1MTk=, ActorId: [1:7385280255935135870:4307], ActorState: ReadyState, TraceId: 01j1dnmbzq4j8x39tnt6vyk7rr, received request, proxyRequestId: 11 prepared: 0 tx_control: 1 action: QUERY_ACTION_EXECUTE type: QUERY_TYPE_SQL_DML text: -- TRefreshPoolStateQuery::OnRunQuery DECLARE $database AS Text; DECLARE $pool_id AS Text; DECLARE $node_id AS Uint32; DECLARE $lease_duration AS Interval; UPDATE `.metadata/workload_manager/delayed_requests` SET lease_deadline = CurrentUtcTimestamp() + $lease_duration WHERE database = $database AND pool_id = $pool_id AND node_id = $node_id AND (wait_deadline IS NULL OR wait_deadline >= CurrentUtcTimestamp()) AND lease_deadline >= CurrentUtcTimestamp(); UPDATE `.metadata/workload_manager/running_requests` SET lease_deadline = CurrentUtcTimestamp() + $lease_duration WHERE database = $database AND pool_id = $pool_id AND node_id = $node_id AND lease_deadline >= CurrentUtcTimestamp(); rpcActor: [1:7385280255935135871:4322] database: /Root pool id: 2024-06-27T20:19:15.575249Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ODk4MzFhNTktMmJiZDc5MjktMmQ4NDgyYTEtZjJlNmI1MTk=, ActorId: [1:7385280255935135870:4307], ActorState: ReadyState, TraceId: 01j1dnmbzq4j8x39tnt6vyk7rr, Sending CompileQuery request 2024-06-27T20:19:15.575474Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ODk4MzFhNTktMmJiZDc5MjktMmQ4NDgyYTEtZjJlNmI1MTk=, ActorId: [1:7385280255935135870:4307], ActorState: ExecuteState, TraceId: 01j1dnmbzq4j8x39tnt6vyk7rr, ExecutePhyTx, tx: 0x0000075C7AC19698 literal: 0 commit: 0 txCtx.DeferredEffects.size(): 0 2024-06-27T20:19:15.575498Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ODk4MzFhNTktMmJiZDc5MjktMmQ4NDgyYTEtZjJlNmI1MTk=, ActorId: [1:7385280255935135870:4307], ActorState: ExecuteState, TraceId: 01j1dnmbzq4j8x39tnt6vyk7rr, Sending to Executer TraceId: 0 8 2024-06-27T20:19:15.575513Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ODk4MzFhNTktMmJiZDc5MjktMmQ4NDgyYTEtZjJlNmI1MTk=, ActorId: [1:7385280255935135870:4307], ActorState: ExecuteState, TraceId: 01j1dnmbzq4j8x39tnt6vyk7rr, Created new KQP executer: [1:7385280255935135874:4307] isRollback: 0 2024-06-27T20:19:15.577478Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ODk4MzFhNTktMmJiZDc5MjktMmQ4NDgyYTEtZjJlNmI1MTk=, ActorId: [1:7385280255935135870:4307], ActorState: ExecuteState, TraceId: 01j1dnmbzq4j8x39tnt6vyk7rr, TEvTxResponse, CurrentTx: 1/2 response.status: SUCCESS 2024-06-27T20:19:15.577524Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ODk4MzFhNTktMmJiZDc5MjktMmQ4NDgyYTEtZjJlNmI1MTk=, ActorId: [1:7385280255935135870:4307], ActorState: ExecuteState, TraceId: 01j1dnmbzq4j8x39tnt6vyk7rr, ExecutePhyTx, tx: 0x0000000000000000 literal: 0 commit: 1 txCtx.DeferredEffects.size(): 1 2024-06-27T20:19:15.577532Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ODk4MzFhNTktMmJiZDc5MjktMmQ4NDgyYTEtZjJlNmI1MTk=, ActorId: [1:7385280255935135870:4307], ActorState: ExecuteState, TraceId: 01j1dnmbzq4j8x39tnt6vyk7rr, TExecPhysicalRequest, add DeferredEffect to Transaction, current Transactions.size(): 1 2024-06-27T20:19:15.577534Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ODk4MzFhNTktMmJiZDc5MjktMmQ4NDgyYTEtZjJlNmI1MTk=, ActorId: [1:7385280255935135870:4307], ActorState: ExecuteState, TraceId: 01j1dnmbzq4j8x39tnt6vyk7rr, TExecPhysicalRequest, tx has commit locks 2024-06-27T20:19:15.577540Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ODk4MzFhNTktMmJiZDc5MjktMmQ4NDgyYTEtZjJlNmI1MTk=, ActorId: [1:7385280255935135870:4307], ActorState: ExecuteState, TraceId: 01j1dnmbzq4j8x39tnt6vyk7rr, Sending to Executer TraceId: 0 8 2024-06-27T20:19:15.577546Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ODk4MzFhNTktMmJiZDc5MjktMmQ4NDgyYTEtZjJlNmI1MTk=, ActorId: [1:7385280255935135870:4307], ActorState: ExecuteState, TraceId: 01j1dnmbzq4j8x39tnt6vyk7rr, Created new KQP executer: [1:7385280255935135890:4307] isRollback: 0 2024-06-27T20:19:15.579573Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ODk4MzFhNTktMmJiZDc5MjktMmQ4NDgyYTEtZjJlNmI1MTk=, ActorId: [1:7385280255935135870:4307], ActorState: ExecuteState, TraceId: 01j1dnmbzq4j8x39tnt6vyk7rr, TEvTxResponse, CurrentTx: 2/2 response.status: SUCCESS 2024-06-27T20:19:15.579614Z node 1 :KQP_SESSION INFO: SessionId: ydb://session/3?node_id=1&id=ODk4MzFhNTktMmJiZDc5MjktMmQ4NDgyYTEtZjJlNmI1MTk=, ActorId: [1:7385280255935135870:4307], ActorState: ExecuteState, TraceId: 01j1dnmbzq4j8x39tnt6vyk7rr, txInfo Status: Committed Kind: ReadWrite TotalDuration: 4.163 ServerDuration: 4.137 QueriesCount: 2 2024-06-27T20:19:15.579636Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ODk4MzFhNTktMmJiZDc5MjktMmQ4NDgyYTEtZjJlNmI1MTk=, ActorId: [1:7385280255935135870:4307], ActorState: ExecuteState, TraceId: 01j1dnmbzq4j8x39tnt6vyk7rr, Create QueryResponse for action: QUERY_ACTION_EXECUTE with SUCCESS status 2024-06-27T20:19:15.579644Z node 1 :KQP_SESSION INFO: SessionId: ydb://session/3?node_id=1&id=ODk4MzFhNTktMmJiZDc5MjktMmQ4NDgyYTEtZjJlNmI1MTk=, ActorId: [1:7385280255935135870:4307], ActorState: ExecuteState, TraceId: 01j1dnmbzq4j8x39tnt6vyk7rr, Cleanup start, isFinal: 0 CleanupCtx: 0 TransactionsToBeAborted.size(): 0 WorkerId: [0:0:0] WorkloadServiceCleanup: 0 2024-06-27T20:19:15.579646Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ODk4MzFhNTktMmJiZDc5MjktMmQ4NDgyYTEtZjJlNmI1MTk=, ActorId: [1:7385280255935135870:4307], ActorState: ExecuteState, TraceId: 01j1dnmbzq4j8x39tnt6vyk7rr, EndCleanup, isFinal: 0 2024-06-27T20:19:15.579653Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ODk4MzFhNTktMmJiZDc5MjktMmQ4NDgyYTEtZjJlNmI1MTk=, ActorId: [1:7385280255935135870:4307], ActorState: ExecuteState, TraceId: 01j1dnmbzq4j8x39tnt6vyk7rr, Sent query response back to proxy, proxyRequestId: 11, proxyId: [1:7385280251640167895:12299] 2024-06-27T20:19:15.579729Z node 1 :KQP_WORKLOAD_SERVICE DEBUG: [TQueryBase] [TRefreshPoolStateQuery] TraceId: sample_pool_id, RequestDatabase: Root, RequestSessionId: , State: Update lease, TEvDataQueryResult SUCCESS, Issues: , SessionId: ydb://session/3?node_id=1&id=ODk4MzFhNTktMmJiZDc5MjktMmQ4NDgyYTEtZjJlNmI1MTk=, TxId: 2024-06-27T20:19:15.579759Z node 1 :KQP_WORKLOAD_SERVICE DEBUG: [TQueryBase] [TRefreshPoolStateQuery] TraceId: sample_pool_id, RequestDatabase: Root, RequestSessionId: , State: Update lease, RunDataQuery: -- TRefreshPoolStateQuery::OnLeaseUpdated DECLARE $database AS Text; DECLARE $pool_id AS Text; SELECT COUNT(*) AS delayed_requests FROM `.metadata/workload_manager/delayed_requests` WHERE database = $database AND pool_id = $pool_id AND (wait_deadline IS NULL OR wait_deadline >= CurrentUtcTimestamp()) AND lease_deadline >= CurrentUtcTimestamp(); SELECT COUNT(*) AS running_requests FROM `.metadata/workload_manager/running_requests` WHERE database = $database AND pool_id = $pool_id AND lease_deadline >= CurrentUtcTimestamp(); 2024-06-27T20:19:15.579898Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ODk4MzFhNTktMmJiZDc5MjktMmQ4NDgyYTEtZjJlNmI1MTk=, ActorId: [1:7385280255935135870:4307], ActorState: ReadyState, TraceId: 01j1dnmbzv0cea7kvk6ga4k00s, received request, proxyRequestId: 12 prepared: 0 tx_control: 1 action: QUERY_ACTION_EXECUTE type: QUERY_TYPE_SQL_DML text: -- TRefreshPoolStateQuery::OnLeaseUpdated DECLARE $database AS Text; DECLARE $pool_id AS Text; SELECT COUNT(*) AS delayed_requests FROM `.metadata/workload_manager/delayed_requests` WHERE database = $database AND pool_id = $pool_id AND (wait_deadline IS NULL OR wait_deadline >= CurrentUtcTimestamp()) AND lease_deadline >= CurrentUtcTimestamp(); SELECT COUNT(*) AS running_requests FROM `.metadata/workload_manager/running_requests` WHERE database = $database AND pool_id = $pool_id AND lease_deadline >= CurrentUtcTimestamp(); rpcActor: [1:7385280255935135899:4299] database: /Root pool id: 2024-06-27T20:19:15.579909Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ODk4MzFhNTktMmJiZDc5MjktMmQ4NDgyYTEtZjJlNmI1MTk=, ActorId: [1:7385280255935135870:4307], ActorState: ReadyState, TraceId: 01j1dnmbzv0cea7kvk6ga4k00s, Sending CompileQuery request 2024-06-27T20:19:15.579950Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=YzNiMDM5NDQtNWE1MjdlYzktMWQyNDk1ZDctOGUwZTBjMGI=, ActorId: [1:7385280255935135587:4294], ActorState: ExecuteState, TraceId: 01j1dnmbnwb3znjgdtw3kv6eed, ExecutePhyTx, tx: 0x0000075C7AC24698 literal: 0 commit: 1 txCtx.DeferredEffects.size(): 0 2024-06-27T20:19:15.579958Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=YzNiMDM5NDQtNWE1MjdlYzktMWQyNDk1ZDctOGUwZTBjMGI=, ActorId: [1:7385280255935135587:4294], ActorState: ExecuteState, TraceId: 01j1dnmbnwb3znjgdtw3kv6eed, Sending to Executer TraceId: 0 8 2024-06-27T20:19:15.579964Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=YzNiMDM5NDQtNWE1MjdlYzktMWQyNDk1ZDctOGUwZTBjMGI=, ActorId: [1:7385280255935135587:4294], ActorState: ExecuteState, TraceId: 01j1dnmbnwb3znjgdtw3kv6eed, Created new KQP executer: [1:7385280255935135901:4294] isRollback: 0 2024-06-27T20:19:15.580126Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ODk4MzFhNTktMmJiZDc5MjktMmQ4NDgyYTEtZjJlNmI1MTk=, ActorId: [1:7385280255935135870:4307], ActorState: ExecuteState, TraceId: 01j1dnmbzv0cea7kvk6ga4k00s, ExecutePhyTx, tx: 0x0000075C7AC24D98 literal: 0 commit: 0 txCtx.DeferredEffects.size(): 0 2024-06-27T20:19:15.580140Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ODk4MzFhNTktMmJiZDc5MjktMmQ4NDgyYTEtZjJlNmI1MTk=, ActorId: [1:7385280255935135870:4307], ActorState: ExecuteState, TraceId: 01j1dnmbzv0cea7kvk6ga4k00s, Sending to Executer TraceId: 0 8 2024-06-27T20:19:15.580148Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ODk4MzFhNTktMmJiZDc5MjktMmQ4NDgyYTEtZjJlNmI1MTk=, ActorId: [1:7385280255935135870:4307], ActorState: ExecuteState, TraceId: 01j1dnmbzv0cea7kvk6ga4k00s, Created new KQP executer: [1:7385280255935135907:4307] isRollback: 0 2024-06-27T20:19:15.580284Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=YzNiMDM5NDQtNWE1MjdlYzktMWQyNDk1ZDctOGUwZTBjMGI=, ActorId: [1:7385280255935135587:4294], ActorState: ExecuteState, TraceId: 01j1dnmbnwb3znjgdtw3kv6eed, Forwarded TEvStreamData to [1:7385280255935135584:12336] 2024-06-27T20:19:15.581564Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ODk4MzFhNTktMmJiZDc5MjktMmQ4NDgyYTEtZjJlNmI1MTk=, ActorId: [1:7385280255935135870:4307], ActorState: ExecuteState, TraceId: 01j1dnmbzv0cea7kvk6ga4k00s, TEvTxResponse, CurrentTx: 1/2 response.status: SUCCESS 2024-06-27T20:19:15.581595Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ODk4MzFhNTktMmJiZDc5MjktMmQ4NDgyYTEtZjJlNmI1MTk=, ActorId: [1:7385280255935135870:4307], ActorState: ExecuteState, TraceId: 01j1dnmbzv0cea7kvk6ga4k00s, ExecutePhyTx, tx: 0x0000075C7AC24E18 literal: 0 commit: 1 txCtx.DeferredEffects.size(): 0 2024-06-27T20:19:15.581608Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ODk4MzFhNTktMmJiZDc5MjktMmQ4NDgyYTEtZjJlNmI1MTk=, ActorId: [1:7385280255935135870:4307], ActorState: ExecuteState, TraceId: 01j1dnmbzv0cea7kvk6ga4k00s, TExecPhysicalRequest, tx has rollback locks 2024-06-27T20:19:15.581612Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ODk4MzFhNTktMmJiZDc5MjktMmQ4NDgyYTEtZjJlNmI1MTk=, ActorId: [1:7385280255935135870:4307], ActorState: ExecuteState, TraceId: 01j1dnmbzv0cea7kvk6ga4k00s, Sending to Executer TraceId: 0 8 2024-06-27T20:19:15.581622Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ODk4MzFhNTktMmJiZDc5MjktMmQ4NDgyYTEtZjJlNmI1MTk=, ActorId: [1:7385280255935135870:4307], ActorState: ExecuteState, TraceId: 01j1dnmbzv0cea7kvk6ga4k00s, Created new KQP executer: [1:7385280255935135925:4307] isRollback: 0 2024-06-27T20:19:15.581969Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ODk4MzFhNTktMmJiZDc5MjktMmQ4NDgyYTEtZjJlNmI1MTk=, ActorId: [1:7385280255935135870:4307], ActorState: ExecuteState, TraceId: 01j1dnmbzv0cea7kvk6ga4k00s, TEvTxResponse, CurrentTx: 2/2 response.status: SUCCESS 2024-06-27T20:19:15.582001Z node 1 :KQP_SESSION INFO: SessionId: ydb://session/3?node_id=1&id=ODk4MzFhNTktMmJiZDc5MjktMmQ4NDgyYTEtZjJlNmI1MTk=, ActorId: [1:7385280255935135870:4307], ActorState: ExecuteState, TraceId: 01j1dnmbzv0cea7kvk6ga4k00s, txInfo Status: Committed Kind: ReadOnly TotalDuration: 1.897 ServerDuration: 1.877 QueriesCount: 2 2024-06-27T20:19:15.582021Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ODk4MzFhNTktMmJiZDc5MjktMmQ4NDgyYTEtZjJlNmI1MTk=, ActorId: [1:7385280255935135870:4307], ActorState: ExecuteState, TraceId: 01j1dnmbzv0cea7kvk6ga4k00s, Create QueryResponse for action: QUERY_ACTION_EXECUTE with SUCCESS status 2024-06-27T20:19:15.582032Z node 1 :KQP_SESSION INFO: SessionId: ydb://session/3?node_id=1&id=ODk4MzFhNTktMmJiZDc5MjktMmQ4NDgyYTEtZjJlNmI1MTk=, ActorId: [1:7385280255935135870:4307], ActorState: ExecuteState, TraceId: 01j1dnmbzv0cea7kvk6ga4k00s, Cleanup start, isFinal: 0 CleanupCtx: 0 TransactionsToBeAborted.size(): 0 WorkerId: [0:0:0] WorkloadServiceCleanup: 0 2024-06-27T20:19:15.582034Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ODk4MzFhNTktMmJiZDc5MjktMmQ4NDgyYTEtZjJlNmI1MTk=, ActorId: [1:7385280255935135870:4307], ActorState: ExecuteState, TraceId: 01j1dnmbzv0cea7kvk6ga4k00s, EndCleanup, isFinal: 0 2024-06-27T20:19:15.582044Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ODk4MzFhNTktMmJiZDc5MjktMmQ4NDgyYTEtZjJlNmI1MTk=, ActorId: [1:7385280255935135870:4307], ActorState: ExecuteState, TraceId: 01j1dnmbzv0cea7kvk6ga4k00s, Sent query response back to proxy, proxyRequestId: 12, proxyId: [1:7385280251640167895:12299] 2024-06-27T20:19:15.582110Z node 1 :KQP_WORKLOAD_SERVICE DEBUG: [TQueryBase] [TRefreshPoolStateQuery] TraceId: sample_pool_id, RequestDatabase: Root, RequestSessionId: , State: Describe pool, TEvDataQueryResult SUCCESS, Issues: , SessionId: ydb://session/3?node_id=1&id=ODk4MzFhNTktMmJiZDc5MjktMmQ4NDgyYTEtZjJlNmI1MTk=, TxId: 2024-06-27T20:19:15.582131Z node 1 :KQP_WORKLOAD_SERVICE DEBUG: [TQueryBase] [TRefreshPoolStateQuery] TraceId: sample_pool_id, RequestDatabase: Root, RequestSessionId: , State: Describe pool, Finish with SUCCESS, SessionId: ydb://session/3?node_id=1&id=ODk4MzFhNTktMmJiZDc5MjktMmQ4NDgyYTEtZjJlNmI1MTk=, TxId: 2024-06-27T20:19:15.582164Z node 1 :KQP_WORKLOAD_SERVICE TRACE: [WorkloadService] [TPoolHandlerActorBase] ActorId: [1:7385280255935135602:8276], Database: Root, PoolId: sample_pool_id, succefully refreshed pool state, in flight: 1, delayed: 0 2024-06-27T20:19:15.582174Z node 1 :KQP_SESSION INFO: SessionId: ydb://session/3?node_id=1&id=ODk4MzFhNTktMmJiZDc5MjktMmQ4NDgyYTEtZjJlNmI1MTk=, ActorId: [1:7385280255935135870:4307], ActorState: ReadyState, Session closed due to explicit close event 2024-06-27T20:19:15.582177Z node 1 :KQP_SESSION INFO: SessionId: ydb://session/3?node_id=1&id=ODk4MzFhNTktMmJiZDc5MjktMmQ4NDgyYTEtZjJlNmI1MTk=, ActorId: [1:7385280255935135870:4307], ActorState: ReadyState, Cleanup start, isFinal: 1 CleanupCtx: 0 TransactionsToBeAborted.size(): 0 WorkerId: [0:0:0] WorkloadServiceCleanup: 0 2024-06-27T20:19:15.582179Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ODk4MzFhNTktMmJiZDc5MjktMmQ4NDgyYTEtZjJlNmI1MTk=, ActorId: [1:7385280255935135870:4307], ActorState: ReadyState, EndCleanup, isFinal: 1 2024-06-27T20:19:15.582181Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ODk4MzFhNTktMmJiZDc5MjktMmQ4NDgyYTEtZjJlNmI1MTk=, ActorId: [1:7385280255935135870:4307], ActorState: unknown state, Cleanup temp tables: 0 2024-06-27T20:19:15.582189Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ODk4MzFhNTktMmJiZDc5MjktMmQ4NDgyYTEtZjJlNmI1MTk=, ActorId: [1:7385280255935135870:4307], ActorState: unknown state, Session actor destroyed 2024-06-27T20:19:15.582206Z node 1 :KQP_WORKLOAD_SERVICE DEBUG: [TQueryBase] [TDelayRequestQuery] TraceId: sample_pool_id, RequestDatabase: Root, RequestSessionId: ydb://session/3?node_id=1&id=ZmNiMDg3ZmUtODA1OTcyMmMtNDBmZTNlODUtODkzNTI5NTg=, Bootstrap. Database: /Root 2024-06-27T20:19:15.582504Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=NGUyMGM0ZDItZjkyMDMyNWMtZmU4NjdlYTAtMjBmZGExYQ==, ActorId: [0:0:0], ActorState: unknown state, Create session actor with id NGUyMGM0ZDItZjkyMDMyNWMtZmU4NjdlYTAtMjBmZGExYQ== 2024-06-27T20:19:15.582565Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=NGUyMGM0ZDItZjkyMDMyNWMtZmU4NjdlYTAtMjBmZGExYQ==, ActorId: [1:7385280255935135937:4313], ActorState: unknown state, session actor bootstrapped 2024-06-27T20:19:15.582604Z node 1 :KQP_WORKLOAD_SERVICE DEBUG: [TQueryBase] [TDelayRequestQuery] TraceId: sample_pool_id, RequestDatabase: Root, RequestSessionId: ydb://session/3?node_id=1&id=ZmNiMDg3ZmUtODA1OTcyMmMtNDBmZTNlODUtODkzNTI5NTg=, RunDataQuery: -- TDelayRequestQuery::OnRunQuery DECLARE $database AS Text; DECLARE $pool_id AS Text; DECLARE $start_time AS Timestamp; DECLARE $session_id AS Text; DECLARE $node_id AS Uint32; DECLARE $wait_deadline AS Optional; DECLARE $lease_duration AS Interval; UPSERT INTO `.metadata/workload_manager/delayed_requests` (database, pool_id, start_time, session_id, node_id, wait_deadline, lease_deadline) VALUES ( $database, $pool_id, $start_time, $session_id, $node_id, $wait_deadline, CurrentUtcTimestamp() + $lease_duration ); 2024-06-27T20:19:15.582748Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=NGUyMGM0ZDItZjkyMDMyNWMtZmU4NjdlYTAtMjBmZGExYQ==, ActorId: [1:7385280255935135937:4313], ActorState: ReadyState, TraceId: 01j1dnmbzy7cs6kqevj8vt2zdy, received request, proxyRequestId: 14 prepared: 0 tx_control: 1 action: QUERY_ACTION_EXECUTE type: QUERY_TYPE_SQL_DML text: -- TDelayRequestQuery::OnRunQuery DECLARE $database AS Text; DECLARE $pool_id AS Text; DECLARE $start_time AS Timestamp; DECLARE $session_id AS Text; DECLARE $node_id AS Uint32; DECLARE $wait_deadline AS Optional; DECLARE $lease_duration AS Interval; UPSERT INTO `.metadata/workload_manager/delayed_requests` (database, pool_id, start_time, session_id, node_id, wait_deadline, lease_deadline) VALUES ( $database, $pool_id, $start_time, $session_id, $node_id, $wait_deadline, CurrentUtcTimestamp() + $lease_duration ); rpcActor: [1:7385280255935135938:4285] database: /Root pool id: 2024-06-27T20:19:15.582761Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=NGUyMGM0ZDItZjkyMDMyNWMtZmU4NjdlYTAtMjBmZGExYQ==, ActorId: [1:7385280255935135937:4313], ActorState: ReadyState, TraceId: 01j1dnmbzy7cs6kqevj8vt2zdy, Sending CompileQuery request 2024-06-27T20:19:15.593209Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=NGUyMGM0ZDItZjkyMDMyNWMtZmU4NjdlYTAtMjBmZGExYQ==, ActorId: [1:7385280255935135937:4313], ActorState: ExecuteState, TraceId: 01j1dnmbzy7cs6kqevj8vt2zdy, ExecutePhyTx, tx: 0x0000075C7AC16218 literal: 1 commit: 0 txCtx.DeferredEffects.size(): 0 2024-06-27T20:19:15.593492Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=NGUyMGM0ZDItZjkyMDMyNWMtZmU4NjdlYTAtMjBmZGExYQ==, ActorId: [1:7385280255935135937:4313], ActorState: ExecuteState, TraceId: 01j1dnmbzy7cs6kqevj8vt2zdy, TEvTxResponse, CurrentTx: 1/2 response.status: SUCCESS 2024-06-27T20:19:15.593508Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=NGUyMGM0ZDItZjkyMDMyNWMtZmU4NjdlYTAtMjBmZGExYQ==, ActorId: [1:7385280255935135937:4313], ActorState: ExecuteState, TraceId: 01j1dnmbzy7cs6kqevj8vt2zdy, ExecutePhyTx, tx: 0x0000000000000000 literal: 0 commit: 1 txCtx.DeferredEffects.size(): 1 2024-06-27T20:19:15.593511Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=NGUyMGM0ZDItZjkyMDMyNWMtZmU4NjdlYTAtMjBmZGExYQ==, ActorId: [1:7385280255935135937:4313], ActorState: ExecuteState, TraceId: 01j1dnmbzy7cs6kqevj8vt2zdy, TExecPhysicalRequest, add DeferredEffect to Transaction, current Transactions.size(): 1 2024-06-27T20:19:15.593515Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=NGUyMGM0ZDItZjkyMDMyNWMtZmU4NjdlYTAtMjBmZGExYQ==, ActorId: [1:7385280255935135937:4313], ActorState: ExecuteState, TraceId: 01j1dnmbzy7cs6kqevj8vt2zdy, Sending to Executer TraceId: 0 8 2024-06-27T20:19:15.593526Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=NGUyMGM0ZDItZjkyMDMyNWMtZmU4NjdlYTAtMjBmZGExYQ==, ActorId: [1:7385280255935135937:4313], ActorState: ExecuteState, TraceId: 01j1dnmbzy7cs6kqevj8vt2zdy, Created new KQP executer: [1:7385280255935135944:4313] isRollback: 0 2024-06-27T20:19:15.595357Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=NGUyMGM0ZDItZjkyMDMyNWMtZmU4NjdlYTAtMjBmZGExYQ==, ActorId: [1:7385280255935135937:4313], ActorState: ExecuteState, TraceId: 01j1dnmbzy7cs6kqevj8vt2zdy, TEvTxResponse, CurrentTx: 2/2 response.status: SUCCESS 2024-06-27T20:19:15.595399Z node 1 :KQP_SESSION INFO: SessionId: ydb://session/3?node_id=1&id=NGUyMGM0ZDItZjkyMDMyNWMtZmU4NjdlYTAtMjBmZGExYQ==, ActorId: [1:7385280255935135937:4313], ActorState: ExecuteState, TraceId: 01j1dnmbzy7cs6kqevj8vt2zdy, txInfo Status: Committed Kind: WriteOnly TotalDuration: 2.239 ServerDuration: 2.192 QueriesCount: 2 2024-06-27T20:19:15.595418Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=NGUyMGM0ZDItZjkyMDMyNWMtZmU4NjdlYTAtMjBmZGExYQ==, ActorId: [1:7385280255935135937:4313], ActorState: ExecuteState, TraceId: 01j1dnmbzy7cs6kqevj8vt2zdy, Create QueryResponse for action: QUERY_ACTION_EXECUTE with SUCCESS status 2024-06-27T20:19:15.595428Z node 1 :KQP_SESSION INFO: SessionId: ydb://session/3?node_id=1&id=NGUyMGM0ZDItZjkyMDMyNWMtZmU4NjdlYTAtMjBmZGExYQ==, ActorId: [1:7385280255935135937:4313], ActorState: ExecuteState, TraceId: 01j1dnmbzy7cs6kqevj8vt2zdy, Cleanup start, isFinal: 0 CleanupCtx: 0 TransactionsToBeAborted.size(): 0 WorkerId: [0:0:0] WorkloadServiceCleanup: 0 2024-06-27T20:19:15.595431Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=NGUyMGM0ZDItZjkyMDMyNWMtZmU4NjdlYTAtMjBmZGExYQ==, ActorId: [1:7385280255935135937:4313], ActorState: ExecuteState, TraceId: 01j1dnmbzy7cs6kqevj8vt2zdy, EndCleanup, isFinal: 0 2024-06-27T20:19:15.595445Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=NGUyMGM0ZDItZjkyMDMyNWMtZmU4NjdlYTAtMjBmZGExYQ==, ActorId: [1:7385280255935135937:4313], ActorState: ExecuteState, TraceId: 01j1dnmbzy7cs6kqevj8vt2zdy, Sent query response back to proxy, proxyRequestId: 14, proxyId: [1:7385280251640167895:12299] 2024-06-27T20:19:15.595560Z node 1 :KQP_WORKLOAD_SERVICE DEBUG: [TQueryBase] [TDelayRequestQuery] TraceId: sample_pool_id, RequestDatabase: Root, RequestSessionId: ydb://session/3?node_id=1&id=ZmNiMDg3ZmUtODA1OTcyMmMtNDBmZTNlODUtODkzNTI5NTg=, TEvDataQueryResult SUCCESS, Issues: , SessionId: ydb://session/3?node_id=1&id=NGUyMGM0ZDItZjkyMDMyNWMtZmU4NjdlYTAtMjBmZGExYQ==, TxId: 2024-06-27T20:19:15.595569Z node 1 :KQP_WORKLOAD_SERVICE DEBUG: [TQueryBase] [TDelayRequestQuery] TraceId: sample_pool_id, RequestDatabase: Root, RequestSessionId: ydb://session/3?node_id=1&id=ZmNiMDg3ZmUtODA1OTcyMmMtNDBmZTNlODUtODkzNTI5NTg=, Finish with SUCCESS, SessionId: ydb://session/3?node_id=1&id=NGUyMGM0ZDItZjkyMDMyNWMtZmU4NjdlYTAtMjBmZGExYQ==, TxId: 2024-06-27T20:19:15.595598Z node 1 :KQP_WORKLOAD_SERVICE DEBUG: [WorkloadService] [TPoolHandlerActorBase] ActorId: [1:7385280255935135602:8276], Database: Root, PoolId: sample_pool_id, succefully delayed request, session id: ydb://session/3?node_id=1&id=ZmNiMDg3ZmUtODA1OTcyMmMtNDBmZTNlODUtODkzNTI5NTg= 2024-06-27T20:19:15.595617Z node 1 :KQP_SESSION INFO: SessionId: ydb://session/3?node_id=1&id=NGUyMGM0ZDItZjkyMDMyNWMtZmU4NjdlYTAtMjBmZGExYQ==, ActorId: [1:7385280255935135937:4313], ActorState: ReadyState, Session closed due to explicit close event 2024-06-27T20:19:15.595643Z node 1 :KQP_SESSION INFO: SessionId: ydb://session/3?node_id=1&id=NGUyMGM0ZDItZjkyMDMyNWMtZmU4NjdlYTAtMjBmZGExYQ==, ActorId: [1:7385280255935135937:4313], ActorState: ReadyState, Cleanup start, isFinal: 1 CleanupCtx: 0 TransactionsToBeAborted.size(): 0 WorkerId: [0:0:0] WorkloadServiceCleanup: 0 2024-06-27T20:19:15.595645Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=NGUyMGM0ZDItZjkyMDMyNWMtZmU4NjdlYTAtMjBmZGExYQ==, ActorId: [1:7385280255935135937:4313], ActorState: ReadyState, EndCleanup, isFinal: 1 2024-06-27T20:19:15.595648Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=NGUyMGM0ZDItZjkyMDMyNWMtZmU4NjdlYTAtMjBmZGExYQ==, ActorId: [1:7385280255935135937:4313], ActorState: unknown state, Cleanup temp tables: 0 2024-06-27T20:19:15.595666Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=NGUyMGM0ZDItZjkyMDMyNWMtZmU4NjdlYTAtMjBmZGExYQ==, ActorId: [1:7385280255935135937:4313], ActorState: unknown state, Session actor destroyed 2024-06-27T20:19:19.865762Z node 1 :METADATA_PROVIDER ERROR: fline=table_exists.cpp:59;actor=TTableExistsActor;event=timeout;self_id=[1:7385280251640167694:4098];send_to=[0:7307199536658146131:7762515]; 2024-06-27T20:19:19.865796Z node 1 :METADATA_PROVIDER ERROR: fline=accessor_snapshot_base.cpp:68;action=cannot detect path existence;path=//Root/.metadata/initialization/migrations;error=timeout; 2024-06-27T20:19:25.261378Z node 1 :KQP_WORKLOAD_SERVICE DEBUG: [WorkloadService] [TPoolHandlerActorBase] ActorId: [1:7385280255935135602:8276], Database: Root, PoolId: sample_pool_id, Cancel request by deadline, worker id: [1:7385280255935135587:4294], session id: ydb://session/3?node_id=1&id=YzNiMDM5NDQtNWE1MjdlYzktMWQyNDk1ZDctOGUwZTBjMGI= 2024-06-27T20:19:25.261476Z node 1 :KQP_WORKLOAD_SERVICE DEBUG: [WorkloadService] [TPoolHandlerActorBase] ActorId: [1:7385280255935135602:8276], Database: Root, PoolId: sample_pool_id, Cancel request by deadline, worker id: [1:7385280255935135589:4295], session id: ydb://session/3?node_id=1&id=ZmNiMDg3ZmUtODA1OTcyMmMtNDBmZTNlODUtODkzNTI5NTg= 2024-06-27T20:19:25.261600Z node 1 :KQP_WORKLOAD_SERVICE DEBUG: [TQueryBase] [TCleanupRequestsQuery] TraceId: sample_pool_id, RequestDatabase: Root, RequestSessionId: , Bootstrap. Database: /Root 2024-06-27T20:19:25.262378Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ZTcxMTE4ZjAtYjEwOTY2ZTEtYmU3ZjEzZjQtMmIzZTg0YTI=, ActorId: [0:0:0], ActorState: unknown state, Create session actor with id ZTcxMTE4ZjAtYjEwOTY2ZTEtYmU3ZjEzZjQtMmIzZTg0YTI= 2024-06-27T20:19:25.262441Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ZTcxMTE4ZjAtYjEwOTY2ZTEtYmU3ZjEzZjQtMmIzZTg0YTI=, ActorId: [1:7385280298884808987:4325], ActorState: unknown state, session actor bootstrapped 2024-06-27T20:19:25.262554Z node 1 :KQP_WORKLOAD_SERVICE TRACE: [WorkloadService] [TCleanupRequestsQuery] ActorId: [1:7385280298884808985:8328], Database: Root, PoolId: sample_pool_id, Cleanup request with session id: ydb://session/3?node_id=1&id=YzNiMDM5NDQtNWE1MjdlYzktMWQyNDk1ZDctOGUwZTBjMGI= 2024-06-27T20:19:25.262569Z node 1 :KQP_WORKLOAD_SERVICE DEBUG: [TQueryBase] [TCleanupRequestsQuery] TraceId: sample_pool_id, RequestDatabase: Root, RequestSessionId: , RunDataQuery: -- TCleanupRequestsQuery::OnRunQuery PRAGMA AnsiInForEmptyOrNullableItemsCollections; DECLARE $database AS Text; DECLARE $pool_id AS Text; DECLARE $node_id AS Uint32; DECLARE $session_ids AS List; DELETE FROM `.metadata/workload_manager/delayed_requests` WHERE database = $database AND pool_id = $pool_id AND session_id IN $session_ids; DELETE FROM `.metadata/workload_manager/running_requests` WHERE database = $database AND pool_id = $pool_id AND node_id = $node_id AND session_id IN $session_ids; 2024-06-27T20:19:25.262919Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ZTcxMTE4ZjAtYjEwOTY2ZTEtYmU3ZjEzZjQtMmIzZTg0YTI=, ActorId: [1:7385280298884808987:4325], ActorState: ReadyState, TraceId: 01j1dnmnee76tgkx19q2zweh97, received request, proxyRequestId: 16 prepared: 0 tx_control: 1 action: QUERY_ACTION_EXECUTE type: QUERY_TYPE_SQL_DML text: -- TCleanupRequestsQuery::OnRunQuery PRAGMA AnsiInForEmptyOrNullableItemsCollections; DECLARE $database AS Text; DECLARE $pool_id AS Text; DECLARE $node_id AS Uint32; DECLARE $session_ids AS List; DELETE FROM `.metadata/workload_manager/delayed_requests` WHERE database = $database AND pool_id = $pool_id AND session_id IN $session_ids; DELETE FROM `.metadata/workload_manager/running_requests` WHERE database = $database AND pool_id = $pool_id AND node_id = $node_id AND session_id IN $session_ids; rpcActor: [1:7385280298884808988:4305] database: /Root pool id: 2024-06-27T20:19:25.262939Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ZTcxMTE4ZjAtYjEwOTY2ZTEtYmU3ZjEzZjQtMmIzZTg0YTI=, ActorId: [1:7385280298884808987:4325], ActorState: ReadyState, TraceId: 01j1dnmnee76tgkx19q2zweh97, Sending CompileQuery request 2024-06-27T20:19:25.321149Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ZTcxMTE4ZjAtYjEwOTY2ZTEtYmU3ZjEzZjQtMmIzZTg0YTI=, ActorId: [1:7385280298884808987:4325], ActorState: ExecuteState, TraceId: 01j1dnmnee76tgkx19q2zweh97, ExecutePhyTx, tx: 0x0000075C7AC18318 literal: 0 commit: 0 txCtx.DeferredEffects.size(): 0 2024-06-27T20:19:25.321172Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ZTcxMTE4ZjAtYjEwOTY2ZTEtYmU3ZjEzZjQtMmIzZTg0YTI=, ActorId: [1:7385280298884808987:4325], ActorState: ExecuteState, TraceId: 01j1dnmnee76tgkx19q2zweh97, Sending to Executer TraceId: 0 8 2024-06-27T20:19:25.321193Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ZTcxMTE4ZjAtYjEwOTY2ZTEtYmU3ZjEzZjQtMmIzZTg0YTI=, ActorId: [1:7385280298884808987:4325], ActorState: ExecuteState, TraceId: 01j1dnmnee76tgkx19q2zweh97, Created new KQP executer: [1:7385280298884808998:4325] isRollback: 0 2024-06-27T20:19:25.322752Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ZTcxMTE4ZjAtYjEwOTY2ZTEtYmU3ZjEzZjQtMmIzZTg0YTI=, ActorId: [1:7385280298884808987:4325], ActorState: ExecuteState, TraceId: 01j1dnmnee76tgkx19q2zweh97, TEvTxResponse, CurrentTx: 1/2 response.status: SUCCESS 2024-06-27T20:19:25.322809Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ZTcxMTE4ZjAtYjEwOTY2ZTEtYmU3ZjEzZjQtMmIzZTg0YTI=, ActorId: [1:7385280298884808987:4325], ActorState: ExecuteState, TraceId: 01j1dnmnee76tgkx19q2zweh97, ExecutePhyTx, tx: 0x0000000000000000 literal: 0 commit: 1 txCtx.DeferredEffects.size(): 1 2024-06-27T20:19:25.322817Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ZTcxMTE4ZjAtYjEwOTY2ZTEtYmU3ZjEzZjQtMmIzZTg0YTI=, ActorId: [1:7385280298884808987:4325], ActorState: ExecuteState, TraceId: 01j1dnmnee76tgkx19q2zweh97, TExecPhysicalRequest, add DeferredEffect to Transaction, current Transactions.size(): 1 2024-06-27T20:19:25.322819Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ZTcxMTE4ZjAtYjEwOTY2ZTEtYmU3ZjEzZjQtMmIzZTg0YTI=, ActorId: [1:7385280298884808987:4325], ActorState: ExecuteState, TraceId: 01j1dnmnee76tgkx19q2zweh97, TExecPhysicalRequest, tx has commit locks 2024-06-27T20:19:25.322824Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ZTcxMTE4ZjAtYjEwOTY2ZTEtYmU3ZjEzZjQtMmIzZTg0YTI=, ActorId: [1:7385280298884808987:4325], ActorState: ExecuteState, TraceId: 01j1dnmnee76tgkx19q2zweh97, Sending to Executer TraceId: 0 8 2024-06-27T20:19:25.322832Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ZTcxMTE4ZjAtYjEwOTY2ZTEtYmU3ZjEzZjQtMmIzZTg0YTI=, ActorId: [1:7385280298884808987:4325], ActorState: ExecuteState, TraceId: 01j1dnmnee76tgkx19q2zweh97, Created new KQP executer: [1:7385280298884809010:4325] isRollback: 0 2024-06-27T20:19:25.325453Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ZTcxMTE4ZjAtYjEwOTY2ZTEtYmU3ZjEzZjQtMmIzZTg0YTI=, ActorId: [1:7385280298884808987:4325], ActorState: ExecuteState, TraceId: 01j1dnmnee76tgkx19q2zweh97, TEvTxResponse, CurrentTx: 2/2 response.status: SUCCESS 2024-06-27T20:19:25.325517Z node 1 :KQP_SESSION INFO: SessionId: ydb://session/3?node_id=1&id=ZTcxMTE4ZjAtYjEwOTY2ZTEtYmU3ZjEzZjQtMmIzZTg0YTI=, ActorId: [1:7385280298884808987:4325], ActorState: ExecuteState, TraceId: 01j1dnmnee76tgkx19q2zweh97, txInfo Status: Committed Kind: ReadWrite TotalDuration: 4.44 ServerDuration: 4.378 QueriesCount: 2 2024-06-27T20:19:25.325556Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ZTcxMTE4ZjAtYjEwOTY2ZTEtYmU3ZjEzZjQtMmIzZTg0YTI=, ActorId: [1:7385280298884808987:4325], ActorState: ExecuteState, TraceId: 01j1dnmnee76tgkx19q2zweh97, Create QueryResponse for action: QUERY_ACTION_EXECUTE with SUCCESS status 2024-06-27T20:19:25.325569Z node 1 :KQP_SESSION INFO: SessionId: ydb://session/3?node_id=1&id=ZTcxMTE4ZjAtYjEwOTY2ZTEtYmU3ZjEzZjQtMmIzZTg0YTI=, ActorId: [1:7385280298884808987:4325], ActorState: ExecuteState, TraceId: 01j1dnmnee76tgkx19q2zweh97, Cleanup start, isFinal: 0 CleanupCtx: 0 TransactionsToBeAborted.size(): 0 WorkerId: [0:0:0] WorkloadServiceCleanup: 0 2024-06-27T20:19:25.325574Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ZTcxMTE4ZjAtYjEwOTY2ZTEtYmU3ZjEzZjQtMmIzZTg0YTI=, ActorId: [1:7385280298884808987:4325], ActorState: ExecuteState, TraceId: 01j1dnmnee76tgkx19q2zweh97, EndCleanup, isFinal: 0 2024-06-27T20:19:25.325589Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ZTcxMTE4ZjAtYjEwOTY2ZTEtYmU3ZjEzZjQtMmIzZTg0YTI=, ActorId: [1:7385280298884808987:4325], ActorState: ExecuteState, TraceId: 01j1dnmnee76tgkx19q2zweh97, Sent query response back to proxy, proxyRequestId: 16, proxyId: [1:7385280251640167895:12299] 2024-06-27T20:19:25.325721Z node 1 :KQP_WORKLOAD_SERVICE DEBUG: [TQueryBase] [TCleanupRequestsQuery] TraceId: sample_pool_id, RequestDatabase: Root, RequestSessionId: , TEvDataQueryResult SUCCESS, Issues: , SessionId: ydb://session/3?node_id=1&id=ZTcxMTE4ZjAtYjEwOTY2ZTEtYmU3ZjEzZjQtMmIzZTg0YTI=, TxId: 2024-06-27T20:19:25.325744Z node 1 :KQP_WORKLOAD_SERVICE DEBUG: [TQueryBase] [TCleanupRequestsQuery] TraceId: sample_pool_id, RequestDatabase: Root, RequestSessionId: , Finish with SUCCESS, SessionId: ydb://session/3?node_id=1&id=ZTcxMTE4ZjAtYjEwOTY2ZTEtYmU3ZjEzZjQtMmIzZTg0YTI=, TxId: 2024-06-27T20:19:25.325778Z node 1 :KQP_WORKLOAD_SERVICE TRACE: [WorkloadService] [TPoolHandlerActorBase] ActorId: [1:7385280255935135602:8276], Database: Root, PoolId: sample_pool_id, succefully cleanuped request, session id: ydb://session/3?node_id=1&id=YzNiMDM5NDQtNWE1MjdlYzktMWQyNDk1ZDctOGUwZTBjMGI= 2024-06-27T20:19:25.325797Z node 1 :KQP_WORKLOAD_SERVICE INFO: [WorkloadService] [TPoolHandlerActorBase] ActorId: [1:7385280255935135602:8276], Database: Root, PoolId: sample_pool_id, Cancel request for worker [1:7385280255935135587:4294], session id: ydb://session/3?node_id=1&id=YzNiMDM5NDQtNWE1MjdlYzktMWQyNDk1ZDctOGUwZTBjMGI=, local in flight: 0 2024-06-27T20:19:25.325832Z node 1 :KQP_WORKLOAD_SERVICE DEBUG: [TQueryBase] [TCleanupRequestsQuery] TraceId: sample_pool_id, RequestDatabase: Root, RequestSessionId: , Bootstrap. Database: /Root 2024-06-27T20:19:25.325835Z node 1 :KQP_SESSION INFO: SessionId: ydb://session/3?node_id=1&id=ZTcxMTE4ZjAtYjEwOTY2ZTEtYmU3ZjEzZjQtMmIzZTg0YTI=, ActorId: [1:7385280298884808987:4325], ActorState: ReadyState, Session closed due to explicit close event 2024-06-27T20:19:25.325840Z node 1 :KQP_SESSION INFO: SessionId: ydb://session/3?node_id=1&id=ZTcxMTE4ZjAtYjEwOTY2ZTEtYmU3ZjEzZjQtMmIzZTg0YTI=, ActorId: [1:7385280298884808987:4325], ActorState: ReadyState, Cleanup start, isFinal: 1 CleanupCtx: 0 TransactionsToBeAborted.size(): 0 WorkerId: [0:0:0] WorkloadServiceCleanup: 0 2024-06-27T20:19:25.325843Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ZTcxMTE4ZjAtYjEwOTY2ZTEtYmU3ZjEzZjQtMmIzZTg0YTI=, ActorId: [1:7385280298884808987:4325], ActorState: ReadyState, EndCleanup, isFinal: 1 2024-06-27T20:19:25.325845Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ZTcxMTE4ZjAtYjEwOTY2ZTEtYmU3ZjEzZjQtMmIzZTg0YTI=, ActorId: [1:7385280298884808987:4325], ActorState: unknown state, Cleanup temp tables: 0 2024-06-27T20:19:25.325867Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ZTcxMTE4ZjAtYjEwOTY2ZTEtYmU3ZjEzZjQtMmIzZTg0YTI=, ActorId: [1:7385280298884808987:4325], ActorState: unknown state, Session actor destroyed 2024-06-27T20:19:25.326026Z node 1 :KQP_SESSION INFO: SessionId: ydb://session/3?node_id=1&id=YzNiMDM5NDQtNWE1MjdlYzktMWQyNDk1ZDctOGUwZTBjMGI=, ActorId: [1:7385280255935135587:4294], ActorState: ExecuteState, TraceId: 01j1dnmbnwb3znjgdtw3kv6eed, got TEvAbortExecution in ExecuteState, status: CANCELLED send to: [1:7385280255935135901:4294] 2024-06-27T20:19:25.326072Z node 1 :KQP_EXECUTER ERROR: ActorId: [1:7385280255935135901:4294] TxId: 281474976715669. Ctx: { TraceId: 01j1dnmbnwb3znjgdtw3kv6eed, Database: Root, SessionId: ydb://session/3?node_id=1&id=YzNiMDM5NDQtNWE1MjdlYzktMWQyNDk1ZDctOGUwZTBjMGI=, CurrentExecutionId: , CustomerSuppliedId: , PoolId: sample_pool_id}. CANCELLED: {
: Error: Request timeout exceeded, cancelling after 10065 milliseconds. } 2024-06-27T20:19:25.326341Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=YTY4MzMwM2UtNGU1YWYyMGMtY2ZkNmQ5ZDQtOGE4OTVjOTY=, ActorId: [0:0:0], ActorState: unknown state, Create session actor with id YTY4MzMwM2UtNGU1YWYyMGMtY2ZkNmQ5ZDQtOGE4OTVjOTY= 2024-06-27T20:19:25.326476Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=YTY4MzMwM2UtNGU1YWYyMGMtY2ZkNmQ5ZDQtOGE4OTVjOTY=, ActorId: [1:7385280298884809024:4299], ActorState: unknown state, session actor bootstrapped 2024-06-27T20:19:25.326560Z node 1 :KQP_WORKLOAD_SERVICE TRACE: [WorkloadService] [TCleanupRequestsQuery] ActorId: [1:7385280298884809021:8326], Database: Root, PoolId: sample_pool_id, Cleanup request with session id: ydb://session/3?node_id=1&id=ZmNiMDg3ZmUtODA1OTcyMmMtNDBmZTNlODUtODkzNTI5NTg= 2024-06-27T20:19:25.326570Z node 1 :KQP_WORKLOAD_SERVICE DEBUG: [TQueryBase] [TCleanupRequestsQuery] TraceId: sample_pool_id, RequestDatabase: Root, RequestSessionId: , RunDataQuery: -- TCleanupRequestsQuery::OnRunQuery PRAGMA AnsiInForEmptyOrNullableItemsCollections; DECLARE $database AS Text; DECLARE $pool_id AS Text; DECLARE $node_id AS Uint32; DECLARE $session_ids AS List; DELETE FROM `.metadata/workload_manager/delayed_requests` WHERE database = $database AND pool_id = $pool_id AND session_id IN $session_ids; DELETE FROM `.metadata/workload_manager/running_requests` WHERE database = $database AND pool_id = $pool_id AND node_id = $node_id AND session_id IN $session_ids; 2024-06-27T20:19:25.327085Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=YTY4MzMwM2UtNGU1YWYyMGMtY2ZkNmQ5ZDQtOGE4OTVjOTY=, ActorId: [1:7385280298884809024:4299], ActorState: ReadyState, TraceId: 01j1dnmngf3r8h7bnm00h2nwj9, received request, proxyRequestId: 19 prepared: 0 tx_control: 1 action: QUERY_ACTION_EXECUTE type: QUERY_TYPE_SQL_DML text: -- TCleanupRequestsQuery::OnRunQuery PRAGMA AnsiInForEmptyOrNullableItemsCollections; DECLARE $database AS Text; DECLARE $pool_id AS Text; DECLARE $node_id AS Uint32; DECLARE $session_ids AS List; DELETE FROM `.metadata/workload_manager/delayed_requests` WHERE database = $database AND pool_id = $pool_id AND session_id IN $session_ids; DELETE FROM `.metadata/workload_manager/running_requests` WHERE database = $database AND pool_id = $pool_id AND node_id = $node_id AND session_id IN $session_ids; rpcActor: [1:7385280298884809026:4339] database: /Root pool id: 2024-06-27T20:19:25.327100Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=YTY4MzMwM2UtNGU1YWYyMGMtY2ZkNmQ5ZDQtOGE4OTVjOTY=, ActorId: [1:7385280298884809024:4299], ActorState: ReadyState, TraceId: 01j1dnmngf3r8h7bnm00h2nwj9, Sending CompileQuery request 2024-06-27T20:19:25.327423Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=YTY4MzMwM2UtNGU1YWYyMGMtY2ZkNmQ5ZDQtOGE4OTVjOTY=, ActorId: [1:7385280298884809024:4299], ActorState: ExecuteState, TraceId: 01j1dnmngf3r8h7bnm00h2nwj9, ExecutePhyTx, tx: 0x0000075C7AC18318 literal: 0 commit: 0 txCtx.DeferredEffects.size(): 0 2024-06-27T20:19:25.327444Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=YTY4MzMwM2UtNGU1YWYyMGMtY2ZkNmQ5ZDQtOGE4OTVjOTY=, ActorId: [1:7385280298884809024:4299], ActorState: ExecuteState, TraceId: 01j1dnmngf3r8h7bnm00h2nwj9, Sending to Executer TraceId: 0 8 2024-06-27T20:19:25.327455Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=YTY4MzMwM2UtNGU1YWYyMGMtY2ZkNmQ5ZDQtOGE4OTVjOTY=, ActorId: [1:7385280298884809024:4299], ActorState: ExecuteState, TraceId: 01j1dnmngf3r8h7bnm00h2nwj9, Created new KQP executer: [1:7385280298884809029:4299] isRollback: 0 2024-06-27T20:19:25.327499Z node 1 :KQP_COMPUTE ERROR: SelfId: [1:7385280255935135906:4294], TxId: 281474976715669, task: 1. Ctx: { CustomerSuppliedId : . TraceId : 01j1dnmbnwb3znjgdtw3kv6eed. SessionId : ydb://session/3?node_id=1&id=YzNiMDM5NDQtNWE1MjdlYzktMWQyNDk1ZDctOGUwZTBjMGI=. CurrentExecutionId : . Database : Root. PoolId : sample_pool_id. }. Handle abort execution event from: [1:7385280255935135901:4294], status: CANCELLED, reason: {
: Error: Request timeout exceeded, cancelling after 10065 milliseconds. } 2024-06-27T20:19:25.327579Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=YzNiMDM5NDQtNWE1MjdlYzktMWQyNDk1ZDctOGUwZTBjMGI=, ActorId: [1:7385280255935135587:4294], ActorState: ExecuteState, TraceId: 01j1dnmbnwb3znjgdtw3kv6eed, TEvTxResponse, CurrentTx: 1/1 response.status: CANCELLED 2024-06-27T20:19:25.327588Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=YzNiMDM5NDQtNWE1MjdlYzktMWQyNDk1ZDctOGUwZTBjMGI=, ActorId: [1:7385280255935135587:4294], ActorState: ExecuteState, TraceId: 01j1dnmbnwb3znjgdtw3kv6eed, TEvTxResponse has non-success status, CurrentTx: 1 ExecutionType: Data 2024-06-27T20:19:25.327592Z node 1 :KQP_SESSION WARN: SessionId: ydb://session/3?node_id=1&id=YzNiMDM5NDQtNWE1MjdlYzktMWQyNDk1ZDctOGUwZTBjMGI=, ActorId: [1:7385280255935135587:4294], ActorState: ExecuteState, TraceId: 01j1dnmbnwb3znjgdtw3kv6eed, Create QueryResponse for error on request, msg: 2024-06-27T20:19:25.327604Z node 1 :KQP_SESSION INFO: SessionId: ydb://session/3?node_id=1&id=YzNiMDM5NDQtNWE1MjdlYzktMWQyNDk1ZDctOGUwZTBjMGI=, ActorId: [1:7385280255935135587:4294], ActorState: ExecuteState, TraceId: 01j1dnmbnwb3znjgdtw3kv6eed, txInfo Status: Aborted Kind: Pure TotalDuration: 0 ServerDuration: 9747.653 QueriesCount: 2 2024-06-27T20:19:25.327614Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=YzNiMDM5NDQtNWE1MjdlYzktMWQyNDk1ZDctOGUwZTBjMGI=, ActorId: [1:7385280255935135587:4294], ActorState: ExecuteState, TraceId: 01j1dnmbnwb3znjgdtw3kv6eed, Sending to Executer TraceId: 0 8 2024-06-27T20:19:25.327629Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=YzNiMDM5NDQtNWE1MjdlYzktMWQyNDk1ZDctOGUwZTBjMGI=, ActorId: [1:7385280255935135587:4294], ActorState: ExecuteState, TraceId: 01j1dnmbnwb3znjgdtw3kv6eed, Created new KQP executer: [1:7385280298884809033:4294] isRollback: 1 2024-06-27T20:19:25.327645Z node 1 :KQP_SESSION INFO: SessionId: ydb://session/3?node_id=1&id=YzNiMDM5NDQtNWE1MjdlYzktMWQyNDk1ZDctOGUwZTBjMGI=, ActorId: [1:7385280255935135587:4294], ActorState: ExecuteState, TraceId: 01j1dnmbnwb3znjgdtw3kv6eed, Cleanup start, isFinal: 1 CleanupCtx: 1 TransactionsToBeAborted.size(): 1 WorkerId: [0:0:0] WorkloadServiceCleanup: 1 2024-06-27T20:19:25.327662Z node 1 :KQP_WORKLOAD_SERVICE DEBUG: [WorkloadService] [Service] Finished request with worker actor [1:7385280255935135587:4294], Database: Root, PoolId: sample_pool_id, SessionId: ydb://session/3?node_id=1&id=YzNiMDM5NDQtNWE1MjdlYzktMWQyNDk1ZDctOGUwZTBjMGI= 2024-06-27T20:19:25.327827Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=YzNiMDM5NDQtNWE1MjdlYzktMWQyNDk1ZDctOGUwZTBjMGI=, ActorId: [1:7385280255935135587:4294], ActorState: CleanupState, TraceId: 01j1dnmbnwb3znjgdtw3kv6eed, EndCleanup, isFinal: 1 2024-06-27T20:19:25.327871Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=YzNiMDM5NDQtNWE1MjdlYzktMWQyNDk1ZDctOGUwZTBjMGI=, ActorId: [1:7385280255935135587:4294], ActorState: CleanupState, TraceId: 01j1dnmbnwb3znjgdtw3kv6eed, Sent query response back to proxy, proxyRequestId: 3, proxyId: [1:7385280251640167895:12299] 2024-06-27T20:19:25.327879Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=YzNiMDM5NDQtNWE1MjdlYzktMWQyNDk1ZDctOGUwZTBjMGI=, ActorId: [1:7385280255935135587:4294], ActorState: unknown state, TraceId: 01j1dnmbnwb3znjgdtw3kv6eed, Cleanup temp tables: 0 2024-06-27T20:19:25.327891Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=YzNiMDM5NDQtNWE1MjdlYzktMWQyNDk1ZDctOGUwZTBjMGI=, ActorId: [1:7385280255935135587:4294], ActorState: unknown state, TraceId: 01j1dnmbnwb3znjgdtw3kv6eed, Session actor destroyed 2024-06-27T20:19:25.328263Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=YTY4MzMwM2UtNGU1YWYyMGMtY2ZkNmQ5ZDQtOGE4OTVjOTY=, ActorId: [1:7385280298884809024:4299], ActorState: ExecuteState, TraceId: 01j1dnmngf3r8h7bnm00h2nwj9, TEvTxResponse, CurrentTx: 1/2 response.status: SUCCESS 2024-06-27T20:19:25.328306Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=YTY4MzMwM2UtNGU1YWYyMGMtY2ZkNmQ5ZDQtOGE4OTVjOTY=, ActorId: [1:7385280298884809024:4299], ActorState: ExecuteState, TraceId: 01j1dnmngf3r8h7bnm00h2nwj9, ExecutePhyTx, tx: 0x0000000000000000 literal: 0 commit: 1 txCtx.DeferredEffects.size(): 1 2024-06-27T20:19:25.328309Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=YTY4MzMwM2UtNGU1YWYyMGMtY2ZkNmQ5ZDQtOGE4OTVjOTY=, ActorId: [1:7385280298884809024:4299], ActorState: ExecuteState, TraceId: 01j1dnmngf3r8h7bnm00h2nwj9, TExecPhysicalRequest, add DeferredEffect to Transaction, current Transactions.size(): 1 2024-06-27T20:19:25.328311Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=YTY4MzMwM2UtNGU1YWYyMGMtY2ZkNmQ5ZDQtOGE4OTVjOTY=, ActorId: [1:7385280298884809024:4299], ActorState: ExecuteState, TraceId: 01j1dnmngf3r8h7bnm00h2nwj9, TExecPhysicalRequest, tx has commit locks 2024-06-27T20:19:25.328316Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=YTY4MzMwM2UtNGU1YWYyMGMtY2ZkNmQ5ZDQtOGE4OTVjOTY=, ActorId: [1:7385280298884809024:4299], ActorState: ExecuteState, TraceId: 01j1dnmngf3r8h7bnm00h2nwj9, Sending to Executer TraceId: 0 8 2024-06-27T20:19:25.328321Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=YTY4MzMwM2UtNGU1YWYyMGMtY2ZkNmQ5ZDQtOGE4OTVjOTY=, ActorId: [1:7385280298884809024:4299], ActorState: ExecuteState, TraceId: 01j1dnmngf3r8h7bnm00h2nwj9, Created new KQP executer: [1:7385280298884809044:4299] isRollback: 0 2024-06-27T20:19:25.330598Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=YTY4MzMwM2UtNGU1YWYyMGMtY2ZkNmQ5ZDQtOGE4OTVjOTY=, ActorId: [1:7385280298884809024:4299], ActorState: ExecuteState, TraceId: 01j1dnmngf3r8h7bnm00h2nwj9, TEvTxResponse, CurrentTx: 2/2 response.status: SUCCESS 2024-06-27T20:19:25.330633Z node 1 :KQP_SESSION INFO: SessionId: ydb://session/3?node_id=1&id=YTY4MzMwM2UtNGU1YWYyMGMtY2ZkNmQ5ZDQtOGE4OTVjOTY=, ActorId: [1:7385280298884809024:4299], ActorState: ExecuteState, TraceId: 01j1dnmngf3r8h7bnm00h2nwj9, txInfo Status: Committed Kind: ReadWrite TotalDuration: 3.254 ServerDuration: 3.219 QueriesCount: 2 2024-06-27T20:19:25.330653Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=YTY4MzMwM2UtNGU1YWYyMGMtY2ZkNmQ5ZDQtOGE4OTVjOTY=, ActorId: [1:7385280298884809024:4299], ActorState: ExecuteState, TraceId: 01j1dnmngf3r8h7bnm00h2nwj9, Create QueryResponse for action: QUERY_ACTION_EXECUTE with SUCCESS status 2024-06-27T20:19:25.330662Z node 1 :KQP_SESSION INFO: SessionId: ydb://session/3?node_id=1&id=YTY4MzMwM2UtNGU1YWYyMGMtY2ZkNmQ5ZDQtOGE4OTVjOTY=, ActorId: [1:7385280298884809024:4299], ActorState: ExecuteState, TraceId: 01j1dnmngf3r8h7bnm00h2nwj9, Cleanup start, isFinal: 0 CleanupCtx: 0 TransactionsToBeAborted.size(): 0 WorkerId: [0:0:0] WorkloadServiceCleanup: 0 2024-06-27T20:19:25.330664Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=YTY4MzMwM2UtNGU1YWYyMGMtY2ZkNmQ5ZDQtOGE4OTVjOTY=, ActorId: [1:7385280298884809024:4299], ActorState: ExecuteState, TraceId: 01j1dnmngf3r8h7bnm00h2nwj9, EndCleanup, isFinal: 0 2024-06-27T20:19:25.330677Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=YTY4MzMwM2UtNGU1YWYyMGMtY2ZkNmQ5ZDQtOGE4OTVjOTY=, ActorId: [1:7385280298884809024:4299], ActorState: ExecuteState, TraceId: 01j1dnmngf3r8h7bnm00h2nwj9, Sent query response back to proxy, proxyRequestId: 19, proxyId: [1:7385280251640167895:12299] 2024-06-27T20:19:25.330823Z node 1 :KQP_WORKLOAD_SERVICE DEBUG: [TQueryBase] [TCleanupRequestsQuery] TraceId: sample_pool_id, RequestDatabase: Root, RequestSessionId: , TEvDataQueryResult SUCCESS, Issues: , SessionId: ydb://session/3?node_id=1&id=YTY4MzMwM2UtNGU1YWYyMGMtY2ZkNmQ5ZDQtOGE4OTVjOTY=, TxId: 2024-06-27T20:19:25.330831Z node 1 :KQP_WORKLOAD_SERVICE DEBUG: [TQueryBase] [TCleanupRequestsQuery] TraceId: sample_pool_id, RequestDatabase: Root, RequestSessionId: , Finish with SUCCESS, SessionId: ydb://session/3?node_id=1&id=YTY4MzMwM2UtNGU1YWYyMGMtY2ZkNmQ5ZDQtOGE4OTVjOTY=, TxId: 2024-06-27T20:19:25.330857Z node 1 :KQP_WORKLOAD_SERVICE TRACE: [WorkloadService] [TPoolHandlerActorBase] ActorId: [1:7385280255935135602:8276], Database: Root, PoolId: sample_pool_id, succefully cleanuped request, session id: ydb://session/3?node_id=1&id=ZmNiMDg3ZmUtODA1OTcyMmMtNDBmZTNlODUtODkzNTI5NTg= 2024-06-27T20:19:25.330876Z node 1 :KQP_WORKLOAD_SERVICE INFO: [WorkloadService] [TPoolHandlerActorBase] ActorId: [1:7385280255935135602:8276], Database: Root, PoolId: sample_pool_id, Reply cancelled to [1:7385280255935135589:4295], session id: ydb://session/3?node_id=1&id=ZmNiMDg3ZmUtODA1OTcyMmMtNDBmZTNlODUtODkzNTI5NTg=, issues: 2024-06-27T20:19:25.330902Z node 1 :KQP_SESSION WARN: SessionId: ydb://session/3?node_id=1&id=ZmNiMDg3ZmUtODA1OTcyMmMtNDBmZTNlODUtODkzNTI5NTg=, ActorId: [1:7385280255935135589:4295], ActorState: ExecuteState, TraceId: 01j1dnmbnw7se85r900xdda22m, Create QueryResponse for error on request, msg: Query failed during adding/waiting in workload pool sample_pool_id 2024-06-27T20:19:25.330904Z node 1 :KQP_WORKLOAD_SERVICE DEBUG: [TQueryBase] [TRefreshPoolStateQuery] TraceId: sample_pool_id, RequestDatabase: Root, RequestSessionId: , Bootstrap. Database: /Root 2024-06-27T20:19:25.330932Z node 1 :KQP_SESSION INFO: SessionId: ydb://session/3?node_id=1&id=ZmNiMDg3ZmUtODA1OTcyMmMtNDBmZTNlODUtODkzNTI5NTg=, ActorId: [1:7385280255935135589:4295], ActorState: ExecuteState, TraceId: 01j1dnmbnw7se85r900xdda22m, Cleanup start, isFinal: 1 CleanupCtx: 1 TransactionsToBeAborted.size(): 0 WorkerId: [0:0:0] WorkloadServiceCleanup: 1 2024-06-27T20:19:25.330934Z node 1 :KQP_WORKLOAD_SERVICE DEBUG: [WorkloadService] [Service] Finished request with worker actor [1:7385280255935135589:4295], Database: Root, PoolId: sample_pool_id, SessionId: ydb://session/3?node_id=1&id=ZmNiMDg3ZmUtODA1OTcyMmMtNDBmZTNlODUtODkzNTI5NTg= 2024-06-27T20:19:25.330954Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ZmNiMDg3ZmUtODA1OTcyMmMtNDBmZTNlODUtODkzNTI5NTg=, ActorId: [1:7385280255935135589:4295], ActorState: CleanupState, TraceId: 01j1dnmbnw7se85r900xdda22m, EndCleanup, isFinal: 1 2024-06-27T20:19:25.330969Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ZmNiMDg3ZmUtODA1OTcyMmMtNDBmZTNlODUtODkzNTI5NTg=, ActorId: [1:7385280255935135589:4295], ActorState: CleanupState, TraceId: 01j1dnmbnw7se85r900xdda22m, Sent query response back to proxy, proxyRequestId: 4, proxyId: [1:7385280251640167895:12299] 2024-06-27T20:19:25.330977Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ZmNiMDg3ZmUtODA1OTcyMmMtNDBmZTNlODUtODkzNTI5NTg=, ActorId: [1:7385280255935135589:4295], ActorState: unknown state, TraceId: 01j1dnmbnw7se85r900xdda22m, Cleanup temp tables: 0 2024-06-27T20:19:25.330987Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ZmNiMDg3ZmUtODA1OTcyMmMtNDBmZTNlODUtODkzNTI5NTg=, ActorId: [1:7385280255935135589:4295], ActorState: unknown state, TraceId: 01j1dnmbnw7se85r900xdda22m, Session actor destroyed 2024-06-27T20:19:25.331034Z node 1 :KQP_SESSION INFO: SessionId: ydb://session/3?node_id=1&id=YTY4MzMwM2UtNGU1YWYyMGMtY2ZkNmQ5ZDQtOGE4OTVjOTY=, ActorId: [1:7385280298884809024:4299], ActorState: ReadyState, Session closed due to explicit close event 2024-06-27T20:19:25.331046Z node 1 :KQP_SESSION INFO: SessionId: ydb://session/3?node_id=1&id=YTY4MzMwM2UtNGU1YWYyMGMtY2ZkNmQ5ZDQtOGE4OTVjOTY=, ActorId: [1:7385280298884809024:4299], ActorState: ReadyState, Cleanup start, isFinal: 1 CleanupCtx: 0 TransactionsToBeAborted.size(): 0 WorkerId: [0:0:0] WorkloadServiceCleanup: 0 2024-06-27T20:19:25.331048Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=YTY4MzMwM2UtNGU1YWYyMGMtY2ZkNmQ5ZDQtOGE4OTVjOTY=, ActorId: [1:7385280298884809024:4299], ActorState: ReadyState, EndCleanup, isFinal: 1 2024-06-27T20:19:25.331051Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=YTY4MzMwM2UtNGU1YWYyMGMtY2ZkNmQ5ZDQtOGE4OTVjOTY=, ActorId: [1:7385280298884809024:4299], ActorState: unknown state, Cleanup temp tables: 0 2024-06-27T20:19:25.331065Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=YTY4MzMwM2UtNGU1YWYyMGMtY2ZkNmQ5ZDQtOGE4OTVjOTY=, ActorId: [1:7385280298884809024:4299], ActorState: unknown state, Session actor destroyed 2024-06-27T20:19:25.331504Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ZWVkZmZmMjEtMzdiZjVlMTMtY2VlYjc1MTgtYjk0NmMwM2U=, ActorId: [0:0:0], ActorState: unknown state, Create session actor with id ZWVkZmZmMjEtMzdiZjVlMTMtY2VlYjc1MTgtYjk0NmMwM2U= 2024-06-27T20:19:25.331524Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ZWVkZmZmMjEtMzdiZjVlMTMtY2VlYjc1MTgtYjk0NmMwM2U=, ActorId: [1:7385280298884809057:4312], ActorState: unknown state, session actor bootstrapped 2024-06-27T20:19:25.331594Z node 1 :KQP_WORKLOAD_SERVICE DEBUG: [TQueryBase] [TRefreshPoolStateQuery] TraceId: sample_pool_id, RequestDatabase: Root, RequestSessionId: , RunDataQuery: -- TRefreshPoolStateQuery::OnRunQuery DECLARE $database AS Text; DECLARE $pool_id AS Text; DECLARE $node_id AS Uint32; DECLARE $lease_duration AS Interval; UPDATE `.metadata/workload_manager/delayed_requests` SET lease_deadline = CurrentUtcTimestamp() + $lease_duration WHERE database = $database AND pool_id = $pool_id AND node_id = $node_id AND (wait_deadline IS NULL OR wait_deadline >= CurrentUtcTimestamp()) AND lease_deadline >= CurrentUtcTimestamp(); UPDATE `.metadata/workload_manager/running_requests` SET lease_deadline = CurrentUtcTimestamp() + $lease_duration WHERE database = $database AND pool_id = $pool_id AND node_id = $node_id AND lease_deadline >= CurrentUtcTimestamp(); 2024-06-27T20:19:25.331704Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ZWVkZmZmMjEtMzdiZjVlMTMtY2VlYjc1MTgtYjk0NmMwM2U=, ActorId: [1:7385280298884809057:4312], ActorState: ReadyState, TraceId: 01j1dnmngk0d6jwk44mzh1cg25, received request, proxyRequestId: 21 prepared: 0 tx_control: 1 action: QUERY_ACTION_EXECUTE type: QUERY_TYPE_SQL_DML text: -- TRefreshPoolStateQuery::OnRunQuery DECLARE $database AS Text; DECLARE $pool_id AS Text; DECLARE $node_id AS Uint32; DECLARE $lease_duration AS Interval; UPDATE `.metadata/workload_manager/delayed_requests` SET lease_deadline = CurrentUtcTimestamp() + $lease_duration WHERE database = $database AND pool_id = $pool_id AND node_id = $node_id AND (wait_deadline IS NULL OR wait_deadline >= CurrentUtcTimestamp()) AND lease_deadline >= CurrentUtcTimestamp(); UPDATE `.metadata/workload_manager/running_requests` SET lease_deadline = CurrentUtcTimestamp() + $lease_duration WHERE database = $database AND pool_id = $pool_id AND node_id = $node_id AND lease_deadline >= CurrentUtcTimestamp(); rpcActor: [1:7385280298884809058:4341] database: /Root pool id: 2024-06-27T20:19:25.331727Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ZWVkZmZmMjEtMzdiZjVlMTMtY2VlYjc1MTgtYjk0NmMwM2U=, ActorId: [1:7385280298884809057:4312], ActorState: ReadyState, TraceId: 01j1dnmngk0d6jwk44mzh1cg25, Sending CompileQuery request 2024-06-27T20:19:25.332015Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ZWVkZmZmMjEtMzdiZjVlMTMtY2VlYjc1MTgtYjk0NmMwM2U=, ActorId: [1:7385280298884809057:4312], ActorState: ExecuteState, TraceId: 01j1dnmngk0d6jwk44mzh1cg25, ExecutePhyTx, tx: 0x0000075C7AC19698 literal: 0 commit: 0 txCtx.DeferredEffects.size(): 0 2024-06-27T20:19:25.332033Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ZWVkZmZmMjEtMzdiZjVlMTMtY2VlYjc1MTgtYjk0NmMwM2U=, ActorId: [1:7385280298884809057:4312], ActorState: ExecuteState, TraceId: 01j1dnmngk0d6jwk44mzh1cg25, Sending to Executer TraceId: 0 8 2024-06-27T20:19:25.332041Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ZWVkZmZmMjEtMzdiZjVlMTMtY2VlYjc1MTgtYjk0NmMwM2U=, ActorId: [1:7385280298884809057:4312], ActorState: ExecuteState, TraceId: 01j1dnmngk0d6jwk44mzh1cg25, Created new KQP executer: [1:7385280298884809061:4312] isRollback: 0 2024-06-27T20:19:25.332988Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ZWVkZmZmMjEtMzdiZjVlMTMtY2VlYjc1MTgtYjk0NmMwM2U=, ActorId: [1:7385280298884809057:4312], ActorState: ExecuteState, TraceId: 01j1dnmngk0d6jwk44mzh1cg25, TEvTxResponse, CurrentTx: 1/2 response.status: SUCCESS 2024-06-27T20:19:25.333029Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ZWVkZmZmMjEtMzdiZjVlMTMtY2VlYjc1MTgtYjk0NmMwM2U=, ActorId: [1:7385280298884809057:4312], ActorState: ExecuteState, TraceId: 01j1dnmngk0d6jwk44mzh1cg25, ExecutePhyTx, tx: 0x0000000000000000 literal: 0 commit: 1 txCtx.DeferredEffects.size(): 1 2024-06-27T20:19:25.333037Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ZWVkZmZmMjEtMzdiZjVlMTMtY2VlYjc1MTgtYjk0NmMwM2U=, ActorId: [1:7385280298884809057:4312], ActorState: ExecuteState, TraceId: 01j1dnmngk0d6jwk44mzh1cg25, TExecPhysicalRequest, add DeferredEffect to Transaction, current Transactions.size(): 1 2024-06-27T20:19:25.333039Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ZWVkZmZmMjEtMzdiZjVlMTMtY2VlYjc1MTgtYjk0NmMwM2U=, ActorId: [1:7385280298884809057:4312], ActorState: ExecuteState, TraceId: 01j1dnmngk0d6jwk44mzh1cg25, TExecPhysicalRequest, tx has commit locks 2024-06-27T20:19:25.333044Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ZWVkZmZmMjEtMzdiZjVlMTMtY2VlYjc1MTgtYjk0NmMwM2U=, ActorId: [1:7385280298884809057:4312], ActorState: ExecuteState, TraceId: 01j1dnmngk0d6jwk44mzh1cg25, Sending to Executer TraceId: 0 8 2024-06-27T20:19:25.333050Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ZWVkZmZmMjEtMzdiZjVlMTMtY2VlYjc1MTgtYjk0NmMwM2U=, ActorId: [1:7385280298884809057:4312], ActorState: ExecuteState, TraceId: 01j1dnmngk0d6jwk44mzh1cg25, Created new KQP executer: [1:7385280298884809077:4312] isRollback: 0 2024-06-27T20:19:25.337649Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ZWVkZmZmMjEtMzdiZjVlMTMtY2VlYjc1MTgtYjk0NmMwM2U=, ActorId: [1:7385280298884809057:4312], ActorState: ExecuteState, TraceId: 01j1dnmngk0d6jwk44mzh1cg25, TEvTxResponse, CurrentTx: 2/2 response.status: SUCCESS 2024-06-27T20:19:25.337689Z node 1 :KQP_SESSION INFO: SessionId: ydb://session/3?node_id=1&id=ZWVkZmZmMjEtMzdiZjVlMTMtY2VlYjc1MTgtYjk0NmMwM2U=, ActorId: [1:7385280298884809057:4312], ActorState: ExecuteState, TraceId: 01j1dnmngk0d6jwk44mzh1cg25, txInfo Status: Committed Kind: ReadWrite TotalDuration: 5.698 ServerDuration: 5.67 QueriesCount: 2 2024-06-27T20:19:25.337708Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ZWVkZmZmMjEtMzdiZjVlMTMtY2VlYjc1MTgtYjk0NmMwM2U=, ActorId: [1:7385280298884809057:4312], ActorState: ExecuteState, TraceId: 01j1dnmngk0d6jwk44mzh1cg25, Create QueryResponse for action: QUERY_ACTION_EXECUTE with SUCCESS status 2024-06-27T20:19:25.337722Z node 1 :KQP_SESSION INFO: SessionId: ydb://session/3?node_id=1&id=ZWVkZmZmMjEtMzdiZjVlMTMtY2VlYjc1MTgtYjk0NmMwM2U=, ActorId: [1:7385280298884809057:4312], ActorState: ExecuteState, TraceId: 01j1dnmngk0d6jwk44mzh1cg25, Cleanup start, isFinal: 0 CleanupCtx: 0 TransactionsToBeAborted.size(): 0 WorkerId: [0:0:0] WorkloadServiceCleanup: 0 2024-06-27T20:19:25.337734Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ZWVkZmZmMjEtMzdiZjVlMTMtY2VlYjc1MTgtYjk0NmMwM2U=, ActorId: [1:7385280298884809057:4312], ActorState: ExecuteState, TraceId: 01j1dnmngk0d6jwk44mzh1cg25, EndCleanup, isFinal: 0 2024-06-27T20:19:25.337746Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ZWVkZmZmMjEtMzdiZjVlMTMtY2VlYjc1MTgtYjk0NmMwM2U=, ActorId: [1:7385280298884809057:4312], ActorState: ExecuteState, TraceId: 01j1dnmngk0d6jwk44mzh1cg25, Sent query response back to proxy, proxyRequestId: 21, proxyId: [1:7385280251640167895:12299] 2024-06-27T20:19:25.337846Z node 1 :KQP_WORKLOAD_SERVICE DEBUG: [TQueryBase] [TRefreshPoolStateQuery] TraceId: sample_pool_id, RequestDatabase: Root, RequestSessionId: , State: Update lease, TEvDataQueryResult SUCCESS, Issues: , SessionId: ydb://session/3?node_id=1&id=ZWVkZmZmMjEtMzdiZjVlMTMtY2VlYjc1MTgtYjk0NmMwM2U=, TxId: 2024-06-27T20:19:25.337875Z node 1 :KQP_WORKLOAD_SERVICE DEBUG: [TQueryBase] [TRefreshPoolStateQuery] TraceId: sample_pool_id, RequestDatabase: Root, RequestSessionId: , State: Update lease, RunDataQuery: -- TRefreshPoolStateQuery::OnLeaseUpdated DECLARE $database AS Text; DECLARE $pool_id AS Text; SELECT COUNT(*) AS delayed_requests FROM `.metadata/workload_manager/delayed_requests` WHERE database = $database AND pool_id = $pool_id AND (wait_deadline IS NULL OR wait_deadline >= CurrentUtcTimestamp()) AND lease_deadline >= CurrentUtcTimestamp(); SELECT COUNT(*) AS running_requests FROM `.metadata/workload_manager/running_requests` WHERE database = $database AND pool_id = $pool_id AND lease_deadline >= CurrentUtcTimestamp(); 2024-06-27T20:19:25.338023Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ZWVkZmZmMjEtMzdiZjVlMTMtY2VlYjc1MTgtYjk0NmMwM2U=, ActorId: [1:7385280298884809057:4312], ActorState: ReadyState, TraceId: 01j1dnmngs1fje7fjp0ww9192y, received request, proxyRequestId: 22 prepared: 0 tx_control: 1 action: QUERY_ACTION_EXECUTE type: QUERY_TYPE_SQL_DML text: -- TRefreshPoolStateQuery::OnLeaseUpdated DECLARE $database AS Text; DECLARE $pool_id AS Text; SELECT COUNT(*) AS delayed_requests FROM `.metadata/workload_manager/delayed_requests` WHERE database = $database AND pool_id = $pool_id AND (wait_deadline IS NULL OR wait_deadline >= CurrentUtcTimestamp()) AND lease_deadline >= CurrentUtcTimestamp(); SELECT COUNT(*) AS running_requests FROM `.metadata/workload_manager/running_requests` WHERE database = $database AND pool_id = $pool_id AND lease_deadline >= CurrentUtcTimestamp(); rpcActor: [1:7385280298884809086:4302] database: /Root pool id: 2024-06-27T20:19:25.338038Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ZWVkZmZmMjEtMzdiZjVlMTMtY2VlYjc1MTgtYjk0NmMwM2U=, ActorId: [1:7385280298884809057:4312], ActorState: ReadyState, TraceId: 01j1dnmngs1fje7fjp0ww9192y, Sending CompileQuery request 2024-06-27T20:19:25.338253Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ZWVkZmZmMjEtMzdiZjVlMTMtY2VlYjc1MTgtYjk0NmMwM2U=, ActorId: [1:7385280298884809057:4312], ActorState: ExecuteState, TraceId: 01j1dnmngs1fje7fjp0ww9192y, ExecutePhyTx, tx: 0x0000075C7AC24D98 literal: 0 commit: 0 txCtx.DeferredEffects.size(): 0 2024-06-27T20:19:25.338269Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ZWVkZmZmMjEtMzdiZjVlMTMtY2VlYjc1MTgtYjk0NmMwM2U=, ActorId: [1:7385280298884809057:4312], ActorState: ExecuteState, TraceId: 01j1dnmngs1fje7fjp0ww9192y, Sending to Executer TraceId: 0 8 2024-06-27T20:19:25.338277Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ZWVkZmZmMjEtMzdiZjVlMTMtY2VlYjc1MTgtYjk0NmMwM2U=, ActorId: [1:7385280298884809057:4312], ActorState: ExecuteState, TraceId: 01j1dnmngs1fje7fjp0ww9192y, Created new KQP executer: [1:7385280298884809089:4312] isRollback: 0 2024-06-27T20:19:25.339721Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ZWVkZmZmMjEtMzdiZjVlMTMtY2VlYjc1MTgtYjk0NmMwM2U=, ActorId: [1:7385280298884809057:4312], ActorState: ExecuteState, TraceId: 01j1dnmngs1fje7fjp0ww9192y, TEvTxResponse, CurrentTx: 1/2 response.status: SUCCESS 2024-06-27T20:19:25.339775Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ZWVkZmZmMjEtMzdiZjVlMTMtY2VlYjc1MTgtYjk0NmMwM2U=, ActorId: [1:7385280298884809057:4312], ActorState: ExecuteState, TraceId: 01j1dnmngs1fje7fjp0ww9192y, ExecutePhyTx, tx: 0x0000075C7AC24E18 literal: 0 commit: 1 txCtx.DeferredEffects.size(): 0 2024-06-27T20:19:25.339791Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ZWVkZmZmMjEtMzdiZjVlMTMtY2VlYjc1MTgtYjk0NmMwM2U=, ActorId: [1:7385280298884809057:4312], ActorState: ExecuteState, TraceId: 01j1dnmngs1fje7fjp0ww9192y, TExecPhysicalRequest, tx has rollback locks 2024-06-27T20:19:25.339797Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ZWVkZmZmMjEtMzdiZjVlMTMtY2VlYjc1MTgtYjk0NmMwM2U=, ActorId: [1:7385280298884809057:4312], ActorState: ExecuteState, TraceId: 01j1dnmngs1fje7fjp0ww9192y, Sending to Executer TraceId: 0 8 2024-06-27T20:19:25.339802Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ZWVkZmZmMjEtMzdiZjVlMTMtY2VlYjc1MTgtYjk0NmMwM2U=, ActorId: [1:7385280298884809057:4312], ActorState: ExecuteState, TraceId: 01j1dnmngs1fje7fjp0ww9192y, Created new KQP executer: [1:7385280298884809105:4312] isRollback: 0 2024-06-27T20:19:25.340239Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ZWVkZmZmMjEtMzdiZjVlMTMtY2VlYjc1MTgtYjk0NmMwM2U=, ActorId: [1:7385280298884809057:4312], ActorState: ExecuteState, TraceId: 01j1dnmngs1fje7fjp0ww9192y, TEvTxResponse, CurrentTx: 2/2 response.status: SUCCESS 2024-06-27T20:19:25.340273Z node 1 :KQP_SESSION INFO: SessionId: ydb://session/3?node_id=1&id=ZWVkZmZmMjEtMzdiZjVlMTMtY2VlYjc1MTgtYjk0NmMwM2U=, ActorId: [1:7385280298884809057:4312], ActorState: ExecuteState, TraceId: 01j1dnmngs1fje7fjp0ww9192y, txInfo Status: Committed Kind: ReadOnly TotalDuration: 2.043 ServerDuration: 2.019 QueriesCount: 2 2024-06-27T20:19:25.340297Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ZWVkZmZmMjEtMzdiZjVlMTMtY2VlYjc1MTgtYjk0NmMwM2U=, ActorId: [1:7385280298884809057:4312], ActorState: ExecuteState, TraceId: 01j1dnmngs1fje7fjp0ww9192y, Create QueryResponse for action: QUERY_ACTION_EXECUTE with SUCCESS status 2024-06-27T20:19:25.340314Z node 1 :KQP_SESSION INFO: SessionId: ydb://session/3?node_id=1&id=ZWVkZmZmMjEtMzdiZjVlMTMtY2VlYjc1MTgtYjk0NmMwM2U=, ActorId: [1:7385280298884809057:4312], ActorState: ExecuteState, TraceId: 01j1dnmngs1fje7fjp0ww9192y, Cleanup start, isFinal: 0 CleanupCtx: 0 TransactionsToBeAborted.size(): 0 WorkerId: [0:0:0] WorkloadServiceCleanup: 0 2024-06-27T20:19:25.340317Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ZWVkZmZmMjEtMzdiZjVlMTMtY2VlYjc1MTgtYjk0NmMwM2U=, ActorId: [1:7385280298884809057:4312], ActorState: ExecuteState, TraceId: 01j1dnmngs1fje7fjp0ww9192y, EndCleanup, isFinal: 0 2024-06-27T20:19:25.340324Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ZWVkZmZmMjEtMzdiZjVlMTMtY2VlYjc1MTgtYjk0NmMwM2U=, ActorId: [1:7385280298884809057:4312], ActorState: ExecuteState, TraceId: 01j1dnmngs1fje7fjp0ww9192y, Sent query response back to proxy, proxyRequestId: 22, proxyId: [1:7385280251640167895:12299] 2024-06-27T20:19:25.340396Z node 1 :KQP_WORKLOAD_SERVICE DEBUG: [TQueryBase] [TRefreshPoolStateQuery] TraceId: sample_pool_id, RequestDatabase: Root, RequestSessionId: , State: Describe pool, TEvDataQueryResult SUCCESS, Issues: , SessionId: ydb://session/3?node_id=1&id=ZWVkZmZmMjEtMzdiZjVlMTMtY2VlYjc1MTgtYjk0NmMwM2U=, TxId: 2024-06-27T20:19:25.340436Z node 1 :KQP_WORKLOAD_SERVICE DEBUG: [TQueryBase] [TRefreshPoolStateQuery] TraceId: sample_pool_id, RequestDatabase: Root, RequestSessionId: , State: Describe pool, Finish with SUCCESS, SessionId: ydb://session/3?node_id=1&id=ZWVkZmZmMjEtMzdiZjVlMTMtY2VlYjc1MTgtYjk0NmMwM2U=, TxId: 2024-06-27T20:19:25.340480Z node 1 :KQP_WORKLOAD_SERVICE TRACE: [WorkloadService] [TPoolHandlerActorBase] ActorId: [1:7385280255935135602:8276], Database: Root, PoolId: sample_pool_id, succefully refreshed pool state, in flight: 0, delayed: 0 2024-06-27T20:19:25.340530Z node 1 :KQP_SESSION INFO: SessionId: ydb://session/3?node_id=1&id=ZWVkZmZmMjEtMzdiZjVlMTMtY2VlYjc1MTgtYjk0NmMwM2U=, ActorId: [1:7385280298884809057:4312], ActorState: ReadyState, Session closed due to explicit close event 2024-06-27T20:19:25.340537Z node 1 :KQP_SESSION INFO: SessionId: ydb://session/3?node_id=1&id=ZWVkZmZmMjEtMzdiZjVlMTMtY2VlYjc1MTgtYjk0NmMwM2U=, ActorId: [1:7385280298884809057:4312], ActorState: ReadyState, Cleanup start, isFinal: 1 CleanupCtx: 0 TransactionsToBeAborted.size(): 0 WorkerId: [0:0:0] WorkloadServiceCleanup: 0 2024-06-27T20:19:25.340539Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ZWVkZmZmMjEtMzdiZjVlMTMtY2VlYjc1MTgtYjk0NmMwM2U=, ActorId: [1:7385280298884809057:4312], ActorState: ReadyState, EndCleanup, isFinal: 1 2024-06-27T20:19:25.340541Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ZWVkZmZmMjEtMzdiZjVlMTMtY2VlYjc1MTgtYjk0NmMwM2U=, ActorId: [1:7385280298884809057:4312], ActorState: unknown state, Cleanup temp tables: 0 2024-06-27T20:19:25.340557Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=ZWVkZmZmMjEtMzdiZjVlMTMtY2VlYjc1MTgtYjk0NmMwM2U=, ActorId: [1:7385280298884809057:4312], ActorState: unknown state, Session actor destroyed 2024-06-27T20:19:27.097200Z node 1 :KQP_SESSION INFO: SessionId: ydb://session/3?node_id=1&id=Y2Q4YmY5MzUtYzIzYTMxZjctZGRkMmUxYWYtNDYxZmU1ZGQ=, ActorId: [1:7385280255935135548:4273], ActorState: ReadyState, Session closed due to explicit close event 2024-06-27T20:19:27.097233Z node 1 :KQP_SESSION INFO: SessionId: ydb://session/3?node_id=1&id=Y2Q4YmY5MzUtYzIzYTMxZjctZGRkMmUxYWYtNDYxZmU1ZGQ=, ActorId: [1:7385280255935135548:4273], ActorState: ReadyState, Cleanup start, isFinal: 1 CleanupCtx: 0 TransactionsToBeAborted.size(): 0 WorkerId: [0:0:0] WorkloadServiceCleanup: 0 2024-06-27T20:19:27.097237Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=Y2Q4YmY5MzUtYzIzYTMxZjctZGRkMmUxYWYtNDYxZmU1ZGQ=, ActorId: [1:7385280255935135548:4273], ActorState: ReadyState, EndCleanup, isFinal: 1 2024-06-27T20:19:27.097269Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=Y2Q4YmY5MzUtYzIzYTMxZjctZGRkMmUxYWYtNDYxZmU1ZGQ=, ActorId: [1:7385280255935135548:4273], ActorState: unknown state, Cleanup temp tables: 0 2024-06-27T20:19:27.097297Z node 1 :KQP_SESSION DEBUG: SessionId: ydb://session/3?node_id=1&id=Y2Q4YmY5MzUtYzIzYTMxZjctZGRkMmUxYWYtNDYxZmU1ZGQ=, ActorId: [1:7385280255935135548:4273], ActorState: unknown state, Session actor destroyed [[bad]]strings contains assertion failed at ydb/core/kqp/workload_service/ut/common/kqp_workload_service_ut_common.h:125, static void NKikimr::NKqp::NWorkload::TSampleQueries::CheckCancelled(const TResult &) [TResult = NKikimr::NKqp::NWorkload::TQueryRunnerResult]: "
: Error: Delay deadline exceeded in pool sample_pool_id
: Error: Query failed during adding/waiting in workload pool sample_pool_id " does not contain "Request timeout exceeded, cancelling after", [[rst]] [[alt1]]0. /-S/library/cpp/testing/unittest/registar.cpp:47: NUnitTest::NPrivate::RaiseError(char const*, TBasicString> const&, bool) @ 0x11B38E07 1. /-S/ydb/core/kqp/workload_service/ut/common/kqp_workload_service_ut_common.h:125: void NKikimr::NKqp::NWorkload::TSampleQueries::CheckCancelled(NKikimr::NKqp::NWorkload::TQueryRunnerResult const&) @ 0x1194A740 2. /-S/ydb/core/kqp/workload_service/ut/kqp_workload_service_ut.cpp:113: NKikimr::NKqp::NTestSuiteKqpWorkloadService::TTestCaseTestQueryCancelAfterPoolWithLimits::Execute_(NUnitTest::TTestContext&) @ 0x1194B0C7 3. /-S/ydb/core/kqp/workload_service/ut/kqp_workload_service_ut.cpp:12: NKikimr::NKqp::NTestSuiteKqpWorkloadService::TCurrentTest::Execute()::'lambda'()::operator()() const @ 0x11955CF6 4. /-S/library/cpp/testing/unittest/registar.cpp:374: NUnitTest::TTestBase::Run(std::__y1::function, TBasicString> const&, char const*, bool) @ 0x11B3ADBE 5. /-S/ydb/core/kqp/workload_service/ut/kqp_workload_service_ut.cpp:12: NKikimr::NKqp::NTestSuiteKqpWorkloadService::TCurrentTest::Execute() @ 0x11955488 6. /-S/library/cpp/testing/unittest/registar.cpp:495: NUnitTest::TTestFactory::Execute() @ 0x11B3B51B 7. /-S/library/cpp/testing/unittest/utmain.cpp:872: NUnitTest::RunMain(int, char**) @ 0x11B4A9CC 8. ??:0: ?? @ 0x7FAA7571DD8F 9. ??:0: ?? @ 0x7FAA7571DE3F 10. ??:0: ?? @ 0x10D2C028 [[rst]]