search

apache / kyuubi

Apache Kyuubi is a distributed and multi-tenant gateway to provide serverless SQL on data warehouses and lakehouses.
https://kyuubi.apache.org/
Apache License 2.0
2.07k stars 902 forks source link

[Bug] KyuubiSQLException: Error while cleaning up the engine resources #4267

Closed hanna-liashchuk closed 1 year ago

hanna-liashchuk commented 1 year ago

Code of Conduct

Search before asking

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

: 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

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

## 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

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?

pan3793 commented 1 year ago

Invalid SessionHandle [9626c8e7-91db-4b0d-b127-dc7790a83102]

could you please search the whole log of the Kyuubi Server using the session uuid to find what happened on this session?

hanna-liashchuk commented 1 year ago

Interesting that this session id occurs only twice, for the first time here - 2023-02-07 15:36:19.688 INFO org.apache.kyuubi.session.KyuubiSessionImpl: [v.user:172.17.0.186] SessionHandle [e767b53b-059b-45f8-b1e3-4ccc64366126] - Connected to engine [172.17.13.124:44855] with SessionHandle [9626c8e7-91db-4b0d-b127-dc7790a83102]

and second here - Caused by: org.apache.kyuubi.KyuubiSQLException: Invalid SessionHandle [9626c8e7-91db-4b0d-b127-dc7790a83102]

According to logs, the error is received by user X while the session id belongs to user Y. we had from 10 to 15 total connections at this time range

hanna-liashchuk commented 1 year ago

There is a spark engine log of one of the failing sessions @pan3793 

23/02/14 09:17:18 WARN NativeCodeLoader: Unable to load native-hadoop library for your platform... using builtin-java classes where applicable
2023-02-14 09:17:18.714 INFO util.SignalRegister: Registering signal handler for TERM
2023-02-14 09:17:18.715 INFO util.SignalRegister: Registering signal handler for HUP
2023-02-14 09:17:18.715 INFO util.SignalRegister: Registering signal handler for INT
2023-02-14 09:17:18.850 INFO conf.HiveConf: Found configuration file file:/opt/spark-3.2.2-bin-hadoop3.2/conf/hive-site.xml
2023-02-14 09:17:18.974 INFO spark.SparkContext: Running Spark version 3.2.2
2023-02-14 09:17:19.002 INFO resource.ResourceUtils: ==============================================================
2023-02-14 09:17:19.002 INFO resource.ResourceUtils: No custom resources configured for spark.driver.
2023-02-14 09:17:19.002 INFO resource.ResourceUtils: ==============================================================
2023-02-14 09:17:19.003 INFO spark.SparkContext: Submitted application: kyuubi_CONNECTION_SPARK_SQL_as-ol.lysiuk_3a27bf56-0c1b-4d96-b82c-66389785e5b4
2023-02-14 09:17:19.026 INFO resource.ResourceProfile: Default ResourceProfile created, executor resources: Map(cores -> name: cores, amount: 1, script: , vendor: , memory -> name: memory, amount: 2048, script: , vendor: , offHeap -> name: offHeap, amount: 0, script: , vendor: ), task resources: Map(cpus -> name: cpus, amount: 1.0)
2023-02-14 09:17:19.040 INFO resource.ResourceProfile: Limiting resource is cpus at 1 tasks per executor
2023-02-14 09:17:19.042 INFO resource.ResourceProfileManager: Added ResourceProfile id: 0
2023-02-14 09:17:19.093 INFO spark.SecurityManager: Changing view acls to: kyuubi,as-ol.lysiuk
2023-02-14 09:17:19.094 INFO spark.SecurityManager: Changing modify acls to: kyuubi,as-ol.lysiuk
2023-02-14 09:17:19.094 INFO spark.SecurityManager: Changing view acls groups to: 
2023-02-14 09:17:19.094 INFO spark.SecurityManager: Changing modify acls groups to: 
2023-02-14 09:17:19.095 INFO spark.SecurityManager: SecurityManager: authentication disabled; ui acls disabled; users  with view permissions: Set(kyuubi, as-ol.lysiuk); groups with view permissions: Set(); users  with modify permissions: Set(kyuubi, as-ol.lysiuk); groups with modify permissions: Set()
2023-02-14 09:17:19.327 INFO util.Utils: Successfully started service 'sparkDriver' on port 35609.
2023-02-14 09:17:19.352 INFO spark.SparkEnv: Registering MapOutputTracker
2023-02-14 09:17:19.388 INFO spark.SparkEnv: Registering BlockManagerMaster
2023-02-14 09:17:19.411 INFO storage.BlockManagerMasterEndpoint: Using org.apache.spark.storage.DefaultTopologyMapper for getting topology information
2023-02-14 09:17:19.411 INFO storage.BlockManagerMasterEndpoint: BlockManagerMasterEndpoint up
2023-02-14 09:17:19.414 INFO spark.SparkEnv: Registering BlockManagerMasterHeartbeat
2023-02-14 09:17:19.435 INFO storage.DiskBlockManager: Created local directory at /tmp/blockmgr-a3f486f1-e5e7-4d1a-acba-e054c1aa4366
2023-02-14 09:17:19.456 INFO memory.MemoryStore: MemoryStore started with capacity 1458.6 MiB
2023-02-14 09:17:19.471 INFO spark.SparkEnv: Registering OutputCommitCoordinator
2023-02-14 09:17:19.487 INFO spark.SparkContext: Added JAR file:/opt/kyuubi/externals/engines/spark/kyuubi-spark-sql-engine_2.12-1.5.2-incubating.jar at spark://172.17.18.136:35609/jars/kyuubi-spark-sql-engine_2.12-1.5.2-incubating.jar with timestamp 1676359038966
2023-02-14 09:17:19.535 INFO k8s.SparkKubernetesClientFactory: Auto-configuring K8S client using current context from users K8S config file
2023-02-14 09:17:20.358 WARN util.Utils: spark.executor.instances less than spark.dynamicAllocation.minExecutors is invalid, ignoring its setting, please update your configs.
2023-02-14 09:17:20.359 INFO util.Utils: Using initial executors = 1, max of spark.dynamicAllocation.initialExecutors, spark.dynamicAllocation.minExecutors and spark.executor.instances
2023-02-14 09:17:20.462 INFO k8s.ExecutorPodsAllocator: Going to request 1 executors from Kubernetes for ResourceProfile Id: 0, target: 1, known: 0, sharedSlotFromPendingPods: 1.
2023-02-14 09:17:20.482 INFO submit.KubernetesClientUtils: Spark configuration files loaded from Some(/opt/spark/conf) : hive-site.xml,metrics.properties
2023-02-14 09:17:20.504 INFO submit.KubernetesClientUtils: Spark configuration files loaded from Some(/opt/spark/conf) : hive-site.xml,metrics.properties
2023-02-14 09:17:20.519 INFO features.BasicExecutorFeatureStep: Adding decommission script to lifecycle
2023-02-14 09:17:20.579 INFO util.Utils: Successfully started service 'org.apache.spark.network.netty.NettyBlockTransferService' on port 36651.
2023-02-14 09:17:20.579 INFO netty.NettyBlockTransferService: Server created on 172.17.18.136:36651
2023-02-14 09:17:20.581 INFO storage.BlockManager: Using org.apache.spark.storage.RandomBlockReplicationPolicy for block replication policy
2023-02-14 09:17:20.588 INFO storage.BlockManagerMaster: Registering BlockManager BlockManagerId(driver, 172.17.18.136, 36651, None)
2023-02-14 09:17:20.592 INFO storage.BlockManagerMasterEndpoint: Registering block manager 172.17.18.136:36651 with 1458.6 MiB RAM, BlockManagerId(driver, 172.17.18.136, 36651, None)
2023-02-14 09:17:20.594 INFO storage.BlockManagerMaster: Registered BlockManager BlockManagerId(driver, 172.17.18.136, 36651, None)
2023-02-14 09:17:20.595 INFO storage.BlockManager: Initialized BlockManager: BlockManagerId(driver, 172.17.18.136, 36651, None)
2023-02-14 09:17:20.610 INFO sink.StatsdSink: StatsdSink started with prefix: ''
2023-02-14 09:17:20.641 INFO util.log: Logging initialized @3127ms to org.sparkproject.jetty.util.log.Slf4jLog
2023-02-14 09:17:22.090 INFO history.RollingEventLogFilesWriter: Logging events to file:/opt/kyuubi/spark-history/eventlog_v2_spark-application-1676359040353/events_1_spark-application-1676359040353.snappy
2023-02-14 09:17:22.231 WARN util.Utils: spark.executor.instances less than spark.dynamicAllocation.minExecutors is invalid, ignoring its setting, please update your configs.
2023-02-14 09:17:22.232 INFO util.Utils: Using initial executors = 1, max of spark.dynamicAllocation.initialExecutors, spark.dynamicAllocation.minExecutors and spark.executor.instances
2023-02-14 09:17:22.232 WARN spark.ExecutorAllocationManager: Dynamic allocation without a shuffle service is an experimental feature.
2023-02-14 09:17:24.398 INFO k8s.KubernetesClusterSchedulerBackend$KubernetesDriverEndpoint: Registered executor NettyRpcEndpointRef(spark-client://Executor) (172.17.11.222:43108) with ID 1,  ResourceProfileId 0
2023-02-14 09:17:24.405 INFO dynalloc.ExecutorMonitor: New executor 1 has registered (new total is 1)
2023-02-14 09:17:24.458 INFO k8s.KubernetesClusterSchedulerBackend: SchedulerBackend is ready for scheduling beginning after reached minRegisteredResourcesRatio: 0.8
2023-02-14 09:17:24.520 INFO storage.BlockManagerMasterEndpoint: Registering block manager 172.17.11.222:41311 with 1007.8 MiB RAM, BlockManagerId(1, 172.17.11.222, 41311, None)
2023-02-14 09:17:24.564 INFO internal.SharedState: spark.sql.warehouse.dir is not set, but hive.metastore.warehouse.dir is set. Setting spark.sql.warehouse.dir to the value of hive.metastore.warehouse.dir.
2023-02-14 09:17:24.664 WARN impl.MetricsConfig: Cannot locate configuration: tried hadoop-metrics2-s3a-file-system.properties,hadoop-metrics2.properties
2023-02-14 09:17:24.675 INFO impl.MetricsSystemImpl: Scheduled Metric snapshot period at 10 second(s).
2023-02-14 09:17:24.675 INFO impl.MetricsSystemImpl: s3a-file-system metrics system started
2023-02-14 09:17:25.071 INFO internal.SharedState: Warehouse path is 's3a://warehouse/'.
2023-02-14 09:17:27.734 INFO hive.HiveUtils: Initializing HiveMetastoreConnection version 2.3.9 using Spark classes.
2023-02-14 09:17:27.797 INFO conf.HiveConf: Found configuration file file:/opt/spark-3.2.2-bin-hadoop3.2/conf/hive-site.xml
2023-02-14 09:17:27.951 WARN conf.HiveConf: HiveConf of name hive.metastore.uri.selection does not exist
2023-02-14 09:17:27.984 INFO client.HiveClientImpl: Warehouse location for Hive client (version 2.3.9) is s3a://warehouse/
2023-02-14 09:17:28.030 INFO hive.metastore: Trying to connect to metastore with URI thrift://hive-metastore-1.hive-metastore-hs.hive-metastore.svc:9083
2023-02-14 09:17:28.048 INFO hive.metastore: Opened a connection to metastore, current connections: 1
2023-02-14 09:17:28.253 WARN security.ShellBasedUnixGroupsMapping: unable to return groups for user as-ol.lysiuk
PartialGroupNameException The user name 'as-ol.lysiuk' is not found. id: ‘as-ol.lysiuk’: no such user
id: ‘as-ol.lysiuk’: no such user

    at org.apache.hadoop.security.ShellBasedUnixGroupsMapping.resolvePartialGroupNames(ShellBasedUnixGroupsMapping.java:294)
    at org.apache.hadoop.security.ShellBasedUnixGroupsMapping.getUnixGroups(ShellBasedUnixGroupsMapping.java:207)
    at org.apache.hadoop.security.ShellBasedUnixGroupsMapping.getGroups(ShellBasedUnixGroupsMapping.java:97)
    at org.apache.hadoop.security.JniBasedUnixGroupsMappingWithFallback.getGroups(JniBasedUnixGroupsMappingWithFallback.java:51)
    at org.apache.hadoop.security.Groups$GroupCacheLoader.fetchGroupList(Groups.java:387)
    at org.apache.hadoop.security.Groups$GroupCacheLoader.load(Groups.java:321)
    at org.apache.hadoop.security.Groups$GroupCacheLoader.load(Groups.java:270)
    at org.apache.hadoop.thirdparty.com.google.common.cache.LocalCache$LoadingValueReference.loadFuture(LocalCache.java:3529)
    at org.apache.hadoop.thirdparty.com.google.common.cache.LocalCache$Segment.loadSync(LocalCache.java:2278)
    at org.apache.hadoop.thirdparty.com.google.common.cache.LocalCache$Segment.lockedGetOrLoad(LocalCache.java:2155)
    at org.apache.hadoop.thirdparty.com.google.common.cache.LocalCache$Segment.get(LocalCache.java:2045)
    at org.apache.hadoop.thirdparty.com.google.common.cache.LocalCache.get(LocalCache.java:3962)
    at org.apache.hadoop.thirdparty.com.google.common.cache.LocalCache.getOrLoad(LocalCache.java:3985)
    at org.apache.hadoop.thirdparty.com.google.common.cache.LocalCache$LocalLoadingCache.get(LocalCache.java:4946)
    at org.apache.hadoop.security.Groups.getGroups(Groups.java:228)
    at org.apache.hadoop.security.UserGroupInformation.getGroups(UserGroupInformation.java:1734)
    at org.apache.hadoop.security.UserGroupInformation.getGroupNames(UserGroupInformation.java:1722)
    at org.apache.hadoop.hive.metastore.HiveMetaStoreClient.open(HiveMetaStoreClient.java:496)
    at org.apache.hadoop.hive.metastore.HiveMetaStoreClient.<init>(HiveMetaStoreClient.java:245)
    at org.apache.hadoop.hive.ql.metadata.SessionHiveMetaStoreClient.<init>(SessionHiveMetaStoreClient.java:70)
    at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
    at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
    at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
    at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
    at org.apache.hadoop.hive.metastore.MetaStoreUtils.newInstance(MetaStoreUtils.java:1740)
    at org.apache.hadoop.hive.metastore.RetryingMetaStoreClient.<init>(RetryingMetaStoreClient.java:83)
    at org.apache.hadoop.hive.metastore.RetryingMetaStoreClient.getProxy(RetryingMetaStoreClient.java:133)
    at org.apache.hadoop.hive.metastore.RetryingMetaStoreClient.getProxy(RetryingMetaStoreClient.java:104)
    at org.apache.hadoop.hive.ql.metadata.Hive.createMetaStoreClient(Hive.java:3607)
    at org.apache.hadoop.hive.ql.metadata.Hive.getMSC(Hive.java:3659)
    at org.apache.hadoop.hive.ql.metadata.Hive.getMSC(Hive.java:3639)
    at org.apache.hadoop.hive.ql.metadata.Hive.getDatabase(Hive.java:1563)
    at org.apache.hadoop.hive.ql.metadata.Hive.databaseExists(Hive.java:1552)
    at org.apache.spark.sql.hive.client.HiveClientImpl.$anonfun$databaseExists$1(HiveClientImpl.scala:396)
    at scala.runtime.java8.JFunction0$mcZ$sp.apply(JFunction0$mcZ$sp.java:23)
    at org.apache.spark.sql.hive.client.HiveClientImpl.$anonfun$withHiveState$1(HiveClientImpl.scala:305)
    at org.apache.spark.sql.hive.client.HiveClientImpl.liftedTree1$1(HiveClientImpl.scala:236)
    at org.apache.spark.sql.hive.client.HiveClientImpl.retryLocked(HiveClientImpl.scala:235)
    at org.apache.spark.sql.hive.client.HiveClientImpl.withHiveState(HiveClientImpl.scala:285)
    at org.apache.spark.sql.hive.client.HiveClientImpl.databaseExists(HiveClientImpl.scala:396)
    at org.apache.spark.sql.hive.HiveExternalCatalog.$anonfun$databaseExists$1(HiveExternalCatalog.scala:224)
    at scala.runtime.java8.JFunction0$mcZ$sp.apply(JFunction0$mcZ$sp.java:23)
    at org.apache.spark.sql.hive.HiveExternalCatalog.withClient(HiveExternalCatalog.scala:102)
    at org.apache.spark.sql.hive.HiveExternalCatalog.databaseExists(HiveExternalCatalog.scala:224)
    at org.apache.spark.sql.internal.SharedState.externalCatalog$lzycompute(SharedState.scala:150)
    at org.apache.spark.sql.internal.SharedState.externalCatalog(SharedState.scala:140)
    at org.apache.spark.sql.hive.HiveSessionStateBuilder.externalCatalog(HiveSessionStateBuilder.scala:45)
    at org.apache.spark.sql.hive.HiveSessionStateBuilder.$anonfun$catalog$1(HiveSessionStateBuilder.scala:60)
    at org.apache.spark.sql.catalyst.catalog.SessionCatalog.externalCatalog$lzycompute(SessionCatalog.scala:118)
    at org.apache.spark.sql.catalyst.catalog.SessionCatalog.externalCatalog(SessionCatalog.scala:118)
    at org.apache.spark.sql.catalyst.catalog.SessionCatalog.listDatabases(SessionCatalog.scala:298)
    at org.apache.spark.sql.execution.datasources.v2.V2SessionCatalog.listNamespaces(V2SessionCatalog.scala:205)
    at org.apache.spark.sql.connector.catalog.DelegatingCatalogExtension.listNamespaces(DelegatingCatalogExtension.java:116)
    at org.apache.spark.sql.execution.datasources.v2.ShowNamespacesExec.run(ShowNamespacesExec.scala:42)
    at org.apache.spark.sql.execution.datasources.v2.V2CommandExec.result$lzycompute(V2CommandExec.scala:43)
    at org.apache.spark.sql.execution.datasources.v2.V2CommandExec.result(V2CommandExec.scala:43)
    at org.apache.spark.sql.execution.datasources.v2.V2CommandExec.executeCollect(V2CommandExec.scala:49)
    at org.apache.spark.sql.execution.QueryExecution$$anonfun$eagerlyExecuteCommands$1.$anonfun$applyOrElse$1(QueryExecution.scala:97)
    at org.apache.spark.sql.execution.SQLExecution$.$anonfun$withNewExecutionId$5(SQLExecution.scala:103)
    at org.apache.spark.sql.execution.SQLExecution$.withSQLConfPropagated(SQLExecution.scala:163)
    at org.apache.spark.sql.execution.SQLExecution$.$anonfun$withNewExecutionId$1(SQLExecution.scala:90)
    at org.apache.spark.sql.SparkSession.withActive(SparkSession.scala:775)
    at org.apache.spark.sql.execution.SQLExecution$.withNewExecutionId(SQLExecution.scala:64)
    at org.apache.spark.sql.execution.QueryExecution$$anonfun$eagerlyExecuteCommands$1.applyOrElse(QueryExecution.scala:97)
    at org.apache.spark.sql.execution.QueryExecution$$anonfun$eagerlyExecuteCommands$1.applyOrElse(QueryExecution.scala:93)
    at org.apache.spark.sql.catalyst.trees.TreeNode.$anonfun$transformDownWithPruning$1(TreeNode.scala:481)
    at org.apache.spark.sql.catalyst.trees.CurrentOrigin$.withOrigin(TreeNode.scala:82)
    at org.apache.spark.sql.catalyst.trees.TreeNode.transformDownWithPruning(TreeNode.scala:481)
    at org.apache.spark.sql.catalyst.plans.logical.LogicalPlan.org$apache$spark$sql$catalyst$plans$logical$AnalysisHelper$$super$transformDownWithPruning(LogicalPlan.scala:30)
    at org.apache.spark.sql.catalyst.plans.logical.AnalysisHelper.transformDownWithPruning(AnalysisHelper.scala:267)
    at org.apache.spark.sql.catalyst.plans.logical.AnalysisHelper.transformDownWithPruning$(AnalysisHelper.scala:263)
    at org.apache.spark.sql.catalyst.plans.logical.LogicalPlan.transformDownWithPruning(LogicalPlan.scala:30)
    at org.apache.spark.sql.catalyst.plans.logical.LogicalPlan.transformDownWithPruning(LogicalPlan.scala:30)
    at org.apache.spark.sql.catalyst.trees.TreeNode.transformDown(TreeNode.scala:457)
    at org.apache.spark.sql.execution.QueryExecution.eagerlyExecuteCommands(QueryExecution.scala:93)
    at org.apache.spark.sql.execution.QueryExecution.commandExecuted$lzycompute(QueryExecution.scala:80)
    at org.apache.spark.sql.execution.QueryExecution.commandExecuted(QueryExecution.scala:78)
    at org.apache.spark.sql.Dataset.<init>(Dataset.scala:219)
    at org.apache.spark.sql.Dataset$.$anonfun$ofRows$2(Dataset.scala:99)
    at org.apache.spark.sql.SparkSession.withActive(SparkSession.scala:775)
    at org.apache.spark.sql.Dataset$.ofRows(Dataset.scala:96)
    at org.apache.spark.sql.SparkSession.$anonfun$sql$1(SparkSession.scala:618)
    at org.apache.spark.sql.SparkSession.withActive(SparkSession.scala:775)
    at org.apache.spark.sql.SparkSession.sql(SparkSession.scala:613)
    at org.apache.kyuubi.engine.spark.SparkSQLEngine$.$anonfun$createSpark$1(SparkSQLEngine.scala:135)
    at org.apache.kyuubi.engine.spark.SparkSQLEngine$.$anonfun$createSpark$1$adapted(SparkSQLEngine.scala:129)
    at scala.collection.mutable.ResizableArray.foreach(ResizableArray.scala:62)
    at scala.collection.mutable.ResizableArray.foreach$(ResizableArray.scala:55)
    at scala.collection.mutable.ArrayBuffer.foreach(ArrayBuffer.scala:49)
    at org.apache.kyuubi.engine.spark.SparkSQLEngine$.createSpark(SparkSQLEngine.scala:129)
    at org.apache.kyuubi.engine.spark.SparkSQLEngine$.main(SparkSQLEngine.scala:199)
    at org.apache.kyuubi.engine.spark.SparkSQLEngine.main(SparkSQLEngine.scala)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:498)
    at org.apache.spark.deploy.JavaMainApplication.start(SparkApplication.scala:52)
    at org.apache.spark.deploy.SparkSubmit.org$apache$spark$deploy$SparkSubmit$$runMain(SparkSubmit.scala:955)
    at org.apache.spark.deploy.SparkSubmit$$anon$1.run(SparkSubmit.scala:165)
    at org.apache.spark.deploy.SparkSubmit$$anon$1.run(SparkSubmit.scala:163)
    at java.security.AccessController.doPrivileged(Native Method)
    at javax.security.auth.Subject.doAs(Subject.java:422)
    at org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1878)
    at org.apache.spark.deploy.SparkSubmit.doRunMain$1(SparkSubmit.scala:163)
    at org.apache.spark.deploy.SparkSubmit.submit(SparkSubmit.scala:203)
    at org.apache.spark.deploy.SparkSubmit.doSubmit(SparkSubmit.scala:90)
    at org.apache.spark.deploy.SparkSubmit$$anon$2.doSubmit(SparkSubmit.scala:1043)
    at org.apache.spark.deploy.SparkSubmit$.main(SparkSubmit.scala:1052)
    at org.apache.spark.deploy.SparkSubmit.main(SparkSubmit.scala)
