hanna-liashchuk opened a new issue, #4267: URL: https://github.com/apache/kyuubi/issues/4267
### Code of Conduct - [X] I agree to follow this project's [Code of Conduct](https://www.apache.org/foundation/policies/conduct) ### Search before asking - [X] I have searched in the [issues](https://github.com/apache/kyuubi/issues?q=is%3Aissue) and found no similar issues. ### Describe the bug We are running dbt models connected to Kyuubi server. Some models are failing with `KyuubiSQLException: Error while cleaning up the engine resources` This issue is not reproducible every time, hits different models and we cannot say what would be the root cause. ### Affects Version(s) 1.5.2-incubating ### Kyuubi Server Log Output ```logtalk : 94155K->471K(105472K), 0.0012083 secs] 125598K->31914K(456536K), 0.0012657 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 2023-02-07T18:44:30.324+0200: 414604.028: [GC (Allocation Failure) 2023-02-07T18:44:30.324+0200: 414604.028: [ParNew Desired survivor size 5996544 bytes, new threshold 6 (max 6) - age 1: 32576 bytes, 32576 total - age 2: 3192 bytes, 35768 total - age 4: 1888 bytes, 37656 total - age 5: 3176 bytes, 40832 total - age 6: 12624 bytes, 53456 total : 94231K->304K(105472K), 0.0011580 secs] 125674K->31746K(456536K), 0.0012213 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 2023-02-07T18:45:30.328+0200: 414664.032: [GC (Allocation Failure) 2023-02-07T18:45:30.328+0200: 414664.032: [ParNew Desired survivor size 5996544 bytes, new threshold 6 (max 6) - age 1: 284656 bytes, 284656 total - age 2: 992 bytes, 285648 total - age 3: 2104 bytes, 287752 total - age 5: 1888 bytes, 289640 total - age 6: 3176 bytes, 292816 total : 94064K->336K(105472K), 0.0014882 secs] 125506K->31791K(456536K), 0.0015514 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 2023-02-07T18:46:30.333+0200: 414724.037: [GC (Allocation Failure) 2023-02-07T18:46:30.333+0200: 414724.037: [ParNew Desired survivor size 5996544 bytes, new threshold 6 (max 6) - age 1: 153320 bytes, 153320 total - age 2: 6832 bytes, 160152 total - age 3: 32 bytes, 160184 total - age 4: 2080 bytes, 162264 total - age 6: 1888 bytes, 164152 total : 94096K->259K(105472K), 0.0014922 secs] 125551K->31717K(456536K), 0.0015539 secs] [Times: user=0.02 sys=0.00, real=0.00 secs] 2023-02-07T18:47:40.327+0200: 414794.032: [GC (Allocation Failure) 2023-02-07T18:47:40.328+0200: 414794.032: [ParNew Desired survivor size 5996544 bytes, new threshold 6 (max 6) - age 1: 284760 bytes, 284760 total - age 2: 1040 bytes, 285800 total - age 3: 5896 bytes, 291696 total - age 4: 32 bytes, 291728 total - age 5: 2080 bytes, 293808 total : 94019K->377K(105472K), 0.0012563 secs] 125477K->31837K(456536K), 0.0013262 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 2023-02-07T18:48:40.328+0200: 414854.032: [GC (Allocation Failure) 2023-02-07T18:48:40.328+0200: 414854.032: [ParNew Desired survivor size 5996544 bytes, new threshold 6 (max 6) - age 1: 605624 bytes, 605624 total - age 2: 968 bytes, 606592 total - age 3: 56 bytes, 606648 total - age 4: 5744 bytes, 612392 total - age 5: 32 bytes, 612424 total - age 6: 2080 bytes, 614504 total : 94137K->707K(105472K), 0.0012355 secs] 125597K->32167K(456536K), 0.0013117 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 2023-02-07T18:49:40.325+0200: 414914.029: [GC (Allocation Failure) 2023-02-07T18:49:40.325+0200: 414914.029: [ParNew Desired survivor size 5996544 bytes, new threshold 6 (max 6) - age 1: 374080 bytes, 374080 total - age 2: 47120 bytes, 421200 total - age 3: 936 bytes, 422136 total - age 4: 32 bytes, 422168 total - age 5: 5744 bytes, 427912 total ``` ### Kyuubi Engine Log Output ```logtalk 2023-02-07T18:42:48+02:00 2023-02-07 18:42:48.477 INFO org.apache.kyuubi.operation.log.OperationLog: Creating operation log file /opt/kyuubi/work/server_operation_logs/3b92bf69-1bdd-45ba-af0a-fc011b1d358b/cc70a1ef-24b2-4fda-a21f-5757ec196c0d 2023-02-07T18:42:48+02:00 2023-02-07 18:42:48.477 INFO org.apache.kyuubi.operation.ExecuteStatement: Processing <REDUCTED>'s query[cc70a1ef-24b2-4fda-a21f-5757ec196c0d]: INITIALIZED_STATE -> PENDING_STATE, statement: SELECT current_database() 2023-02-07T18:42:48+02:00 2023-02-07 18:42:48.479 INFO org.apache.kyuubi.operation.ExecuteStatement: Processing <REDUCTED>'s query[cc70a1ef-24b2-4fda-a21f-5757ec196c0d]: PENDING_STATE -> RUNNING_STATE, statement: SELECT current_database() 2023-02-07T18:42:48+02:00 2023-02-07 18:42:48.513 INFO org.apache.kyuubi.operation.ExecuteStatement: Query[cc70a1ef-24b2-4fda-a21f-5757ec196c0d] in FINISHED_STATE 2023-02-07T18:42:48+02:00 2023-02-07 18:42:48.513 INFO org.apache.kyuubi.operation.ExecuteStatement: Processing <REDUCTED>'s query[cc70a1ef-24b2-4fda-a21f-5757ec196c0d]: RUNNING_STATE -> FINISHED_STATE, statement: SELECT current_database(), time taken: 0.034 seconds 2023-02-07T18:42:48+02:00 2023-02-07 18:42:48.702 INFO org.apache.kyuubi.operation.ExecuteStatement: Processing <REDUCTED>'s query[cc70a1ef-24b2-4fda-a21f-5757ec196c0d]: FINISHED_STATE -> CLOSED_STATE, statement: SELECT current_database() 2023-02-07T18:42:48+02:00 2023-02-07 18:42:48.702 INFO org.apache.kyuubi.client.KyuubiSyncThriftClient: TCloseOperationReq(operationHandle:TOperationHandle(operationId:THandleIdentifier(guid:C6 0F B6 8A AD A2 4B A1 B6 12 86 10 37 20 85 88, secret:31 F5 C7 16 E1 BB 49 1D B8 38 92 D3 9D B1 00 A0), operationType:EXECUTE_STATEMENT, hasResultSet:true)) succeed on engine side 2023-02-07T18:42:48+02:00 2023-02-07 18:42:48.893 INFO org.apache.kyuubi.operation.log.OperationLog: Creating operation log file /opt/kyuubi/work/server_operation_logs/3b92bf69-1bdd-45ba-af0a-fc011b1d358b/5f9c4798-eec3-459d-bac0-43a37bc22fee 2023-02-07T18:42:48+02:00 2023-02-07 18:42:48.893 INFO org.apache.kyuubi.operation.ExecuteStatement: Processing <REDUCTED>'s query[5f9c4798-eec3-459d-bac0-43a37bc22fee]: INITIALIZED_STATE -> PENDING_STATE, statement: select 2023-02-07T18:42:48+02:00 dcr.ver, 2023-02-07T18:42:48+02:00 count(*) as cntRec, 2023-02-07T18:42:48+02:00 max(modifiedDP) as modifiedDP_MAX 2023-02-07T18:42:48+02:00 from 2023-02-07T18:42:48+02:00 dbt_salesdp.dir_calcrules as dcr 2023-02-07T18:42:48+02:00 group by 2023-02-07T18:42:48+02:00 dcr.ver 2023-02-07T18:42:48+02:00 order by 2023-02-07T18:42:48+02:00 dcr.ver 2023-02-07T18:42:48+02:00 2023-02-07 18:42:48.895 INFO org.apache.kyuubi.operation.ExecuteStatement: Processing <REDUCTED>'s query[5f9c4798-eec3-459d-bac0-43a37bc22fee]: PENDING_STATE -> RUNNING_STATE, statement: select 2023-02-07T18:42:48+02:00 dcr.ver, 2023-02-07T18:42:48+02:00 count(*) as cntRec, 2023-02-07T18:42:48+02:00 max(modifiedDP) as modifiedDP_MAX 2023-02-07T18:42:48+02:00 from 2023-02-07T18:42:48+02:00 dbt_salesdp.dir_calcrules as dcr 2023-02-07T18:42:48+02:00 group by 2023-02-07T18:42:48+02:00 dcr.ver 2023-02-07T18:42:48+02:00 order by 2023-02-07T18:42:48+02:00 dcr.ver 2023-02-07T18:42:51+02:00 2023-02-07 18:42:51.394 INFO org.apache.kyuubi.operation.ExecuteStatement: Query[5f9c4798-eec3-459d-bac0-43a37bc22fee] in FINISHED_STATE 2023-02-07T18:42:51+02:00 2023-02-07 18:42:51.394 INFO org.apache.kyuubi.operation.ExecuteStatement: Processing <REDUCTED>'s query[5f9c4798-eec3-459d-bac0-43a37bc22fee]: RUNNING_STATE -> FINISHED_STATE, statement: select 2023-02-07T18:42:51+02:00 dcr.ver, 2023-02-07T18:42:51+02:00 count(*) as cntRec, 2023-02-07T18:42:51+02:00 max(modifiedDP) as modifiedDP_MAX 2023-02-07T18:42:51+02:00 from 2023-02-07T18:42:51+02:00 dbt_salesdp.dir_calcrules as dcr 2023-02-07T18:42:51+02:00 group by 2023-02-07T18:42:51+02:00 dcr.ver 2023-02-07T18:42:51+02:00 order by 2023-02-07T18:42:51+02:00 dcr.ver, time taken: 2.499 seconds 2023-02-07T18:42:52+02:00 2023-02-07 18:42:52.429 INFO org.apache.kyuubi.operation.ExecuteStatement: Processing <REDUCTED>'s query[5f9c4798-eec3-459d-bac0-43a37bc22fee]: FINISHED_STATE -> CLOSED_STATE, statement: select 2023-02-07T18:42:52+02:00 dcr.ver, 2023-02-07T18:42:52+02:00 count(*) as cntRec, 2023-02-07T18:42:52+02:00 max(modifiedDP) as modifiedDP_MAX 2023-02-07T18:42:52+02:00 from 2023-02-07T18:42:52+02:00 dbt_salesdp.dir_calcrules as dcr 2023-02-07T18:42:52+02:00 group by 2023-02-07T18:42:52+02:00 dcr.ver 2023-02-07T18:42:52+02:00 order by 2023-02-07T18:42:52+02:00 dcr.ver 2023-02-07T18:42:52+02:00 2023-02-07 18:42:52.430 INFO org.apache.kyuubi.client.KyuubiSyncThriftClient: TCloseOperationReq(operationHandle:TOperationHandle(operationId:THandleIdentifier(guid:C9 F7 11 CE BF 2D 47 A4 BE 2F 62 15 30 78 D2 5C, secret:3E 77 6D B4 00 BD 40 D5 A7 51 87 D8 20 C8 D6 CF), operationType:EXECUTE_STATEMENT, hasResultSet:true)) succeed on engine side 2023-02-07T18:45:04+02:00 2023-02-07 18:45:04.709 INFO org.apache.kyuubi.server.KyuubiTBinaryFrontendService: Session [SessionHandle [e767b53b-059b-45f8-b1e3-4ccc64366126]] disconnected without closing properly, close it now 2023-02-07T18:45:04+02:00 2023-02-07 18:45:04.709 INFO org.apache.kyuubi.session.KyuubiSessionManager: SessionHandle [e767b53b-059b-45f8-b1e3-4ccc64366126] is closed, current opening sessions 2 2023-02-07T18:45:04+02:00 2023-02-07 18:45:04.721 ERROR org.apache.kyuubi.server.KyuubiTBinaryFrontendService: Failed closing session 2023-02-07T18:45:04+02:00 org.apache.kyuubi.KyuubiSQLException: Error while cleaning up the engine resources 2023-02-07T18:45:04+02:00 at org.apache.kyuubi.KyuubiSQLException$.apply(KyuubiSQLException.scala:69) ~[kyuubi-common_2.12-1.5.2-incubating.jar:1.5.2-incubating] 2023-02-07T18:45:04+02:00 at org.apache.kyuubi.client.KyuubiSyncThriftClient.closeSession(KyuubiSyncThriftClient.scala:90) ~[kyuubi-server_2.12-1.5.2-incubating.jar:1.5.2-incubating] 2023-02-07T18:45:04+02:00 at org.apache.kyuubi.session.KyuubiSessionImpl.close(KyuubiSessionImpl.scala:154) ~[kyuubi-server_2.12-1.5.2-incubating.jar:1.5.2-incubating] 2023-02-07T18:45:04+02:00 at org.apache.kyuubi.session.SessionManager.closeSession(SessionManager.scala:94) ~[kyuubi-common_2.12-1.5.2-incubating.jar:1.5.2-incubating] 2023-02-07T18:45:04+02:00 at org.apache.kyuubi.service.AbstractBackendService.closeSession(AbstractBackendService.scala:49) ~[kyuubi-common_2.12-1.5.2-incubating.jar:1.5.2-incubating] 2023-02-07T18:45:04+02:00 at org.apache.kyuubi.server.KyuubiServer$$anon$1.org$apache$kyuubi$server$BackendServiceMetric$$super$closeSession(KyuubiServer.scala:142) ~[kyuubi-server_2.12-1.5.2-incubating.jar:1.5.2-incubating] 2023-02-07T18:45:04+02:00 at org.apache.kyuubi.server.BackendServiceMetric.$anonfun$closeSession$1(BackendServiceMetric.scala:43) ~[kyuubi-server_2.12-1.5.2-incubating.jar:1.5.2-incubating] 2023-02-07T18:45:04+02:00 at scala.runtime.java8.JFunction0$mcV$sp.apply(JFunction0$mcV$sp.java:23) ~[scala-library-2.12.15.jar:?] 2023-02-07T18:45:04+02:00 at org.apache.kyuubi.metrics.MetricsSystem$.timerTracing(MetricsSystem.scala:111) ~[kyuubi-metrics_2.12-1.5.2-incubating.jar:1.5.2-incubating] 2023-02-07T18:45:04+02:00 at org.apache.kyuubi.server.BackendServiceMetric.closeSession(BackendServiceMetric.scala:43) ~[kyuubi-server_2.12-1.5.2-incubating.jar:1.5.2-incubating] 2023-02-07T18:45:04+02:00 at org.apache.kyuubi.server.BackendServiceMetric.closeSession$(BackendServiceMetric.scala:41) ~[kyuubi-server_2.12-1.5.2-incubating.jar:1.5.2-incubating] 2023-02-07T18:45:04+02:00 at org.apache.kyuubi.server.KyuubiServer$$anon$1.closeSession(KyuubiServer.scala:142) ~[kyuubi-server_2.12-1.5.2-incubating.jar:1.5.2-incubating] 2023-02-07T18:45:04+02:00 at org.apache.kyuubi.service.TFrontendService$FeTServerEventHandler.deleteContext(TFrontendService.scala:521) ~[kyuubi-common_2.12-1.5.2-incubating.jar:1.5.2-incubating] 2023-02-07T18:45:04+02:00 at org.apache.thrift.server.TThreadPoolServer$WorkerProcess.run(TThreadPoolServer.java:300) ~[libthrift-0.9.3.jar:0.9.3] 2023-02-07T18:45:04+02:00 at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) ~[?:1.8.0_342] 2023-02-07T18:45:04+02:00 at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) ~[?:1.8.0_342] 2023-02-07T18:45:04+02:00 at java.lang.Thread.run(Thread.java:750) ~[?:1.8.0_342] 2023-02-07T18:45:04+02:00 Caused by: org.apache.kyuubi.KyuubiSQLException: Invalid SessionHandle [9626c8e7-91db-4b0d-b127-dc7790a83102] 2023-02-07T18:45:04+02:00 at org.apache.kyuubi.KyuubiSQLException$.apply(KyuubiSQLException.scala:69) ~[kyuubi-common_2.12-1.5.2-incubating.jar:1.5.2-incubating] 2023-02-07T18:45:04+02:00 at org.apache.kyuubi.session.SessionManager.closeSession(SessionManager.scala:90) ~[kyuubi-common_2.12-1.5.2-incubating.jar:1.5.2-incubating] 2023-02-07T18:45:04+02:00 at org.apache.kyuubi.engine.spark.session.SparkSQLSessionManager.closeSession(SparkSQLSessionManager.scala:107) ~[?:?] 2023-02-07T18:45:04+02:00 at org.apache.kyuubi.service.AbstractBackendService.closeSession(AbstractBackendService.scala:49) ~[kyuubi-common_2.12-1.5.2-incubating.jar:1.5.2-incubating] 2023-02-07T18:45:04+02:00 at org.apache.kyuubi.service.TFrontendService.CloseSession(TFrontendService.scala:189) ~[kyuubi-common_2.12-1.5.2-incubating.jar:1.5.2-incubating] 2023-02-07T18:45:04+02:00 at org.apache.hive.service.rpc.thrift.TCLIService$Processor$CloseSession.getResult(TCLIService.java:1517) ~[hive-service-rpc-3.1.2.jar:3.1.2] 2023-02-07T18:45:04+02:00 at org.apache.hive.service.rpc.thrift.TCLIService$Processor$CloseSession.getResult(TCLIService.java:1502) ~[hive-service-rpc-3.1.2.jar:3.1.2] 2023-02-07T18:45:04+02:00 at org.apache.thrift.ProcessFunction.process(ProcessFunction.java:38) ~[libthrift-0.9.3.jar:0.9.3] 2023-02-07T18:45:04+02:00 at org.apache.thrift.TBaseProcessor.process(TBaseProcessor.java:39) ~[libthrift-0.9.3.jar:0.9.3] 2023-02-07T18:45:04+02:00 at org.apache.kyuubi.service.authentication.TSetIpAddressProcessor.process(TSetIpAddressProcessor.scala:36) ~[kyuubi-common_2.12-1.5.2-incubating.jar:1.5.2-incubating] 2023-02-07T18:45:04+02:00 at org.apache.thrift.server.TThreadPoolServer$WorkerProcess.run(TThreadPoolServer.java:310) ~[libthrift-0.9.3.jar:0.9.3] 2023-02-07T18:45:04+02:00 ... 3 more ``` ### Kyuubi Server Configurations ```yaml ## Kyuubi authentication kyuubi.authentication ${KYUUBI_AUTHENTICATION} kyuubi.authentication.custom.class ${KYUUBI_AUTHENTICATION_CUSTOM_CLASS} kyuubi.authentication.ldap.url ${KYUUBI_AUTHENTICATION_LDAP_URL} # Kyuubi Metrics # https://kyuubi.readthedocs.io/en/latest/monitor/metrics.html # https://kyuubi.apache.org/docs/latest/deployment/settings.html#metrics kyuubi.metrics.enabled true kyuubi.metrics.reporters PROMETHEUS,JSON kyuubi.metrics.prometheus.path /metrics kyuubi.metrics.prometheus.port 10019 kyuubi.metrics.json.interval PT10S kyuubi.metrics.json.location ${KYUUBI_METRICS_JSON_LOCATION} # Kyuubi frontend kyuubi.frontend.login.timeout PT40S kyuubi.frontend.thrift.binary.bind.host ${POD_IP} kyuubi.frontend.thrift.binary.bind.port 10009 kyuubi.session.idle.timeout PT30M kyuubi.session.engine.initialize.timeout PT1M kyuubi.ha.zookeeper.quorum ${ZOOKEEPER_CONNECT} kyuubi.ha.zookeeper.namespace ${POD_NAMESPACE} kyuubi.engine.connection.url.use.hostname false kyuubi.engine.share.level CONNECTION ``` ### Kyuubi Engine Configurations ```yaml spark.master k8s://https://kubernetes.default.svc spark.driver.host ${POD_IP} spark.driver.memory 3g spark.driver.maxResultSize 2g spark.executor.memory 2g spark.executor.cores 1 spark.kubernetes.executor.limit.cores 1 spark.kubernetes.executor.request.cores 0.3 spark.kubernetes.driver.pod.name ${POD_NAME} spark.kubernetes.container.image spark:spark3.2.2-hadoop3.2-delta2.0.0-scala2.12 spark.kubernetes.container.image.pullPolicy Always spark.kubernetes.container.image.pullSecrets spark.kubernetes.namespace ${POD_NAMESPACE} spark.kubernetes.authenticate.serviceAccountName kyuubi-spark spark.kubernetes.driver.label.spark-component spark-job spark.kubernetes.executor.label.spark-component spark-job spark.kubernetes.memoryOverheadFactor 0.4 spark.ui.prometheus.enabled true spark.decommission.enabled true spark.sql.adaptive.localShuffleReader.enabled true #Dynamic allocation spark.dynamicAllocation.enabled true spark.dynamicAllocation.shuffleTracking.enabled true spark.dynamicAllocation.schedulerBacklogTimeout 3s spark.dynamicAllocation.minExecutors 1 spark.dynamicAllocation.maxExecutors 10 spark.cleaner.periodicGC.interval 10min spark.dynamicAllocation.executorAllocationRatio 0.75 spark.kubernetes.dynamicAllocation.deleteGracePeriod 20s spark.kubernetes.allocation.maxPendingPods 1 # Delta spark.sql.extensions io.delta.sql.DeltaSparkSessionExtension spark.sql.catalog.spark_catalog org.apache.spark.sql.delta.catalog.DeltaCatalog # Log into Spark History Server spark.eventLog.enabled true spark.eventLog.dir file://${SPARK_EVENT_LOG_DIR} spark.eventLog.compress true spark.eventLog.compression.codec snappy spark.eventLog.rolling.enabled true spark.ui.enabled false ``` ### Additional context _No response_ ### Are you willing to submit PR? - [ ] Yes. I would be willing to submit a PR with guidance from the Kyuubi community to fix. - [X] No. I cannot submit a PR at this time. -- This is an automated message from the Apache Git Service. To respond to the message, please log on to GitHub and use the URL above to go to the specific comment. To unsubscribe, e-mail: [email protected] For queries about this service, please contact Infrastructure at: [email protected] --------------------------------------------------------------------- To unsubscribe, e-mail: [email protected] For additional commands, e-mail: [email protected]