2023-02-14 09:17:28.263 INFO hive.metastore: Connected to metastore.
2023-02-14 09:17:28.621 INFO codegen.CodeGenerator: Code generated in 187.022965 ms
2023-02-14 09:17:28.684 INFO codegen.CodeGenerator: Code generated in 7.368197 ms
2023-02-14 09:17:28.753 INFO codegen.CodeGenerator: Code generated in 10.990492 ms
2023-02-14 09:17:28.836 INFO spark.SparkContext: Starting job: isEmpty at SparkSQLEngine.scala:135
2023-02-14 09:17:28.854 INFO scheduler.DAGScheduler: Got job 0 (isEmpty at SparkSQLEngine.scala:135) with 1 output partitions
2023-02-14 09:17:28.854 INFO scheduler.DAGScheduler: Final stage: ResultStage 0 (isEmpty at SparkSQLEngine.scala:135)
2023-02-14 09:17:28.854 INFO scheduler.DAGScheduler: Parents of final stage: List()
2023-02-14 09:17:28.855 INFO scheduler.DAGScheduler: Missing parents: List()
2023-02-14 09:17:28.859 INFO scheduler.DAGScheduler: Submitting ResultStage 0 (MapPartitionsRDD[2] at isEmpty at SparkSQLEngine.scala:135), which has no missing parents
2023-02-14 09:17:28.970 INFO memory.MemoryStore: Block broadcast_0 stored as values in memory (estimated size 6.7 KiB, free 1458.6 MiB)
2023-02-14 09:17:29.005 INFO memory.MemoryStore: Block broadcast_0_piece0 stored as bytes in memory (estimated size 3.6 KiB, free 1458.6 MiB)
2023-02-14 09:17:29.007 INFO storage.BlockManagerInfo: Added broadcast_0_piece0 in memory on 172.17.18.136:36651 (size: 3.6 KiB, free: 1458.6 MiB)
2023-02-14 09:17:29.010 INFO spark.SparkContext: Created broadcast 0 from broadcast at DAGScheduler.scala:1478
2023-02-14 09:17:29.023 INFO scheduler.DAGScheduler: Submitting 1 missing tasks from ResultStage 0 (MapPartitionsRDD[2] at isEmpty at SparkSQLEngine.scala:135) (first 15 tasks are for partitions Vector(0))
2023-02-14 09:17:29.024 INFO scheduler.TaskSchedulerImpl: Adding task set 0.0 with 1 tasks resource profile 0
2023-02-14 09:17:29.055 INFO scheduler.TaskSetManager: Starting task 0.0 in stage 0.0 (TID 0) (172.17.11.222, executor 1, partition 0, PROCESS_LOCAL, 5577 bytes) taskResourceAssignments Map()
2023-02-14 09:17:29.421 INFO storage.BlockManagerInfo: Added broadcast_0_piece0 in memory on 172.17.11.222:41311 (size: 3.6 KiB, free: 1007.8 MiB)
2023-02-14 09:17:30.809 INFO scheduler.TaskSetManager: Finished task 0.0 in stage 0.0 (TID 0) in 1763 ms on 172.17.11.222 (executor 1) (1/1)
2023-02-14 09:17:30.811 INFO scheduler.TaskSchedulerImpl: Removed TaskSet 0.0, whose tasks have all completed, from pool 
2023-02-14 09:17:30.817 INFO scheduler.DAGScheduler: ResultStage 0 (isEmpty at SparkSQLEngine.scala:135) finished in 1.929 s
2023-02-14 09:17:30.820 INFO scheduler.DAGScheduler: Job 0 is finished. Cancelling potential speculative or zombie tasks for this job
2023-02-14 09:17:30.820 INFO scheduler.TaskSchedulerImpl: Killing all running tasks in stage 0: Stage finished
2023-02-14 09:17:30.822 INFO scheduler.DAGScheduler: Job 0 finished: isEmpty at SparkSQLEngine.scala:135, took 1.986090 s
2023-02-14 09:17:30.863 INFO events.SparkEventLoggingService: Service[EventLogging] is initialized.
2023-02-14 09:17:30.864 INFO events.SparkEventLoggingService: Service[EventLogging] is started.
2023-02-14 09:17:30.871 INFO util.ThreadUtils: SparkSQLSessionManager-exec-pool: pool size: 100, wait queue size: 100, thread keepalive time: 60000 ms
2023-02-14 09:17:30.873 INFO operation.SparkSQLOperationManager: Service[SparkSQLOperationManager] is initialized.
2023-02-14 09:17:30.875 INFO session.SparkSQLSessionManager: Service[SparkSQLSessionManager] is initialized.
2023-02-14 09:17:30.875 INFO spark.SparkSQLBackendService: Service[SparkSQLBackendService] is initialized.
2023-02-14 09:17:30.890 INFO spark.SparkTBinaryFrontendService: Initializing SparkTBinaryFrontend on kyuubi-server-1:44757 with [9, 999] worker threads
2023-02-14 09:17:30.973 INFO imps.CuratorFrameworkImpl: Starting
2023-02-14 09:17:30.982 INFO zookeeper.ZooKeeper: Client environment:zookeeper.version=3.6.2--803c7f1a12f85978cb049af5e4ef23bd8b688715, built on 09/04/2020 12:44 GMT
2023-02-14 09:17:30.982 INFO zookeeper.ZooKeeper: Client environment:host.name=kyuubi-server-1.kyuubi-hs.kyuubi.svc.cluster.local
2023-02-14 09:17:30.982 INFO zookeeper.ZooKeeper: Client environment:java.version=1.8.0_342
2023-02-14 09:17:30.982 INFO zookeeper.ZooKeeper: Client environment:java.vendor=Azul Systems, Inc.
2023-02-14 09:17:30.982 INFO zookeeper.ZooKeeper: Client environment:java.home=/usr/lib/jvm/zulu8-ca-amd64/jre
2023-02-14 09:17:30.982 INFO zookeeper.ZooKeeper: Client environment:java.class.path=/opt/spark/conf/:/opt/spark/jars/javax.jdo-3.2.0-m3.jar:/opt/spark/jars/kubernetes-model-scheduling-5.4.1.jar:/opt/spark/jars/kubernetes-model-flowcontrol-5.4.1.jar:/opt/spark/jars/scala-xml_2.12-1.2.0.jar:/opt/spark/jars/spire-macros_2.12-0.17.0.jar:/opt/spark/jars/datanucleus-api-jdo-4.2.4.jar:/opt/spark/jars/hive-jdbc-2.3.9.jar:/opt/spark/jars/metrics-graphite-4.2.0.jar:/opt/spark/jars/avro-mapred-1.10.2.jar:/opt/spark/jars/aopalliance-repackaged-2.6.1.jar:/opt/spark/jars/velocity-1.5.jar:/opt/spark/jars/jackson-dataformat-yaml-2.12.3.jar:/opt/spark/jars/commons-dbcp-1.4.jar:/opt/spark/jars/okhttp-3.12.12.jar:/opt/spark/jars/commons-compress-1.21.jar:/opt/spark/jars/threeten-extra-1.5.0.jar:/opt/spark/jars/breeze-macros_2.12-1.2.jar:/opt/spark/jars/kubernetes-model-storageclass-5.4.1.jar:/opt/spark/jars/arpack-2.2.1.jar:/opt/spark/jars/avro-1.10.2.jar:/opt/spark/jars/hk2-locator-2.6.1.jar:/opt/spark/jars/arrow-vector-2.0.0.jar:/opt/spark/jars/univocity-parsers-2.9.1.jar:/opt/spark/jars/spark-kvstore_2.12-3.2.2.jar:/opt/spark/jars/hive-beeline-2.3.9.jar:/opt/spark/jars/lapack-2.2.1.jar:/opt/spark/jars/datanucleus-core-4.1.17.jar:/opt/spark/jars/hadoop-client-runtime-3.3.1.jar:/opt/spark/jars/generex-1.0.2.jar:/opt/spark/jars/tink-1.6.0.jar:/opt/spark/jars/spark-repl_2.12-3.2.2.jar:/opt/spark/jars/scala-collection-compat_2.12-2.1.1.jar:/opt/spark/jars/kubernetes-model-policy-5.4.1.jar:/opt/spark/jars/jaxb-runtime-2.3.2.jar:/opt/spark/jars/libthrift-0.12.0.jar:/opt/spark/jars/RoaringBitmap-0.9.0.jar:/opt/spark/jars/jaxb-api-2.2.11.jar:/opt/spark/jars/rocksdbjni-6.20.3.jar:/opt/spark/jars/commons-text-1.6.jar:/opt/spark/jars/ST4-4.0.4.jar:/opt/spark/jars/jsr305-3.0.0.jar:/opt/spark/jars/kubernetes-model-networking-5.4.1.jar:/opt/spark/jars/arpack_combined_all-0.1.jar:/opt/spark/jars/libfb303-0.9.3.jar:/opt/spark/jars/jta-1.1.jar:/opt/spark/jars/commons-compiler-3.0.16.jar:/opt/spark/jars/hive-metastore-2.3.9.jar:/opt/spark/jars/commons-logging-1.1.3.jar:/opt/spark/jars/xbean-asm9-shaded-4.20.jar:/opt/spark/jars/jackson-core-asl-1.9.13.jar:/opt/spark/jars/delta-core_2.12-2.0.0.jar:/opt/spark/jars/kubernetes-model-coordination-5.4.1.jar:/opt/spark/jars/jackson-module-scala_2.12-2.12.3.jar:/opt/spark/jars/hive-serde-2.3.9.jar:/opt/spark/jars/chill_2.12-0.10.0.jar:/opt/spark/jars/kubernetes-model-common-5.4.1.jar:/opt/spark/jars/spark-sql_2.12-3.2.2.jar:/opt/spark/jars/hive-shims-common-2.3.9.jar:/opt/spark/jars/jersey-client-2.34.jar:/opt/spark/jars/hk2-utils-2.6.1.jar:/opt/spark/jars/derby-10.14.2.0.jar:/opt/spark/jars/jersey-hk2-2.34.jar:/opt/spark/jars/HikariCP-2.5.1.jar:/opt/spark/jars/jersey-container-servlet-core-2.34.jar:/opt/spark/jars/spark-network-shuffle_2.12-3.2.2.jar:/opt/spark/jars/kubernetes-model-certificates-5.4.1.jar:/opt/spark/jars/kubernetes-model-core-5.4.1.jar:/opt/spark/jars/htrace-core4-4.1.0-incubating.jar:/opt/spark/jars/core-1.1.2.jar:/opt/spark/jars/aws-java-sdk-bundle-1.11.901.jar:/opt/spark/jars/curator-framework-2.13.0.jar:/opt/spark/jars/hive-common-2.3.9.jar:/opt/spark/jars/jline-2.14.6.jar:/opt/spark/jars/audience-annotations-0.5.0.jar:/opt/spark/jars/scala-parser-combinators_2.12-1.1.2.jar:/opt/spark/jars/hive-exec-2.3.9-core.jar:/opt/spark/jars/jdo-api-3.0.1.jar:/opt/spark/jars/macro-compat_2.12-1.1.1.jar:/opt/spark/jars/okio-1.14.0.jar:/opt/spark/jars/spark-mesos_2.12-3.2.2.jar:/opt/spark/jars/commons-cli-1.2.jar:/opt/spark/jars/commons-lang-2.6.jar:/opt/spark/jars/hive-cli-2.3.9.jar:/opt/spark/jars/javassist-3.25.0-GA.jar:/opt/spark/jars/kubernetes-model-apiextensions-5.4.1.jar:/opt/spark/jars/joda-time-2.10.10.jar:/opt/spark/jars/avro-ipc-1.10.2.jar:/opt/spark/jars/scala-library-2.12.14.jar:/opt/spark/jars/jersey-common-2.34.jar:/opt/spark/jars/jpam-1.1.jar:/opt/spark/jars/stax-api-1.0.1.jar:/opt/spark/jars/ivy-2.5.0.jar:/opt/spark/jars/commons-io-2.8.0.jar:/opt/spark/jars/hadoop-shaded-guava-1.1.1.jar:/opt/spark/jars/JTransforms-3.1.jar:/opt/spark/jars/hive-shims-scheduler-2.3.9.jar:/opt/spark/jars/kryo-shaded-4.0.2.jar:/opt/spark/jars/py4j-0.10.9.5.jar:/opt/spark/jars/hive-shims-0.23-2.3.9.jar:/opt/spark/jars/slf4j-log4j12-1.7.30.jar:/opt/spark/jars/osgi-resource-locator-1.0.3.jar:/opt/spark/jars/arrow-format-2.0.0.jar:/opt/spark/jars/zstd-jni-1.5.0-4.jar:/opt/spark/jars/commons-collections-3.2.2.jar:/opt/spark/jars/commons-crypto-1.1.0.jar:/opt/spark/jars/spark-hive-thriftserver_2.12-3.2.2.jar:/opt/spark/jars/slf4j-api-1.7.30.jar:/opt/spark/jars/mesos-1.4.0-shaded-protobuf.jar:/opt/spark/jars/orc-mapreduce-1.6.14.jar:/opt/spark/jars/spark-hive_2.12-3.2.2.jar:/opt/spark/jars/spark-streaming_2.12-3.2.2.jar:/opt/spark/jars/bonecp-0.8.0.RELEASE.jar:/opt/spark/jars/jakarta.validation-api-2.0.2.jar:/opt/spark/jars/kubernetes-model-autoscaling-5.4.1.jar:/opt/spark/jars/spark-yarn_2.12-3.2.2.jar:/opt/spark/jars/kubernetes-model-metrics-5.4.1.jar:/opt/spark/jars/kubernetes-model-discovery-5.4.1.jar:/opt/spark/jars/istack-commons-runtime-3.0.8.jar:/opt/spark/jars/wildfly-openssl-1.0.7.Final.jar:/opt/spark/jars/datanucleus-rdbms-4.1.19.jar:/opt/spark/jars/javolution-5.5.1.jar:/opt/spark/jars/JLargeArrays-1.5.jar:/opt/spark/jars/jtds-1.3.1.jar:/opt/spark/jars/jersey-container-servlet-2.34.jar:/opt/spark/jars/hk2-api-2.6.1.jar:/opt/spark/jars/kubernetes-model-rbac-5.4.1.jar:/opt/spark/jars/httpcore-4.4.14.jar:/opt/spark/jars/metrics-jmx-4.2.0.jar:/opt/spark/jars/compress-lzf-1.0.3.jar:/opt/spark/jars/commons-net-3.1.jar:/opt/spark/jars/metrics-core-4.2.0.jar:/opt/spark/jars/spire_2.12-0.17.0.jar:/opt/spark/jars/hadoop-yarn-server-web-proxy-3.3.1.jar:/opt/spark/jars/spark-kubernetes_2.12-3.2.2.jar:/opt/spark/jars/objenesis-2.6.jar:/opt/spark/jars/aircompressor-0.21.jar:/opt/spark/jars/oro-2.0.8.jar:/opt/spark/jars/shims-0.9.0.jar:/opt/spark/jars/leveldbjni-all-1.8.jar:/opt/spark/jars/spark-tags_2.12-3.2.2-tests.jar:/opt/spark/jars/zookeeper-3.6.2.jar:/opt/spark/jars/protobuf-java-2.5.0.jar:/opt/spark/jars/parquet-format-structures-1.12.2.jar:/opt/spark/jars/opencsv-2.3.jar:/opt/spark/jars/jakarta.servlet-api-4.0.3.jar:/opt/spark/jars/kubernetes-model-extensions-5.4.1.jar:/opt/spark/jars/super-csv-2.2.0.jar:/opt/spark/jars/stream-2.9.6.jar:/opt/spark/jars/scala-reflect-2.12.15.jar:/opt/spark/jars/hive-storage-api-2.7.2.jar:/opt/spark/jars/jackson-databind-2.12.3.jar:/opt/spark/jars/kubernetes-model-admissionregistration-5.4.1.jar:/opt/spark/jars/parquet-common-1.12.2.jar:/opt/spark/jars/flatbuffers-java-1.9.0.jar:/opt/spark/jars/json4s-core_2.12-3.7.0-M11.jar:/opt/spark/jars/transaction-api-1.1.jar:/opt/spark/jars/jakarta.ws.rs-api-2.1.6.jar:/opt/spark/jars/hive-llap-common-2.3.9.jar:/opt/spark/jars/json-1.8.jar:/opt/spark/jars/jackson-mapper-asl-1.9.13.jar:/opt/spark/jars/spark-sketch_2.12-3.2.2.jar:/opt/spark/jars/commons-lang3-3.12.0.jar:/opt/spark/jars/httpclient-4.5.13.jar:/opt/spark/jars/logging-interceptor-3.12.12.jar:/opt/spark/jars/hadoop-client-api-3.3.1.jar:/opt/spark/jars/hive-shims-2.3.9.jar:/opt/spark/jars/shapeless_2.12-2.3.3.jar:/opt/spark/jars/spark-mllib_2.12-3.2.2.jar:/opt/spark/jars/antlr-runtime-3.5.2.jar:/opt/spark/jars/snakeyaml-1.27.jar:/opt/spark/jars/json4s-ast_2.12-3.7.0-M11.jar:/opt/spark/jars/algebra_2.12-2.0.1.jar:/opt/spark/jars/jakarta.annotation-api-1.3.5.jar:/opt/spark/jars/spark-mllib-local_2.12-3.2.2.jar:/opt/spark/jars/spark-graphx_2.12-3.2.2.jar:/opt/spark/jars/guava-14.0.1.jar:/opt/spark/jars/commons-codec-1.15.jar:/opt/spark/jars/paranamer-2.8.jar:/opt/spark/jars/lz4-java-1.7.1.jar:/opt/spark/jars/snappy-java-1.1.8.4.jar:/opt/spark/jars/jcl-over-slf4j-1.7.30.jar:/opt/spark/jars/log4j-1.2.17.jar:/opt/spark/jars/scala-compiler-2.12.15.jar:/opt/spark/jars/netty-all-4.1.68.Final.jar:/opt/spark/jars/arrow-memory-core-2.0.0.jar:/opt/spark/jars/parquet-column-1.12.2.jar:/opt/spark/jars/spire-util_2.12-0.17.0.jar:/opt/spark/jars/janino-3.0.16.jar:/opt/spark/jars/orc-shims-1.6.14.jar:/opt/spark/jars/spark-tags_2.12-3.2.2.jar:/opt/spark/jars/dropwizard-metrics-hadoop-metrics2-reporter-0.1.2.jar:/opt/spark/jars/zjsonpatch-0.3.0.jar:/opt/spark/jars/zookeeper-jute-3.6.2.jar:/opt/spark/jars/kubernetes-model-node-5.4.1.jar:/opt/spark/jars/metrics-jvm-4.2.0.jar:/opt/spark/jars/hadoop-aws-3.3.1.jar:/opt/spark/jars/commons-math3-3.4.1.jar:/opt/spark/jars/jersey-server-2.34.jar:/opt/spark/jars/parquet-hadoop-1.12.2.jar:/opt/spark/jars/pyrolite-4.30.jar:/opt/spark/jars/kubernetes-model-apps-5.4.1.jar:/opt/spark/jars/jodd-core-3.5.2.jar:/opt/spark/jars/hive-vector-code-gen-2.3.9.jar:/opt/spark/jars/jackson-datatype-jsr310-2.11.2.jar:/opt/spark/jars/jackson-annotations-2.12.3.jar:/opt/spark/jars/jakarta.inject-2.6.1.jar:/opt/spark/jars/kubernetes-client-5.4.1.jar:/opt/spark/jars/parquet-encoding-1.12.2.jar:/opt/spark/jars/json4s-jackson_2.12-3.7.0-M11.jar:/opt/spark/jars/curator-client-2.13.0.jar:/opt/spark/jars/spark-core_2.12-3.2.2.jar:/opt/spark/jars/scala-library-2.12.15.jar:/opt/spark/jars/parquet-jackson-1.12.2.jar:/opt/spark/jars/annotations-17.0.0.jar:/opt/spark/jars/jul-to-slf4j-1.7.30.jar:/opt/spark/jars/minlog-1.3.0.jar:/opt/spark/jars/chill-java-0.10.0.jar:/opt/spark/jars/cats-kernel_2.12-2.1.1.jar:/opt/spark/jars/kubernetes-model-events-5.4.1.jar:/opt/spark/jars/delta-storage-2.0.0.jar:/opt/spark/jars/automaton-1.11-8.jar:/opt/spark/jars/kubernetes-model-batch-5.4.1.jar:/opt/spark/jars/jakarta.xml.bind-api-2.3.2.jar:/opt/spark/jars/jackson-core-2.12.3.jar:/opt/spark/jars/gson-2.2.4.jar:/opt/spark/jars/breeze_2.12-1.2.jar:/opt/spark/jars/metrics-json-4.2.0.jar:/opt/spark/jars/hive-service-rpc-3.1.2.jar:/opt/spark/jars/spark-launcher_2.12-3.2.2.jar:/opt/spark/jars/antlr4-runtime-4.8.jar:/opt/spark/jars/json4s-scalap_2.12-3.7.0-M11.jar:/opt/spark/jars/blas-2.2.1.jar:/opt/spark/jars/activation-1.1.1.jar:/opt/spark/jars/spark-catalyst_2.12-3.2.2.jar:/opt/spark/jars/spark-unsafe_2.12-3.2.2.jar:/opt/spark/jars/orc-core-1.6.14.jar:/opt/spark/jars/xz-1.8.jar:/opt/spark/jars/arrow-memory-netty-2.0.0.jar:/opt/spark/jars/commons-pool-1.5.4.jar:/opt/spark/jars/spark-network-common_2.12-3.2.2.jar:/opt/spark/jars/curator-recipes-2.13.0.jar:/opt/spark/jars/spire-platform_2.12-0.17.0.jar
2023-02-14 09:17:30.982 INFO zookeeper.ZooKeeper: Client environment:java.library.path=/usr/java/packages/lib/amd64:/usr/lib64:/lib64:/lib:/usr/lib
2023-02-14 09:17:30.982 INFO zookeeper.ZooKeeper: Client environment:java.io.tmpdir=/tmp
2023-02-14 09:17:30.982 INFO zookeeper.ZooKeeper: Client environment:java.compiler=<NA>
2023-02-14 09:17:30.982 INFO zookeeper.ZooKeeper: Client environment:os.name=Linux
2023-02-14 09:17:30.982 INFO zookeeper.ZooKeeper: Client environment:os.arch=amd64
2023-02-14 09:17:30.982 INFO zookeeper.ZooKeeper: Client environment:os.version=4.18.0-372.26.1.el8_6.x86_64
2023-02-14 09:17:30.982 INFO zookeeper.ZooKeeper: Client environment:user.name=kyuubi
2023-02-14 09:17:30.982 INFO zookeeper.ZooKeeper: Client environment:user.home=/home/kyuubi
2023-02-14 09:17:30.982 INFO zookeeper.ZooKeeper: Client environment:user.dir=/opt/kyuubi/work/as-ol.lysiuk
2023-02-14 09:17:30.982 INFO zookeeper.ZooKeeper: Client environment:os.memory.free=647MB
2023-02-14 09:17:30.982 INFO zookeeper.ZooKeeper: Client environment:os.memory.max=2731MB
2023-02-14 09:17:30.982 INFO zookeeper.ZooKeeper: Client environment:os.memory.total=807MB
2023-02-14 09:17:30.985 INFO zookeeper.ZooKeeper: Initiating client connection, connectString=zookeeper-connect.kafka.svc:2181 sessionTimeout=60000 watcher=org.apache.kyuubi.shade.org.apache.curator.ConnectionState@589d831e
2023-02-14 09:17:30.989 INFO common.X509Util: Setting -D jdk.tls.rejectClientInitiatedRenegotiation=true to disable client-initiated TLS renegotiation
2023-02-14 09:17:30.993 INFO zookeeper.ClientCnxnSocket: jute.maxbuffer value is 1048575 Bytes
2023-02-14 09:17:30.999 INFO zookeeper.ClientCnxn: zookeeper.request.timeout value is 0. feature enabled=false
2023-02-14 09:17:31.006 INFO client.EngineServiceDiscovery: Service[EngineServiceDiscovery] is initialized.
2023-02-14 09:17:31.006 INFO spark.SparkTBinaryFrontendService: Service[SparkTBinaryFrontend] is initialized.
2023-02-14 09:17:31.006 INFO spark.SparkSQLEngine: Service[SparkSQLEngine] is initialized.
2023-02-14 09:17:31.008 INFO zookeeper.ClientCnxn: Opening socket connection to server zookeeper-connect.kafka.svc/10.10.179.151:2181.
2023-02-14 09:17:31.009 INFO zookeeper.ClientCnxn: SASL config status: Will not attempt to authenticate using SASL (unknown error)
2023-02-14 09:17:31.009 INFO zookeeper.ClientCnxn: Socket connection established, initiating session, client: /172.17.18.136:51380, server: zookeeper-connect.kafka.svc/10.10.179.151:2181
2023-02-14 09:17:31.013 INFO operation.SparkSQLOperationManager: Service[SparkSQLOperationManager] is started.
2023-02-14 09:17:31.013 INFO session.SparkSQLSessionManager: Service[SparkSQLSessionManager] is started.
2023-02-14 09:17:31.013 INFO spark.SparkSQLBackendService: Service[SparkSQLBackendService] is started.
2023-02-14 09:17:31.014 INFO zookeeper.ClientCnxn: Session establishment complete on server zookeeper-connect.kafka.svc/10.10.179.151:2181, session id = 0x100f5d5f47b69f1, negotiated timeout = 40000
2023-02-14 09:17:31.026 INFO state.ConnectionStateManager: State change: CONNECTED
2023-02-14 09:17:31.028 INFO zookeeper.ServiceDiscoveryClient: Zookeeper client connection state changed to: CONNECTED
2023-02-14 09:17:31.069 INFO zookeeper.ServiceDiscoveryClient: Created a /kyuubi_1.5.2-incubating_CONNECTION_SPARK_SQL/as-ol.lysiuk/3a27bf56-0c1b-4d96-b82c-66389785e5b4/serviceUri=172.17.18.136:44757;version=1.5.2-incubating;refId=3a27bf56-0c1b-4d96-b82c-66389785e5b4;sequence=0000000000 on ZooKeeper for KyuubiServer uri: 172.17.18.136:44757
2023-02-14 09:17:31.071 INFO client.EngineServiceDiscovery: Service[EngineServiceDiscovery] is started.
2023-02-14 09:17:31.071 INFO spark.SparkTBinaryFrontendService: Service[SparkTBinaryFrontend] is started.
2023-02-14 09:17:31.071 INFO spark.SparkSQLEngine: Service[SparkSQLEngine] is started.
2023-02-14 09:17:31.084 INFO spark.SparkSQLEngine: 
    Spark application name: kyuubi_CONNECTION_SPARK_SQL_as-ol.lysiuk_3a27bf56-0c1b-4d96-b82c-66389785e5b4
          application ID:  spark-application-1676359040353
          application web UI: 
          master: k8s://https://kubernetes.default.svc
          version: 3.2.2
          driver: [cpu: 1, mem: 3g]
          executor: [cpu: 1, mem: 2g, maxNum: 10]
    Start time: Tue Feb 14 09:17:18 EET 2023

    User: as-ol.lysiuk (shared mode: CONNECTION)
    State: STARTED

2023-02-14 09:17:31.376 INFO spark.SparkTBinaryFrontendService: Client protocol version: HIVE_CLI_SERVICE_PROTOCOL_V10
2023-02-14 09:17:31.385 INFO session.SparkSQLSessionManager: Opening session for as-ol.lysiuk@172.17.0.186
2023-02-14 09:17:31.549 INFO session.SparkSQLSessionManager: as-ol.lysiuk's session with SessionHandle [904407b1-8cf3-476f-a730-929eecc53a90] is opened, current opening sessions 1
2023-02-14 09:17:31.591 INFO log.OperationLog: Creating operation log file /opt/kyuubi/work/engine_operation_logs/904407b1-8cf3-476f-a730-929eecc53a90/633b1833-54e7-42ca-8384-55e3808c2f28
2023-02-14 09:17:31.598 INFO operation.ExecuteStatement: Processing as-ol.lysiuk's query[633b1833-54e7-42ca-8384-55e3808c2f28]: INITIALIZED_STATE -> PENDING_STATE, statement: SELECT current_database()
2023-02-14 09:17:31.601 INFO operation.ExecuteStatement: Processing as-ol.lysiuk's query[633b1833-54e7-42ca-8384-55e3808c2f28]: PENDING_STATE -> RUNNING_STATE, statement: SELECT current_database()
2023-02-14 09:17:31.605 INFO operation.ExecuteStatement: 
           Spark application name: kyuubi_CONNECTION_SPARK_SQL_as-ol.lysiuk_3a27bf56-0c1b-4d96-b82c-66389785e5b4
                 application ID: spark-application-1676359040353
                 application web UI: 
                 master: k8s://https://kubernetes.default.svc
                 deploy mode: client
                 version: 3.2.2
           Start time: 2023-02-14T09:17:18.966
           User: as-ol.lysiuk
2023-02-14 09:17:31.661 INFO operation.ExecuteStatement: Processing as-ol.lysiuk's query[633b1833-54e7-42ca-8384-55e3808c2f28]: RUNNING_STATE -> RUNNING_STATE, statement: SELECT current_database()
2023-02-14 09:17:31.661 INFO operation.ExecuteStatement: Execute in full collect mode
2023-02-14 09:17:31.710 INFO codegen.CodeGenerator: Code generated in 7.573834 ms
2023-02-14 09:17:31.725 INFO spark.SparkContext: Starting job: collect at ExecuteStatement.scala:90
2023-02-14 09:17:31.726 INFO scheduler.DAGScheduler: Got job 1 (collect at ExecuteStatement.scala:90) with 1 output partitions
2023-02-14 09:17:31.726 INFO scheduler.DAGScheduler: Final stage: ResultStage 1 (collect at ExecuteStatement.scala:90)
2023-02-14 09:17:31.726 INFO scheduler.DAGScheduler: Parents of final stage: List()
2023-02-14 09:17:31.727 INFO scheduler.DAGScheduler: Missing parents: List()
2023-02-14 09:17:31.728 INFO scheduler.DAGScheduler: Submitting ResultStage 1 (MapPartitionsRDD[5] at collect at ExecuteStatement.scala:90), which has no missing parents
2023-02-14 09:17:31.729 INFO kyuubi.SQLOperationListener: Query [633b1833-54e7-42ca-8384-55e3808c2f28]: Job 1 started with 1 stages, 1 active jobs running
2023-02-14 09:17:31.730 INFO kyuubi.SQLOperationListener: Query [633b1833-54e7-42ca-8384-55e3808c2f28]: Stage 1 started with 1 tasks, 1 active stages running
2023-02-14 09:17:31.731 INFO memory.MemoryStore: Block broadcast_1 stored as values in memory (estimated size 7.2 KiB, free 1458.6 MiB)
2023-02-14 09:17:31.733 INFO memory.MemoryStore: Block broadcast_1_piece0 stored as bytes in memory (estimated size 3.7 KiB, free 1458.6 MiB)
2023-02-14 09:17:31.734 INFO storage.BlockManagerInfo: Added broadcast_1_piece0 in memory on 172.17.18.136:36651 (size: 3.7 KiB, free: 1458.6 MiB)
2023-02-14 09:17:31.735 INFO spark.SparkContext: Created broadcast 1 from broadcast at DAGScheduler.scala:1478
2023-02-14 09:17:31.736 INFO scheduler.DAGScheduler: Submitting 1 missing tasks from ResultStage 1 (MapPartitionsRDD[5] at collect at ExecuteStatement.scala:90) (first 15 tasks are for partitions Vector(0))
2023-02-14 09:17:31.736 INFO scheduler.TaskSchedulerImpl: Adding task set 1.0 with 1 tasks resource profile 0
2023-02-14 09:17:31.738 INFO scheduler.TaskSetManager: Starting task 0.0 in stage 1.0 (TID 1) (172.17.11.222, executor 1, partition 0, PROCESS_LOCAL, 4673 bytes) taskResourceAssignments Map()
2023-02-14 09:17:31.753 INFO storage.BlockManagerInfo: Added broadcast_1_piece0 in memory on 172.17.11.222:41311 (size: 3.7 KiB, free: 1007.8 MiB)
2023-02-14 09:17:31.778 INFO scheduler.TaskSetManager: Finished task 0.0 in stage 1.0 (TID 1) in 41 ms on 172.17.11.222 (executor 1) (1/1)
2023-02-14 09:17:31.778 INFO scheduler.TaskSchedulerImpl: Removed TaskSet 1.0, whose tasks have all completed, from pool 
2023-02-14 09:17:31.779 INFO scheduler.DAGScheduler: ResultStage 1 (collect at ExecuteStatement.scala:90) finished in 0.050 s
2023-02-14 09:17:31.779 INFO scheduler.DAGScheduler: Job 1 is finished. Cancelling potential speculative or zombie tasks for this job
2023-02-14 09:17:31.779 INFO scheduler.TaskSchedulerImpl: Killing all running tasks in stage 1: Stage finished
2023-02-14 09:17:31.780 INFO scheduler.DAGScheduler: Job 1 finished: collect at ExecuteStatement.scala:90, took 0.054720 s
2023-02-14 09:17:31.782 INFO kyuubi.SQLOperationListener: Finished stage: Stage(1, 0); Name: 'collect at ExecuteStatement.scala:90'; Status: succeeded; numTasks: 1; Took: 50 msec
2023-02-14 09:17:31.797 INFO scheduler.StatsReportListener: task runtime:(count: 1, mean: 41.000000, stdev: 0.000000, max: 41.000000, min: 41.000000)
2023-02-14 09:17:31.798 INFO scheduler.StatsReportListener:     0%  5%  10% 25% 50% 75% 90% 95% 100%
2023-02-14 09:17:31.798 INFO scheduler.StatsReportListener:     41.0 ms 41.0 ms 41.0 ms 41.0 ms 41.0 ms 41.0 ms 41.0 ms 41.0 ms 41.0 ms
2023-02-14 09:17:31.799 INFO scheduler.StatsReportListener: shuffle bytes written:(count: 1, mean: 0.000000, stdev: 0.000000, max: 0.000000, min: 0.000000)
2023-02-14 09:17:31.799 INFO scheduler.StatsReportListener:     0%  5%  10% 25% 50% 75% 90% 95% 100%
2023-02-14 09:17:31.799 INFO scheduler.StatsReportListener:     0.0 B   0.0 B   0.0 B   0.0 B   0.0 B   0.0 B   0.0 B   0.0 B   0.0 B
2023-02-14 09:17:31.800 INFO scheduler.StatsReportListener: fetch wait time:(count: 1, mean: 0.000000, stdev: 0.000000, max: 0.000000, min: 0.000000)
2023-02-14 09:17:31.800 INFO scheduler.StatsReportListener:     0%  5%  10% 25% 50% 75% 90% 95% 100%
2023-02-14 09:17:31.800 INFO scheduler.StatsReportListener:     0.0 ms  0.0 ms  0.0 ms  0.0 ms  0.0 ms  0.0 ms  0.0 ms  0.0 ms  0.0 ms
2023-02-14 09:17:31.801 INFO codegen.CodeGenerator: Code generated in 7.056005 ms
2023-02-14 09:17:31.801 INFO scheduler.StatsReportListener: remote bytes read:(count: 1, mean: 0.000000, stdev: 0.000000, max: 0.000000, min: 0.000000)
2023-02-14 09:17:31.801 INFO scheduler.StatsReportListener:     0%  5%  10% 25% 50% 75% 90% 95% 100%
2023-02-14 09:17:31.801 INFO scheduler.StatsReportListener:     0.0 B   0.0 B   0.0 B   0.0 B   0.0 B   0.0 B   0.0 B   0.0 B   0.0 B
2023-02-14 09:17:31.802 INFO scheduler.StatsReportListener: task result size:(count: 1, mean: 1412.000000, stdev: 0.000000, max: 1412.000000, min: 1412.000000)
2023-02-14 09:17:31.802 INFO scheduler.StatsReportListener:     0%  5%  10% 25% 50% 75% 90% 95% 100%
2023-02-14 09:17:31.802 INFO scheduler.StatsReportListener:     1412.0 B    1412.0 B    1412.0 B    1412.0 B    1412.0 B    1412.0 B    1412.0 B    1412.0 B    1412.0 B
2023-02-14 09:17:31.806 INFO operation.ExecuteStatement: Processing as-ol.lysiuk's query[633b1833-54e7-42ca-8384-55e3808c2f28]: RUNNING_STATE -> FINISHED_STATE, statement: SELECT current_database(), time taken: 0.205 seconds
2023-02-14 09:17:31.806 INFO scheduler.StatsReportListener: executor (non-fetch) time pct: (count: 1, mean: 34.146341, stdev: 0.000000, max: 34.146341, min: 34.146341)
2023-02-14 09:17:31.806 INFO scheduler.StatsReportListener:     0%  5%  10% 25% 50% 75% 90% 95% 100%
2023-02-14 09:17:31.806 INFO scheduler.StatsReportListener:     34 %    34 %    34 %    34 %    34 %    34 %    34 %    34 %    34 %
2023-02-14 09:17:31.807 INFO scheduler.StatsReportListener: fetch wait time pct: (count: 1, mean: 0.000000, stdev: 0.000000, max: 0.000000, min: 0.000000)
2023-02-14 09:17:31.807 INFO scheduler.StatsReportListener:     0%  5%  10% 25% 50% 75% 90% 95% 100%
2023-02-14 09:17:31.807 INFO scheduler.StatsReportListener:      0 %     0 %     0 %     0 %     0 %     0 %     0 %     0 %     0 %
2023-02-14 09:17:31.808 INFO scheduler.StatsReportListener: other time pct: (count: 1, mean: 65.853659, stdev: 0.000000, max: 65.853659, min: 65.853659)
2023-02-14 09:17:31.808 INFO scheduler.StatsReportListener:     0%  5%  10% 25% 50% 75% 90% 95% 100%
2023-02-14 09:17:31.808 INFO scheduler.StatsReportListener:     66 %    66 %    66 %    66 %    66 %    66 %    66 %    66 %    66 %
2023-02-14 09:17:31.808 INFO kyuubi.SparkSQLEngineListener: Job end. Job 1 state is JobSucceeded
2023-02-14 09:17:31.810 INFO kyuubi.SQLOperationListener: Query [633b1833-54e7-42ca-8384-55e3808c2f28]: Job 1 succeeded, 0 active jobs running
2023-02-14 09:17:32.119 INFO log.OperationLog: Creating operation log file /opt/kyuubi/work/engine_operation_logs/904407b1-8cf3-476f-a730-929eecc53a90/3c66872b-d715-4eef-99fb-25a4d70f543d
2023-02-14 09:17:32.119 INFO operation.ExecuteStatement: Processing as-ol.lysiuk's query[3c66872b-d715-4eef-99fb-25a4d70f543d]: INITIALIZED_STATE -> PENDING_STATE, statement: SELECT current_database()
2023-02-14 09:17:32.120 INFO operation.ExecuteStatement: Processing as-ol.lysiuk's query[3c66872b-d715-4eef-99fb-25a4d70f543d]: PENDING_STATE -> RUNNING_STATE, statement: SELECT current_database()
2023-02-14 09:17:32.121 INFO operation.ExecuteStatement: 
           Spark application name: kyuubi_CONNECTION_SPARK_SQL_as-ol.lysiuk_3a27bf56-0c1b-4d96-b82c-66389785e5b4
                 application ID: spark-application-1676359040353
                 application web UI: 
                 master: k8s://https://kubernetes.default.svc
                 deploy mode: client
                 version: 3.2.2
           Start time: 2023-02-14T09:17:18.966
           User: as-ol.lysiuk
2023-02-14 09:17:32.127 INFO operation.ExecuteStatement: Processing as-ol.lysiuk's query[3c66872b-d715-4eef-99fb-25a4d70f543d]: RUNNING_STATE -> RUNNING_STATE, statement: SELECT current_database()
2023-02-14 09:17:32.128 INFO operation.ExecuteStatement: Execute in full collect mode
2023-02-14 09:17:32.152 INFO spark.SparkContext: Starting job: collect at ExecuteStatement.scala:90
2023-02-14 09:17:32.153 INFO scheduler.DAGScheduler: Got job 2 (collect at ExecuteStatement.scala:90) with 1 output partitions
2023-02-14 09:17:32.153 INFO scheduler.DAGScheduler: Final stage: ResultStage 2 (collect at ExecuteStatement.scala:90)
2023-02-14 09:17:32.153 INFO scheduler.DAGScheduler: Parents of final stage: List()
2023-02-14 09:17:32.153 INFO scheduler.DAGScheduler: Missing parents: List()
2023-02-14 09:17:32.154 INFO kyuubi.SQLOperationListener: Query [3c66872b-d715-4eef-99fb-25a4d70f543d]: Job 2 started with 1 stages, 1 active jobs running
2023-02-14 09:17:32.154 INFO scheduler.DAGScheduler: Submitting ResultStage 2 (MapPartitionsRDD[7] at collect at ExecuteStatement.scala:90), which has no missing parents
2023-02-14 09:17:32.155 INFO kyuubi.SQLOperationListener: Query [3c66872b-d715-4eef-99fb-25a4d70f543d]: Stage 2 started with 1 tasks, 1 active stages running
2023-02-14 09:17:32.157 INFO memory.MemoryStore: Block broadcast_2 stored as values in memory (estimated size 7.2 KiB, free 1458.6 MiB)
2023-02-14 09:17:32.159 INFO memory.MemoryStore: Block broadcast_2_piece0 stored as bytes in memory (estimated size 3.7 KiB, free 1458.6 MiB)
2023-02-14 09:17:32.160 INFO storage.BlockManagerInfo: Added broadcast_2_piece0 in memory on 172.17.18.136:36651 (size: 3.7 KiB, free: 1458.6 MiB)
2023-02-14 09:17:32.160 INFO spark.SparkContext: Created broadcast 2 from broadcast at DAGScheduler.scala:1478
2023-02-14 09:17:32.161 INFO scheduler.DAGScheduler: Submitting 1 missing tasks from ResultStage 2 (MapPartitionsRDD[7] at collect at ExecuteStatement.scala:90) (first 15 tasks are for partitions Vector(0))
2023-02-14 09:17:32.161 INFO scheduler.TaskSchedulerImpl: Adding task set 2.0 with 1 tasks resource profile 0
2023-02-14 09:17:32.162 INFO scheduler.TaskSetManager: Starting task 0.0 in stage 2.0 (TID 2) (172.17.11.222, executor 1, partition 0, PROCESS_LOCAL, 4673 bytes) taskResourceAssignments Map()
2023-02-14 09:17:32.174 INFO storage.BlockManagerInfo: Added broadcast_2_piece0 in memory on 172.17.11.222:41311 (size: 3.7 KiB, free: 1007.8 MiB)
2023-02-14 09:17:32.184 INFO scheduler.TaskSetManager: Finished task 0.0 in stage 2.0 (TID 2) in 22 ms on 172.17.11.222 (executor 1) (1/1)
2023-02-14 09:17:32.185 INFO scheduler.TaskSchedulerImpl: Removed TaskSet 2.0, whose tasks have all completed, from pool 
2023-02-14 09:17:32.185 INFO scheduler.DAGScheduler: ResultStage 2 (collect at ExecuteStatement.scala:90) finished in 0.030 s
2023-02-14 09:17:32.185 INFO kyuubi.SQLOperationListener: Finished stage: Stage(2, 0); Name: 'collect at ExecuteStatement.scala:90'; Status: succeeded; numTasks: 1; Took: 30 msec
2023-02-14 09:17:32.185 INFO scheduler.DAGScheduler: Job 2 is finished. Cancelling potential speculative or zombie tasks for this job
2023-02-14 09:17:32.186 INFO scheduler.TaskSchedulerImpl: Killing all running tasks in stage 2: Stage finished
2023-02-14 09:17:32.186 INFO scheduler.DAGScheduler: Job 2 finished: collect at ExecuteStatement.scala:90, took 0.033929 s
2023-02-14 09:17:32.186 INFO scheduler.StatsReportListener: task runtime:(count: 1, mean: 22.000000, stdev: 0.000000, max: 22.000000, min: 22.000000)
2023-02-14 09:17:32.186 INFO scheduler.StatsReportListener:     0%  5%  10% 25% 50% 75% 90% 95% 100%
2023-02-14 09:17:32.186 INFO scheduler.StatsReportListener:     22.0 ms 22.0 ms 22.0 ms 22.0 ms 22.0 ms 22.0 ms 22.0 ms 22.0 ms 22.0 ms
2023-02-14 09:17:32.187 INFO scheduler.StatsReportListener: shuffle bytes written:(count: 1, mean: 0.000000, stdev: 0.000000, max: 0.000000, min: 0.000000)
2023-02-14 09:17:32.187 INFO scheduler.StatsReportListener:     0%  5%  10% 25% 50% 75% 90% 95% 100%
2023-02-14 09:17:32.187 INFO scheduler.StatsReportListener:     0.0 B   0.0 B   0.0 B   0.0 B   0.0 B   0.0 B   0.0 B   0.0 B   0.0 B
2023-02-14 09:17:32.188 INFO scheduler.StatsReportListener: fetch wait time:(count: 1, mean: 0.000000, stdev: 0.000000, max: 0.000000, min: 0.000000)
2023-02-14 09:17:32.188 INFO scheduler.StatsReportListener:     0%  5%  10% 25% 50% 75% 90% 95% 100%
2023-02-14 09:17:32.188 INFO scheduler.StatsReportListener:     0.0 ms  0.0 ms  0.0 ms  0.0 ms  0.0 ms  0.0 ms  0.0 ms  0.0 ms  0.0 ms
2023-02-14 09:17:32.188 INFO operation.ExecuteStatement: Processing as-ol.lysiuk's query[3c66872b-d715-4eef-99fb-25a4d70f543d]: RUNNING_STATE -> FINISHED_STATE, statement: SELECT current_database(), time taken: 0.068 seconds
2023-02-14 09:17:32.188 INFO scheduler.StatsReportListener: remote bytes read:(count: 1, mean: 0.000000, stdev: 0.000000, max: 0.000000, min: 0.000000)
2023-02-14 09:17:32.188 INFO scheduler.StatsReportListener:     0%  5%  10% 25% 50% 75% 90% 95% 100%
2023-02-14 09:17:32.189 INFO scheduler.StatsReportListener:     0.0 B   0.0 B   0.0 B   0.0 B   0.0 B   0.0 B   0.0 B   0.0 B   0.0 B
2023-02-14 09:17:32.189 INFO scheduler.StatsReportListener: task result size:(count: 1, mean: 1412.000000, stdev: 0.000000, max: 1412.000000, min: 1412.000000)
2023-02-14 09:17:32.189 INFO scheduler.StatsReportListener:     0%  5%  10% 25% 50% 75% 90% 95% 100%
2023-02-14 09:17:32.189 INFO scheduler.StatsReportListener:     1412.0 B    1412.0 B    1412.0 B    1412.0 B    1412.0 B    1412.0 B    1412.0 B    1412.0 B    1412.0 B
2023-02-14 09:17:32.190 INFO scheduler.StatsReportListener: executor (non-fetch) time pct: (count: 1, mean: 4.545455, stdev: 0.000000, max: 4.545455, min: 4.545455)
2023-02-14 09:17:32.190 INFO scheduler.StatsReportListener:     0%  5%  10% 25% 50% 75% 90% 95% 100%
2023-02-14 09:17:32.190 INFO scheduler.StatsReportListener:      5 %     5 %     5 %     5 %     5 %     5 %     5 %     5 %     5 %
2023-02-14 09:17:32.190 INFO scheduler.StatsReportListener: fetch wait time pct: (count: 1, mean: 0.000000, stdev: 0.000000, max: 0.000000, min: 0.000000)
2023-02-14 09:17:32.190 INFO scheduler.StatsReportListener:     0%  5%  10% 25% 50% 75% 90% 95% 100%
2023-02-14 09:17:32.191 INFO scheduler.StatsReportListener:      0 %     0 %     0 %     0 %     0 %     0 %     0 %     0 %     0 %
2023-02-14 09:17:32.191 INFO scheduler.StatsReportListener: other time pct: (count: 1, mean: 95.454545, stdev: 0.000000, max: 95.454545, min: 95.454545)
2023-02-14 09:17:32.191 INFO scheduler.StatsReportListener:     0%  5%  10% 25% 50% 75% 90% 95% 100%
2023-02-14 09:17:32.191 INFO scheduler.StatsReportListener:     95 %    95 %    95 %    95 %    95 %    95 %    95 %    95 %    95 %
2023-02-14 09:17:32.191 INFO kyuubi.SparkSQLEngineListener: Job end. Job 2 state is JobSucceeded
2023-02-14 09:17:32.191 INFO kyuubi.SQLOperationListener: Query [3c66872b-d715-4eef-99fb-25a4d70f543d]: Job 2 succeeded, 0 active jobs running
2023-02-14 09:17:32.411 INFO log.OperationLog: Creating operation log file /opt/kyuubi/work/engine_operation_logs/904407b1-8cf3-476f-a730-929eecc53a90/ec26d2e6-457a-4e59-a816-fc40a5dc896c
2023-02-14 09:17:32.411 INFO operation.ExecuteStatement: Processing as-ol.lysiuk's query[ec26d2e6-457a-4e59-a816-fc40a5dc896c]: INITIALIZED_STATE -> PENDING_STATE, statement: select
    filid,
    count(IF(is_hole = 0, NULL, is_hole)) * 1.0/count(*) as ratio
from dashboard_team_dbt.holes_main_all_lagers_mart
where
    report_day = '2023-02-14'
    and business_id = 1
group by filid
2023-02-14 09:17:32.412 INFO operation.ExecuteStatement: Processing as-ol.lysiuk's query[ec26d2e6-457a-4e59-a816-fc40a5dc896c]: PENDING_STATE -> RUNNING_STATE, statement: select
    filid,
    count(IF(is_hole = 0, NULL, is_hole)) * 1.0/count(*) as ratio
from dashboard_team_dbt.holes_main_all_lagers_mart
where
    report_day = '2023-02-14'
    and business_id = 1
group by filid
2023-02-14 09:17:32.413 INFO operation.ExecuteStatement: 
           Spark application name: kyuubi_CONNECTION_SPARK_SQL_as-ol.lysiuk_3a27bf56-0c1b-4d96-b82c-66389785e5b4
                 application ID: spark-application-1676359040353
                 application web UI: 
                 master: k8s://https://kubernetes.default.svc
                 deploy mode: client
                 version: 3.2.2
           Start time: 2023-02-14T09:17:18.966
           User: as-ol.lysiuk
2023-02-14 09:17:32.696 INFO storage.DelegatingLogStore: LogStore `LogStoreAdapter(io.delta.storage.S3SingleDriverLogStore)` is used for scheme `s3a`
2023-02-14 09:17:40.249 INFO delta.DeltaLog: Loading version 46 starting from checkpoint 40.
2023-02-14 09:17:40.292 INFO delta.Snapshot: [tableId=70d7a059-cb65-4839-96a7-d97ccebfb312] DELTA: Compute snapshot for version: 46
2023-02-14 09:17:40.422 INFO storage.BlockManagerInfo: Removed broadcast_0_piece0 on 172.17.18.136:36651 in memory (size: 3.6 KiB, free: 1458.6 MiB)
2023-02-14 09:17:40.426 INFO storage.BlockManagerInfo: Removed broadcast_0_piece0 on 172.17.11.222:41311 in memory (size: 3.6 KiB, free: 1007.8 MiB)
2023-02-14 09:17:40.437 INFO storage.BlockManagerInfo: Removed broadcast_1_piece0 on 172.17.18.136:36651 in memory (size: 3.7 KiB, free: 1458.6 MiB)
2023-02-14 09:17:40.438 INFO storage.BlockManagerInfo: Removed broadcast_1_piece0 on 172.17.11.222:41311 in memory (size: 3.7 KiB, free: 1007.8 MiB)
2023-02-14 09:17:40.444 INFO storage.BlockManagerInfo: Removed broadcast_2_piece0 on 172.17.18.136:36651 in memory (size: 3.7 KiB, free: 1458.6 MiB)
2023-02-14 09:17:40.445 INFO storage.BlockManagerInfo: Removed broadcast_2_piece0 on 172.17.11.222:41311 in memory (size: 3.7 KiB, free: 1007.8 MiB)
2023-02-14 09:17:40.492 INFO memory.MemoryStore: Block broadcast_3 stored as values in memory (estimated size 384.3 KiB, free 1458.2 MiB)
2023-02-14 09:17:40.512 INFO memory.MemoryStore: Block broadcast_3_piece0 stored as bytes in memory (estimated size 37.8 KiB, free 1458.2 MiB)
2023-02-14 09:17:40.513 INFO storage.BlockManagerInfo: Added broadcast_3_piece0 in memory on 172.17.18.136:36651 (size: 37.8 KiB, free: 1458.6 MiB)
2023-02-14 09:17:40.514 INFO spark.SparkContext: Created broadcast 3 from $anonfun$recordDeltaOperationInternal$1 at DatabricksLogging.scala:77
2023-02-14 09:17:40.538 INFO delta.DeltaLogFileIndex: Created DeltaLogFileIndex(Parquet, numFilesInSegment: 1, totalFileSize: 23620)
2023-02-14 09:17:40.541 INFO delta.DeltaLogFileIndex: Created DeltaLogFileIndex(JSON, numFilesInSegment: 6, totalFileSize: 14578)
2023-02-14 09:17:41.384 INFO datasources.FileSourceStrategy: Pushed Filters: 
2023-02-14 09:17:41.385 INFO datasources.FileSourceStrategy: Post-Scan Filters: 
2023-02-14 09:17:41.386 INFO datasources.FileSourceStrategy: Output Data Schema: struct<txn: struct<appId: string, version: bigint, lastUpdated: bigint ... 1 more fields>, add: struct<path: string, partitionValues: map<string,string>, size: bigint, modificationTime: bigint, dataChange: boolean ... 5 more fields>, remove: struct<path: string, deletionTimestamp: bigint, dataChange: boolean, extendedFileMetadata: boolean, partitionValues: map<string,string> ... 5 more fields>, metaData: struct<id: string, name: string, description: string, format: struct<provider: string, options: map<string,string>>, schemaString: string ... 6 more fields>, protocol: struct<minReaderVersion: int, minWriterVersion: int> ... 5 more fields>
2023-02-14 09:17:41.391 INFO datasources.FileSourceStrategy: Pushed Filters: 
2023-02-14 09:17:41.392 INFO datasources.FileSourceStrategy: Post-Scan Filters: 
2023-02-14 09:17:41.392 INFO datasources.FileSourceStrategy: Output Data Schema: struct<txn: struct<appId: string, version: bigint, lastUpdated: bigint ... 1 more fields>, add: struct<path: string, partitionValues: map<string,string>, size: bigint, modificationTime: bigint, dataChange: boolean ... 5 more fields>, remove: struct<path: string, deletionTimestamp: bigint, dataChange: boolean, extendedFileMetadata: boolean, partitionValues: map<string,string> ... 5 more fields>, metaData: struct<id: string, name: string, description: string, format: struct<provider: string, options: map<string,string>>, schemaString: string ... 6 more fields>, protocol: struct<minReaderVersion: int, minWriterVersion: int> ... 5 more fields>
2023-02-14 09:17:41.615 INFO codegen.CodeGenerator: Code generated in 133.471575 ms
2023-02-14 09:17:41.633 INFO memory.MemoryStore: Block broadcast_4 stored as values in memory (estimated size 408.7 KiB, free 1457.8 MiB)
2023-02-14 09:17:41.642 INFO memory.MemoryStore: Block broadcast_4_piece0 stored as bytes in memory (estimated size 40.3 KiB, free 1457.7 MiB)
2023-02-14 09:17:41.643 INFO storage.BlockManagerInfo: Added broadcast_4_piece0 in memory on 172.17.18.136:36651 (size: 40.3 KiB, free: 1458.5 MiB)
2023-02-14 09:17:41.645 INFO spark.SparkContext: Created broadcast 4 from $anonfun$recordDeltaOperationInternal$1 at DatabricksLogging.scala:77
2023-02-14 09:17:41.655 INFO execution.FileSourceScanExec: Planning scan with bin packing, max size: 4194304 bytes, open cost is considered as scanning 4194304 bytes.
2023-02-14 09:17:41.669 INFO memory.MemoryStore: Block broadcast_5 stored as values in memory (estimated size 384.3 KiB, free 1457.4 MiB)
2023-02-14 09:17:41.678 INFO memory.MemoryStore: Block broadcast_5_piece0 stored as bytes in memory (estimated size 37.8 KiB, free 1457.3 MiB)
2023-02-14 09:17:41.678 INFO storage.BlockManagerInfo: Added broadcast_5_piece0 in memory on 172.17.18.136:36651 (size: 37.8 KiB, free: 1458.5 MiB)
2023-02-14 09:17:41.680 INFO spark.SparkContext: Created broadcast 5 from $anonfun$recordDeltaOperationInternal$1 at DatabricksLogging.scala:77
2023-02-14 09:17:41.693 INFO execution.FileSourceScanExec: Planning scan with bin packing, max size: 12590201 bytes, open cost is considered as scanning 4194304 bytes.
2023-02-14 09:17:41.760 INFO scheduler.DAGScheduler: Registering RDD 14 ($anonfun$recordDeltaOperationInternal$1 at DatabricksLogging.scala:77) as input to shuffle 0
2023-02-14 09:17:41.764 INFO scheduler.DAGScheduler: Got map stage job 3 ($anonfun$recordDeltaOperationInternal$1 at DatabricksLogging.scala:77) with 3 output partitions
2023-02-14 09:17:41.765 INFO scheduler.DAGScheduler: Final stage: ShuffleMapStage 3 ($anonfun$recordDeltaOperationInternal$1 at DatabricksLogging.scala:77)
2023-02-14 09:17:41.765 INFO scheduler.DAGScheduler: Parents of final stage: List()
2023-02-14 09:17:41.765 INFO scheduler.DAGScheduler: Missing parents: List()
2023-02-14 09:17:41.767 INFO kyuubi.SQLOperationListener: Query [ec26d2e6-457a-4e59-a816-fc40a5dc896c]: Job 3 started with 1 stages, 1 active jobs running
2023-02-14 09:17:41.767 INFO scheduler.DAGScheduler: Submitting ShuffleMapStage 3 (MapPartitionsRDD[14] at $anonfun$recordDeltaOperationInternal$1 at DatabricksLogging.scala:77), which has no missing parents
2023-02-14 09:17:41.771 INFO kyuubi.SQLOperationListener: Query [ec26d2e6-457a-4e59-a816-fc40a5dc896c]: Stage 3 started with 3 tasks, 1 active stages running
2023-02-14 09:17:41.815 INFO memory.MemoryStore: Block broadcast_6 stored as values in memory (estimated size 125.5 KiB, free 1457.2 MiB)
2023-02-14 09:17:41.816 INFO memory.MemoryStore: Block broadcast_6_piece0 stored as bytes in memory (estimated size 35.7 KiB, free 1457.2 MiB)
2023-02-14 09:17:41.817 INFO storage.BlockManagerInfo: Added broadcast_6_piece0 in memory on 172.17.18.136:36651 (size: 35.7 KiB, free: 1458.5 MiB)
2023-02-14 09:17:41.817 INFO spark.SparkContext: Created broadcast 6 from broadcast at DAGScheduler.scala:1478
2023-02-14 09:17:41.818 INFO scheduler.DAGScheduler: Submitting 3 missing tasks from ShuffleMapStage 3 (MapPartitionsRDD[14] at $anonfun$recordDeltaOperationInternal$1 at DatabricksLogging.scala:77) (first 15 tasks are for partitions Vector(0, 1, 2))
2023-02-14 09:17:41.819 INFO scheduler.TaskSchedulerImpl: Adding task set 3.0 with 3 tasks resource profile 0
2023-02-14 09:17:41.822 INFO scheduler.TaskSetManager: Starting task 0.0 in stage 3.0 (TID 3) (172.17.11.222, executor 1, partition 0, PROCESS_LOCAL, 5050 bytes) taskResourceAssignments Map()
2023-02-14 09:17:41.838 INFO storage.BlockManagerInfo: Added broadcast_6_piece0 in memory on 172.17.11.222:41311 (size: 35.7 KiB, free: 1007.8 MiB)
2023-02-14 09:17:43.289 INFO storage.BlockManagerInfo: Added broadcast_4_piece0 in memory on 172.17.11.222:41311 (size: 40.3 KiB, free: 1007.8 MiB)
2023-02-14 09:17:44.844 INFO k8s.ExecutorPodsAllocator: Going to request 1 executors from Kubernetes for ResourceProfile Id: 0, target: 2, known: 1, sharedSlotFromPendingPods: 1.
2023-02-14 09:17:44.845 INFO spark.ExecutorAllocationManager: Requesting 1 new executor because tasks are backlogged (new desired total will be 2 for resource profile id: 0)
2023-02-14 09:17:44.846 INFO submit.KubernetesClientUtils: Spark configuration files loaded from Some(/opt/spark/conf) : hive-site.xml,metrics.properties
2023-02-14 09:17:44.848 INFO features.BasicExecutorFeatureStep: Adding decommission script to lifecycle
2023-02-14 09:17:47.617 INFO storage.BlockManagerInfo: Added broadcast_3_piece0 in memory on 172.17.11.222:41311 (size: 37.8 KiB, free: 1007.7 MiB)
2023-02-14 09:17:47.798 INFO scheduler.TaskSetManager: Starting task 1.0 in stage 3.0 (TID 4) (172.17.11.222, executor 1, partition 1, PROCESS_LOCAL, 5298 bytes) taskResourceAssignments Map()
2023-02-14 09:17:47.801 INFO scheduler.TaskSetManager: Finished task 0.0 in stage 3.0 (TID 3) in 5982 ms on 172.17.11.222 (executor 1) (1/3)
2023-02-14 09:17:47.986 INFO storage.BlockManagerInfo: Added broadcast_5_piece0 in memory on 172.17.11.222:41311 (size: 37.8 KiB, free: 1007.7 MiB)
2023-02-14 09:17:48.265 INFO scheduler.TaskSetManager: Starting task 2.0 in stage 3.0 (TID 5) (172.17.11.222, executor 1, partition 2, PROCESS_LOCAL, 5298 bytes) taskResourceAssignments Map()
2023-02-14 09:17:48.265 INFO scheduler.TaskSetManager: Finished task 1.0 in stage 3.0 (TID 4) in 467 ms on 172.17.11.222 (executor 1) (2/3)
2023-02-14 09:17:48.496 INFO scheduler.TaskSetManager: Finished task 2.0 in stage 3.0 (TID 5) in 232 ms on 172.17.11.222 (executor 1) (3/3)
2023-02-14 09:17:48.496 INFO scheduler.TaskSchedulerImpl: Removed TaskSet 3.0, whose tasks have all completed, from pool 
2023-02-14 09:17:48.496 INFO scheduler.DAGScheduler: ShuffleMapStage 3 ($anonfun$recordDeltaOperationInternal$1 at DatabricksLogging.scala:77) finished in 6.725 s
2023-02-14 09:17:48.497 INFO kyuubi.SQLOperationListener: Finished stage: Stage(3, 0); Name: '$anonfun$recordDeltaOperationInternal$1 at DatabricksLogging.scala:77'; Status: succeeded; numTasks: 3; Took: 6726 msec
2023-02-14 09:17:48.497 INFO scheduler.DAGScheduler: looking for newly runnable stages
2023-02-14 09:17:48.497 INFO scheduler.StatsReportListener: task runtime:(count: 3, mean: 2227.000000, stdev: 2656.918641, max: 5982.000000, min: 232.000000)
2023-02-14 09:17:48.497 INFO scheduler.StatsReportListener:     0%  5%  10% 25% 50% 75% 90% 95% 100%
2023-02-14 09:17:48.497 INFO scheduler.DAGScheduler: running: Set()
2023-02-14 09:17:48.497 INFO scheduler.StatsReportListener:     232.0 ms    232.0 ms    232.0 ms    232.0 ms    467.0 ms    6.0 s   6.0 s   6.0 s   6.0 s
2023-02-14 09:17:48.498 INFO scheduler.DAGScheduler: waiting: Set()
2023-02-14 09:17:48.498 INFO scheduler.DAGScheduler: failed: Set()
2023-02-14 09:17:48.498 INFO scheduler.StatsReportListener: shuffle bytes written:(count: 3, mean: 7530.000000, stdev: 4632.617475, max: 14077.000000, min: 4046.000000)
2023-02-14 09:17:48.499 INFO scheduler.StatsReportListener:     0%  5%  10% 25% 50% 75% 90% 95% 100%
2023-02-14 09:17:48.499 INFO scheduler.StatsReportListener:     4.0 KiB 4.0 KiB 4.0 KiB 4.0 KiB 4.4 KiB 13.7 KiB    13.7 KiB    13.7 KiB    13.7 KiB
2023-02-14 09:17:48.499 INFO scheduler.StatsReportListener: fetch wait time:(count: 3, mean: 0.000000, stdev: 0.000000, max: 0.000000, min: 0.000000)
2023-02-14 09:17:48.499 INFO scheduler.StatsReportListener:     0%  5%  10% 25% 50% 75% 90% 95% 100%
2023-02-14 09:17:48.499 INFO scheduler.StatsReportListener:     0.0 ms  0.0 ms  0.0 ms  0.0 ms  0.0 ms  0.0 ms  0.0 ms  0.0 ms  0.0 ms
2023-02-14 09:17:48.499 INFO scheduler.StatsReportListener: remote bytes read:(count: 3, mean: 0.000000, stdev: 0.000000, max: 0.000000, min: 0.000000)
2023-02-14 09:17:48.500 INFO scheduler.StatsReportListener:     0%  5%  10% 25% 50% 75% 90% 95% 100%
2023-02-14 09:17:48.500 INFO scheduler.StatsReportListener:     0.0 B   0.0 B   0.0 B   0.0 B   0.0 B   0.0 B   0.0 B   0.0 B   0.0 B
2023-02-14 09:17:48.500 INFO scheduler.StatsReportListener: task result size:(count: 3, mean: 2135.666667, stdev: 20.270394, max: 2150.000000, min: 2107.000000)
2023-02-14 09:17:48.500 INFO scheduler.StatsReportListener:     0%  5%  10% 25% 50% 75% 90% 95% 100%
2023-02-14 09:17:48.500 INFO scheduler.StatsReportListener:     2.1 KiB 2.1 KiB 2.1 KiB 2.1 KiB 2.1 KiB 2.1 KiB 2.1 KiB 2.1 KiB 2.1 KiB
2023-02-14 09:17:48.501 INFO scheduler.StatsReportListener: executor (non-fetch) time pct: (count: 3, mean: 95.406401, stdev: 1.605933, max: 97.216274, min: 93.313273)
2023-02-14 09:17:48.501 INFO scheduler.StatsReportListener:     0%  5%  10% 25% 50% 75% 90% 95% 100%
2023-02-14 09:17:48.501 INFO scheduler.StatsReportListener:     93 %    93 %    93 %    93 %    96 %    97 %    97 %    97 %    97 %
2023-02-14 09:17:48.501 INFO scheduler.StatsReportListener: fetch wait time pct: (count: 3, mean: 0.000000, stdev: 0.000000, max: 0.000000, min: 0.000000)
2023-02-14 09:17:48.501 INFO scheduler.StatsReportListener:     0%  5%  10% 25% 50% 75% 90% 95% 100%
2023-02-14 09:17:48.501 INFO scheduler.StatsReportListener:      0 %     0 %     0 %     0 %     0 %     0 %     0 %     0 %     0 %
2023-02-14 09:17:48.502 INFO scheduler.StatsReportListener: other time pct: (count: 3, mean: 4.593599, stdev: 1.605933, max: 6.686727, min: 2.783726)
2023-02-14 09:17:48.502 INFO scheduler.StatsReportListener:     0%  5%  10% 25% 50% 75% 90% 95% 100%
2023-02-14 09:17:48.502 INFO scheduler.StatsReportListener:      3 %     3 %     3 %     3 %     4 %     7 %     7 %     7 %     7 %
2023-02-14 09:17:48.503 INFO kyuubi.SparkSQLEngineListener: Job end. Job 3 state is JobSucceeded
2023-02-14 09:17:48.503 INFO kyuubi.SQLOperationListener: Query [ec26d2e6-457a-4e59-a816-fc40a5dc896c]: Job 3 succeeded, 0 active jobs running
2023-02-14 09:17:48.616 INFO storage.BlockManagerInfo: Removed broadcast_6_piece0 on 172.17.18.136:36651 in memory (size: 35.7 KiB, free: 1458.5 MiB)
2023-02-14 09:17:48.617 INFO storage.BlockManagerInfo: Removed broadcast_6_piece0 on 172.17.11.222:41311 in memory (size: 35.7 KiB, free: 1007.7 MiB)
2023-02-14 09:17:48.733 INFO codegen.CodeGenerator: Generated method too long to be JIT compiled: org.apache.spark.sql.catalyst.expressions.GeneratedClass$GeneratedIteratorForCodegenStage3.serializefromobject_doConsume_0$ is 14899 bytes
2023-02-14 09:17:48.734 INFO codegen.CodeGenerator: Code generated in 112.479496 ms
2023-02-14 09:17:48.788 INFO codegen.CodeGenerator: Code generated in 36.253439 ms
2023-02-14 09:17:48.989 INFO k8s.KubernetesClusterSchedulerBackend$KubernetesDriverEndpoint: Registered executor NettyRpcEndpointRef(spark-client://Executor) (172.17.14.122:47336) with ID 2,  ResourceProfileId 0
2023-02-14 09:17:48.989 INFO dynalloc.ExecutorMonitor: New executor 2 has registered (new total is 3)
2023-02-14 09:17:49.088 INFO codegen.CodeGenerator: Code generated in 31.016594 ms
2023-02-14 09:17:49.098 INFO scheduler.DAGScheduler: Registering RDD 24 ($anonfun$recordDeltaOperationInternal$1 at DatabricksLogging.scala:77) as input to shuffle 1
2023-02-14 09:17:49.099 INFO scheduler.DAGScheduler: Got map stage job 4 ($anonfun$recordDeltaOperationInternal$1 at DatabricksLogging.scala:77) with 50 output partitions
2023-02-14 09:17:49.099 INFO scheduler.DAGScheduler: Final stage: ShuffleMapStage 5 ($anonfun$recordDeltaOperationInternal$1 at DatabricksLogging.scala:77)
2023-02-14 09:17:49.099 INFO scheduler.DAGScheduler: Parents of final stage: List(ShuffleMapStage 4)
2023-02-14 09:17:49.101 INFO scheduler.DAGScheduler: Missing parents: List()
2023-02-14 09:17:49.102 INFO kyuubi.SQLOperationListener: Query [ec26d2e6-457a-4e59-a816-fc40a5dc896c]: Job 4 started with 2 stages, 1 active jobs running
2023-02-14 09:17:49.102 INFO scheduler.DAGScheduler: Submitting ShuffleMapStage 5 (MapPartitionsRDD[24] at $anonfun$recordDeltaOperationInternal$1 at DatabricksLogging.scala:77), which has no missing parents
2023-02-14 09:17:49.114 INFO kyuubi.SQLOperationListener: Query [ec26d2e6-457a-4e59-a816-fc40a5dc896c]: Stage 5 started with 50 tasks, 1 active stages running
2023-02-14 09:17:49.156 INFO storage.BlockManagerMasterEndpoint: Registering block manager 172.17.14.122:42947 with 1007.8 MiB RAM, BlockManagerId(2, 172.17.14.122, 42947, None)
2023-02-14 09:17:49.182 INFO memory.MemoryStore: Block broadcast_7 stored as values in memory (estimated size 422.3 KiB, free 1456.9 MiB)
2023-02-14 09:17:49.184 INFO memory.MemoryStore: Block broadcast_7_piece0 stored as bytes in memory (estimated size 104.0 KiB, free 1456.8 MiB)
2023-02-14 09:17:49.185 INFO storage.BlockManagerInfo: Added broadcast_7_piece0 in memory on 172.17.18.136:36651 (size: 104.0 KiB, free: 1458.4 MiB)
2023-02-14 09:17:49.185 INFO spark.SparkContext: Created broadcast 7 from broadcast at DAGScheduler.scala:1478
2023-02-14 09:17:49.186 INFO scheduler.DAGScheduler: Submitting 50 missing tasks from ShuffleMapStage 5 (MapPartitionsRDD[24] at $anonfun$recordDeltaOperationInternal$1 at DatabricksLogging.scala:77) (first 15 tasks are for partitions Vector(0, 1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14))
2023-02-14 09:17:49.186 INFO scheduler.TaskSchedulerImpl: Adding task set 5.0 with 50 tasks resource profile 0
2023-02-14 09:17:49.193 INFO scheduler.TaskSetManager: Starting task 0.0 in stage 5.0 (TID 6) (172.17.11.222, executor 1, partition 0, NODE_LOCAL, 4454 bytes) taskResourceAssignments Map()
2023-02-14 09:17:49.205 INFO storage.BlockManagerInfo: Added broadcast_7_piece0 in memory on 172.17.11.222:41311 (size: 104.0 KiB, free: 1007.6 MiB)
2023-02-14 09:17:49.285 INFO scheduler.TaskSetManager: Starting task 1.0 in stage 5.0 (TID 7) (172.17.14.122, executor 2, partition 1, PROCESS_LOCAL, 4454 bytes) taskResourceAssignments Map()
2023-02-14 09:17:49.445 INFO spark.MapOutputTrackerMasterEndpoint: Asked to send map output locations for shuffle 0 to 172.17.11.222:43108
2023-02-14 09:17:49.591 INFO storage.BlockManagerInfo: Added broadcast_7_piece0 in memory on 172.17.14.122:42947 (size: 104.0 KiB, free: 1007.7 MiB)
2023-02-14 09:17:50.316 INFO storage.BlockManagerInfo: Added rdd_21_0 in memory on 172.17.11.222:41311 (size: 454.0 B, free: 1007.6 MiB)
2023-02-14 09:17:50.716 INFO scheduler.TaskSetManager: Starting task 4.0 in stage 5.0 (TID 8) (172.17.11.222, executor 1, partition 4, NODE_LOCAL, 4454 bytes) taskResourceAssignments Map()
2023-02-14 09:17:50.716 INFO scheduler.TaskSetManager: Finished task 0.0 in stage 5.0 (TID 6) in 1525 ms on 172.17.11.222 (executor 1) (1/50)
2023-02-14 09:17:50.757 INFO spark.MapOutputTrackerMasterEndpoint: Asked to send map output locations for shuffle 0 to 172.17.14.122:47336
2023-02-14 09:17:50.817 INFO storage.BlockManagerInfo: Added rdd_21_4 in memory on 172.17.11.222:41311 (size: 1532.0 B, free: 1007.6 MiB)
2023-02-14 09:17:50.898 INFO scheduler.TaskSetManager: Starting task 5.0 in stage 5.0 (TID 9) (172.17.11.222, executor 1, partition 5, NODE_LOCAL, 4454 bytes) taskResourceAssignments Map()
2023-02-14 09:17:50.898 INFO scheduler.TaskSetManager: Finished task 4.0 in stage 5.0 (TID 8) in 183 ms on 172.17.11.222 (executor 1) (2/50)
2023-02-14 09:17:50.999 INFO storage.BlockManagerInfo: Added rdd_21_5 in memory on 172.17.11.222:41311 (size: 1587.0 B, free: 1007.6 MiB)
2023-02-14 09:17:51.022 INFO scheduler.TaskSetManager: Starting task 8.0 in stage 5.0 (TID 10) (172.17.11.222, executor 1, partition 8, NODE_LOCAL, 4454 bytes) taskResourceAssignments Map()
2023-02-14 09:17:51.022 INFO scheduler.TaskSetManager: Finished task 5.0 in stage 5.0 (TID 9) in 124 ms on 172.17.11.222 (executor 1) (3/50)
2023-02-14 09:17:51.114 INFO storage.BlockManagerInfo: Added rdd_21_8 in memory on 172.17.11.222:41311 (size: 1208.0 B, free: 1007.6 MiB)
2023-02-14 09:17:51.188 INFO scheduler.TaskSetManager: Starting task 13.0 in stage 5.0 (TID 11) (172.17.11.222, executor 1, partition 13, NODE_LOCAL, 4454 bytes) taskResourceAssignments Map()
2023-02-14 09:17:51.188 INFO scheduler.TaskSetManager: Finished task 8.0 in stage 5.0 (TID 10) in 166 ms on 172.17.11.222 (executor 1) (4/50)
2023-02-14 09:17:51.287 INFO storage.BlockManagerInfo: Added rdd_21_13 in memory on 172.17.11.222:41311 (size: 1587.0 B, free: 1007.6 MiB)
2023-02-14 09:17:51.309 INFO scheduler.TaskSetManager: Starting task 15.0 in stage 5.0 (TID 12) (172.17.11.222, executor 1, partition 15, NODE_LOCAL, 4454 bytes) taskResourceAssignments Map()
2023-02-14 09:17:51.309 INFO scheduler.TaskSetManager: Finished task 13.0 in stage 5.0 (TID 11) in 121 ms on 172.17.11.222 (executor 1) (5/50)
2023-02-14 09:17:51.403 INFO storage.BlockManagerInfo: Added rdd_21_15 in memory on 172.17.11.222:41311 (size: 1587.0 B, free: 1007.6 MiB)
2023-02-14 09:17:51.485 INFO scheduler.TaskSetManager: Starting task 16.0 in stage 5.0 (TID 13) (172.17.11.222, executor 1, partition 16, NODE_LOCAL, 4454 bytes) taskResourceAssignments Map()
2023-02-14 09:17:51.485 INFO scheduler.TaskSetManager: Finished task 15.0 in stage 5.0 (TID 12) in 176 ms on 172.17.11.222 (executor 1) (6/50)
2023-02-14 09:17:51.520 INFO storage.BlockManagerInfo: Added rdd_21_16 in memory on 172.17.11.222:41311 (size: 1208.0 B, free: 1007.6 MiB)
2023-02-14 09:17:51.595 INFO scheduler.TaskSetManager: Starting task 19.0 in stage 5.0 (TID 14) (172.17.11.222, executor 1, partition 19, NODE_LOCAL, 4454 bytes) taskResourceAssignments Map()
2023-02-14 09:17:51.596 INFO scheduler.TaskSetManager: Finished task 16.0 in stage 5.0 (TID 13) in 112 ms on 172.17.11.222 (executor 1) (7/50)
2023-02-14 09:17:51.686 INFO storage.BlockManagerInfo: Added rdd_21_19 in memory on 172.17.11.222:41311 (size: 1208.0 B, free: 1007.6 MiB)
2023-02-14 09:17:51.703 INFO scheduler.TaskSetManager: Starting task 22.0 in stage 5.0 (TID 15) (172.17.11.222, executor 1, partition 22, NODE_LOCAL, 4454 bytes) taskResourceAssignments Map()
2023-02-14 09:17:51.703 INFO scheduler.TaskSetManager: Finished task 19.0 in stage 5.0 (TID 14) in 108 ms on 172.17.11.222 (executor 1) (8/50)
2023-02-14 09:17:51.790 INFO storage.BlockManagerInfo: Added rdd_21_22 in memory on 172.17.11.222:41311 (size: 1579.0 B, free: 1007.6 MiB)
2023-02-14 09:17:51.806 INFO scheduler.TaskSetManager: Starting task 23.0 in stage 5.0 (TID 16) (172.17.11.222, executor 1, partition 23, NODE_LOCAL, 4454 bytes) taskResourceAssignments Map()
2023-02-14 09:17:51.806 INFO scheduler.TaskSetManager: Finished task 22.0 in stage 5.0 (TID 15) in 103 ms on 172.17.11.222 (executor 1) (9/50)
2023-02-14 09:17:51.890 INFO storage.BlockManagerInfo: Added rdd_21_23 in memory on 172.17.11.222:41311 (size: 1208.0 B, free: 1007.6 MiB)
2023-02-14 09:17:51.907 INFO scheduler.TaskSetManager: Starting task 26.0 in stage 5.0 (TID 17) (172.17.11.222, executor 1, partition 26, NODE_LOCAL, 4454 bytes) taskResourceAssignments Map()
2023-02-14 09:17:51.907 INFO scheduler.TaskSetManager: Finished task 23.0 in stage 5.0 (TID 16) in 101 ms on 172.17.11.222 (executor 1) (10/50)
2023-02-14 09:17:51.990 INFO storage.BlockManagerInfo: Added rdd_21_26 in memory on 172.17.11.222:41311 (size: 1208.0 B, free: 1007.6 MiB)
2023-02-14 09:17:52.003 INFO scheduler.TaskSetManager: Starting task 27.0 in stage 5.0 (TID 18) (172.17.11.222, executor 1, partition 27, NODE_LOCAL, 4454 bytes) taskResourceAssignments Map()
2023-02-14 09:17:52.004 INFO scheduler.TaskSetManager: Finished task 26.0 in stage 5.0 (TID 17) in 98 ms on 172.17.11.222 (executor 1) (11/50)
2023-02-14 09:17:52.085 INFO storage.BlockManagerInfo: Added rdd_21_27 in memory on 172.17.11.222:41311 (size: 1579.0 B, free: 1007.6 MiB)
2023-02-14 09:17:52.098 INFO scheduler.TaskSetManager: Starting task 30.0 in stage 5.0 (TID 19) (172.17.11.222, executor 1, partition 30, NODE_LOCAL, 4454 bytes) taskResourceAssignments Map()
2023-02-14 09:17:52.098 INFO scheduler.TaskSetManager: Finished task 27.0 in stage 5.0 (TID 18) in 95 ms on 172.17.11.222 (executor 1) (12/50)
2023-02-14 09:17:52.167 INFO spark.ExecutorAllocationManager: Requesting 2 new executors because tasks are backlogged (new desired total will be 3 for resource profile id: 0)
2023-02-14 09:17:52.168 INFO k8s.ExecutorPodsAllocator: Going to request 1 executors from Kubernetes for ResourceProfile Id: 0, target: 3, known: 2, sharedSlotFromPendingPods: 1.
2023-02-14 09:17:52.169 INFO submit.KubernetesClientUtils: Spark configuration files loaded from Some(/opt/spark/conf) : hive-site.xml,metrics.properties
2023-02-14 09:17:52.170 INFO features.BasicExecutorFeatureStep: Adding decommission script to lifecycle
2023-02-14 09:17:52.178 INFO storage.BlockManagerInfo: Added rdd_21_30 in memory on 172.17.11.222:41311 (size: 1587.0 B, free: 1007.6 MiB)
2023-02-14 09:17:52.191 INFO scheduler.TaskSetManager: Starting task 31.0 in stage 5.0 (TID 20) (172.17.11.222, executor 1, partition 31, NODE_LOCAL, 4454 bytes) taskResourceAssignments Map()
2023-02-14 09:17:52.191 INFO scheduler.TaskSetManager: Finished task 30.0 in stage 5.0 (TID 19) in 93 ms on 172.17.11.222 (executor 1) (13/50)
2023-02-14 09:17:52.214 INFO storage.BlockManagerInfo: Added rdd_21_31 in memory on 172.17.11.222:41311 (size: 1208.0 B, free: 1007.6 MiB)
2023-02-14 09:17:52.281 INFO scheduler.TaskSetManager: Starting task 32.0 in stage 5.0 (TID 21) (172.17.11.222, executor 1, partition 32, NODE_LOCAL, 4454 bytes) taskResourceAssignments Map()
2023-02-14 09:17:52.281 INFO scheduler.TaskSetManager: Finished task 31.0 in stage 5.0 (TID 20) in 91 ms on 172.17.11.222 (executor 1) (14/50)
2023-02-14 09:17:52.324 INFO storage.BlockManagerInfo: Added rdd_21_32 in memory on 172.17.11.222:41311 (size: 1579.0 B, free: 1007.6 MiB)
2023-02-14 09:17:52.383 INFO scheduler.TaskSetManager: Starting task 34.0 in stage 5.0 (TID 22) (172.17.11.222, executor 1, partition 34, NODE_LOCAL, 4454 bytes) taskResourceAssignments Map()
2023-02-14 09:17:52.383 INFO scheduler.TaskSetManager: Finished task 32.0 in stage 5.0 (TID 21) in 102 ms on 172.17.11.222 (executor 1) (15/50)
2023-02-14 09:17:52.409 INFO storage.BlockManagerInfo: Added rdd_21_34 in memory on 172.17.11.222:41311 (size: 1208.0 B, free: 1007.6 MiB)
2023-02-14 09:17:52.421 INFO scheduler.TaskSetManager: Starting task 35.0 in stage 5.0 (TID 23) (172.17.11.222, executor 1, partition 35, NODE_LOCAL, 4454 bytes) taskResourceAssignments Map()
2023-02-14 09:17:52.422 INFO scheduler.TaskSetManager: Finished task 34.0 in stage 5.0 (TID 22) in 39 ms on 172.17.11.222 (executor 1) (16/50)
2023-02-14 09:17:52.498 INFO storage.BlockManagerInfo: Added rdd_21_35 in memory on 172.17.11.222:41311 (size: 1208.0 B, free: 1007.6 MiB)
2023-02-14 09:17:52.509 INFO scheduler.TaskSetManager: Starting task 37.0 in stage 5.0 (TID 24) (172.17.11.222, executor 1, partition 37, NODE_LOCAL, 4454 bytes) taskResourceAssignments Map()
2023-02-14 09:17:52.509 INFO scheduler.TaskSetManager: Finished task 35.0 in stage 5.0 (TID 23) in 88 ms on 172.17.11.222 (executor 1) (17/50)
2023-02-14 09:17:52.586 INFO storage.BlockManagerInfo: Added rdd_21_37 in memory on 172.17.11.222:41311 (size: 1919.0 B, free: 1007.6 MiB)
2023-02-14 09:17:52.598 INFO scheduler.TaskSetManager: Starting task 40.0 in stage 5.0 (TID 25) (172.17.11.222, executor 1, partition 40, NODE_LOCAL, 4454 bytes) taskResourceAssignments Map()
2023-02-14 09:17:52.598 INFO scheduler.TaskSetManager: Finished task 37.0 in stage 5.0 (TID 24) in 89 ms on 172.17.11.222 (executor 1) (18/50)
2023-02-14 09:17:52.621 INFO storage.BlockManagerInfo: Added rdd_21_40 in memory on 172.17.11.222:41311 (size: 4.0 B, free: 1007.6 MiB)
2023-02-14 09:17:52.686 INFO scheduler.TaskSetManager: Starting task 42.0 in stage 5.0 (TID 26) (172.17.11.222, executor 1, partition 42, NODE_LOCAL, 4454 bytes) taskResourceAssignments Map()
2023-02-14 09:17:52.686 INFO scheduler.TaskSetManager: Finished task 40.0 in stage 5.0 (TID 25) in 88 ms on 172.17.11.222 (executor 1) (19/50)
2023-02-14 09:17:53.000 INFO storage.BlockManagerInfo: Added rdd_21_42 in memory on 172.17.11.222:41311 (size: 1924.0 B, free: 1007.6 MiB)
2023-02-14 09:17:53.012 INFO scheduler.TaskSetManager: Starting task 43.0 in stage 5.0 (TID 27) (172.17.11.222, executor 1, partition 43, NODE_LOCAL, 4454 bytes) taskResourceAssignments Map()
2023-02-14 09:17:53.013 INFO scheduler.TaskSetManager: Finished task 42.0 in stage 5.0 (TID 26) in 327 ms on 172.17.11.222 (executor 1) (20/50)
2023-02-14 09:17:53.097 INFO storage.BlockManagerInfo: Added rdd_21_43 in memory on 172.17.11.222:41311 (size: 454.0 B, free: 1007.6 MiB)
2023-02-14 09:17:53.108 INFO scheduler.TaskSetManager: Starting task 44.0 in stage 5.0 (TID 28) (172.17.11.222, executor 1, partition 44, NODE_LOCAL, 4454 bytes) taskResourceAssignments Map()
2023-02-14 09:17:53.108 INFO scheduler.TaskSetManager: Finished task 43.0 in stage 5.0 (TID 27) in 96 ms on 172.17.11.222 (executor 1) (21/50)
2023-02-14 09:17:53.182 INFO storage.BlockManagerInfo: Added rdd_21_44 in memory on 172.17.11.222:41311 (size: 1208.0 B, free: 1007.6 MiB)
2023-02-14 09:17:53.193 INFO scheduler.TaskSetManager: Starting task 45.0 in stage 5.0 (TID 29) (172.17.11.222, executor 1, partition 45, NODE_LOCAL, 4454 bytes) taskResourceAssignments Map()
2023-02-14 09:17:53.194 INFO scheduler.TaskSetManager: Finished task 44.0 in stage 5.0 (TID 28) in 87 ms on 172.17.11.222 (executor 1) (22/50)
2023-02-14 09:17:53.216 INFO storage.BlockManagerInfo: Added rdd_21_45 in memory on 172.17.11.222:41311 (size: 1208.0 B, free: 1007.6 MiB)
2023-02-14 09:17:53.279 INFO scheduler.TaskSetManager: Starting task 46.0 in stage 5.0 (TID 30) (172.17.11.222, executor 1, partition 46, NODE_LOCAL, 4454 bytes) taskResourceAssignments Map()
2023-02-14 09:17:53.280 INFO scheduler.TaskSetManager: Finished task 45.0 in stage 5.0 (TID 29) in 86 ms on 172.17.11.222 (executor 1) (23/50)
2023-02-14 09:17:53.302 INFO storage.BlockManagerInfo: Added rdd_21_46 in memory on 172.17.11.222:41311 (size: 1208.0 B, free: 1007.6 MiB)
2023-02-14 09:17:53.313 INFO scheduler.TaskSetManager: Starting task 2.0 in stage 5.0 (TID 31) (172.17.11.222, executor 1, partition 2, PROCESS_LOCAL, 4454 bytes) taskResourceAssignments Map()
2023-02-14 09:17:53.314 INFO scheduler.TaskSetManager: Finished task 46.0 in stage 5.0 (TID 30) in 35 ms on 172.17.11.222 (executor 1) (24/50)
2023-02-14 09:17:53.393 INFO storage.BlockManagerInfo: Added rdd_21_2 in memory on 172.17.11.222:41311 (size: 4.0 B, free: 1007.6 MiB)
2023-02-14 09:17:53.404 INFO scheduler.TaskSetManager: Starting task 3.0 in stage 5.0 (TID 32) (172.17.11.222, executor 1, partition 3, PROCESS_LOCAL, 4454 bytes) taskResourceAssignments Map()
2023-02-14 09:17:53.405 INFO scheduler.TaskSetManager: Finished task 2.0 in stage 5.0 (TID 31) in 92 ms on 172.17.11.222 (executor 1) (25/50)
2023-02-14 09:17:53.481 INFO storage.BlockManagerInfo: Added rdd_21_3 in memory on 172.17.11.222:41311 (size: 4.0 B, free: 1007.6 MiB)
2023-02-14 09:17:53.493 INFO scheduler.TaskSetManager: Starting task 6.0 in stage 5.0 (TID 33) (172.17.11.222, executor 1, partition 6, PROCESS_LOCAL, 4454 bytes) taskResourceAssignments Map()
2023-02-14 09:17:53.493 INFO scheduler.TaskSetManager: Finished task 3.0 in stage 5.0 (TID 32) in 89 ms on 172.17.11.222 (executor 1) (26/50)
2023-02-14 09:17:53.513 INFO storage.BlockManagerInfo: Added rdd_21_6 in memory on 172.17.11.222:41311 (size: 4.0 B, free: 1007.6 MiB)
2023-02-14 09:17:53.580 INFO scheduler.TaskSetManager: Starting task 7.0 in stage 5.0 (TID 34) (172.17.11.222, executor 1, partition 7, PROCESS_LOCAL, 4454 bytes) taskResourceAssignments Map()
2023-02-14 09:17:53.580 INFO scheduler.TaskSetManager: Finished task 6.0 in stage 5.0 (TID 33) in 88 ms on 172.17.11.222 (executor 1) (27/50)
2023-02-14 09:17:53.601 INFO storage.BlockManagerInfo: Added rdd_21_7 in memory on 172.17.11.222:41311 (size: 4.0 B, free: 1007.6 MiB)
2023-02-14 09:17:53.611 INFO scheduler.TaskSetManager: Starting task 9.0 in stage 5.0 (TID 35) (172.17.11.222, executor 1, partition 9, PROCESS_LOCAL, 4454 bytes) taskResourceAssignments Map()
2023-02-14 09:17:53.612 INFO scheduler.TaskSetManager: Finished task 7.0 in stage 5.0 (TID 34) in 32 ms on 172.17.11.222 (executor 1) (28/50)
2023-02-14 09:17:53.684 INFO storage.BlockManagerInfo: Added rdd_21_9 in memory on 172.17.11.222:41311 (size: 4.0 B, free: 1007.6 MiB)
2023-02-14 09:17:53.695 INFO scheduler.TaskSetManager: Starting task 10.0 in stage 5.0 (TID 36) (172.17.11.222, executor 1, partition 10, PROCESS_LOCAL, 4454 bytes) taskResourceAssignments Map()
2023-02-14 09:17:53.696 INFO scheduler.TaskSetManager: Finished task 9.0 in stage 5.0 (TID 35) in 85 ms on 172.17.11.222 (executor 1) (29/50)
2023-02-14 09:17:53.716 INFO storage.BlockManagerInfo: Added rdd_21_10 in memory on 172.17.11.222:41311 (size: 4.0 B, free: 1007.6 MiB)
2023-02-14 09:17:53.783 INFO scheduler.TaskSetManager: Starting task 11.0 in stage 5.0 (TID 37) (172.17.11.222, executor 1, partition 11, PROCESS_LOCAL, 4454 bytes) taskResourceAssignments Map()
2023-02-14 09:17:53.783 INFO scheduler.TaskSetManager: Finished task 10.0 in stage 5.0 (TID 36) in 88 ms on 172.17.11.222 (executor 1) (30/50)
2023-02-14 09:17:53.804 INFO storage.BlockManagerInfo: Added rdd_21_11 in memory on 172.17.11.222:41311 (size: 4.0 B, free: 1007.6 MiB)
2023-02-14 09:17:53.815 INFO scheduler.TaskSetManager: Starting task 12.0 in stage 5.0 (TID 38) (172.17.11.222, executor 1, partition 12, PROCESS_LOCAL, 4454 bytes) taskResourceAssignments Map()
2023-02-14 09:17:53.816 INFO scheduler.TaskSetManager: Finished task 11.0 in stage 5.0 (TID 37) in 33 ms on 172.17.11.222 (executor 1) (31/50)
2023-02-14 09:17:53.889 INFO storage.BlockManagerInfo: Added rdd_21_12 in memory on 172.17.11.222:41311 (size: 4.0 B, free: 1007.6 MiB)
2023-02-14 09:17:53.900 INFO scheduler.TaskSetManager: Starting task 14.0 in stage 5.0 (TID 39) (172.17.11.222, executor 1, partition 14, PROCESS_LOCAL, 4454 bytes) taskResourceAssignments Map()
2023-02-14 09:17:53.900 INFO scheduler.TaskSetManager: Finished task 12.0 in stage 5.0 (TID 38) in 85 ms on 172.17.11.222 (executor 1) (32/50)
2023-02-14 09:17:53.978 INFO storage.BlockManagerInfo: Added rdd_21_14 in memory on 172.17.11.222:41311 (size: 4.0 B, free: 1007.6 MiB)
2023-02-14 09:17:53.989 INFO scheduler.TaskSetManager: Starting task 17.0 in stage 5.0 (TID 40) (172.17.11.222, executor 1, partition 17, PROCESS_LOCAL, 4454 bytes) taskResourceAssignments Map()
2023-02-14 09:17:53.989 INFO scheduler.TaskSetManager: Finished task 14.0 in stage 5.0 (TID 39) in 89 ms on 172.17.11.222 (executor 1) (33/50)
2023-02-14 09:17:54.009 INFO storage.BlockManagerInfo: Added rdd_21_17 in memory on 172.17.11.222:41311 (size: 4.0 B, free: 1007.6 MiB)
2023-02-14 09:17:54.020 INFO scheduler.TaskSetManager: Starting task 18.0 in stage 5.0 (TID 41) (172.17.11.222, executor 1, partition 18, PROCESS_LOCAL, 4454 bytes) taskResourceAssignments Map()
2023-02-14 09:17:54.020 INFO scheduler.TaskSetManager: Finished task 17.0 in stage 5.0 (TID 40) in 31 ms on 172.17.11.222 (executor 1) (34/50)
2023-02-14 09:17:54.112 INFO storage.BlockManagerInfo: Added rdd_21_18 in memory on 172.17.11.222:41311 (size: 4.0 B, free: 1007.6 MiB)
2023-02-14 09:17:54.123 INFO scheduler.TaskSetManager: Starting task 20.0 in stage 5.0 (TID 42) (172.17.11.222, executor 1, partition 20, PROCESS_LOCAL, 4454 bytes) taskResourceAssignments Map()
2023-02-14 09:17:54.123 INFO scheduler.TaskSetManager: Finished task 18.0 in stage 5.0 (TID 41) in 103 ms on 172.17.11.222 (executor 1) (35/50)
2023-02-14 09:17:54.188 INFO storage.BlockManagerInfo: Added rdd_21_20 in memory on 172.17.11.222:41311 (size: 4.0 B, free: 1007.6 MiB)
2023-02-14 09:17:54.199 INFO scheduler.TaskSetManager: Starting task 21.0 in stage 5.0 (TID 43) (172.17.11.222, executor 1, partition 21, PROCESS_LOCAL, 4454 bytes) taskResourceAssignments Map()
2023-02-14 09:17:54.199 INFO scheduler.TaskSetManager: Finished task 20.0 in stage 5.0 (TID 42) in 76 ms on 172.17.11.222 (executor 1) (36/50)
2023-02-14 09:17:54.219 INFO storage.BlockManagerInfo: Added rdd_21_21 in memory on 172.17.11.222:41311 (size: 4.0 B, free: 1007.6 MiB)
2023-02-14 09:17:54.283 INFO scheduler.TaskSetManager: Starting task 24.0 in stage 5.0 (TID 44) (172.17.11.222, executor 1, partition 24, PROCESS_LOCAL, 4454 bytes) taskResourceAssignments Map()
2023-02-14 09:17:54.283 INFO scheduler.TaskSetManager: Finished task 21.0 in stage 5.0 (TID 43) in 85 ms on 172.17.11.222 (executor 1) (37/50)
2023-02-14 09:17:54.303 INFO storage.BlockManagerInfo: Added rdd_21_24 in memory on 172.17.11.222:41311 (size: 4.0 B, free: 1007.6 MiB)
2023-02-14 09:17:54.313 INFO scheduler.TaskSetManager: Starting task 25.0 in stage 5.0 (TID 45) (172.17.11.222, executor 1, partition 25, PROCESS_LOCAL, 4454 bytes) taskResourceAssignments Map()
2023-02-14 09:17:54.313 INFO scheduler.TaskSetManager: Finished task 24.0 in stage 5.0 (TID 44) in 31 ms on 172.17.11.222 (executor 1) (38/50)
2023-02-14 09:17:54.383 INFO storage.BlockManagerInfo: Added rdd_21_25 in memory on 172.17.11.222:41311 (size: 4.0 B, free: 1007.6 MiB)
2023-02-14 09:17:54.393 INFO scheduler.TaskSetManager: Starting task 28.0 in stage 5.0 (TID 46) (172.17.11.222, executor 1, partition 28, PROCESS_LOCAL, 4454 bytes) taskResourceAssignments Map()
2023-02-14 09:17:54.393 INFO scheduler.TaskSetManager: Finished task 25.0 in stage 5.0 (TID 45) in 80 ms on 172.17.11.222 (executor 1) (39/50)
2023-02-14 09:17:54.414 INFO storage.BlockManagerInfo: Added rdd_21_28 in memory on 172.17.11.222:41311 (size: 4.0 B, free: 1007.6 MiB)
2023-02-14 09:17:54.480 INFO scheduler.TaskSetManager: Starting task 29.0 in stage 5.0 (TID 47) (172.17.11.222, executor 1, partition 29, PROCESS_LOCAL, 4454 bytes) taskResourceAssignments Map()
2023-02-14 09:17:54.480 INFO scheduler.TaskSetManager: Finished task 28.0 in stage 5.0 (TID 46) in 87 ms on 172.17.11.222 (executor 1) (40/50)
2023-02-14 09:17:54.501 INFO storage.BlockManagerInfo: Added rdd_21_29 in memory on 172.17.11.222:41311 (size: 4.0 B, free: 1007.6 MiB)
2023-02-14 09:17:54.511 INFO scheduler.TaskSetManager: Starting task 33.0 in stage 5.0 (TID 48) (172.17.11.222, executor 1, partition 33, PROCESS_LOCAL, 4454 bytes) taskResourceAssignments Map()
2023-02-14 09:17:54.511 INFO scheduler.TaskSetManager: Finished task 29.0 in stage 5.0 (TID 47) in 31 ms on 172.17.11.222 (executor 1) (41/50)
2023-02-14 09:17:54.586 INFO storage.BlockManagerInfo: Added rdd_21_33 in memory on 172.17.11.222:41311 (size: 4.0 B, free: 1007.6 MiB)
2023-02-14 09:17:54.599 INFO scheduler.TaskSetManager: Starting task 36.0 in stage 5.0 (TID 49) (172.17.11.222, executor 1, partition 36, PROCESS_LOCAL, 4454 bytes) taskResourceAssignments Map()
2023-02-14 09:17:54.599 INFO scheduler.TaskSetManager: Finished task 33.0 in stage 5.0 (TID 48) in 88 ms on 172.17.11.222 (executor 1) (42/50)
2023-02-14 09:17:54.621 INFO storage.BlockManagerInfo: Added rdd_21_36 in memory on 172.17.11.222:41311 (size: 4.0 B, free: 1007.6 MiB)
2023-02-14 09:17:54.685 INFO scheduler.TaskSetManager: Starting task 38.0 in stage 5.0 (TID 50) (172.17.11.222, executor 1, partition 38, PROCESS_LOCAL, 4454 bytes) taskResourceAssignments Map()
2023-02-14 09:17:54.685 INFO scheduler.TaskSetManager: Finished task 36.0 in stage 5.0 (TID 49) in 87 ms on 172.17.11.222 (executor 1) (43/50)
2023-02-14 09:17:54.704 INFO storage.BlockManagerInfo: Added rdd_21_38 in memory on 172.17.11.222:41311 (size: 4.0 B, free: 1007.6 MiB)
2023-02-14 09:17:54.714 INFO scheduler.TaskSetManager: Starting task 39.0 in stage 5.0 (TID 51) (172.17.11.222, executor 1, partition 39, PROCESS_LOCAL, 4454 bytes) taskResourceAssignments Map()
2023-02-14 09:17:54.714 INFO scheduler.TaskSetManager: Finished task 38.0 in stage 5.0 (TID 50) in 30 ms on 172.17.11.222 (executor 1) (44/50)
2023-02-14 09:17:54.776 INFO storage.BlockManagerInfo: Added rdd_21_1 in memory on 172.17.14.122:42947 (size: 4.0 B, free: 1007.7 MiB)
2023-02-14 09:17:54.786 INFO storage.BlockManagerInfo: Added rdd_21_39 in memory on 172.17.11.222:41311 (size: 4.0 B, free: 1007.6 MiB)
2023-02-14 09:17:54.796 INFO scheduler.TaskSetManager: Starting task 41.0 in stage 5.0 (TID 52) (172.17.11.222, executor 1, partition 41, PROCESS_LOCAL, 4454 bytes) taskResourceAssignments Map()
2023-02-14 09:17:54.797 INFO scheduler.TaskSetManager: Finished task 39.0 in stage 5.0 (TID 51) in 83 ms on 172.17.11.222 (executor 1) (45/50)
2023-02-14 09:17:54.817 INFO storage.BlockManagerInfo: Added rdd_21_41 in memory on 172.17.11.222:41311 (size: 4.0 B, free: 1007.6 MiB)
2023-02-14 09:17:54.878 INFO scheduler.TaskSetManager: Starting task 47.0 in stage 5.0 (TID 53) (172.17.11.222, executor 1, partition 47, PROCESS_LOCAL, 4454 bytes) taskResourceAssignments Map()
2023-02-14 09:17:54.879 INFO scheduler.TaskSetManager: Finished task 41.0 in stage 5.0 (TID 52) in 83 ms on 172.17.11.222 (executor 1) (46/50)
2023-02-14 09:17:54.898 INFO storage.BlockManagerInfo: Added rdd_21_47 in memory on 172.17.11.222:41311 (size: 4.0 B, free: 1007.6 MiB)
2023-02-14 09:17:54.908 INFO scheduler.TaskSetManager: Starting task 48.0 in stage 5.0 (TID 54) (172.17.11.222, executor 1, partition 48, PROCESS_LOCAL, 4454 bytes) taskResourceAssignments Map()
2023-02-14 09:17:54.908 INFO scheduler.TaskSetManager: Finished task 47.0 in stage 5.0 (TID 53) in 30 ms on 172.17.11.222 (executor 1) (47/50)
2023-02-14 09:17:54.983 INFO storage.BlockManagerInfo: Added rdd_21_48 in memory on 172.17.11.222:41311 (size: 4.0 B, free: 1007.6 MiB)
2023-02-14 09:17:54.993 INFO scheduler.TaskSetManager: Starting task 49.0 in stage 5.0 (TID 55) (172.17.11.222, executor 1, partition 49, PROCESS_LOCAL, 4454 bytes) taskResourceAssignments Map()
2023-02-14 09:17:54.994 INFO scheduler.TaskSetManager: Finished task 48.0 in stage 5.0 (TID 54) in 86 ms on 172.17.11.222 (executor 1) (48/50)
2023-02-14 09:17:55.013 INFO storage.BlockManagerInfo: Added rdd_21_49 in memory on 172.17.11.222:41311 (size: 4.0 B, free: 1007.6 MiB)
2023-02-14 09:17:55.023 INFO scheduler.TaskSetManager: Finished task 49.0 in stage 5.0 (TID 55) in 30 ms on 172.17.11.222 (executor 1) (49/50)
2023-02-14 09:17:55.370 INFO scheduler.TaskSetManager: Finished task 1.0 in stage 5.0 (TID 7) in 6085 ms on 172.17.14.122 (executor 2) (50/50)
2023-02-14 09:17:55.370 INFO scheduler.TaskSchedulerImpl: Removed TaskSet 5.0, whose tasks have all completed, from pool 
2023-02-14 09:17:55.370 INFO scheduler.DAGScheduler: ShuffleMapStage 5 ($anonfun$recordDeltaOperationInternal$1 at DatabricksLogging.scala:77) finished in 6.256 s
2023-02-14 09:17:55.371 INFO scheduler.DAGScheduler: looking for newly runnable stages
2023-02-14 09:17:55.371 INFO scheduler.DAGScheduler: running: Set()
2023-02-14 09:17:55.371 INFO scheduler.DAGScheduler: waiting: Set()
2023-02-14 09:17:55.371 INFO scheduler.DAGScheduler: failed: Set()
2023-02-14 09:17:55.371 INFO kyuubi.SQLOperationListener: Finished stage: Stage(5, 0); Name: '$anonfun$recordDeltaOperationInternal$1 at DatabricksLogging.scala:77'; Status: succeeded; numTasks: 50; Took: 6257 msec
2023-02-14 09:17:55.372 INFO scheduler.StatsReportListener: task runtime:(count: 50, mean: 238.800000, stdev: 860.323985, max: 6085.000000, min: 30.000000)
2023-02-14 09:17:55.372 INFO scheduler.StatsReportListener:     0%  5%  10% 25% 50% 75% 90% 95% 100%
2023-02-14 09:17:55.372 INFO scheduler.StatsReportListener:     30.0 ms 30.0 ms 31.0 ms 83.0 ms 88.0 ms 102.0 ms    176.0 ms    327.0 ms    6.1 s
2023-02-14 09:17:55.372 INFO scheduler.StatsReportListener: shuffle bytes written:(count: 50, mean: 98.840000, stdev: 79.519899, max: 653.000000, min: 81.000000)
2023-02-14 09:17:55.372 INFO scheduler.StatsReportListener:     0%  5%  10% 25% 50% 75% 90% 95% 100%
2023-02-14 09:17:55.372 INFO scheduler.StatsReportListener:     81.0 B  81.0 B  81.0 B  81.0 B  81.0 B  96.0 B  96.0 B  101.0 B 653.0 B
2023-02-14 09:17:55.373 INFO scheduler.StatsReportListener: fetch wait time:(count: 50, mean: 0.000000, stdev: 0.000000, max: 0.000000, min: 0.000000)
2023-02-14 09:17:55.373 INFO scheduler.StatsReportListener:     0%  5%  10% 25% 50% 75% 90% 95% 100%
2023-02-14 09:17:55.373 INFO scheduler.StatsReportListener:     0.0 ms  0.0 ms  0.0 ms  0.0 ms  0.0 ms  0.0 ms  0.0 ms  0.0 ms  0.0 ms
2023-02-14 09:17:55.373 INFO scheduler.StatsReportListener: remote bytes read:(count: 50, mean: 0.000000, stdev: 0.000000, max: 0.000000, min: 0.000000)
2023-02-14 09:17:55.373 INFO scheduler.StatsReportListener:     0%  5%  10% 25% 50% 75% 90% 95% 100%
2023-02-14 09:17:55.373 INFO scheduler.StatsReportListener:     0.0 B   0.0 B   0.0 B   0.0 B   0.0 B   0.0 B   0.0 B   0.0 B   0.0 B
2023-02-14 09:17:55.374 INFO scheduler.StatsReportListener: task result size:(count: 50, mean: 4051.440000, stdev: 11.665608, max: 4091.000000, min: 4048.000000)
2023-02-14 09:17:55.374 INFO scheduler.StatsReportListener:     0%  5%  10% 25% 50% 75% 90% 95% 100%
2023-02-14 09:17:55.374 INFO scheduler.StatsReportListener:     4.0 KiB 4.0 KiB 4.0 KiB 4.0 KiB 4.0 KiB 4.0 KiB 4.0 KiB 4.0 KiB 4.0 KiB
2023-02-14 09:17:55.375 INFO scheduler.StatsReportListener: executor (non-fetch) time pct: (count: 50, mean: 78.828141, stdev: 18.409124, max: 96.941896, min: 26.041667)
2023-02-14 09:17:55.375 INFO scheduler.StatsReportListener:     0%  5%  10% 25% 50% 75% 90% 95% 100%
2023-02-14 09:17:55.375 INFO scheduler.StatsReportListener:     26 %    28 %    60 %    73 %    89 %    90 %    91 %    91 %    97 %
2023-02-14 09:17:55.375 INFO scheduler.StatsReportListener: fetch wait time pct: (count: 50, mean: 0.000000, stdev: 0.000000, max: 0.000000, min: 0.000000)
2023-02-14 09:17:55.375 INFO scheduler.StatsReportListener:     0%  5%  10% 25% 50% 75% 90% 95% 100%
2023-02-14 09:17:55.375 INFO scheduler.StatsReportListener:      0 %     0 %     0 %     0 %     0 %     0 %     0 %     0 %     0 %
2023-02-14 09:17:55.375 INFO scheduler.StatsReportListener: other time pct: (count: 50, mean: 21.171859, stdev: 18.409124, max: 73.958333, min: 3.058104)
2023-02-14 09:17:55.375 INFO scheduler.StatsReportListener:     0%  5%  10% 25% 50% 75% 90% 95% 100%
2023-02-14 09:17:55.375 INFO scheduler.StatsReportListener:      3 %     9 %     9 %    10 %    11 %    27 %    61 %    72 %    74 %
2023-02-14 09:17:55.375 INFO kyuubi.SparkSQLEngineListener: Job end. Job 4 state is JobSucceeded
2023-02-14 09:17:55.376 INFO kyuubi.SQLOperationListener: Query [ec26d2e6-457a-4e59-a816-fc40a5dc896c]: Job 4 succeeded, 0 active jobs running
2023-02-14 09:17:55.408 INFO spark.SparkContext: Starting job: $anonfun$recordDeltaOperationInternal$1 at DatabricksLogging.scala:77
2023-02-14 09:17:55.410 INFO scheduler.DAGScheduler: Got job 5 ($anonfun$recordDeltaOperationInternal$1 at DatabricksLogging.scala:77) with 1 output partitions
2023-02-14 09:17:55.410 INFO scheduler.DAGScheduler: Final stage: ResultStage 8 ($anonfun$recordDeltaOperationInternal$1 at DatabricksLogging.scala:77)
2023-02-14 09:17:55.410 INFO scheduler.DAGScheduler: Parents of final stage: List(ShuffleMapStage 7)
2023-02-14 09:17:55.410 INFO scheduler.DAGScheduler: Missing parents: List()
2023-02-14 09:17:55.411 INFO kyuubi.SQLOperationListener: Query [ec26d2e6-457a-4e59-a816-fc40a5dc896c]: Job 5 started with 3 stages, 1 active jobs running
2023-02-14 09:17:55.411 INFO scheduler.DAGScheduler: Submitting ResultStage 8 (MapPartitionsRDD[27] at $anonfun$recordDeltaOperationInternal$1 at DatabricksLogging.scala:77), which has no missing parents
2023-02-14 09:17:55.414 INFO kyuubi.SQLOperationListener: Query [ec26d2e6-457a-4e59-a816-fc40a5dc896c]: Stage 8 started with 1 tasks, 1 active stages running
2023-02-14 09:17:55.421 INFO memory.MemoryStore: Block broadcast_8 stored as values in memory (estimated size 367.7 KiB, free 1456.5 MiB)
2023-02-14 09:17:55.425 INFO memory.MemoryStore: Block broadcast_8_piece0 stored as bytes in memory (estimated size 92.5 KiB, free 1456.4 MiB)
2023-02-14 09:17:55.426 INFO storage.BlockManagerInfo: Added broadcast_8_piece0 in memory on 172.17.18.136:36651 (size: 92.5 KiB, free: 1458.3 MiB)
2023-02-14 09:17:55.426 INFO spark.SparkContext: Created broadcast 8 from broadcast at DAGScheduler.scala:1478
2023-02-14 09:17:55.426 INFO scheduler.DAGScheduler: Submitting 1 missing tasks from ResultStage 8 (MapPartitionsRDD[27] at $anonfun$recordDeltaOperationInternal$1 at DatabricksLogging.scala:77) (first 15 tasks are for partitions Vector(0))
2023-02-14 09:17:55.427 INFO scheduler.TaskSchedulerImpl: Adding task set 8.0 with 1 tasks resource profile 0
2023-02-14 09:17:55.428 INFO scheduler.TaskSetManager: Starting task 0.0 in stage 8.0 (TID 56) (172.17.11.222, executor 1, partition 0, NODE_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:17:55.435 INFO storage.BlockManagerInfo: Added broadcast_8_piece0 in memory on 172.17.11.222:41311 (size: 92.5 KiB, free: 1007.5 MiB)
2023-02-14 09:17:55.443 INFO spark.MapOutputTrackerMasterEndpoint: Asked to send map output locations for shuffle 1 to 172.17.11.222:43108
2023-02-14 09:17:55.494 INFO scheduler.TaskSetManager: Finished task 0.0 in stage 8.0 (TID 56) in 66 ms on 172.17.11.222 (executor 1) (1/1)
2023-02-14 09:17:55.494 INFO scheduler.TaskSchedulerImpl: Removed TaskSet 8.0, whose tasks have all completed, from pool 
2023-02-14 09:17:55.494 INFO scheduler.DAGScheduler: ResultStage 8 ($anonfun$recordDeltaOperationInternal$1 at DatabricksLogging.scala:77) finished in 0.081 s
2023-02-14 09:17:55.495 INFO kyuubi.SQLOperationListener: Finished stage: Stage(8, 0); Name: '$anonfun$recordDeltaOperationInternal$1 at DatabricksLogging.scala:77'; Status: succeeded; numTasks: 1; Took: 81 msec
2023-02-14 09:17:55.495 INFO scheduler.DAGScheduler: Job 5 is finished. Cancelling potential speculative or zombie tasks for this job
2023-02-14 09:17:55.495 INFO scheduler.TaskSchedulerImpl: Killing all running tasks in stage 8: Stage finished
2023-02-14 09:17:55.495 INFO scheduler.DAGScheduler: Job 5 finished: $anonfun$recordDeltaOperationInternal$1 at DatabricksLogging.scala:77, took 0.086689 s
2023-02-14 09:17:55.495 INFO scheduler.StatsReportListener: task runtime:(count: 1, mean: 66.000000, stdev: 0.000000, max: 66.000000, min: 66.000000)
2023-02-14 09:17:55.495 INFO scheduler.StatsReportListener:     0%  5%  10% 25% 50% 75% 90% 95% 100%
2023-02-14 09:17:55.495 INFO scheduler.StatsReportListener:     66.0 ms 66.0 ms 66.0 ms 66.0 ms 66.0 ms 66.0 ms 66.0 ms 66.0 ms 66.0 ms
2023-02-14 09:17:55.495 INFO scheduler.StatsReportListener: shuffle bytes written:(count: 1, mean: 0.000000, stdev: 0.000000, max: 0.000000, min: 0.000000)
2023-02-14 09:17:55.496 INFO scheduler.StatsReportListener:     0%  5%  10% 25% 50% 75% 90% 95% 100%
2023-02-14 09:17:55.496 INFO scheduler.StatsReportListener:     0.0 B   0.0 B   0.0 B   0.0 B   0.0 B   0.0 B   0.0 B   0.0 B   0.0 B
2023-02-14 09:17:55.496 INFO scheduler.StatsReportListener: fetch wait time:(count: 1, mean: 0.000000, stdev: 0.000000, max: 0.000000, min: 0.000000)
2023-02-14 09:17:55.496 INFO scheduler.StatsReportListener:     0%  5%  10% 25% 50% 75% 90% 95% 100%
2023-02-14 09:17:55.496 INFO scheduler.StatsReportListener:     0.0 ms  0.0 ms  0.0 ms  0.0 ms  0.0 ms  0.0 ms  0.0 ms  0.0 ms  0.0 ms
2023-02-14 09:17:55.496 INFO scheduler.StatsReportListener: remote bytes read:(count: 1, mean: 81.000000, stdev: 0.000000, max: 81.000000, min: 81.000000)
2023-02-14 09:17:55.496 INFO scheduler.StatsReportListener:     0%  5%  10% 25% 50% 75% 90% 95% 100%
2023-02-14 09:17:55.496 INFO scheduler.StatsReportListener:     81.0 B  81.0 B  81.0 B  81.0 B  81.0 B  81.0 B  81.0 B  81.0 B  81.0 B
2023-02-14 09:17:55.497 INFO scheduler.StatsReportListener: task result size:(count: 1, mean: 5312.000000, stdev: 0.000000, max: 5312.000000, min: 5312.000000)
2023-02-14 09:17:55.497 INFO scheduler.StatsReportListener:     0%  5%  10% 25% 50% 75% 90% 95% 100%
2023-02-14 09:17:55.497 INFO scheduler.StatsReportListener:     5.2 KiB 5.2 KiB 5.2 KiB 5.2 KiB 5.2 KiB 5.2 KiB 5.2 KiB 5.2 KiB 5.2 KiB
2023-02-14 09:17:55.497 INFO scheduler.StatsReportListener: executor (non-fetch) time pct: (count: 1, mean: 74.242424, stdev: 0.000000, max: 74.242424, min: 74.242424)
2023-02-14 09:17:55.497 INFO scheduler.StatsReportListener:     0%  5%  10% 25% 50% 75% 90% 95% 100%
2023-02-14 09:17:55.497 INFO scheduler.StatsReportListener:     74 %    74 %    74 %    74 %    74 %    74 %    74 %    74 %    74 %
2023-02-14 09:17:55.497 INFO scheduler.StatsReportListener: fetch wait time pct: (count: 1, mean: 0.000000, stdev: 0.000000, max: 0.000000, min: 0.000000)
2023-02-14 09:17:55.497 INFO scheduler.StatsReportListener:     0%  5%  10% 25% 50% 75% 90% 95% 100%
2023-02-14 09:17:55.497 INFO scheduler.StatsReportListener:      0 %     0 %     0 %     0 %     0 %     0 %     0 %     0 %     0 %
2023-02-14 09:17:55.498 INFO scheduler.StatsReportListener: other time pct: (count: 1, mean: 25.757576, stdev: 0.000000, max: 25.757576, min: 25.757576)
2023-02-14 09:17:55.498 INFO scheduler.StatsReportListener:     0%  5%  10% 25% 50% 75% 90% 95% 100%
2023-02-14 09:17:55.498 INFO scheduler.StatsReportListener:     26 %    26 %    26 %    26 %    26 %    26 %    26 %    26 %    26 %
2023-02-14 09:17:55.498 INFO kyuubi.SparkSQLEngineListener: Job end. Job 5 state is JobSucceeded
2023-02-14 09:17:55.498 INFO kyuubi.SQLOperationListener: Query [ec26d2e6-457a-4e59-a816-fc40a5dc896c]: Job 5 succeeded, 0 active jobs running
2023-02-14 09:17:55.530 INFO codegen.CodeGenerator: Code generated in 22.686021 ms
2023-02-14 09:17:55.534 INFO delta.Snapshot: [tableId=a124aa70-c56e-42c8-bbab-1b34ad17a9d2] DELTA: Done
2023-02-14 09:17:55.537 INFO delta.Snapshot: [tableId=b0261329-a817-46c4-b21d-bc42f72266c5] Created snapshot Snapshot(path=s3a://warehouse/dashboard_team_dbt.db/holes_main_all_lagers_mart/_delta_log, version=46, metadata=Metadata(e8e99a47-de1b-40a5-b41e-e450b8b8b287,null,null,Format(parquet,Map()),{"type":"struct","fields":[{"name":"report_day","type":"string","nullable":true,"metadata":{}},{"name":"business_id","type":"integer","nullable":true,"metadata":{"scale":0}},{"name":"filid","type":"integer","nullable":true,"metadata":{"scale":0}},{"name":"lagerid","type":"integer","nullable":true,"metadata":{"scale":0}},{"name":"date_active_from","type":"date","nullable":true,"metadata":{}},{"name":"stores_next_day","type":"decimal(27,7)","nullable":true,"metadata":{}},{"name":"stores_report_day","type":"decimal(27,7)","nullable":true,"metadata":{}},{"name":"stores_hour16","type":"decimal(28,7)","nullable":true,"metadata":{}},{"name":"sales_prev_day","type":"decimal(38,3)","nullable":true,"metadata":{}},{"name":"sales_report_day","type":"decimal(38,3)","nullable":true,"metadata":{}},{"name":"msp","type":"decimal(22,0)","nullable":true,"metadata":{}},{"name":"is_hole","type":"integer","nullable":true,"metadata":{}},{"name":"sales_28days","type":"decimal(22,7)","nullable":true,"metadata":{}},{"name":"limit_hole","type":"decimal(18,3)","nullable":true,"metadata":{}},{"name":"forecast","type":"decimal(18,5)","nullable":true,"metadata":{}},{"name":"min_count","type":"decimal(26,8)","nullable":true,"metadata":{}},{"name":"price","type":"decimal(18,5)","nullable":true,"metadata":{}},{"name":"lost_sales","type":"decimal(38,6)","nullable":true,"metadata":{}}]},List(report_day),Map(),Some(1674751487046)), logSegment=LogSegment(s3a://warehouse/dashboard_team_dbt.db/holes_main_all_lagers_mart/_delta_log,46,WrappedArray(S3AFileStatus{path=s3a://warehouse/dashboard_team_dbt.db/holes_main_all_lagers_mart/_delta_log/00000000000000000041.json; isDirectory=false; length=2386; replication=1; blocksize=33554432; modification_time=1676186519711; access_time=0; owner=as-ol.lysiuk; group=as-ol.lysiuk; permission=rw-rw-rw-; isSymlink=false; hasAcl=false; isEncrypted=true; isErasureCoded=false} isEmptyDirectory=FALSE eTag=6cffa241bcc607eeb125fff191d54b66 versionId=null, S3AFileStatus{path=s3a://warehouse/dashboard_team_dbt.db/holes_main_all_lagers_mart/_delta_log/00000000000000000042.json; isDirectory=false; length=2389; replication=1; blocksize=33554432; modification_time=1676191886988; access_time=0; owner=as-ol.lysiuk; group=as-ol.lysiuk; permission=rw-rw-rw-; isSymlink=false; hasAcl=false; isEncrypted=true; isErasureCoded=false} isEmptyDirectory=FALSE eTag=f6fcad38eaea20b223ce7ee99ecd18f3 versionId=null, S3AFileStatus{path=s3a://warehouse/dashboard_team_dbt.db/holes_main_all_lagers_mart/_delta_log/00000000000000000043.json; isDirectory=false; length=2388; replication=1; blocksize=33554432; modification_time=1676196779308; access_time=0; owner=as-ol.lysiuk; group=as-ol.lysiuk; permission=rw-rw-rw-; isSymlink=false; hasAcl=false; isEncrypted=true; isErasureCoded=false} isEmptyDirectory=FALSE eTag=9e3642f81af3a5324ccc972bdc1ee977 versionId=null, S3AFileStatus{path=s3a://warehouse/dashboard_team_dbt.db/holes_main_all_lagers_mart/_delta_log/00000000000000000044.json; isDirectory=false; length=2646; replication=1; blocksize=33554432; modification_time=1676216447776; access_time=0; owner=as-ol.lysiuk; group=as-ol.lysiuk; permission=rw-rw-rw-; isSymlink=false; hasAcl=false; isEncrypted=true; isErasureCoded=false} isEmptyDirectory=FALSE eTag=95c8d5aafefc13c6398204030f82a3d5 versionId=null, S3AFileStatus{path=s3a://warehouse/dashboard_team_dbt.db/holes_main_all_lagers_mart/_delta_log/00000000000000000045.json; isDirectory=false; length=2382; replication=1; blocksize=33554432; modification_time=1676270091871; access_time=0; owner=as-ol.lysiuk; group=as-ol.lysiuk; permission=rw-rw-rw-; isSymlink=false; hasAcl=false; isEncrypted=true; isErasureCoded=false} isEmptyDirectory=FALSE eTag=49f371bb10cd63043e70d68da796fe2c versionId=null, S3AFileStatus{path=s3a://warehouse/dashboard_team_dbt.db/holes_main_all_lagers_mart/_delta_log/00000000000000000046.json; isDirectory=false; length=2387; replication=1; blocksize=33554432; modification_time=1676353186026; access_time=0; owner=as-ol.lysiuk; group=as-ol.lysiuk; permission=rw-rw-rw-; isSymlink=false; hasAcl=false; isEncrypted=true; isErasureCoded=false} isEmptyDirectory=FALSE eTag=ce0ba8a9d8ebfd59f738ce9fa80772cf versionId=null),WrappedArray(S3AFileStatus{path=s3a://warehouse/dashboard_team_dbt.db/holes_main_all_lagers_mart/_delta_log/00000000000000000040.checkpoint.parquet; isDirectory=false; length=23620; replication=1; blocksize=33554432; modification_time=1676149125687; access_time=0; owner=as-ol.lysiuk; group=as-ol.lysiuk; permission=rw-rw-rw-; isSymlink=false; hasAcl=false; isEncrypted=true; isErasureCoded=false} isEmptyDirectory=FALSE eTag=894b0b158c05a5cb0f7c07a9611b826e versionId=null),Some(40),1676353186026), checksumOpt=None)
2023-02-14 09:17:55.547 INFO delta.DeltaLog: Returning initial snapshot Snapshot(path=s3a://warehouse/dashboard_team_dbt.db/holes_main_all_lagers_mart/_delta_log, version=46, metadata=Metadata(e8e99a47-de1b-40a5-b41e-e450b8b8b287,null,null,Format(parquet,Map()),{"type":"struct","fields":[{"name":"report_day","type":"string","nullable":true,"metadata":{}},{"name":"business_id","type":"integer","nullable":true,"metadata":{"scale":0}},{"name":"filid","type":"integer","nullable":true,"metadata":{"scale":0}},{"name":"lagerid","type":"integer","nullable":true,"metadata":{"scale":0}},{"name":"date_active_from","type":"date","nullable":true,"metadata":{}},{"name":"stores_next_day","type":"decimal(27,7)","nullable":true,"metadata":{}},{"name":"stores_report_day","type":"decimal(27,7)","nullable":true,"metadata":{}},{"name":"stores_hour16","type":"decimal(28,7)","nullable":true,"metadata":{}},{"name":"sales_prev_day","type":"decimal(38,3)","nullable":true,"metadata":{}},{"name":"sales_report_day","type":"decimal(38,3)","nullable":true,"metadata":{}},{"name":"msp","type":"decimal(22,0)","nullable":true,"metadata":{}},{"name":"is_hole","type":"integer","nullable":true,"metadata":{}},{"name":"sales_28days","type":"decimal(22,7)","nullable":true,"metadata":{}},{"name":"limit_hole","type":"decimal(18,3)","nullable":true,"metadata":{}},{"name":"forecast","type":"decimal(18,5)","nullable":true,"metadata":{}},{"name":"min_count","type":"decimal(26,8)","nullable":true,"metadata":{}},{"name":"price","type":"decimal(18,5)","nullable":true,"metadata":{}},{"name":"lost_sales","type":"decimal(38,6)","nullable":true,"metadata":{}}]},List(report_day),Map(),Some(1674751487046)), logSegment=LogSegment(s3a://warehouse/dashboard_team_dbt.db/holes_main_all_lagers_mart/_delta_log,46,WrappedArray(S3AFileStatus{path=s3a://warehouse/dashboard_team_dbt.db/holes_main_all_lagers_mart/_delta_log/00000000000000000041.json; isDirectory=false; length=2386; replication=1; blocksize=33554432; modification_time=1676186519711; access_time=0; owner=as-ol.lysiuk; group=as-ol.lysiuk; permission=rw-rw-rw-; isSymlink=false; hasAcl=false; isEncrypted=true; isErasureCoded=false} isEmptyDirectory=FALSE eTag=6cffa241bcc607eeb125fff191d54b66 versionId=null, S3AFileStatus{path=s3a://warehouse/dashboard_team_dbt.db/holes_main_all_lagers_mart/_delta_log/00000000000000000042.json; isDirectory=false; length=2389; replication=1; blocksize=33554432; modification_time=1676191886988; access_time=0; owner=as-ol.lysiuk; group=as-ol.lysiuk; permission=rw-rw-rw-; isSymlink=false; hasAcl=false; isEncrypted=true; isErasureCoded=false} isEmptyDirectory=FALSE eTag=f6fcad38eaea20b223ce7ee99ecd18f3 versionId=null, S3AFileStatus{path=s3a://warehouse/dashboard_team_dbt.db/holes_main_all_lagers_mart/_delta_log/00000000000000000043.json; isDirectory=false; length=2388; replication=1; blocksize=33554432; modification_time=1676196779308; access_time=0; owner=as-ol.lysiuk; group=as-ol.lysiuk; permission=rw-rw-rw-; isSymlink=false; hasAcl=false; isEncrypted=true; isErasureCoded=false} isEmptyDirectory=FALSE eTag=9e3642f81af3a5324ccc972bdc1ee977 versionId=null, S3AFileStatus{path=s3a://warehouse/dashboard_team_dbt.db/holes_main_all_lagers_mart/_delta_log/00000000000000000044.json; isDirectory=false; length=2646; replication=1; blocksize=33554432; modification_time=1676216447776; access_time=0; owner=as-ol.lysiuk; group=as-ol.lysiuk; permission=rw-rw-rw-; isSymlink=false; hasAcl=false; isEncrypted=true; isErasureCoded=false} isEmptyDirectory=FALSE eTag=95c8d5aafefc13c6398204030f82a3d5 versionId=null, S3AFileStatus{path=s3a://warehouse/dashboard_team_dbt.db/holes_main_all_lagers_mart/_delta_log/00000000000000000045.json; isDirectory=false; length=2382; replication=1; blocksize=33554432; modification_time=1676270091871; access_time=0; owner=as-ol.lysiuk; group=as-ol.lysiuk; permission=rw-rw-rw-; isSymlink=false; hasAcl=false; isEncrypted=true; isErasureCoded=false} isEmptyDirectory=FALSE eTag=49f371bb10cd63043e70d68da796fe2c versionId=null, S3AFileStatus{path=s3a://warehouse/dashboard_team_dbt.db/holes_main_all_lagers_mart/_delta_log/00000000000000000046.json; isDirectory=false; length=2387; replication=1; blocksize=33554432; modification_time=1676353186026; access_time=0; owner=as-ol.lysiuk; group=as-ol.lysiuk; permission=rw-rw-rw-; isSymlink=false; hasAcl=false; isEncrypted=true; isErasureCoded=false} isEmptyDirectory=FALSE eTag=ce0ba8a9d8ebfd59f738ce9fa80772cf versionId=null),WrappedArray(S3AFileStatus{path=s3a://warehouse/dashboard_team_dbt.db/holes_main_all_lagers_mart/_delta_log/00000000000000000040.checkpoint.parquet; isDirectory=false; length=23620; replication=1; blocksize=33554432; modification_time=1676149125687; access_time=0; owner=as-ol.lysiuk; group=as-ol.lysiuk; permission=rw-rw-rw-; isSymlink=false; hasAcl=false; isEncrypted=true; isErasureCoded=false} isEmptyDirectory=FALSE eTag=894b0b158c05a5cb0f7c07a9611b826e versionId=null),Some(40),1676353186026), checksumOpt=None)
2023-02-14 09:17:55.612 INFO operation.ExecuteStatement: Processing as-ol.lysiuk's query[ec26d2e6-457a-4e59-a816-fc40a5dc896c]: RUNNING_STATE -> RUNNING_STATE, statement: select
    filid,
    count(IF(is_hole = 0, NULL, is_hole)) * 1.0/count(*) as ratio
from dashboard_team_dbt.holes_main_all_lagers_mart
where
    report_day = '2023-02-14'
    and business_id = 1
group by filid
2023-02-14 09:17:55.612 INFO operation.ExecuteStatement: Execute in full collect mode
2023-02-14 09:17:55.919 INFO storage.BlockManagerInfo: Removed broadcast_7_piece0 on 172.17.18.136:36651 in memory (size: 104.0 KiB, free: 1458.4 MiB)
2023-02-14 09:17:55.920 INFO storage.BlockManagerInfo: Removed broadcast_7_piece0 on 172.17.11.222:41311 in memory (size: 104.0 KiB, free: 1007.6 MiB)
2023-02-14 09:17:55.926 INFO storage.BlockManagerInfo: Removed broadcast_7_piece0 on 172.17.14.122:42947 in memory (size: 104.0 KiB, free: 1007.8 MiB)
2023-02-14 09:17:55.930 INFO storage.BlockManagerInfo: Removed broadcast_8_piece0 on 172.17.18.136:36651 in memory (size: 92.5 KiB, free: 1458.5 MiB)
2023-02-14 09:17:55.931 INFO storage.BlockManagerInfo: Removed broadcast_8_piece0 on 172.17.11.222:41311 in memory (size: 92.5 KiB, free: 1007.7 MiB)
2023-02-14 09:17:56.496 INFO k8s.KubernetesClusterSchedulerBackend$KubernetesDriverEndpoint: Registered executor NettyRpcEndpointRef(spark-client://Executor) (172.17.19.106:52600) with ID 3,  ResourceProfileId 0
2023-02-14 09:17:56.497 INFO dynalloc.ExecutorMonitor: New executor 3 has registered (new total is 4)
2023-02-14 09:17:56.669 INFO storage.BlockManagerMasterEndpoint: Registering block manager 172.17.19.106:41349 with 1007.8 MiB RAM, BlockManagerId(3, 172.17.19.106, 41349, None)
2023-02-14 09:18:00.606 INFO stats.PrepareDeltaScan: DELTA: Filtering files for query
2023-02-14 09:18:00.923 INFO codegen.CodeGenerator: Code generated in 55.917477 ms
2023-02-14 09:18:01.107 INFO codegen.CodeGenerator: Code generated in 51.656379 ms
2023-02-14 09:18:01.146 INFO spark.SparkContext: Starting job: $anonfun$recordDeltaOperationInternal$1 at DatabricksLogging.scala:77
2023-02-14 09:18:01.147 INFO scheduler.DAGScheduler: Got job 6 ($anonfun$recordDeltaOperationInternal$1 at DatabricksLogging.scala:77) with 50 output partitions
2023-02-14 09:18:01.147 INFO scheduler.DAGScheduler: Final stage: ResultStage 10 ($anonfun$recordDeltaOperationInternal$1 at DatabricksLogging.scala:77)
2023-02-14 09:18:01.147 INFO scheduler.DAGScheduler: Parents of final stage: List(ShuffleMapStage 9)
2023-02-14 09:18:01.148 INFO scheduler.DAGScheduler: Missing parents: List()
2023-02-14 09:18:01.148 INFO scheduler.DAGScheduler: Submitting ResultStage 10 (MapPartitionsRDD[33] at $anonfun$recordDeltaOperationInternal$1 at DatabricksLogging.scala:77), which has no missing parents
2023-02-14 09:18:01.154 INFO memory.MemoryStore: Block broadcast_9 stored as values in memory (estimated size 578.4 KiB, free 1456.8 MiB)
2023-02-14 09:18:01.157 INFO memory.MemoryStore: Block broadcast_9_piece0 stored as bytes in memory (estimated size 142.7 KiB, free 1456.6 MiB)
2023-02-14 09:18:01.157 INFO storage.BlockManagerInfo: Added broadcast_9_piece0 in memory on 172.17.18.136:36651 (size: 142.7 KiB, free: 1458.3 MiB)
2023-02-14 09:18:01.157 INFO spark.SparkContext: Created broadcast 9 from broadcast at DAGScheduler.scala:1478
2023-02-14 09:18:01.158 INFO scheduler.DAGScheduler: Submitting 50 missing tasks from ResultStage 10 (MapPartitionsRDD[33] at $anonfun$recordDeltaOperationInternal$1 at DatabricksLogging.scala:77) (first 15 tasks are for partitions Vector(0, 1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14))
2023-02-14 09:18:01.158 INFO scheduler.TaskSchedulerImpl: Adding task set 10.0 with 50 tasks resource profile 0
2023-02-14 09:18:01.160 INFO scheduler.TaskSetManager: Starting task 1.0 in stage 10.0 (TID 57) (172.17.14.122, executor 2, partition 1, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:01.160 INFO scheduler.TaskSetManager: Starting task 0.0 in stage 10.0 (TID 58) (172.17.11.222, executor 1, partition 0, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:01.167 INFO storage.BlockManagerInfo: Added broadcast_9_piece0 in memory on 172.17.11.222:41311 (size: 142.7 KiB, free: 1007.6 MiB)
2023-02-14 09:18:01.172 INFO storage.BlockManagerInfo: Added broadcast_9_piece0 in memory on 172.17.14.122:42947 (size: 142.7 KiB, free: 1007.7 MiB)
2023-02-14 09:18:01.505 INFO storage.BlockManagerInfo: Added rdd_31_0 in memory on 172.17.11.222:41311 (size: 4.0 B, free: 1007.6 MiB)
2023-02-14 09:18:01.611 INFO scheduler.TaskSetManager: Starting task 2.0 in stage 10.0 (TID 59) (172.17.11.222, executor 1, partition 2, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:01.612 INFO scheduler.TaskSetManager: Finished task 0.0 in stage 10.0 (TID 58) in 452 ms on 172.17.11.222 (executor 1) (1/50)
2023-02-14 09:18:01.623 INFO storage.BlockManagerInfo: Added rdd_31_2 in memory on 172.17.11.222:41311 (size: 4.0 B, free: 1007.6 MiB)
2023-02-14 09:18:01.626 INFO scheduler.TaskSetManager: Starting task 3.0 in stage 10.0 (TID 60) (172.17.11.222, executor 1, partition 3, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:01.626 INFO scheduler.TaskSetManager: Finished task 2.0 in stage 10.0 (TID 59) in 15 ms on 172.17.11.222 (executor 1) (2/50)
2023-02-14 09:18:01.685 INFO storage.BlockManagerInfo: Added rdd_31_3 in memory on 172.17.11.222:41311 (size: 4.0 B, free: 1007.6 MiB)
2023-02-14 09:18:01.688 INFO scheduler.TaskSetManager: Starting task 4.0 in stage 10.0 (TID 61) (172.17.11.222, executor 1, partition 4, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:01.688 INFO scheduler.TaskSetManager: Finished task 3.0 in stage 10.0 (TID 60) in 62 ms on 172.17.11.222 (executor 1) (3/50)
2023-02-14 09:18:01.783 INFO storage.BlockManagerInfo: Added rdd_31_4 in memory on 172.17.11.222:41311 (size: 1150.0 B, free: 1007.6 MiB)
2023-02-14 09:18:01.794 INFO scheduler.TaskSetManager: Starting task 5.0 in stage 10.0 (TID 62) (172.17.11.222, executor 1, partition 5, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:01.794 INFO scheduler.TaskSetManager: Finished task 4.0 in stage 10.0 (TID 61) in 107 ms on 172.17.11.222 (executor 1) (4/50)
2023-02-14 09:18:01.806 INFO storage.BlockManagerInfo: Added rdd_31_5 in memory on 172.17.11.222:41311 (size: 1150.0 B, free: 1007.6 MiB)
2023-02-14 09:18:01.809 INFO scheduler.TaskSetManager: Starting task 6.0 in stage 10.0 (TID 63) (172.17.11.222, executor 1, partition 6, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:01.809 INFO scheduler.TaskSetManager: Finished task 5.0 in stage 10.0 (TID 62) in 16 ms on 172.17.11.222 (executor 1) (5/50)
2023-02-14 09:18:01.819 INFO storage.BlockManagerInfo: Added rdd_31_6 in memory on 172.17.11.222:41311 (size: 4.0 B, free: 1007.6 MiB)
2023-02-14 09:18:01.821 INFO scheduler.TaskSetManager: Starting task 7.0 in stage 10.0 (TID 64) (172.17.11.222, executor 1, partition 7, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:01.821 INFO scheduler.TaskSetManager: Finished task 6.0 in stage 10.0 (TID 63) in 12 ms on 172.17.11.222 (executor 1) (6/50)
2023-02-14 09:18:01.860 INFO storage.BlockManagerInfo: Added rdd_31_1 in memory on 172.17.14.122:42947 (size: 4.0 B, free: 1007.7 MiB)
2023-02-14 09:18:01.882 INFO storage.BlockManagerInfo: Added rdd_31_7 in memory on 172.17.11.222:41311 (size: 4.0 B, free: 1007.6 MiB)
2023-02-14 09:18:01.884 INFO scheduler.TaskSetManager: Starting task 8.0 in stage 10.0 (TID 65) (172.17.11.222, executor 1, partition 8, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:01.884 INFO scheduler.TaskSetManager: Finished task 7.0 in stage 10.0 (TID 64) in 63 ms on 172.17.11.222 (executor 1) (7/50)
2023-02-14 09:18:01.896 INFO storage.BlockManagerInfo: Added rdd_31_8 in memory on 172.17.11.222:41311 (size: 1150.0 B, free: 1007.6 MiB)
2023-02-14 09:18:01.899 INFO scheduler.TaskSetManager: Starting task 9.0 in stage 10.0 (TID 66) (172.17.11.222, executor 1, partition 9, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:01.899 INFO scheduler.TaskSetManager: Finished task 8.0 in stage 10.0 (TID 65) in 15 ms on 172.17.11.222 (executor 1) (8/50)
2023-02-14 09:18:01.909 INFO storage.BlockManagerInfo: Added rdd_31_9 in memory on 172.17.11.222:41311 (size: 4.0 B, free: 1007.6 MiB)
2023-02-14 09:18:01.911 INFO scheduler.TaskSetManager: Starting task 10.0 in stage 10.0 (TID 67) (172.17.11.222, executor 1, partition 10, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:01.912 INFO scheduler.TaskSetManager: Finished task 9.0 in stage 10.0 (TID 66) in 13 ms on 172.17.11.222 (executor 1) (9/50)
2023-02-14 09:18:01.922 INFO storage.BlockManagerInfo: Added rdd_31_10 in memory on 172.17.11.222:41311 (size: 4.0 B, free: 1007.6 MiB)
2023-02-14 09:18:01.924 INFO scheduler.TaskSetManager: Starting task 11.0 in stage 10.0 (TID 68) (172.17.11.222, executor 1, partition 11, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:01.924 INFO scheduler.TaskSetManager: Finished task 10.0 in stage 10.0 (TID 67) in 13 ms on 172.17.11.222 (executor 1) (10/50)
2023-02-14 09:18:01.986 INFO storage.BlockManagerInfo: Added rdd_31_11 in memory on 172.17.11.222:41311 (size: 4.0 B, free: 1007.6 MiB)
2023-02-14 09:18:01.989 INFO scheduler.TaskSetManager: Starting task 12.0 in stage 10.0 (TID 69) (172.17.11.222, executor 1, partition 12, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:01.989 INFO scheduler.TaskSetManager: Finished task 11.0 in stage 10.0 (TID 68) in 65 ms on 172.17.11.222 (executor 1) (11/50)
2023-02-14 09:18:01.999 INFO storage.BlockManagerInfo: Added rdd_31_12 in memory on 172.17.11.222:41311 (size: 4.0 B, free: 1007.6 MiB)
2023-02-14 09:18:02.001 INFO scheduler.TaskSetManager: Starting task 13.0 in stage 10.0 (TID 70) (172.17.11.222, executor 1, partition 13, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:02.001 INFO scheduler.TaskSetManager: Finished task 12.0 in stage 10.0 (TID 69) in 13 ms on 172.17.11.222 (executor 1) (12/50)
2023-02-14 09:18:02.013 INFO storage.BlockManagerInfo: Added rdd_31_13 in memory on 172.17.11.222:41311 (size: 1150.0 B, free: 1007.6 MiB)
2023-02-14 09:18:02.016 INFO scheduler.TaskSetManager: Starting task 14.0 in stage 10.0 (TID 71) (172.17.11.222, executor 1, partition 14, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:02.016 INFO scheduler.TaskSetManager: Finished task 13.0 in stage 10.0 (TID 70) in 15 ms on 172.17.11.222 (executor 1) (13/50)
2023-02-14 09:18:02.060 INFO scheduler.TaskSetManager: Finished task 1.0 in stage 10.0 (TID 57) in 900 ms on 172.17.14.122 (executor 2) (14/50)
2023-02-14 09:18:02.078 INFO storage.BlockManagerInfo: Added rdd_31_14 in memory on 172.17.11.222:41311 (size: 4.0 B, free: 1007.6 MiB)
2023-02-14 09:18:02.080 INFO scheduler.TaskSetManager: Starting task 15.0 in stage 10.0 (TID 72) (172.17.11.222, executor 1, partition 15, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:02.080 INFO scheduler.TaskSetManager: Finished task 14.0 in stage 10.0 (TID 71) in 64 ms on 172.17.11.222 (executor 1) (15/50)
2023-02-14 09:18:02.091 INFO storage.BlockManagerInfo: Added rdd_31_15 in memory on 172.17.11.222:41311 (size: 1150.0 B, free: 1007.6 MiB)
2023-02-14 09:18:02.094 INFO scheduler.TaskSetManager: Starting task 16.0 in stage 10.0 (TID 73) (172.17.11.222, executor 1, partition 16, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:02.094 INFO scheduler.TaskSetManager: Finished task 15.0 in stage 10.0 (TID 72) in 14 ms on 172.17.11.222 (executor 1) (16/50)
2023-02-14 09:18:02.105 INFO storage.BlockManagerInfo: Added rdd_31_16 in memory on 172.17.11.222:41311 (size: 1150.0 B, free: 1007.6 MiB)
2023-02-14 09:18:02.108 INFO scheduler.TaskSetManager: Starting task 17.0 in stage 10.0 (TID 74) (172.17.11.222, executor 1, partition 17, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:02.109 INFO scheduler.TaskSetManager: Finished task 16.0 in stage 10.0 (TID 73) in 15 ms on 172.17.11.222 (executor 1) (17/50)
2023-02-14 09:18:02.118 INFO storage.BlockManagerInfo: Added rdd_31_17 in memory on 172.17.11.222:41311 (size: 4.0 B, free: 1007.6 MiB)
2023-02-14 09:18:02.121 INFO scheduler.TaskSetManager: Starting task 18.0 in stage 10.0 (TID 75) (172.17.11.222, executor 1, partition 18, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:02.121 INFO scheduler.TaskSetManager: Finished task 17.0 in stage 10.0 (TID 74) in 13 ms on 172.17.11.222 (executor 1) (18/50)
2023-02-14 09:18:02.179 INFO storage.BlockManagerInfo: Added rdd_31_18 in memory on 172.17.11.222:41311 (size: 4.0 B, free: 1007.6 MiB)
2023-02-14 09:18:02.181 INFO scheduler.TaskSetManager: Starting task 19.0 in stage 10.0 (TID 76) (172.17.11.222, executor 1, partition 19, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:02.181 INFO scheduler.TaskSetManager: Finished task 18.0 in stage 10.0 (TID 75) in 61 ms on 172.17.11.222 (executor 1) (19/50)
2023-02-14 09:18:02.192 INFO storage.BlockManagerInfo: Added rdd_31_19 in memory on 172.17.11.222:41311 (size: 1150.0 B, free: 1007.6 MiB)
2023-02-14 09:18:02.196 INFO scheduler.TaskSetManager: Starting task 20.0 in stage 10.0 (TID 77) (172.17.11.222, executor 1, partition 20, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:02.196 INFO scheduler.TaskSetManager: Finished task 19.0 in stage 10.0 (TID 76) in 15 ms on 172.17.11.222 (executor 1) (20/50)
2023-02-14 09:18:02.205 INFO storage.BlockManagerInfo: Added rdd_31_20 in memory on 172.17.11.222:41311 (size: 4.0 B, free: 1007.6 MiB)
2023-02-14 09:18:02.207 INFO scheduler.TaskSetManager: Starting task 21.0 in stage 10.0 (TID 78) (172.17.11.222, executor 1, partition 21, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:02.208 INFO scheduler.TaskSetManager: Finished task 20.0 in stage 10.0 (TID 77) in 12 ms on 172.17.11.222 (executor 1) (21/50)
2023-02-14 09:18:02.217 INFO storage.BlockManagerInfo: Added rdd_31_21 in memory on 172.17.11.222:41311 (size: 4.0 B, free: 1007.6 MiB)
2023-02-14 09:18:02.219 INFO scheduler.TaskSetManager: Starting task 22.0 in stage 10.0 (TID 79) (172.17.11.222, executor 1, partition 22, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:02.219 INFO scheduler.TaskSetManager: Finished task 21.0 in stage 10.0 (TID 78) in 12 ms on 172.17.11.222 (executor 1) (22/50)
2023-02-14 09:18:02.281 INFO storage.BlockManagerInfo: Added rdd_31_22 in memory on 172.17.11.222:41311 (size: 1150.0 B, free: 1007.6 MiB)
2023-02-14 09:18:02.285 INFO scheduler.TaskSetManager: Starting task 23.0 in stage 10.0 (TID 80) (172.17.11.222, executor 1, partition 23, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:02.285 INFO scheduler.TaskSetManager: Finished task 22.0 in stage 10.0 (TID 79) in 66 ms on 172.17.11.222 (executor 1) (23/50)
2023-02-14 09:18:02.296 INFO storage.BlockManagerInfo: Added rdd_31_23 in memory on 172.17.11.222:41311 (size: 1150.0 B, free: 1007.6 MiB)
2023-02-14 09:18:02.299 INFO scheduler.TaskSetManager: Starting task 24.0 in stage 10.0 (TID 81) (172.17.11.222, executor 1, partition 24, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:02.299 INFO scheduler.TaskSetManager: Finished task 23.0 in stage 10.0 (TID 80) in 15 ms on 172.17.11.222 (executor 1) (24/50)
2023-02-14 09:18:02.309 INFO storage.BlockManagerInfo: Added rdd_31_24 in memory on 172.17.11.222:41311 (size: 4.0 B, free: 1007.6 MiB)
2023-02-14 09:18:02.311 INFO scheduler.TaskSetManager: Starting task 25.0 in stage 10.0 (TID 82) (172.17.11.222, executor 1, partition 25, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:02.311 INFO scheduler.TaskSetManager: Finished task 24.0 in stage 10.0 (TID 81) in 12 ms on 172.17.11.222 (executor 1) (25/50)
2023-02-14 09:18:02.321 INFO storage.BlockManagerInfo: Added rdd_31_25 in memory on 172.17.11.222:41311 (size: 4.0 B, free: 1007.6 MiB)
2023-02-14 09:18:02.323 INFO scheduler.TaskSetManager: Starting task 26.0 in stage 10.0 (TID 83) (172.17.11.222, executor 1, partition 26, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:02.323 INFO scheduler.TaskSetManager: Finished task 25.0 in stage 10.0 (TID 82) in 12 ms on 172.17.11.222 (executor 1) (26/50)
2023-02-14 09:18:02.381 INFO storage.BlockManagerInfo: Added rdd_31_26 in memory on 172.17.11.222:41311 (size: 1150.0 B, free: 1007.6 MiB)
2023-02-14 09:18:02.384 INFO scheduler.TaskSetManager: Starting task 27.0 in stage 10.0 (TID 84) (172.17.11.222, executor 1, partition 27, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:02.385 INFO scheduler.TaskSetManager: Finished task 26.0 in stage 10.0 (TID 83) in 62 ms on 172.17.11.222 (executor 1) (27/50)
2023-02-14 09:18:02.397 INFO storage.BlockManagerInfo: Added rdd_31_27 in memory on 172.17.11.222:41311 (size: 1150.0 B, free: 1007.6 MiB)
2023-02-14 09:18:02.400 INFO scheduler.TaskSetManager: Starting task 28.0 in stage 10.0 (TID 85) (172.17.11.222, executor 1, partition 28, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:02.400 INFO scheduler.TaskSetManager: Finished task 27.0 in stage 10.0 (TID 84) in 16 ms on 172.17.11.222 (executor 1) (28/50)
2023-02-14 09:18:02.411 INFO storage.BlockManagerInfo: Added rdd_31_28 in memory on 172.17.11.222:41311 (size: 4.0 B, free: 1007.6 MiB)
2023-02-14 09:18:02.413 INFO scheduler.TaskSetManager: Starting task 29.0 in stage 10.0 (TID 86) (172.17.11.222, executor 1, partition 29, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:02.413 INFO scheduler.TaskSetManager: Finished task 28.0 in stage 10.0 (TID 85) in 13 ms on 172.17.11.222 (executor 1) (29/50)
2023-02-14 09:18:02.423 INFO storage.BlockManagerInfo: Added rdd_31_29 in memory on 172.17.11.222:41311 (size: 4.0 B, free: 1007.6 MiB)
2023-02-14 09:18:02.425 INFO scheduler.TaskSetManager: Starting task 30.0 in stage 10.0 (TID 87) (172.17.11.222, executor 1, partition 30, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:02.426 INFO scheduler.TaskSetManager: Finished task 29.0 in stage 10.0 (TID 86) in 13 ms on 172.17.11.222 (executor 1) (30/50)
2023-02-14 09:18:02.487 INFO storage.BlockManagerInfo: Added rdd_31_30 in memory on 172.17.11.222:41311 (size: 1150.0 B, free: 1007.6 MiB)
2023-02-14 09:18:02.491 INFO scheduler.TaskSetManager: Starting task 31.0 in stage 10.0 (TID 88) (172.17.11.222, executor 1, partition 31, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:02.491 INFO scheduler.TaskSetManager: Finished task 30.0 in stage 10.0 (TID 87) in 66 ms on 172.17.11.222 (executor 1) (31/50)
2023-02-14 09:18:02.503 INFO storage.BlockManagerInfo: Added rdd_31_31 in memory on 172.17.11.222:41311 (size: 1150.0 B, free: 1007.6 MiB)
2023-02-14 09:18:02.506 INFO scheduler.TaskSetManager: Starting task 32.0 in stage 10.0 (TID 89) (172.17.11.222, executor 1, partition 32, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:02.506 INFO scheduler.TaskSetManager: Finished task 31.0 in stage 10.0 (TID 88) in 15 ms on 172.17.11.222 (executor 1) (32/50)
2023-02-14 09:18:02.517 INFO storage.BlockManagerInfo: Added rdd_31_32 in memory on 172.17.11.222:41311 (size: 1150.0 B, free: 1007.6 MiB)
2023-02-14 09:18:02.521 INFO scheduler.TaskSetManager: Starting task 33.0 in stage 10.0 (TID 90) (172.17.11.222, executor 1, partition 33, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:02.521 INFO scheduler.TaskSetManager: Finished task 32.0 in stage 10.0 (TID 89) in 15 ms on 172.17.11.222 (executor 1) (33/50)
2023-02-14 09:18:02.585 INFO storage.BlockManagerInfo: Added rdd_31_33 in memory on 172.17.11.222:41311 (size: 4.0 B, free: 1007.6 MiB)
2023-02-14 09:18:02.587 INFO scheduler.TaskSetManager: Starting task 34.0 in stage 10.0 (TID 91) (172.17.11.222, executor 1, partition 34, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:02.587 INFO scheduler.TaskSetManager: Finished task 33.0 in stage 10.0 (TID 90) in 66 ms on 172.17.11.222 (executor 1) (34/50)
2023-02-14 09:18:02.597 INFO storage.BlockManagerInfo: Added rdd_31_34 in memory on 172.17.11.222:41311 (size: 1150.0 B, free: 1007.6 MiB)
2023-02-14 09:18:02.601 INFO scheduler.TaskSetManager: Starting task 35.0 in stage 10.0 (TID 92) (172.17.11.222, executor 1, partition 35, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:02.601 INFO scheduler.TaskSetManager: Finished task 34.0 in stage 10.0 (TID 91) in 14 ms on 172.17.11.222 (executor 1) (35/50)
2023-02-14 09:18:02.611 INFO storage.BlockManagerInfo: Added rdd_31_35 in memory on 172.17.11.222:41311 (size: 1150.0 B, free: 1007.6 MiB)
2023-02-14 09:18:02.615 INFO scheduler.TaskSetManager: Starting task 36.0 in stage 10.0 (TID 93) (172.17.11.222, executor 1, partition 36, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:02.615 INFO scheduler.TaskSetManager: Finished task 35.0 in stage 10.0 (TID 92) in 14 ms on 172.17.11.222 (executor 1) (36/50)
2023-02-14 09:18:02.625 INFO storage.BlockManagerInfo: Added rdd_31_36 in memory on 172.17.11.222:41311 (size: 4.0 B, free: 1007.6 MiB)
2023-02-14 09:18:02.627 INFO scheduler.TaskSetManager: Starting task 37.0 in stage 10.0 (TID 94) (172.17.11.222, executor 1, partition 37, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:02.627 INFO scheduler.TaskSetManager: Finished task 36.0 in stage 10.0 (TID 93) in 12 ms on 172.17.11.222 (executor 1) (37/50)
2023-02-14 09:18:02.681 INFO storage.BlockManagerInfo: Added rdd_31_37 in memory on 172.17.11.222:41311 (size: 1150.0 B, free: 1007.5 MiB)
2023-02-14 09:18:02.684 INFO scheduler.TaskSetManager: Starting task 38.0 in stage 10.0 (TID 95) (172.17.11.222, executor 1, partition 38, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:02.684 INFO scheduler.TaskSetManager: Finished task 37.0 in stage 10.0 (TID 94) in 57 ms on 172.17.11.222 (executor 1) (38/50)
2023-02-14 09:18:02.693 INFO storage.BlockManagerInfo: Added rdd_31_38 in memory on 172.17.11.222:41311 (size: 4.0 B, free: 1007.5 MiB)
2023-02-14 09:18:02.695 INFO scheduler.TaskSetManager: Starting task 39.0 in stage 10.0 (TID 96) (172.17.11.222, executor 1, partition 39, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:02.695 INFO scheduler.TaskSetManager: Finished task 38.0 in stage 10.0 (TID 95) in 11 ms on 172.17.11.222 (executor 1) (39/50)
2023-02-14 09:18:02.705 INFO storage.BlockManagerInfo: Added rdd_31_39 in memory on 172.17.11.222:41311 (size: 4.0 B, free: 1007.5 MiB)
2023-02-14 09:18:02.707 INFO scheduler.TaskSetManager: Starting task 40.0 in stage 10.0 (TID 97) (172.17.11.222, executor 1, partition 40, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:02.707 INFO scheduler.TaskSetManager: Finished task 39.0 in stage 10.0 (TID 96) in 12 ms on 172.17.11.222 (executor 1) (40/50)
2023-02-14 09:18:02.717 INFO storage.BlockManagerInfo: Added rdd_31_40 in memory on 172.17.11.222:41311 (size: 4.0 B, free: 1007.5 MiB)
2023-02-14 09:18:02.719 INFO scheduler.TaskSetManager: Starting task 41.0 in stage 10.0 (TID 98) (172.17.11.222, executor 1, partition 41, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:02.719 INFO scheduler.TaskSetManager: Finished task 40.0 in stage 10.0 (TID 97) in 12 ms on 172.17.11.222 (executor 1) (41/50)
2023-02-14 09:18:02.779 INFO storage.BlockManagerInfo: Added rdd_31_41 in memory on 172.17.11.222:41311 (size: 4.0 B, free: 1007.5 MiB)
2023-02-14 09:18:02.781 INFO scheduler.TaskSetManager: Starting task 42.0 in stage 10.0 (TID 99) (172.17.11.222, executor 1, partition 42, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:02.782 INFO scheduler.TaskSetManager: Finished task 41.0 in stage 10.0 (TID 98) in 64 ms on 172.17.11.222 (executor 1) (42/50)
2023-02-14 09:18:02.792 INFO storage.BlockManagerInfo: Added rdd_31_42 in memory on 172.17.11.222:41311 (size: 4.0 B, free: 1007.5 MiB)
2023-02-14 09:18:02.794 INFO scheduler.TaskSetManager: Starting task 43.0 in stage 10.0 (TID 100) (172.17.11.222, executor 1, partition 43, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:02.794 INFO scheduler.TaskSetManager: Finished task 42.0 in stage 10.0 (TID 99) in 13 ms on 172.17.11.222 (executor 1) (43/50)
2023-02-14 09:18:02.804 INFO storage.BlockManagerInfo: Added rdd_31_43 in memory on 172.17.11.222:41311 (size: 4.0 B, free: 1007.5 MiB)
2023-02-14 09:18:02.805 INFO scheduler.TaskSetManager: Starting task 44.0 in stage 10.0 (TID 101) (172.17.11.222, executor 1, partition 44, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:02.806 INFO scheduler.TaskSetManager: Finished task 43.0 in stage 10.0 (TID 100) in 12 ms on 172.17.11.222 (executor 1) (44/50)
2023-02-14 09:18:02.816 INFO storage.BlockManagerInfo: Added rdd_31_44 in memory on 172.17.11.222:41311 (size: 1150.0 B, free: 1007.5 MiB)
2023-02-14 09:18:02.819 INFO scheduler.TaskSetManager: Starting task 45.0 in stage 10.0 (TID 102) (172.17.11.222, executor 1, partition 45, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:02.819 INFO scheduler.TaskSetManager: Finished task 44.0 in stage 10.0 (TID 101) in 14 ms on 172.17.11.222 (executor 1) (45/50)
2023-02-14 09:18:02.879 INFO storage.BlockManagerInfo: Added rdd_31_45 in memory on 172.17.11.222:41311 (size: 1150.0 B, free: 1007.5 MiB)
2023-02-14 09:18:02.883 INFO scheduler.TaskSetManager: Starting task 46.0 in stage 10.0 (TID 103) (172.17.11.222, executor 1, partition 46, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:02.883 INFO scheduler.TaskSetManager: Finished task 45.0 in stage 10.0 (TID 102) in 64 ms on 172.17.11.222 (executor 1) (46/50)
2023-02-14 09:18:02.893 INFO storage.BlockManagerInfo: Added rdd_31_46 in memory on 172.17.11.222:41311 (size: 1150.0 B, free: 1007.5 MiB)
2023-02-14 09:18:02.896 INFO scheduler.TaskSetManager: Starting task 47.0 in stage 10.0 (TID 104) (172.17.11.222, executor 1, partition 47, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:02.896 INFO scheduler.TaskSetManager: Finished task 46.0 in stage 10.0 (TID 103) in 14 ms on 172.17.11.222 (executor 1) (47/50)
2023-02-14 09:18:02.907 INFO storage.BlockManagerInfo: Added rdd_31_47 in memory on 172.17.11.222:41311 (size: 4.0 B, free: 1007.5 MiB)
2023-02-14 09:18:02.909 INFO scheduler.TaskSetManager: Starting task 48.0 in stage 10.0 (TID 105) (172.17.11.222, executor 1, partition 48, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:02.909 INFO scheduler.TaskSetManager: Finished task 47.0 in stage 10.0 (TID 104) in 13 ms on 172.17.11.222 (executor 1) (48/50)
2023-02-14 09:18:02.918 INFO storage.BlockManagerInfo: Added rdd_31_48 in memory on 172.17.11.222:41311 (size: 4.0 B, free: 1007.5 MiB)
2023-02-14 09:18:02.920 INFO scheduler.TaskSetManager: Starting task 49.0 in stage 10.0 (TID 106) (172.17.11.222, executor 1, partition 49, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:02.920 INFO scheduler.TaskSetManager: Finished task 48.0 in stage 10.0 (TID 105) in 12 ms on 172.17.11.222 (executor 1) (49/50)
2023-02-14 09:18:02.980 INFO storage.BlockManagerInfo: Added rdd_31_49 in memory on 172.17.11.222:41311 (size: 4.0 B, free: 1007.5 MiB)
2023-02-14 09:18:02.982 INFO scheduler.TaskSetManager: Finished task 49.0 in stage 10.0 (TID 106) in 62 ms on 172.17.11.222 (executor 1) (50/50)
2023-02-14 09:18:02.982 INFO scheduler.TaskSchedulerImpl: Removed TaskSet 10.0, whose tasks have all completed, from pool 
2023-02-14 09:18:02.982 INFO scheduler.DAGScheduler: ResultStage 10 ($anonfun$recordDeltaOperationInternal$1 at DatabricksLogging.scala:77) finished in 1.832 s
2023-02-14 09:18:02.982 INFO scheduler.DAGScheduler: Job 6 is finished. Cancelling potential speculative or zombie tasks for this job
2023-02-14 09:18:02.982 INFO scheduler.TaskSchedulerImpl: Killing all running tasks in stage 10: Stage finished
2023-02-14 09:18:02.982 INFO kyuubi.SparkSQLEngineListener: Job end. Job 6 state is JobSucceeded
2023-02-14 09:18:02.983 INFO scheduler.DAGScheduler: Job 6 finished: $anonfun$recordDeltaOperationInternal$1 at DatabricksLogging.scala:77, took 1.836826 s
2023-02-14 09:18:02.988 INFO stats.PrepareDeltaScan: DELTA: Done
2023-02-14 09:18:03.006 INFO datasources.DataSourceStrategy: Pruning directories with: isnotnull(report_day#335),(report_day#335 = 2023-02-14)
2023-02-14 09:18:03.010 INFO datasources.FileSourceStrategy: Pushed Filters: IsNotNull(business_id),EqualTo(business_id,1)
2023-02-14 09:18:03.010 INFO datasources.FileSourceStrategy: Post-Scan Filters: isnotnull(business_id#336),(business_id#336 = 1)
2023-02-14 09:18:03.010 INFO datasources.FileSourceStrategy: Output Data Schema: struct<business_id: int, filid: int, is_hole: int ... 1 more fields>
2023-02-14 09:18:03.100 INFO codegen.CodeGenerator: Code generated in 33.536347 ms
2023-02-14 09:18:03.106 INFO memory.MemoryStore: Block broadcast_10 stored as values in memory (estimated size 389.1 KiB, free 1456.3 MiB)
2023-02-14 09:18:03.114 INFO memory.MemoryStore: Block broadcast_10_piece0 stored as bytes in memory (estimated size 38.3 KiB, free 1456.2 MiB)
2023-02-14 09:18:03.115 INFO storage.BlockManagerInfo: Added broadcast_10_piece0 in memory on 172.17.18.136:36651 (size: 38.3 KiB, free: 1458.3 MiB)
2023-02-14 09:18:03.116 INFO spark.SparkContext: Created broadcast 10 from collect at ExecuteStatement.scala:90
2023-02-14 09:18:03.118 INFO execution.FileSourceScanExec: Planning scan with bin packing, max size: 4194304 bytes, open cost is considered as scanning 4194304 bytes.
2023-02-14 09:18:03.140 INFO adaptive.ShufflePartitionsUtil: For shuffle(), advisory target size: 67108864, actual target size 1048576, minimum partition size: 1048576
2023-02-14 09:18:03.152 INFO aggregate.HashAggregateExec: spark.sql.codegen.aggregate.map.twolevel.enabled is set to true, but current version of codegened fast hashmap does not support this aggregate.
2023-02-14 09:18:03.169 INFO codegen.CodeGenerator: Code generated in 10.483269 ms
2023-02-14 09:18:03.191 INFO spark.SparkContext: Starting job: collect at ExecuteStatement.scala:90
2023-02-14 09:18:03.192 INFO scheduler.DAGScheduler: Registering RDD 37 (collect at ExecuteStatement.scala:90) as input to shuffle 2
2023-02-14 09:18:03.192 INFO scheduler.DAGScheduler: Got job 7 (collect at ExecuteStatement.scala:90) with 1 output partitions
2023-02-14 09:18:03.193 INFO scheduler.DAGScheduler: Final stage: ResultStage 12 (collect at ExecuteStatement.scala:90)
2023-02-14 09:18:03.193 INFO scheduler.DAGScheduler: Parents of final stage: List(ShuffleMapStage 11)
2023-02-14 09:18:03.193 INFO scheduler.DAGScheduler: Missing parents: List()
2023-02-14 09:18:03.193 INFO scheduler.DAGScheduler: Submitting ResultStage 12 (MapPartitionsRDD[40] at collect at ExecuteStatement.scala:90), which has no missing parents
2023-02-14 09:18:03.195 INFO memory.MemoryStore: Block broadcast_11 stored as values in memory (estimated size 43.0 KiB, free 1456.2 MiB)
2023-02-14 09:18:03.197 INFO memory.MemoryStore: Block broadcast_11_piece0 stored as bytes in memory (estimated size 20.5 KiB, free 1456.2 MiB)
2023-02-14 09:18:03.197 INFO storage.BlockManagerInfo: Added broadcast_11_piece0 in memory on 172.17.18.136:36651 (size: 20.5 KiB, free: 1458.3 MiB)
2023-02-14 09:18:03.197 INFO spark.SparkContext: Created broadcast 11 from broadcast at DAGScheduler.scala:1478
2023-02-14 09:18:03.197 INFO scheduler.DAGScheduler: Submitting 1 missing tasks from ResultStage 12 (MapPartitionsRDD[40] at collect at ExecuteStatement.scala:90) (first 15 tasks are for partitions Vector(0))
2023-02-14 09:18:03.197 INFO scheduler.TaskSchedulerImpl: Adding task set 12.0 with 1 tasks resource profile 0
2023-02-14 09:18:03.198 INFO scheduler.TaskSetManager: Starting task 0.0 in stage 12.0 (TID 107) (172.17.11.222, executor 1, partition 0, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:03.204 INFO storage.BlockManagerInfo: Added broadcast_11_piece0 in memory on 172.17.11.222:41311 (size: 20.5 KiB, free: 1007.5 MiB)
2023-02-14 09:18:03.245 INFO spark.MapOutputTrackerMasterEndpoint: Asked to send map output locations for shuffle 2 to 172.17.11.222:43108
2023-02-14 09:18:03.304 INFO scheduler.TaskSetManager: Finished task 0.0 in stage 12.0 (TID 107) in 106 ms on 172.17.11.222 (executor 1) (1/1)
2023-02-14 09:18:03.304 INFO scheduler.TaskSchedulerImpl: Removed TaskSet 12.0, whose tasks have all completed, from pool 
2023-02-14 09:18:03.304 INFO scheduler.DAGScheduler: ResultStage 12 (collect at ExecuteStatement.scala:90) finished in 0.111 s
2023-02-14 09:18:03.304 INFO scheduler.DAGScheduler: Job 7 is finished. Cancelling potential speculative or zombie tasks for this job
2023-02-14 09:18:03.304 INFO scheduler.TaskSchedulerImpl: Killing all running tasks in stage 12: Stage finished
2023-02-14 09:18:03.304 INFO kyuubi.SparkSQLEngineListener: Job end. Job 7 state is JobSucceeded
2023-02-14 09:18:03.305 INFO scheduler.DAGScheduler: Job 7 finished: collect at ExecuteStatement.scala:90, took 0.113029 s
2023-02-14 09:18:03.305 INFO operation.ExecuteStatement: Processing as-ol.lysiuk's query[ec26d2e6-457a-4e59-a816-fc40a5dc896c]: RUNNING_STATE -> FINISHED_STATE, statement: select
    filid,
    count(IF(is_hole = 0, NULL, is_hole)) * 1.0/count(*) as ratio
from dashboard_team_dbt.holes_main_all_lagers_mart
where
    report_day = '2023-02-14'
    and business_id = 1
group by filid, time taken: 30.893 seconds
2023-02-14 09:18:20.932 INFO log.OperationLog: Creating operation log file /opt/kyuubi/work/engine_operation_logs/904407b1-8cf3-476f-a730-929eecc53a90/4811e515-5e42-45ea-9aeb-4dacdbe2aa41
2023-02-14 09:18:20.932 INFO operation.ExecuteStatement: Processing as-ol.lysiuk's query[4811e515-5e42-45ea-9aeb-4dacdbe2aa41]: INITIALIZED_STATE -> PENDING_STATE, statement: SELECT current_database()
2023-02-14 09:18:20.934 INFO operation.ExecuteStatement: Processing as-ol.lysiuk's query[4811e515-5e42-45ea-9aeb-4dacdbe2aa41]: PENDING_STATE -> RUNNING_STATE, statement: SELECT current_database()
2023-02-14 09:18:20.935 INFO operation.ExecuteStatement: 
           Spark application name: kyuubi_CONNECTION_SPARK_SQL_as-ol.lysiuk_3a27bf56-0c1b-4d96-b82c-66389785e5b4
                 application ID: spark-application-1676359040353
                 application web UI: 
                 master: k8s://https://kubernetes.default.svc
                 deploy mode: client
                 version: 3.2.2
           Start time: 2023-02-14T09:17:18.966
           User: as-ol.lysiuk
2023-02-14 09:18:20.942 INFO operation.ExecuteStatement: Processing as-ol.lysiuk's query[4811e515-5e42-45ea-9aeb-4dacdbe2aa41]: RUNNING_STATE -> RUNNING_STATE, statement: SELECT current_database()
2023-02-14 09:18:20.942 INFO operation.ExecuteStatement: Execute in full collect mode
2023-02-14 09:18:20.961 INFO spark.SparkContext: Starting job: collect at ExecuteStatement.scala:90
2023-02-14 09:18:20.962 INFO scheduler.DAGScheduler: Got job 8 (collect at ExecuteStatement.scala:90) with 1 output partitions
2023-02-14 09:18:20.962 INFO scheduler.DAGScheduler: Final stage: ResultStage 13 (collect at ExecuteStatement.scala:90)
2023-02-14 09:18:20.962 INFO scheduler.DAGScheduler: Parents of final stage: List()
2023-02-14 09:18:20.962 INFO scheduler.DAGScheduler: Missing parents: List()
2023-02-14 09:18:20.963 INFO kyuubi.SQLOperationListener: Query [4811e515-5e42-45ea-9aeb-4dacdbe2aa41]: Job 8 started with 1 stages, 1 active jobs running
2023-02-14 09:18:20.963 INFO scheduler.DAGScheduler: Submitting ResultStage 13 (MapPartitionsRDD[42] at collect at ExecuteStatement.scala:90), which has no missing parents
2023-02-14 09:18:20.963 INFO kyuubi.SQLOperationListener: Query [4811e515-5e42-45ea-9aeb-4dacdbe2aa41]: Stage 13 started with 1 tasks, 1 active stages running
2023-02-14 09:18:20.964 INFO memory.MemoryStore: Block broadcast_12 stored as values in memory (estimated size 7.2 KiB, free 1456.1 MiB)
2023-02-14 09:18:20.966 INFO memory.MemoryStore: Block broadcast_12_piece0 stored as bytes in memory (estimated size 3.7 KiB, free 1456.1 MiB)
2023-02-14 09:18:20.966 INFO storage.BlockManagerInfo: Added broadcast_12_piece0 in memory on 172.17.18.136:36651 (size: 3.7 KiB, free: 1458.3 MiB)
2023-02-14 09:18:20.966 INFO spark.SparkContext: Created broadcast 12 from broadcast at DAGScheduler.scala:1478
2023-02-14 09:18:20.967 INFO scheduler.DAGScheduler: Submitting 1 missing tasks from ResultStage 13 (MapPartitionsRDD[42] at collect at ExecuteStatement.scala:90) (first 15 tasks are for partitions Vector(0))
2023-02-14 09:18:20.967 INFO scheduler.TaskSchedulerImpl: Adding task set 13.0 with 1 tasks resource profile 0
2023-02-14 09:18:20.968 INFO scheduler.TaskSetManager: Starting task 0.0 in stage 13.0 (TID 108) (172.17.11.222, executor 1, partition 0, PROCESS_LOCAL, 4673 bytes) taskResourceAssignments Map()
2023-02-14 09:18:20.974 INFO storage.BlockManagerInfo: Added broadcast_12_piece0 in memory on 172.17.11.222:41311 (size: 3.7 KiB, free: 1007.5 MiB)
2023-02-14 09:18:20.978 INFO scheduler.TaskSetManager: Finished task 0.0 in stage 13.0 (TID 108) in 10 ms on 172.17.11.222 (executor 1) (1/1)
2023-02-14 09:18:20.978 INFO scheduler.TaskSchedulerImpl: Removed TaskSet 13.0, whose tasks have all completed, from pool 
2023-02-14 09:18:20.978 INFO scheduler.DAGScheduler: ResultStage 13 (collect at ExecuteStatement.scala:90) finished in 0.015 s
2023-02-14 09:18:20.978 INFO kyuubi.SQLOperationListener: Finished stage: Stage(13, 0); Name: 'collect at ExecuteStatement.scala:90'; Status: succeeded; numTasks: 1; Took: 15 msec
2023-02-14 09:18:20.978 INFO scheduler.DAGScheduler: Job 8 is finished. Cancelling potential speculative or zombie tasks for this job
2023-02-14 09:18:20.978 INFO scheduler.TaskSchedulerImpl: Killing all running tasks in stage 13: Stage finished
2023-02-14 09:18:20.979 INFO scheduler.DAGScheduler: Job 8 finished: collect at ExecuteStatement.scala:90, took 0.017176 s
2023-02-14 09:18:20.979 INFO scheduler.StatsReportListener: task runtime:(count: 1, mean: 10.000000, stdev: 0.000000, max: 10.000000, min: 10.000000)
2023-02-14 09:18:20.979 INFO scheduler.StatsReportListener:     0%  5%  10% 25% 50% 75% 90% 95% 100%
2023-02-14 09:18:20.979 INFO scheduler.StatsReportListener:     10.0 ms 10.0 ms 10.0 ms 10.0 ms 10.0 ms 10.0 ms 10.0 ms 10.0 ms 10.0 ms
2023-02-14 09:18:20.979 INFO scheduler.StatsReportListener: shuffle bytes written:(count: 1, mean: 0.000000, stdev: 0.000000, max: 0.000000, min: 0.000000)
2023-02-14 09:18:20.979 INFO scheduler.StatsReportListener:     0%  5%  10% 25% 50% 75% 90% 95% 100%
2023-02-14 09:18:20.979 INFO scheduler.StatsReportListener:     0.0 B   0.0 B   0.0 B   0.0 B   0.0 B   0.0 B   0.0 B   0.0 B   0.0 B
2023-02-14 09:18:20.979 INFO scheduler.StatsReportListener: fetch wait time:(count: 1, mean: 0.000000, stdev: 0.000000, max: 0.000000, min: 0.000000)
2023-02-14 09:18:20.979 INFO scheduler.StatsReportListener:     0%  5%  10% 25% 50% 75% 90% 95% 100%
2023-02-14 09:18:20.979 INFO scheduler.StatsReportListener:     0.0 ms  0.0 ms  0.0 ms  0.0 ms  0.0 ms  0.0 ms  0.0 ms  0.0 ms  0.0 ms
2023-02-14 09:18:20.979 INFO scheduler.StatsReportListener: remote bytes read:(count: 1, mean: 0.000000, stdev: 0.000000, max: 0.000000, min: 0.000000)
2023-02-14 09:18:20.979 INFO scheduler.StatsReportListener:     0%  5%  10% 25% 50% 75% 90% 95% 100%
2023-02-14 09:18:20.979 INFO scheduler.StatsReportListener:     0.0 B   0.0 B   0.0 B   0.0 B   0.0 B   0.0 B   0.0 B   0.0 B   0.0 B
2023-02-14 09:18:20.980 INFO scheduler.StatsReportListener: task result size:(count: 1, mean: 1369.000000, stdev: 0.000000, max: 1369.000000, min: 1369.000000)
2023-02-14 09:18:20.980 INFO scheduler.StatsReportListener:     0%  5%  10% 25% 50% 75% 90% 95% 100%
2023-02-14 09:18:20.980 INFO scheduler.StatsReportListener:     1369.0 B    1369.0 B    1369.0 B    1369.0 B    1369.0 B    1369.0 B    1369.0 B    1369.0 B    1369.0 B
2023-02-14 09:18:20.980 INFO scheduler.StatsReportListener: executor (non-fetch) time pct: (count: 1, mean: 0.000000, stdev: 0.000000, max: 0.000000, min: 0.000000)
2023-02-14 09:18:20.980 INFO scheduler.StatsReportListener:     0%  5%  10% 25% 50% 75% 90% 95% 100%
2023-02-14 09:18:20.980 INFO scheduler.StatsReportListener:      0 %     0 %     0 %     0 %     0 %     0 %     0 %     0 %     0 %
2023-02-14 09:18:20.980 INFO scheduler.StatsReportListener: fetch wait time pct: (count: 1, mean: 0.000000, stdev: 0.000000, max: 0.000000, min: 0.000000)
2023-02-14 09:18:20.980 INFO scheduler.StatsReportListener:     0%  5%  10% 25% 50% 75% 90% 95% 100%
2023-02-14 09:18:20.980 INFO scheduler.StatsReportListener:      0 %     0 %     0 %     0 %     0 %     0 %     0 %     0 %     0 %
2023-02-14 09:18:20.980 INFO scheduler.StatsReportListener: other time pct: (count: 1, mean: 100.000000, stdev: 0.000000, max: 100.000000, min: 100.000000)
2023-02-14 09:18:20.980 INFO scheduler.StatsReportListener:     0%  5%  10% 25% 50% 75% 90% 95% 100%
2023-02-14 09:18:20.980 INFO operation.ExecuteStatement: Processing as-ol.lysiuk's query[4811e515-5e42-45ea-9aeb-4dacdbe2aa41]: RUNNING_STATE -> FINISHED_STATE, statement: SELECT current_database(), time taken: 0.046 seconds
2023-02-14 09:18:20.980 INFO scheduler.StatsReportListener:     100 %   100 %   100 %   100 %   100 %   100 %   100 %   100 %   100 %
2023-02-14 09:18:20.980 INFO kyuubi.SparkSQLEngineListener: Job end. Job 8 state is JobSucceeded
2023-02-14 09:18:20.980 INFO kyuubi.SQLOperationListener: Query [4811e515-5e42-45ea-9aeb-4dacdbe2aa41]: Job 8 succeeded, 0 active jobs running
2023-02-14 09:18:21.150 INFO log.OperationLog: Creating operation log file /opt/kyuubi/work/engine_operation_logs/904407b1-8cf3-476f-a730-929eecc53a90/69ef22d9-4c72-4537-b937-68edc29b65e4
2023-02-14 09:18:21.151 INFO operation.ExecuteStatement: Processing as-ol.lysiuk's query[69ef22d9-4c72-4537-b937-68edc29b65e4]: INITIALIZED_STATE -> PENDING_STATE, statement: select
    filid,
    count(IF(is_hole = 0, NULL, is_hole)) * 1.0/count(*) as ratio
from dashboard_team_dbt.holes_main_all_lagers_mart
where
    report_day = '2023-02-13'
    and business_id = 1
group by filid
2023-02-14 09:18:21.151 INFO operation.ExecuteStatement: Processing as-ol.lysiuk's query[69ef22d9-4c72-4537-b937-68edc29b65e4]: PENDING_STATE -> RUNNING_STATE, statement: select
    filid,
    count(IF(is_hole = 0, NULL, is_hole)) * 1.0/count(*) as ratio
from dashboard_team_dbt.holes_main_all_lagers_mart
where
    report_day = '2023-02-13'
    and business_id = 1
group by filid
2023-02-14 09:18:21.152 INFO operation.ExecuteStatement: 
           Spark application name: kyuubi_CONNECTION_SPARK_SQL_as-ol.lysiuk_3a27bf56-0c1b-4d96-b82c-66389785e5b4
                 application ID: spark-application-1676359040353
                 application web UI: 
                 master: k8s://https://kubernetes.default.svc
                 deploy mode: client
                 version: 3.2.2
           Start time: 2023-02-14T09:17:18.966
           User: as-ol.lysiuk
2023-02-14 09:18:26.293 INFO operation.ExecuteStatement: Processing as-ol.lysiuk's query[69ef22d9-4c72-4537-b937-68edc29b65e4]: RUNNING_STATE -> RUNNING_STATE, statement: select
    filid,
    count(IF(is_hole = 0, NULL, is_hole)) * 1.0/count(*) as ratio
from dashboard_team_dbt.holes_main_all_lagers_mart
where
    report_day = '2023-02-13'
    and business_id = 1
group by filid
2023-02-14 09:18:26.293 INFO operation.ExecuteStatement: Execute in full collect mode
2023-02-14 09:18:27.336 INFO stats.PrepareDeltaScan: DELTA: Filtering files for query
2023-02-14 09:18:27.420 INFO spark.SparkContext: Starting job: $anonfun$recordDeltaOperationInternal$1 at DatabricksLogging.scala:77
2023-02-14 09:18:27.422 INFO scheduler.DAGScheduler: Got job 9 ($anonfun$recordDeltaOperationInternal$1 at DatabricksLogging.scala:77) with 50 output partitions
2023-02-14 09:18:27.422 INFO scheduler.DAGScheduler: Final stage: ResultStage 15 ($anonfun$recordDeltaOperationInternal$1 at DatabricksLogging.scala:77)
2023-02-14 09:18:27.422 INFO scheduler.DAGScheduler: Parents of final stage: List(ShuffleMapStage 14)
2023-02-14 09:18:27.422 INFO scheduler.DAGScheduler: Missing parents: List()
2023-02-14 09:18:27.422 INFO kyuubi.SQLOperationListener: Query [69ef22d9-4c72-4537-b937-68edc29b65e4]: Job 9 started with 2 stages, 1 active jobs running
2023-02-14 09:18:27.422 INFO scheduler.DAGScheduler: Submitting ResultStage 15 (MapPartitionsRDD[44] at $anonfun$recordDeltaOperationInternal$1 at DatabricksLogging.scala:77), which has no missing parents
2023-02-14 09:18:27.423 INFO kyuubi.SQLOperationListener: Query [69ef22d9-4c72-4537-b937-68edc29b65e4]: Stage 15 started with 50 tasks, 1 active stages running
2023-02-14 09:18:27.427 INFO memory.MemoryStore: Block broadcast_13 stored as values in memory (estimated size 578.4 KiB, free 1455.6 MiB)
2023-02-14 09:18:27.430 INFO memory.MemoryStore: Block broadcast_13_piece0 stored as bytes in memory (estimated size 142.7 KiB, free 1455.4 MiB)
2023-02-14 09:18:27.430 INFO storage.BlockManagerInfo: Added broadcast_13_piece0 in memory on 172.17.18.136:36651 (size: 142.7 KiB, free: 1458.1 MiB)
2023-02-14 09:18:27.430 INFO spark.SparkContext: Created broadcast 13 from broadcast at DAGScheduler.scala:1478
2023-02-14 09:18:27.431 INFO scheduler.DAGScheduler: Submitting 50 missing tasks from ResultStage 15 (MapPartitionsRDD[44] at $anonfun$recordDeltaOperationInternal$1 at DatabricksLogging.scala:77) (first 15 tasks are for partitions Vector(0, 1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14))
2023-02-14 09:18:27.431 INFO scheduler.TaskSchedulerImpl: Adding task set 15.0 with 50 tasks resource profile 0
2023-02-14 09:18:27.432 INFO scheduler.TaskSetManager: Starting task 0.0 in stage 15.0 (TID 109) (172.17.11.222, executor 1, partition 0, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:27.432 INFO scheduler.TaskSetManager: Starting task 1.0 in stage 15.0 (TID 110) (172.17.14.122, executor 2, partition 1, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:27.438 INFO storage.BlockManagerInfo: Added broadcast_13_piece0 in memory on 172.17.11.222:41311 (size: 142.7 KiB, free: 1007.4 MiB)
2023-02-14 09:18:27.443 INFO storage.BlockManagerInfo: Added broadcast_13_piece0 in memory on 172.17.14.122:42947 (size: 142.7 KiB, free: 1007.6 MiB)
2023-02-14 09:18:27.447 INFO scheduler.TaskSetManager: Starting task 2.0 in stage 15.0 (TID 111) (172.17.11.222, executor 1, partition 2, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:27.447 INFO scheduler.TaskSetManager: Finished task 0.0 in stage 15.0 (TID 109) in 15 ms on 172.17.11.222 (executor 1) (1/50)
2023-02-14 09:18:27.457 INFO scheduler.TaskSetManager: Starting task 3.0 in stage 15.0 (TID 112) (172.17.11.222, executor 1, partition 3, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:27.457 INFO scheduler.TaskSetManager: Finished task 2.0 in stage 15.0 (TID 111) in 10 ms on 172.17.11.222 (executor 1) (2/50)
2023-02-14 09:18:27.462 INFO scheduler.TaskSetManager: Finished task 1.0 in stage 15.0 (TID 110) in 30 ms on 172.17.14.122 (executor 2) (3/50)
2023-02-14 09:18:27.465 INFO scheduler.TaskSetManager: Starting task 4.0 in stage 15.0 (TID 113) (172.17.11.222, executor 1, partition 4, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:27.465 INFO scheduler.TaskSetManager: Finished task 3.0 in stage 15.0 (TID 112) in 8 ms on 172.17.11.222 (executor 1) (4/50)
2023-02-14 09:18:27.474 INFO scheduler.TaskSetManager: Starting task 5.0 in stage 15.0 (TID 114) (172.17.11.222, executor 1, partition 5, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:27.474 INFO scheduler.TaskSetManager: Finished task 4.0 in stage 15.0 (TID 113) in 9 ms on 172.17.11.222 (executor 1) (5/50)
2023-02-14 09:18:27.485 INFO scheduler.TaskSetManager: Starting task 6.0 in stage 15.0 (TID 115) (172.17.11.222, executor 1, partition 6, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:27.485 INFO scheduler.TaskSetManager: Finished task 5.0 in stage 15.0 (TID 114) in 11 ms on 172.17.11.222 (executor 1) (6/50)
2023-02-14 09:18:27.493 INFO scheduler.TaskSetManager: Starting task 7.0 in stage 15.0 (TID 116) (172.17.11.222, executor 1, partition 7, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:27.493 INFO scheduler.TaskSetManager: Finished task 6.0 in stage 15.0 (TID 115) in 8 ms on 172.17.11.222 (executor 1) (7/50)
2023-02-14 09:18:27.501 INFO scheduler.TaskSetManager: Starting task 8.0 in stage 15.0 (TID 117) (172.17.11.222, executor 1, partition 8, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:27.501 INFO scheduler.TaskSetManager: Finished task 7.0 in stage 15.0 (TID 116) in 8 ms on 172.17.11.222 (executor 1) (8/50)
2023-02-14 09:18:27.512 INFO scheduler.TaskSetManager: Starting task 9.0 in stage 15.0 (TID 118) (172.17.11.222, executor 1, partition 9, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:27.512 INFO scheduler.TaskSetManager: Finished task 8.0 in stage 15.0 (TID 117) in 12 ms on 172.17.11.222 (executor 1) (9/50)
2023-02-14 09:18:27.520 INFO scheduler.TaskSetManager: Starting task 10.0 in stage 15.0 (TID 119) (172.17.11.222, executor 1, partition 10, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:27.520 INFO scheduler.TaskSetManager: Finished task 9.0 in stage 15.0 (TID 118) in 8 ms on 172.17.11.222 (executor 1) (10/50)
2023-02-14 09:18:27.527 INFO scheduler.TaskSetManager: Starting task 11.0 in stage 15.0 (TID 120) (172.17.11.222, executor 1, partition 11, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:27.528 INFO scheduler.TaskSetManager: Finished task 10.0 in stage 15.0 (TID 119) in 8 ms on 172.17.11.222 (executor 1) (11/50)
2023-02-14 09:18:27.583 INFO scheduler.TaskSetManager: Starting task 12.0 in stage 15.0 (TID 121) (172.17.11.222, executor 1, partition 12, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:27.583 INFO scheduler.TaskSetManager: Finished task 11.0 in stage 15.0 (TID 120) in 56 ms on 172.17.11.222 (executor 1) (12/50)
2023-02-14 09:18:27.590 INFO scheduler.TaskSetManager: Starting task 13.0 in stage 15.0 (TID 122) (172.17.11.222, executor 1, partition 13, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:27.590 INFO scheduler.TaskSetManager: Finished task 12.0 in stage 15.0 (TID 121) in 7 ms on 172.17.11.222 (executor 1) (13/50)
2023-02-14 09:18:27.598 INFO scheduler.TaskSetManager: Starting task 14.0 in stage 15.0 (TID 123) (172.17.11.222, executor 1, partition 14, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:27.598 INFO scheduler.TaskSetManager: Finished task 13.0 in stage 15.0 (TID 122) in 8 ms on 172.17.11.222 (executor 1) (14/50)
2023-02-14 09:18:27.604 INFO scheduler.TaskSetManager: Starting task 15.0 in stage 15.0 (TID 124) (172.17.11.222, executor 1, partition 15, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:27.605 INFO scheduler.TaskSetManager: Finished task 14.0 in stage 15.0 (TID 123) in 7 ms on 172.17.11.222 (executor 1) (15/50)
2023-02-14 09:18:27.612 INFO scheduler.TaskSetManager: Starting task 16.0 in stage 15.0 (TID 125) (172.17.11.222, executor 1, partition 16, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:27.612 INFO scheduler.TaskSetManager: Finished task 15.0 in stage 15.0 (TID 124) in 8 ms on 172.17.11.222 (executor 1) (16/50)
2023-02-14 09:18:27.620 INFO scheduler.TaskSetManager: Starting task 17.0 in stage 15.0 (TID 126) (172.17.11.222, executor 1, partition 17, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:27.620 INFO scheduler.TaskSetManager: Finished task 16.0 in stage 15.0 (TID 125) in 8 ms on 172.17.11.222 (executor 1) (17/50)
2023-02-14 09:18:27.626 INFO scheduler.TaskSetManager: Starting task 18.0 in stage 15.0 (TID 127) (172.17.11.222, executor 1, partition 18, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:27.627 INFO scheduler.TaskSetManager: Finished task 17.0 in stage 15.0 (TID 126) in 7 ms on 172.17.11.222 (executor 1) (18/50)
2023-02-14 09:18:27.682 INFO scheduler.TaskSetManager: Starting task 19.0 in stage 15.0 (TID 128) (172.17.11.222, executor 1, partition 19, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:27.682 INFO scheduler.TaskSetManager: Finished task 18.0 in stage 15.0 (TID 127) in 56 ms on 172.17.11.222 (executor 1) (19/50)
2023-02-14 09:18:27.690 INFO scheduler.TaskSetManager: Starting task 20.0 in stage 15.0 (TID 129) (172.17.11.222, executor 1, partition 20, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:27.690 INFO scheduler.TaskSetManager: Finished task 19.0 in stage 15.0 (TID 128) in 8 ms on 172.17.11.222 (executor 1) (20/50)
2023-02-14 09:18:27.697 INFO scheduler.TaskSetManager: Starting task 21.0 in stage 15.0 (TID 130) (172.17.11.222, executor 1, partition 21, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:27.697 INFO scheduler.TaskSetManager: Finished task 20.0 in stage 15.0 (TID 129) in 7 ms on 172.17.11.222 (executor 1) (21/50)
2023-02-14 09:18:27.704 INFO scheduler.TaskSetManager: Starting task 22.0 in stage 15.0 (TID 131) (172.17.11.222, executor 1, partition 22, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:27.704 INFO scheduler.TaskSetManager: Finished task 21.0 in stage 15.0 (TID 130) in 7 ms on 172.17.11.222 (executor 1) (22/50)
2023-02-14 09:18:27.712 INFO scheduler.TaskSetManager: Starting task 23.0 in stage 15.0 (TID 132) (172.17.11.222, executor 1, partition 23, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:27.712 INFO scheduler.TaskSetManager: Finished task 22.0 in stage 15.0 (TID 131) in 8 ms on 172.17.11.222 (executor 1) (23/50)
2023-02-14 09:18:27.720 INFO scheduler.TaskSetManager: Starting task 24.0 in stage 15.0 (TID 133) (172.17.11.222, executor 1, partition 24, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:27.720 INFO scheduler.TaskSetManager: Finished task 23.0 in stage 15.0 (TID 132) in 8 ms on 172.17.11.222 (executor 1) (24/50)
2023-02-14 09:18:27.777 INFO scheduler.TaskSetManager: Starting task 25.0 in stage 15.0 (TID 134) (172.17.11.222, executor 1, partition 25, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:27.778 INFO scheduler.TaskSetManager: Finished task 24.0 in stage 15.0 (TID 133) in 58 ms on 172.17.11.222 (executor 1) (25/50)
2023-02-14 09:18:27.785 INFO scheduler.TaskSetManager: Starting task 26.0 in stage 15.0 (TID 135) (172.17.11.222, executor 1, partition 26, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:27.785 INFO scheduler.TaskSetManager: Finished task 25.0 in stage 15.0 (TID 134) in 8 ms on 172.17.11.222 (executor 1) (26/50)
2023-02-14 09:18:27.794 INFO scheduler.TaskSetManager: Starting task 27.0 in stage 15.0 (TID 136) (172.17.11.222, executor 1, partition 27, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:27.794 INFO scheduler.TaskSetManager: Finished task 26.0 in stage 15.0 (TID 135) in 9 ms on 172.17.11.222 (executor 1) (27/50)
2023-02-14 09:18:27.802 INFO scheduler.TaskSetManager: Starting task 28.0 in stage 15.0 (TID 137) (172.17.11.222, executor 1, partition 28, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:27.802 INFO scheduler.TaskSetManager: Finished task 27.0 in stage 15.0 (TID 136) in 8 ms on 172.17.11.222 (executor 1) (28/50)
2023-02-14 09:18:27.809 INFO scheduler.TaskSetManager: Starting task 29.0 in stage 15.0 (TID 138) (172.17.11.222, executor 1, partition 29, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:27.810 INFO scheduler.TaskSetManager: Finished task 28.0 in stage 15.0 (TID 137) in 8 ms on 172.17.11.222 (executor 1) (29/50)
2023-02-14 09:18:27.817 INFO scheduler.TaskSetManager: Starting task 30.0 in stage 15.0 (TID 139) (172.17.11.222, executor 1, partition 30, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:27.817 INFO scheduler.TaskSetManager: Finished task 29.0 in stage 15.0 (TID 138) in 8 ms on 172.17.11.222 (executor 1) (30/50)
2023-02-14 09:18:27.879 INFO scheduler.TaskSetManager: Starting task 31.0 in stage 15.0 (TID 140) (172.17.11.222, executor 1, partition 31, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:27.879 INFO scheduler.TaskSetManager: Finished task 30.0 in stage 15.0 (TID 139) in 62 ms on 172.17.11.222 (executor 1) (31/50)
2023-02-14 09:18:27.888 INFO scheduler.TaskSetManager: Starting task 32.0 in stage 15.0 (TID 141) (172.17.11.222, executor 1, partition 32, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:27.888 INFO scheduler.TaskSetManager: Finished task 31.0 in stage 15.0 (TID 140) in 9 ms on 172.17.11.222 (executor 1) (32/50)
2023-02-14 09:18:27.905 INFO scheduler.TaskSetManager: Starting task 33.0 in stage 15.0 (TID 142) (172.17.11.222, executor 1, partition 33, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:27.906 INFO scheduler.TaskSetManager: Finished task 32.0 in stage 15.0 (TID 141) in 18 ms on 172.17.11.222 (executor 1) (33/50)
2023-02-14 09:18:27.912 INFO scheduler.TaskSetManager: Starting task 34.0 in stage 15.0 (TID 143) (172.17.11.222, executor 1, partition 34, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:27.913 INFO scheduler.TaskSetManager: Finished task 33.0 in stage 15.0 (TID 142) in 8 ms on 172.17.11.222 (executor 1) (34/50)
2023-02-14 09:18:27.920 INFO scheduler.TaskSetManager: Starting task 35.0 in stage 15.0 (TID 144) (172.17.11.222, executor 1, partition 35, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:27.920 INFO scheduler.TaskSetManager: Finished task 34.0 in stage 15.0 (TID 143) in 8 ms on 172.17.11.222 (executor 1) (35/50)
2023-02-14 09:18:27.928 INFO scheduler.TaskSetManager: Starting task 36.0 in stage 15.0 (TID 145) (172.17.11.222, executor 1, partition 36, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:27.928 INFO scheduler.TaskSetManager: Finished task 35.0 in stage 15.0 (TID 144) in 8 ms on 172.17.11.222 (executor 1) (36/50)
2023-02-14 09:18:27.982 INFO scheduler.TaskSetManager: Starting task 37.0 in stage 15.0 (TID 146) (172.17.11.222, executor 1, partition 37, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:27.982 INFO scheduler.TaskSetManager: Finished task 36.0 in stage 15.0 (TID 145) in 54 ms on 172.17.11.222 (executor 1) (37/50)
2023-02-14 09:18:27.990 INFO scheduler.TaskSetManager: Starting task 38.0 in stage 15.0 (TID 147) (172.17.11.222, executor 1, partition 38, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:27.991 INFO scheduler.TaskSetManager: Finished task 37.0 in stage 15.0 (TID 146) in 9 ms on 172.17.11.222 (executor 1) (38/50)
2023-02-14 09:18:27.997 INFO scheduler.TaskSetManager: Starting task 39.0 in stage 15.0 (TID 148) (172.17.11.222, executor 1, partition 39, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:27.998 INFO scheduler.TaskSetManager: Finished task 38.0 in stage 15.0 (TID 147) in 8 ms on 172.17.11.222 (executor 1) (39/50)
2023-02-14 09:18:28.005 INFO scheduler.TaskSetManager: Starting task 40.0 in stage 15.0 (TID 149) (172.17.11.222, executor 1, partition 40, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:28.005 INFO scheduler.TaskSetManager: Finished task 39.0 in stage 15.0 (TID 148) in 8 ms on 172.17.11.222 (executor 1) (40/50)
2023-02-14 09:18:28.012 INFO scheduler.TaskSetManager: Starting task 41.0 in stage 15.0 (TID 150) (172.17.11.222, executor 1, partition 41, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:28.012 INFO scheduler.TaskSetManager: Finished task 40.0 in stage 15.0 (TID 149) in 7 ms on 172.17.11.222 (executor 1) (41/50)
2023-02-14 09:18:28.019 INFO scheduler.TaskSetManager: Starting task 42.0 in stage 15.0 (TID 151) (172.17.11.222, executor 1, partition 42, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:28.019 INFO scheduler.TaskSetManager: Finished task 41.0 in stage 15.0 (TID 150) in 7 ms on 172.17.11.222 (executor 1) (42/50)
2023-02-14 09:18:28.025 INFO scheduler.TaskSetManager: Starting task 43.0 in stage 15.0 (TID 152) (172.17.11.222, executor 1, partition 43, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:28.026 INFO scheduler.TaskSetManager: Finished task 42.0 in stage 15.0 (TID 151) in 8 ms on 172.17.11.222 (executor 1) (43/50)
2023-02-14 09:18:28.032 INFO scheduler.TaskSetManager: Starting task 44.0 in stage 15.0 (TID 153) (172.17.11.222, executor 1, partition 44, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:28.033 INFO scheduler.TaskSetManager: Finished task 43.0 in stage 15.0 (TID 152) in 8 ms on 172.17.11.222 (executor 1) (44/50)
2023-02-14 09:18:28.083 INFO scheduler.TaskSetManager: Starting task 45.0 in stage 15.0 (TID 154) (172.17.11.222, executor 1, partition 45, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:28.083 INFO scheduler.TaskSetManager: Finished task 44.0 in stage 15.0 (TID 153) in 51 ms on 172.17.11.222 (executor 1) (45/50)
2023-02-14 09:18:28.091 INFO scheduler.TaskSetManager: Starting task 46.0 in stage 15.0 (TID 155) (172.17.11.222, executor 1, partition 46, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:28.091 INFO scheduler.TaskSetManager: Finished task 45.0 in stage 15.0 (TID 154) in 9 ms on 172.17.11.222 (executor 1) (46/50)
2023-02-14 09:18:28.099 INFO scheduler.TaskSetManager: Starting task 47.0 in stage 15.0 (TID 156) (172.17.11.222, executor 1, partition 47, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:28.099 INFO scheduler.TaskSetManager: Finished task 46.0 in stage 15.0 (TID 155) in 8 ms on 172.17.11.222 (executor 1) (47/50)
2023-02-14 09:18:28.107 INFO scheduler.TaskSetManager: Starting task 48.0 in stage 15.0 (TID 157) (172.17.11.222, executor 1, partition 48, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:28.107 INFO scheduler.TaskSetManager: Finished task 47.0 in stage 15.0 (TID 156) in 8 ms on 172.17.11.222 (executor 1) (48/50)
2023-02-14 09:18:28.114 INFO scheduler.TaskSetManager: Starting task 49.0 in stage 15.0 (TID 158) (172.17.11.222, executor 1, partition 49, PROCESS_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:28.114 INFO scheduler.TaskSetManager: Finished task 48.0 in stage 15.0 (TID 157) in 8 ms on 172.17.11.222 (executor 1) (49/50)
2023-02-14 09:18:28.121 INFO scheduler.TaskSetManager: Finished task 49.0 in stage 15.0 (TID 158) in 8 ms on 172.17.11.222 (executor 1) (50/50)
2023-02-14 09:18:28.121 INFO scheduler.TaskSchedulerImpl: Removed TaskSet 15.0, whose tasks have all completed, from pool 
2023-02-14 09:18:28.121 INFO scheduler.DAGScheduler: ResultStage 15 ($anonfun$recordDeltaOperationInternal$1 at DatabricksLogging.scala:77) finished in 0.698 s
2023-02-14 09:18:28.121 INFO kyuubi.SQLOperationListener: Finished stage: Stage(15, 0); Name: '$anonfun$recordDeltaOperationInternal$1 at DatabricksLogging.scala:77'; Status: succeeded; numTasks: 50; Took: 698 msec
2023-02-14 09:18:28.121 INFO scheduler.DAGScheduler: Job 9 is finished. Cancelling potential speculative or zombie tasks for this job
2023-02-14 09:18:28.121 INFO scheduler.TaskSchedulerImpl: Killing all running tasks in stage 15: Stage finished
2023-02-14 09:18:28.121 INFO scheduler.DAGScheduler: Job 9 finished: $anonfun$recordDeltaOperationInternal$1 at DatabricksLogging.scala:77, took 0.700743 s
2023-02-14 09:18:28.121 INFO scheduler.StatsReportListener: task runtime:(count: 50, mean: 14.700000, stdev: 15.759759, max: 62.000000, min: 7.000000)
2023-02-14 09:18:28.122 INFO scheduler.StatsReportListener:     0%  5%  10% 25% 50% 75% 90% 95% 100%
2023-02-14 09:18:28.122 INFO scheduler.StatsReportListener:     7.0 ms  7.0 ms  7.0 ms  8.0 ms  8.0 ms  9.0 ms  54.0 ms 56.0 ms 62.0 ms
2023-02-14 09:18:28.122 INFO scheduler.StatsReportListener: shuffle bytes written:(count: 50, mean: 0.000000, stdev: 0.000000, max: 0.000000, min: 0.000000)
2023-02-14 09:18:28.122 INFO scheduler.StatsReportListener:     0%  5%  10% 25% 50% 75% 90% 95% 100%
2023-02-14 09:18:28.122 INFO scheduler.StatsReportListener:     0.0 B   0.0 B   0.0 B   0.0 B   0.0 B   0.0 B   0.0 B   0.0 B   0.0 B
2023-02-14 09:18:28.122 INFO scheduler.StatsReportListener: fetch wait time:(count: 50, mean: 0.000000, stdev: 0.000000, max: 0.000000, min: 0.000000)
2023-02-14 09:18:28.122 INFO scheduler.StatsReportListener:     0%  5%  10% 25% 50% 75% 90% 95% 100%
2023-02-14 09:18:28.122 INFO scheduler.StatsReportListener:     0.0 ms  0.0 ms  0.0 ms  0.0 ms  0.0 ms  0.0 ms  0.0 ms  0.0 ms  0.0 ms
2023-02-14 09:18:28.122 INFO scheduler.StatsReportListener: remote bytes read:(count: 50, mean: 0.000000, stdev: 0.000000, max: 0.000000, min: 0.000000)
2023-02-14 09:18:28.122 INFO scheduler.StatsReportListener:     0%  5%  10% 25% 50% 75% 90% 95% 100%
2023-02-14 09:18:28.122 INFO scheduler.StatsReportListener:     0.0 B   0.0 B   0.0 B   0.0 B   0.0 B   0.0 B   0.0 B   0.0 B   0.0 B
2023-02-14 09:18:28.123 INFO scheduler.StatsReportListener: task result size:(count: 50, mean: 3882.540000, stdev: 51.400471, max: 4100.000000, min: 3843.000000)
2023-02-14 09:18:28.123 INFO scheduler.StatsReportListener:     0%  5%  10% 25% 50% 75% 90% 95% 100%
2023-02-14 09:18:28.123 INFO scheduler.StatsReportListener:     3.8 KiB 3.8 KiB 3.8 KiB 3.8 KiB 3.8 KiB 3.8 KiB 3.8 KiB 3.8 KiB 4.0 KiB
2023-02-14 09:18:28.123 INFO scheduler.StatsReportListener: executor (non-fetch) time pct: (count: 50, mean: 8.461454, stdev: 17.456797, max: 87.500000, min: 0.000000)
2023-02-14 09:18:28.123 INFO scheduler.StatsReportListener:     0%  5%  10% 25% 50% 75% 90% 95% 100%
2023-02-14 09:18:28.123 INFO scheduler.StatsReportListener:      0 %     0 %     0 %     0 %     0 %    13 %    18 %    22 %    88 %
2023-02-14 09:18:28.123 INFO scheduler.StatsReportListener: fetch wait time pct: (count: 50, mean: 0.000000, stdev: 0.000000, max: 0.000000, min: 0.000000)
2023-02-14 09:18:28.123 INFO scheduler.StatsReportListener:     0%  5%  10% 25% 50% 75% 90% 95% 100%
2023-02-14 09:18:28.123 INFO scheduler.StatsReportListener:      0 %     0 %     0 %     0 %     0 %     0 %     0 %     0 %     0 %
2023-02-14 09:18:28.123 INFO scheduler.StatsReportListener: other time pct: (count: 50, mean: 91.538546, stdev: 17.456797, max: 100.000000, min: 12.500000)
2023-02-14 09:18:28.123 INFO scheduler.StatsReportListener:     0%  5%  10% 25% 50% 75% 90% 95% 100%
2023-02-14 09:18:28.123 INFO scheduler.StatsReportListener:     13 %    78 %    83 %    88 %    100 %   100 %   100 %   100 %   100 %
2023-02-14 09:18:28.123 INFO kyuubi.SparkSQLEngineListener: Job end. Job 9 state is JobSucceeded
2023-02-14 09:18:28.124 INFO kyuubi.SQLOperationListener: Query [69ef22d9-4c72-4537-b937-68edc29b65e4]: Job 9 succeeded, 0 active jobs running
2023-02-14 09:18:28.137 INFO codegen.CodeGenerator: Code generated in 12.250011 ms
2023-02-14 09:18:28.139 INFO stats.PrepareDeltaScan: DELTA: Done
2023-02-14 09:18:28.143 INFO datasources.DataSourceStrategy: Pruning directories with: isnotnull(report_day#633),(report_day#633 = 2023-02-13)
2023-02-14 09:18:28.144 INFO datasources.FileSourceStrategy: Pushed Filters: IsNotNull(business_id),EqualTo(business_id,1)
2023-02-14 09:18:28.144 INFO datasources.FileSourceStrategy: Post-Scan Filters: isnotnull(business_id#634),(business_id#634 = 1)
2023-02-14 09:18:28.145 INFO datasources.FileSourceStrategy: Output Data Schema: struct<business_id: int, filid: int, is_hole: int ... 1 more fields>
2023-02-14 09:18:28.166 INFO storage.BlockManagerInfo: Removed broadcast_11_piece0 on 172.17.18.136:36651 in memory (size: 20.5 KiB, free: 1458.2 MiB)
2023-02-14 09:18:28.167 INFO storage.BlockManagerInfo: Removed broadcast_11_piece0 on 172.17.11.222:41311 in memory (size: 20.5 KiB, free: 1007.4 MiB)
2023-02-14 09:18:28.175 INFO memory.MemoryStore: Block broadcast_14 stored as values in memory (estimated size 389.1 KiB, free 1455.1 MiB)
2023-02-14 09:18:28.181 INFO storage.BlockManagerInfo: Removed broadcast_12_piece0 on 172.17.18.136:36651 in memory (size: 3.7 KiB, free: 1458.2 MiB)
2023-02-14 09:18:28.181 INFO storage.BlockManagerInfo: Removed broadcast_12_piece0 on 172.17.11.222:41311 in memory (size: 3.7 KiB, free: 1007.4 MiB)
2023-02-14 09:18:28.184 INFO memory.MemoryStore: Block broadcast_14_piece0 stored as bytes in memory (estimated size 38.3 KiB, free 1455.1 MiB)
2023-02-14 09:18:28.185 INFO storage.BlockManagerInfo: Added broadcast_14_piece0 in memory on 172.17.18.136:36651 (size: 38.3 KiB, free: 1458.1 MiB)
2023-02-14 09:18:28.185 INFO storage.BlockManagerInfo: Removed broadcast_9_piece0 on 172.17.18.136:36651 in memory (size: 142.7 KiB, free: 1458.3 MiB)
2023-02-14 09:18:28.185 INFO storage.BlockManagerInfo: Removed broadcast_9_piece0 on 172.17.11.222:41311 in memory (size: 142.7 KiB, free: 1007.5 MiB)
2023-02-14 09:18:28.185 INFO spark.SparkContext: Created broadcast 14 from collect at ExecuteStatement.scala:90
2023-02-14 09:18:28.187 INFO storage.BlockManagerInfo: Removed broadcast_9_piece0 on 172.17.14.122:42947 in memory (size: 142.7 KiB, free: 1007.7 MiB)
2023-02-14 09:18:28.189 INFO execution.FileSourceScanExec: Planning scan with bin packing, max size: 32431053 bytes, open cost is considered as scanning 4194304 bytes.
2023-02-14 09:18:28.191 INFO storage.BlockManagerInfo: Removed broadcast_13_piece0 on 172.17.18.136:36651 in memory (size: 142.7 KiB, free: 1458.4 MiB)
2023-02-14 09:18:28.191 INFO storage.BlockManagerInfo: Removed broadcast_13_piece0 on 172.17.11.222:41311 in memory (size: 142.7 KiB, free: 1007.7 MiB)
2023-02-14 09:18:28.192 INFO storage.BlockManagerInfo: Removed broadcast_13_piece0 on 172.17.14.122:42947 in memory (size: 142.7 KiB, free: 1007.8 MiB)
2023-02-14 09:18:28.196 INFO scheduler.DAGScheduler: Registering RDD 48 (collect at ExecuteStatement.scala:90) as input to shuffle 3
2023-02-14 09:18:28.196 INFO scheduler.DAGScheduler: Got map stage job 10 (collect at ExecuteStatement.scala:90) with 3 output partitions
2023-02-14 09:18:28.196 INFO scheduler.DAGScheduler: Final stage: ShuffleMapStage 16 (collect at ExecuteStatement.scala:90)
2023-02-14 09:18:28.196 INFO scheduler.DAGScheduler: Parents of final stage: List()
2023-02-14 09:18:28.196 INFO scheduler.DAGScheduler: Missing parents: List()
2023-02-14 09:18:28.196 INFO scheduler.DAGScheduler: Submitting ShuffleMapStage 16 (MapPartitionsRDD[48] at collect at ExecuteStatement.scala:90), which has no missing parents
2023-02-14 09:18:28.199 INFO memory.MemoryStore: Block broadcast_15 stored as values in memory (estimated size 42.9 KiB, free 1456.5 MiB)
2023-02-14 09:18:28.200 INFO memory.MemoryStore: Block broadcast_15_piece0 stored as bytes in memory (estimated size 19.3 KiB, free 1456.4 MiB)
2023-02-14 09:18:28.201 INFO storage.BlockManagerInfo: Added broadcast_15_piece0 in memory on 172.17.18.136:36651 (size: 19.3 KiB, free: 1458.4 MiB)
2023-02-14 09:18:28.201 INFO spark.SparkContext: Created broadcast 15 from broadcast at DAGScheduler.scala:1478
2023-02-14 09:18:28.201 INFO scheduler.DAGScheduler: Submitting 3 missing tasks from ShuffleMapStage 16 (MapPartitionsRDD[48] at collect at ExecuteStatement.scala:90) (first 15 tasks are for partitions Vector(0, 1, 2))
2023-02-14 09:18:28.201 INFO scheduler.TaskSchedulerImpl: Adding task set 16.0 with 3 tasks resource profile 0
2023-02-14 09:18:28.202 INFO scheduler.TaskSetManager: Starting task 0.0 in stage 16.0 (TID 159) (172.17.11.222, executor 1, partition 0, PROCESS_LOCAL, 5054 bytes) taskResourceAssignments Map()
2023-02-14 09:18:28.202 INFO scheduler.TaskSetManager: Starting task 1.0 in stage 16.0 (TID 160) (172.17.14.122, executor 2, partition 1, PROCESS_LOCAL, 5054 bytes) taskResourceAssignments Map()
2023-02-14 09:18:28.202 INFO scheduler.TaskSetManager: Starting task 2.0 in stage 16.0 (TID 161) (172.17.19.106, executor 3, partition 2, PROCESS_LOCAL, 5054 bytes) taskResourceAssignments Map()
2023-02-14 09:18:28.207 INFO storage.BlockManagerInfo: Added broadcast_15_piece0 in memory on 172.17.11.222:41311 (size: 19.3 KiB, free: 1007.7 MiB)
2023-02-14 09:18:28.211 INFO storage.BlockManagerInfo: Added broadcast_15_piece0 in memory on 172.17.14.122:42947 (size: 19.3 KiB, free: 1007.8 MiB)
2023-02-14 09:18:28.294 INFO storage.BlockManagerInfo: Added broadcast_14_piece0 in memory on 172.17.11.222:41311 (size: 38.3 KiB, free: 1007.6 MiB)
2023-02-14 09:18:28.479 INFO scheduler.TaskSetManager: Finished task 0.0 in stage 16.0 (TID 159) in 277 ms on 172.17.11.222 (executor 1) (1/3)
2023-02-14 09:18:28.562 INFO storage.BlockManagerInfo: Added broadcast_14_piece0 in memory on 172.17.14.122:42947 (size: 38.3 KiB, free: 1007.8 MiB)
2023-02-14 09:18:28.667 INFO storage.BlockManagerInfo: Added broadcast_15_piece0 in memory on 172.17.19.106:41349 (size: 19.3 KiB, free: 1007.8 MiB)
2023-02-14 09:18:30.980 INFO storage.BlockManagerInfo: Added broadcast_14_piece0 in memory on 172.17.19.106:41349 (size: 38.3 KiB, free: 1007.8 MiB)
2023-02-14 09:18:32.368 INFO scheduler.TaskSetManager: Finished task 1.0 in stage 16.0 (TID 160) in 4166 ms on 172.17.14.122 (executor 2) (2/3)
2023-02-14 09:18:33.680 INFO scheduler.TaskSetManager: Finished task 2.0 in stage 16.0 (TID 161) in 5478 ms on 172.17.19.106 (executor 3) (3/3)
2023-02-14 09:18:33.681 INFO scheduler.TaskSchedulerImpl: Removed TaskSet 16.0, whose tasks have all completed, from pool 
2023-02-14 09:18:33.681 INFO scheduler.DAGScheduler: ShuffleMapStage 16 (collect at ExecuteStatement.scala:90) finished in 5.484 s
2023-02-14 09:18:33.681 INFO scheduler.DAGScheduler: looking for newly runnable stages
2023-02-14 09:18:33.681 INFO scheduler.DAGScheduler: running: Set()
2023-02-14 09:18:33.681 INFO scheduler.DAGScheduler: waiting: Set()
2023-02-14 09:18:33.681 INFO scheduler.DAGScheduler: failed: Set()
2023-02-14 09:18:33.682 INFO kyuubi.SparkSQLEngineListener: Job end. Job 10 state is JobSucceeded
2023-02-14 09:18:33.683 INFO adaptive.ShufflePartitionsUtil: For shuffle(3), advisory target size: 67108864, actual target size 1048576, minimum partition size: 1048576
2023-02-14 09:18:33.688 INFO aggregate.HashAggregateExec: spark.sql.codegen.aggregate.map.twolevel.enabled is set to true, but current version of codegened fast hashmap does not support this aggregate.
2023-02-14 09:18:33.703 INFO spark.SparkContext: Starting job: collect at ExecuteStatement.scala:90
2023-02-14 09:18:33.703 INFO scheduler.DAGScheduler: Got job 11 (collect at ExecuteStatement.scala:90) with 1 output partitions
2023-02-14 09:18:33.704 INFO scheduler.DAGScheduler: Final stage: ResultStage 18 (collect at ExecuteStatement.scala:90)
2023-02-14 09:18:33.704 INFO scheduler.DAGScheduler: Parents of final stage: List(ShuffleMapStage 17)
2023-02-14 09:18:33.704 INFO scheduler.DAGScheduler: Missing parents: List()
2023-02-14 09:18:33.704 INFO scheduler.DAGScheduler: Submitting ResultStage 18 (MapPartitionsRDD[51] at collect at ExecuteStatement.scala:90), which has no missing parents
2023-02-14 09:18:33.709 INFO memory.MemoryStore: Block broadcast_16 stored as values in memory (estimated size 43.0 KiB, free 1456.4 MiB)
2023-02-14 09:18:33.710 INFO memory.MemoryStore: Block broadcast_16_piece0 stored as bytes in memory (estimated size 20.6 KiB, free 1456.4 MiB)
2023-02-14 09:18:33.711 INFO storage.BlockManagerInfo: Added broadcast_16_piece0 in memory on 172.17.18.136:36651 (size: 20.6 KiB, free: 1458.4 MiB)
2023-02-14 09:18:33.711 INFO spark.SparkContext: Created broadcast 16 from broadcast at DAGScheduler.scala:1478
2023-02-14 09:18:33.711 INFO scheduler.DAGScheduler: Submitting 1 missing tasks from ResultStage 18 (MapPartitionsRDD[51] at collect at ExecuteStatement.scala:90) (first 15 tasks are for partitions Vector(0))
2023-02-14 09:18:33.711 INFO scheduler.TaskSchedulerImpl: Adding task set 18.0 with 1 tasks resource profile 0
2023-02-14 09:18:33.712 INFO scheduler.TaskSetManager: Starting task 0.0 in stage 18.0 (TID 162) (172.17.14.122, executor 2, partition 0, NODE_LOCAL, 4465 bytes) taskResourceAssignments Map()
2023-02-14 09:18:33.730 INFO storage.BlockManagerInfo: Added broadcast_16_piece0 in memory on 172.17.14.122:42947 (size: 20.6 KiB, free: 1007.8 MiB)
2023-02-14 09:18:33.758 INFO spark.MapOutputTrackerMasterEndpoint: Asked to send map output locations for shuffle 3 to 172.17.14.122:47336
2023-02-14 09:18:33.871 INFO scheduler.TaskSetManager: Finished task 0.0 in stage 18.0 (TID 162) in 159 ms on 172.17.14.122 (executor 2) (1/1)
2023-02-14 09:18:33.871 INFO scheduler.TaskSchedulerImpl: Removed TaskSet 18.0, whose tasks have all completed, from pool 
2023-02-14 09:18:33.872 INFO scheduler.DAGScheduler: ResultStage 18 (collect at ExecuteStatement.scala:90) finished in 0.163 s
2023-02-14 09:18:33.872 INFO scheduler.DAGScheduler: Job 11 is finished. Cancelling potential speculative or zombie tasks for this job
2023-02-14 09:18:33.872 INFO scheduler.TaskSchedulerImpl: Killing all running tasks in stage 18: Stage finished
2023-02-14 09:18:33.872 INFO kyuubi.SparkSQLEngineListener: Job end. Job 11 state is JobSucceeded
2023-02-14 09:18:33.872 INFO scheduler.DAGScheduler: Job 11 finished: collect at ExecuteStatement.scala:90, took 0.169065 s
2023-02-14 09:18:33.880 INFO codegen.CodeGenerator: Code generated in 5.308162 ms
2023-02-14 09:18:33.883 INFO operation.ExecuteStatement: Processing as-ol.lysiuk's query[69ef22d9-4c72-4537-b937-68edc29b65e4]: RUNNING_STATE -> FINISHED_STATE, statement: select
    filid,
    count(IF(is_hole = 0, NULL, is_hole)) * 1.0/count(*) as ratio
from dashboard_team_dbt.holes_main_all_lagers_mart
where
    report_day = '2023-02-13'
    and business_id = 1
group by filid, time taken: 12.732 seconds
2023-02-14 09:27:22.565 INFO storage.BlockManagerInfo: Removed broadcast_15_piece0 on 172.17.18.136:36651 in memory (size: 19.3 KiB, free: 1458.4 MiB)
2023-02-14 09:27:22.566 INFO storage.BlockManagerInfo: Removed broadcast_15_piece0 on 172.17.11.222:41311 in memory (size: 19.3 KiB, free: 1007.6 MiB)
2023-02-14 09:27:22.567 INFO storage.BlockManagerInfo: Removed broadcast_15_piece0 on 172.17.14.122:42947 in memory (size: 19.3 KiB, free: 1007.8 MiB)
2023-02-14 09:27:22.571 INFO storage.BlockManagerInfo: Removed broadcast_15_piece0 on 172.17.19.106:41349 in memory (size: 19.3 KiB, free: 1007.8 MiB)
2023-02-14 09:27:22.574 INFO storage.BlockManagerInfo: Removed broadcast_14_piece0 on 172.17.18.136:36651 in memory (size: 38.3 KiB, free: 1458.4 MiB)
2023-02-14 09:27:22.574 INFO storage.BlockManagerInfo: Removed broadcast_14_piece0 on 172.17.11.222:41311 in memory (size: 38.3 KiB, free: 1007.7 MiB)
2023-02-14 09:27:22.575 INFO storage.BlockManagerInfo: Removed broadcast_14_piece0 on 172.17.14.122:42947 in memory (size: 38.3 KiB, free: 1007.8 MiB)
2023-02-14 09:27:22.575 INFO storage.BlockManagerInfo: Removed broadcast_14_piece0 on 172.17.19.106:41349 in memory (size: 38.3 KiB, free: 1007.8 MiB)
2023-02-14 09:27:22.578 INFO storage.BlockManagerInfo: Removed broadcast_16_piece0 on 172.17.18.136:36651 in memory (size: 20.6 KiB, free: 1458.4 MiB)
2023-02-14 09:27:22.579 INFO storage.BlockManagerInfo: Removed broadcast_16_piece0 on 172.17.14.122:42947 in memory (size: 20.6 KiB, free: 1007.8 MiB)
2023-02-14 09:27:22.582 INFO storage.BlockManagerInfo: Removed broadcast_10_piece0 on 172.17.18.136:36651 in memory (size: 38.3 KiB, free: 1458.5 MiB)
2023-02-14 09:27:22.668 INFO k8s.KubernetesClusterSchedulerBackend: Decommission executors: 3
2023-02-14 09:27:22.669 INFO k8s.KubernetesClusterSchedulerBackend: Notify executor 3 to decommissioning.
2023-02-14 09:27:22.670 INFO storage.BlockManagerMasterEndpoint: Mark BlockManagers (BlockManagerId(3, 172.17.19.106, 41349, None)) as being decommissioning.
2023-02-14 09:27:22.671 INFO spark.ExecutorAllocationManager: Executors 3 removed due to idle timeout.
2023-02-14 09:27:23.685 ERROR scheduler.TaskSchedulerImpl: Lost executor 3 on 172.17.19.106: Executor decommission.
2023-02-14 09:27:23.687 INFO scheduler.DAGScheduler: Executor lost: 3 (epoch 3)
2023-02-14 09:27:23.688 INFO storage.BlockManagerMasterEndpoint: Trying to remove executor 3 from BlockManagerMaster.
2023-02-14 09:27:23.689 INFO storage.BlockManagerMasterEndpoint: Removing block manager BlockManagerId(3, 172.17.19.106, 41349, None)
2023-02-14 09:27:23.689 INFO dynalloc.ExecutorMonitor: Executor 3 is removed. Remove reason statistics: (gracefully decommissioned: 1, decommision unfinished: 0, driver killed: 0, unexpectedly exited: 0).
2023-02-14 09:27:23.689 INFO storage.BlockManagerMaster: Removed 3 successfully in removeExecutor
2023-02-14 09:27:23.689 INFO scheduler.DAGScheduler: Shuffle files lost for executor: 3 (epoch 3)
2023-02-14 09:27:24.569 INFO storage.BlockManagerMasterEndpoint: Trying to remove executor 3 from BlockManagerMaster.
2023-02-14 09:27:24.570 INFO storage.BlockManagerMaster: Removal of executor 3 requested
2023-02-14 09:27:24.570 INFO k8s.KubernetesClusterSchedulerBackend$KubernetesDriverEndpoint: Asked to remove non-existent executor 3
2023-02-14 09:52:31.017 INFO session.SparkSQLSessionManager: SessionHandle [904407b1-8cf3-476f-a730-929eecc53a90] is closed, current opening sessions 0
2023-02-14 09:52:31.019 INFO session.SparkSQLSessionManager: Session stopped due to shared level is Connection.
2023-02-14 09:52:31.020 INFO spark.SparkSQLEngine: Service: [SparkTBinaryFrontend] is stopping.
2023-02-14 09:52:31.020 INFO spark.SparkTBinaryFrontendService: Service: [EngineServiceDiscovery] is stopping.
2023-02-14 09:52:31.026 WARN zookeeper.ServiceDiscoveryClient: This Kyuubi instance 172.17.18.136:44757 is now de-registered from ZooKeeper. The server will be shut down after the last client session completes.
2023-02-14 09:52:31.027 INFO client.EngineServiceDiscovery: Clean up discovery service due to this is connection share level.
2023-02-14 09:52:31.027 INFO imps.CuratorFrameworkImpl: backgroundOperationsLoop exiting
2023-02-14 09:52:31.030 WARN zookeeper.ClientCnxn: An exception was thrown while closing send thread for session 0x100f5d5f47b69f1.
EndOfStreamException: Unable to read additional data from server sessionid 0x100f5d5f47b69f1, likely server has closed socket
    at org.apache.zookeeper.ClientCnxnSocketNIO.doIO(ClientCnxnSocketNIO.java:77)
    at org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(ClientCnxnSocketNIO.java:350)
    at org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1275)
2023-02-14 09:52:31.131 INFO zookeeper.ZooKeeper: Session: 0x100f5d5f47b69f1 closed
2023-02-14 09:52:31.134 INFO client.EngineServiceDiscovery: Service[EngineServiceDiscovery] is stopped.
2023-02-14 09:52:31.134 INFO spark.SparkTBinaryFrontendService: Service[SparkTBinaryFrontend] is stopped.
2023-02-14 09:52:31.134 INFO spark.SparkTBinaryFrontendService: SparkTBinaryFrontend has stopped
2023-02-14 09:52:31.134 INFO spark.SparkSQLEngine: Service: [SparkSQLBackendService] is stopping.
2023-02-14 09:52:31.134 INFO spark.SparkSQLBackendService: Service: [SparkSQLSessionManager] is stopping.
2023-02-14 09:52:31.135 INFO session.SparkSQLSessionManager: Service: [SparkSQLOperationManager] is stopping.
2023-02-14 09:52:31.135 INFO operation.SparkSQLOperationManager: Service[SparkSQLOperationManager] is stopped.
2023-02-14 09:52:31.135 INFO session.SparkSQLSessionManager: Service[SparkSQLSessionManager] is stopped.
2023-02-14 09:52:41.135 INFO spark.SparkSQLBackendService: Service[SparkSQLBackendService] is stopped.
2023-02-14 09:52:41.135 INFO spark.SparkSQLEngine: Service[SparkSQLEngine] is stopped.
2023-02-14 09:52:41.135 INFO zookeeper.ClientCnxn: EventThread shut down for session: 0x100f5d5f47b69f1
2023-02-14 09:52:41.150 INFO k8s.KubernetesClusterSchedulerBackend: Shutting down all executors
2023-02-14 09:52:41.150 INFO k8s.KubernetesClusterSchedulerBackend$KubernetesDriverEndpoint: Asking each executor to shut down
2023-02-14 09:52:41.155 WARN k8s.ExecutorPodsWatchSnapshotSource: Kubernetes client has been closed.
2023-02-14 09:52:41.380 INFO spark.MapOutputTrackerMasterEndpoint: MapOutputTrackerMasterEndpoint stopped!
2023-02-14 09:52:41.400 INFO memory.MemoryStore: MemoryStore cleared
2023-02-14 09:52:41.400 INFO storage.BlockManager: BlockManager stopped
2023-02-14 09:52:41.402 INFO storage.BlockManagerMaster: BlockManagerMaster stopped
2023-02-14 09:52:41.409 INFO sink.StatsdSink: StatsdSink stopped.
2023-02-14 09:52:41.411 INFO scheduler.OutputCommitCoordinator$OutputCommitCoordinatorEndpoint: OutputCommitCoordinator stopped!
2023-02-14 09:52:41.416 INFO spark.SparkContext: Successfully stopped SparkContext
2023-02-14 11:31:11.600 INFO spark.SparkTBinaryFrontendService: Received request of closing SessionHandle [904407b1-8cf3-476f-a730-929eecc53a90]
2023-02-14 11:31:11.610 ERROR spark.SparkTBinaryFrontendService: Error closing session: 
org.apache.kyuubi.KyuubiSQLException: Invalid SessionHandle [904407b1-8cf3-476f-a730-929eecc53a90]
    at org.apache.kyuubi.KyuubiSQLException$.apply(KyuubiSQLException.scala:69)
    at org.apache.kyuubi.session.SessionManager.closeSession(SessionManager.scala:90)
    at org.apache.kyuubi.engine.spark.session.SparkSQLSessionManager.closeSession(SparkSQLSessionManager.scala:107)
    at org.apache.kyuubi.service.AbstractBackendService.closeSession(AbstractBackendService.scala:49)
    at org.apache.kyuubi.service.TFrontendService.CloseSession(TFrontendService.scala:189)
    at org.apache.hive.service.rpc.thrift.TCLIService$Processor$CloseSession.getResult(TCLIService.java:1517)
    at org.apache.hive.service.rpc.thrift.TCLIService$Processor$CloseSession.getResult(TCLIService.java:1502)
    at org.apache.thrift.ProcessFunction.process(ProcessFunction.java:38)
    at org.apache.thrift.TBaseProcessor.process(TBaseProcessor.java:39)
    at org.apache.kyuubi.service.authentication.TSetIpAddressProcessor.process(TSetIpAddressProcessor.scala:36)
    at org.apache.thrift.server.TThreadPoolServer$WorkerProcess.run(TThreadPoolServer.java:310)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:750)
2023-02-14 11:31:11.612 INFO spark.SparkTBinaryFrontendService: Finished closing SessionHandle [904407b1-8cf3-476f-a730-929eecc53a90]
2023-02-14 11:31:11.616 INFO events.SparkEventLoggingService: Service[EventLogging] is stopped.
2023-02-14 11:31:11.617 INFO util.ShutdownHookManager: Shutdown hook called
2023-02-14 11:31:11.618 INFO util.ShutdownHookManager: Deleting directory /tmp/spark-42ddad3b-3e4f-472a-abba-01448b518d38
2023-02-14 11:31:11.620 INFO util.ShutdownHookManager: Deleting directory /tmp/spark-73370cd1-ed14-4598-b01b-9e7cc170bb7c
2023-02-14 11:31:11.623 INFO impl.MetricsSystemImpl: Stopping s3a-file-system metrics system...
2023-02-14 11:31:11.623 INFO impl.MetricsSystemImpl: s3a-file-system metrics system stopped.
2023-02-14 11:31:11.623 INFO impl.MetricsSystemImpl: s3a-file-system metrics system shutdown complete.
hanna-liashchuk commented 1 year ago

@pan3793 I've noticed that session 904407b1-8cf3-476f-a730-929eecc53a90 is closed twice first we can see 

2023-02-14 09:52:31.017 INFO session.SparkSQLSessionManager: SessionHandle [904407b1-8cf3-476f-a730-929eecc53a90] is closed, current opening sessions 0

and then 

2023-02-14 11:31:11.600 INFO spark.SparkTBinaryFrontendService: Received request of closing SessionHandle [904407b1-8cf3-476f-a730-929eecc53a90]
2023-02-14 11:31:11.610 ERROR spark.SparkTBinaryFrontendService: Error closing session: 
org.apache.kyuubi.KyuubiSQLException: Invalid SessionHandle [904407b1-8cf3-476f-a730-929eecc53a90]
hanna-liashchuk commented 1 year ago

@pan3793 WDYT about this PR?

pan3793 commented 1 year ago 
2023-02-14 09:18:33.883 INFO operation.ExecuteStatement: Processing as-ol.lysiuk's query[69ef22d9-4c72-4537-b937-68edc29b65e4]: RUNNING_STATE -> FINISHED_STATE, ...
...
2023-02-14 09:52:31.017 INFO session.SparkSQLSessionManager: SessionHandle [904407b1-8cf3-476f-a730-929eecc53a90] is closed, current opening sessions 0

The first time close caused by session idle timeout, since you have the following configuration

kyuubi.session.idle.timeout                 PT30M
kyuubi.session.check.interval               PT5M (it's default value)

Then later, when the client requested to close the session, it had been closed.