Weird delay during SparkSession opens? #5461

minyk · 2023-10-18T08:28:28Z

minyk
Oct 18, 2023

Hi, all

We're experiencing some unknown delay before query: spark log:

23/10/18 11:08:02 INFO SparkTBinaryFrontendService [SparkTBinaryFrontendHandler-Pool: Thread-562292]: Client protocol version: HIVE_CLI_SERVICE_PROTOCOL_V10
23/10/18 11:08:02 INFO SparkSQLSessionManager [SparkTBinaryFrontendHandler-Pool: Thread-562292]: Opening session for [email protected]
23/10/18 11:08:02 WARN SparkSessionImpl [SparkTBinaryFrontendHandler-Pool: Thread-562292]:  Cannot modify the value of a Spark config: spark.ui.port. See also 'https://spark.apache.org/docs/latest/sql-migration-guide.html#ddl-statements'        
23/10/18 11:08:02 WARN SparkSessionImpl [SparkTBinaryFrontendHandler-Pool: Thread-562292]:  Cannot modify the value of a Spark config: spark.driver.memory. See also 'https://spark.apache.org/docs/latest/sql-migration-guide.html#ddl-statements'        
23/10/18 11:15:39 WARN SparkSessionImpl [SparkTBinaryFrontendHandler-Pool: Thread-562292]:  Cannot modify the value of a Spark config: spark.dynamicAllocation.maxExecutors. See also 'https://spark.apache.org/docs/latest/sql-migration-guide.html#ddl-statements'        
23/10/18 11:15:39 WARN SparkSessionImpl [SparkTBinaryFrontendHandler-Pool: Thread-562292]:  Cannot modify the value of a Spark config: spark.driver.cores. See also 'https://spark.apache.org/docs/latest/sql-migration-guide.html#ddl-statements'        
23/10/18 11:15:39 WARN SparkSessionImpl [SparkTBinaryFrontendHandler-Pool: Thread-562292]:  Cannot modify the value of a Spark config: spark.executor.memory. See also 'https://spark.apache.org/docs/latest/sql-migration-guide.html#ddl-statements'        
23/10/18 11:15:39 WARN SparkSessionImpl [SparkTBinaryFrontendHandler-Pool: Thread-562292]:  Cannot modify the value of a Spark config: spark.executor.cores. See also 'https://spark.apache.org/docs/latest/sql-migration-guide.html#ddl-statements'        
23/10/18 11:15:39 INFO SparkSQLSessionManager [SparkTBinaryFrontendHandler-Pool: Thread-562292]: etladmin's session with SessionHandle [0d3fa5a4-f558-4a54-a868-0a2f8c9af134] is opened, current opening sessions 23
23/10/18 11:15:39 INFO OperationLog [SparkTBinaryFrontendHandler-Pool: Thread-562292]: Creating operation log file /opt/spark/work-dir/engine_operation_logs/0d3fa5a4-f558-4a54-a868-0a2f8c9af134/d6c6004a-b365-4f70-b7b0-a0ea4c81ab6d
23/10/18 11:15:39 INFO OperationLog [SparkTBinaryFrontendHandler-Pool: Thread-562292]: Creating operation log file /opt/spark/work-dir/engine_operation_logs/0d3fa5a4-f558-4a54-a868-0a2f8c9af134/8358571d-b24f-4e98-8443-426dd0074ff4
23/10/18 11:15:49 INFO OperationLog [SparkTBinaryFrontendHandler-Pool: Thread-562292]: Creating operation log file /opt/spark/work-dir/engine_operation_logs/0d3fa5a4-f558-4a54-a868-0a2f8c9af134/af7fbd09-ddbf-4f4c-b106-31017e62a23c
23/10/18 11:16:11 INFO SparkTBinaryFrontendService [SparkTBinaryFrontendHandler-Pool: Thread-562292]: Received request of closing SessionHandle [0d3fa5a4-f558-4a54-a868-0a2f8c9af134]
23/10/18 11:16:11 INFO SparkSQLSessionManager [SparkTBinaryFrontendHandler-Pool: Thread-562292]: SessionHandle [0d3fa5a4-f558-4a54-a868-0a2f8c9af134] is closed, current opening sessions 14
23/10/18 11:16:11 INFO SparkTBinaryFrontendService [SparkTBinaryFrontendHandler-Pool: Thread-562292]: Finished closing SessionHandle [0d3fa5a4-f558-4a54-a868-0a2f8c9af134]

Connected at 11:08:02, but session opened after almost 7.5 minutes after at 11:15:39. The weird delay happened between this two logs:

23/10/18 11:08:02 WARN SparkSessionImpl [SparkTBinaryFrontendHandler-Pool: Thread-562292]:  Cannot modify the value of a Spark config: spark.driver.memory. See also 'https://spark.apache.org/docs/latest/sql-migration-guide.html#ddl-statements'        
23/10/18 11:15:39 WARN SparkSessionImpl [SparkTBinaryFrontendHandler-Pool: Thread-562292]:  Cannot modify the value of a Spark config: spark.dynamicAllocation.maxExecutors. See also 'https://spark.apache.org/docs/latest/sql-migration-guide.html#ddl-statements'

It's not kyuubi's codes but spark's. And sometimes occurs, but if this happens, always happen between this two lines. Almost cases we're fine.

I think it's not related to GC. I could not get any gc logs with G1GC and gc verbose options.

Kyuubi and spark deployed in Kubernetes env.

Any help would be greatly appreciated.

Thank you.

Answered by yaooqinn

Oct 18, 2023

Is it possible to get thread dumps during the jam?

View full answer

yaooqinn · 2023-10-18T09:08:00Z

yaooqinn
Oct 18, 2023
Collaborator

Is it possible to get thread dumps during the jam?

1 reply

minyk Oct 18, 2023
Author

I'll try this tonight. thx.

minyk · 2023-10-20T02:42:23Z

minyk
Oct 20, 2023
Author

We found blocked thread:

2023-10-20T08:58:43+09:00	"SparkTBinaryFrontendHandler-Pool: Thread-1891018" #1891018 prio=5 os_prio=0 tid=0x00007f4d1801a000 nid=0x1d2ff0 waiting for monitor entry [0x00007f489c454000]
2023-10-20T08:58:43+09:00	   java.lang.Thread.State: BLOCKED (on object monitor)
2023-10-20T08:58:43+09:00		at org.apache.spark.sql.hive.HiveExternalCatalog.withClient(HiveExternalCatalog.scala:101)
2023-10-20T08:58:43+09:00		- waiting to lock <0x00007f514744ce08> (a org.apache.spark.sql.hive.HiveExternalCatalog)
2023-10-20T08:58:43+09:00		at org.apache.spark.sql.hive.HiveExternalCatalog.databaseExists(HiveExternalCatalog.scala:223)
2023-10-20T08:58:43+09:00		at org.apache.spark.sql.catalyst.catalog.ExternalCatalogWithListener.databaseExists(ExternalCatalogWithListener.scala:69)
2023-10-20T08:58:43+09:00		at org.apache.spark.sql.catalyst.catalog.SessionCatalog.databaseExists(SessionCatalog.scala:290)
2023-10-20T08:58:43+09:00		at org.apache.spark.sql.catalyst.catalog.SessionCatalog.requireDbExists(SessionCatalog.scala:218)
2023-10-20T08:58:43+09:00		at org.apache.spark.sql.catalyst.catalog.SessionCatalog.setCurrentDatabase(SessionCatalog.scala:309)
2023-10-20T08:58:43+09:00		at org.apache.spark.sql.connector.catalog.CatalogManager.setCurrentNamespace(CatalogManager.scala:109)
2023-10-20T08:58:43+09:00		- locked <0x00007f5a0071d9d8> (a org.apache.spark.sql.connector.catalog.CatalogManager)
2023-10-20T08:58:43+09:00		at org.apache.kyuubi.engine.spark.shim.CatalogShim_v3_0.setCurrentDatabase(CatalogShim_v3_0.scala:142)
2023-10-20T08:58:43+09:00		at org.apache.kyuubi.engine.spark.session.SparkSessionImpl.$anonfun$open$1(SparkSessionImpl.scala:63)
2023-10-20T08:58:43+09:00		at org.apache.kyuubi.engine.spark.session.SparkSessionImpl.$anonfun$open$1$adapted(SparkSessionImpl.scala:53)
2023-10-20T08:58:43+09:00		at org.apache.kyuubi.engine.spark.session.SparkSessionImpl$$Lambda$3644/1954992287.apply(Unknown Source)
2023-10-20T08:58:43+09:00		at scala.collection.immutable.HashMap$HashMap1.foreach(HashMap.scala:400)
2023-10-20T08:58:43+09:00		at scala.collection.immutable.HashMap$HashTrieMap.foreach(HashMap.scala:728)
2023-10-20T08:58:43+09:00		at org.apache.kyuubi.engine.spark.session.SparkSessionImpl.open(SparkSessionImpl.scala:53)
2023-10-20T08:58:43+09:00		at org.apache.kyuubi.session.SessionManager.openSession(SessionManager.scala:101)
2023-10-20T08:58:43+09:00		at org.apache.kyuubi.service.AbstractBackendService.openSession(AbstractBackendService.scala:45)
2023-10-20T08:58:43+09:00		at org.apache.kyuubi.service.TFrontendService.getSessionHandle(TFrontendService.scala:169)
2023-10-20T08:58:43+09:00		at org.apache.kyuubi.engine.spark.SparkTBinaryFrontendService.OpenSession(SparkTBinaryFrontendService.scala:71)
2023-10-20T08:58:43+09:00		at org.apache.kyuubi.shade.org.apache.hive.service.rpc.thrift.TCLIService$Processor$OpenSession.getResult(TCLIService.java:1497)
2023-10-20T08:58:43+09:00		at org.apache.kyuubi.shade.org.apache.hive.service.rpc.thrift.TCLIService$Processor$OpenSession.getResult(TCLIService.java:1482)
2023-10-20T08:58:43+09:00		at org.apache.kyuubi.shade.org.apache.thrift.ProcessFunction.process(ProcessFunction.java:39)
2023-10-20T08:58:43+09:00		at org.apache.kyuubi.shade.org.apache.thrift.TBaseProcessor.process(TBaseProcessor.java:39)
2023-10-20T08:58:43+09:00		at org.apache.kyuubi.service.authentication.TSetIpAddressProcessor.process(TSetIpAddressProcessor.scala:36)
2023-10-20T08:58:43+09:00		at org.apache.kyuubi.shade.org.apache.thrift.server.TThreadPoolServer$WorkerProcess.run(TThreadPoolServer.java:286)
2023-10-20T08:58:43+09:00		at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
2023-10-20T08:58:43+09:00		at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
2023-10-20T08:58:43+09:00		at java.lang.Thread.run(Thread.java:750)

hive-metastore and/or metadata database are our suspects now. thank you.

0 replies

minyk · 2023-10-20T04:06:27Z

minyk
Oct 20, 2023
Author

I'm slightly wrong. The other thead obtain a lock <0x00007f514744ce08>:

2023-10-20T08:58:43+09:00	"SparkSQLSessionManager-exec-pool: Thread-1890554" #1890554 daemon prio=5 os_prio=0 tid=0x00007f4930018000 nid=0x1d2e20 runnable [0x00007f50734f5000]
2023-10-20T08:58:43+09:00	   java.lang.Thread.State: RUNNABLE
2023-10-20T08:58:43+09:00		at java.net.SocketInputStream.socketRead0(Native Method)
2023-10-20T08:58:43+09:00		at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
2023-10-20T08:58:43+09:00		at java.net.SocketInputStream.read(SocketInputStream.java:171)
2023-10-20T08:58:43+09:00		at java.net.SocketInputStream.read(SocketInputStream.java:141)
2023-10-20T08:58:43+09:00		at java.io.BufferedInputStream.fill(BufferedInputStream.java:246)
2023-10-20T08:58:43+09:00		at java.io.BufferedInputStream.read1(BufferedInputStream.java:286)
2023-10-20T08:58:43+09:00		at java.io.BufferedInputStream.read(BufferedInputStream.java:345)
2023-10-20T08:58:43+09:00		- locked <0x00007f5a848ec330> (a java.io.BufferedInputStream)
2023-10-20T08:58:43+09:00		at org.apache.thrift.transport.TIOStreamTransport.read(TIOStreamTransport.java:127)
2023-10-20T08:58:43+09:00		at org.apache.thrift.transport.TTransport.readAll(TTransport.java:86)
2023-10-20T08:58:43+09:00		at org.apache.thrift.protocol.TBinaryProtocol.readAll(TBinaryProtocol.java:429)
2023-10-20T08:58:43+09:00		at org.apache.thrift.protocol.TBinaryProtocol.readI32(TBinaryProtocol.java:318)
2023-10-20T08:58:43+09:00		at org.apache.thrift.protocol.TBinaryProtocol.readMessageBegin(TBinaryProtocol.java:219)
2023-10-20T08:58:43+09:00		at org.apache.thrift.TServiceClient.receiveBase(TServiceClient.java:77)
2023-10-20T08:58:43+09:00		at org.apache.hadoop.hive.metastore.api.ThriftHiveMetastore$Client.recv_get_partitions(ThriftHiveMetastore.java:2958)
2023-10-20T08:58:43+09:00		at org.apache.hadoop.hive.metastore.api.ThriftHiveMetastore$Client.get_partitions(ThriftHiveMetastore.java:2943)
2023-10-20T08:58:43+09:00		at org.apache.hadoop.hive.metastore.HiveMetaStoreClient.listPartitions(HiveMetaStoreClient.java:1368)
2023-10-20T08:58:43+09:00		at org.apache.hadoop.hive.metastore.HiveMetaStoreClient.listPartitions(HiveMetaStoreClient.java:1362)
2023-10-20T08:58:43+09:00		at sun.reflect.GeneratedMethodAccessor484.invoke(Unknown Source)
2023-10-20T08:58:43+09:00		at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
2023-10-20T08:58:43+09:00		at java.lang.reflect.Method.invoke(Method.java:498)
2023-10-20T08:58:43+09:00		at org.apache.hadoop.hive.metastore.RetryingMetaStoreClient.invoke(RetryingMetaStoreClient.java:212)
2023-10-20T08:58:43+09:00		at com.sun.proxy.$Proxy103.listPartitions(Unknown Source)
2023-10-20T08:58:43+09:00		at sun.reflect.GeneratedMethodAccessor484.invoke(Unknown Source)
2023-10-20T08:58:43+09:00		at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
2023-10-20T08:58:43+09:00		at java.lang.reflect.Method.invoke(Method.java:498)
2023-10-20T08:58:43+09:00		at org.apache.hadoop.hive.metastore.HiveMetaStoreClient$SynchronizedHandler.invoke(HiveMetaStoreClient.java:2773)
2023-10-20T08:58:43+09:00		- locked <0x00007f514da24ed8> (a org.apache.hadoop.hive.metastore.HiveMetaStoreClient$SynchronizedHandler)
2023-10-20T08:58:43+09:00		at com.sun.proxy.$Proxy103.listPartitions(Unknown Source)
2023-10-20T08:58:43+09:00		at org.apache.hadoop.hive.ql.metadata.Hive.getAllPartitionsOf(Hive.java:2988)
2023-10-20T08:58:43+09:00		at sun.reflect.GeneratedMethodAccessor499.invoke(Unknown Source)
2023-10-20T08:58:43+09:00		at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
2023-10-20T08:58:43+09:00		at java.lang.reflect.Method.invoke(Method.java:498)
2023-10-20T08:58:43+09:00		at org.apache.spark.sql.hive.client.Shim_v0_13.prunePartitionsFastFallback(HiveShim.scala:1159)
2023-10-20T08:58:43+09:00		at org.apache.spark.sql.hive.client.Shim_v0_13.getPartitionsByFilter(HiveShim.scala:1097)
2023-10-20T08:58:43+09:00		at org.apache.spark.sql.hive.client.HiveClientImpl.$anonfun$getPartitionsByFilter$1(HiveClientImpl.scala:782)
2023-10-20T08:58:43+09:00		at org.apache.spark.sql.hive.client.HiveClientImpl$$Lambda$4451/1716353753.apply(Unknown Source)
2023-10-20T08:58:43+09:00		at org.apache.spark.sql.hive.client.HiveClientImpl.$anonfun$withHiveState$1(HiveClientImpl.scala:298)
2023-10-20T08:58:43+09:00		at org.apache.spark.sql.hive.client.HiveClientImpl$$Lambda$2667/1246132954.apply(Unknown Source)
2023-10-20T08:58:43+09:00		at org.apache.spark.sql.hive.client.HiveClientImpl.liftedTree1$1(HiveClientImpl.scala:229)
2023-10-20T08:58:43+09:00		at org.apache.spark.sql.hive.client.HiveClientImpl.retryLocked(HiveClientImpl.scala:228)
2023-10-20T08:58:43+09:00		- locked <0x00007f5148675ee0> (a org.apache.spark.sql.hive.client.IsolatedClientLoader)
2023-10-20T08:58:43+09:00		at org.apache.spark.sql.hive.client.HiveClientImpl.withHiveState(HiveClientImpl.scala:278)
2023-10-20T08:58:43+09:00		at org.apache.spark.sql.hive.client.HiveClientImpl.getPartitionsByFilter(HiveClientImpl.scala:778)
2023-10-20T08:58:43+09:00		at org.apache.spark.sql.hive.HiveExternalCatalog.$anonfun$listPartitionsByFilter$1(HiveExternalCatalog.scala:1287)
2023-10-20T08:58:43+09:00		at org.apache.spark.sql.hive.HiveExternalCatalog$$Lambda$4445/913345264.apply(Unknown Source)
2023-10-20T08:58:43+09:00		at org.apache.spark.sql.hive.HiveExternalCatalog.withClient(HiveExternalCatalog.scala:101)
2023-10-20T08:58:43+09:00		- locked <0x00007f514744ce08> (a org.apache.spark.sql.hive.HiveExternalCatalog)

3 replies

yaooqinn Oct 20, 2023
Collaborator

listPartitions seems to be an unexpected behavior during session creation. Did this happen because of some initialize queries?

minyk Oct 20, 2023
Author

@yaooqinn It turns out connection to the metastore is unreliable. we found the socket read timeout and metastore client retry message. now we're trying to reduce socket timeout and socket lifetime. Thank you again.

yaooqinn Oct 23, 2023
Collaborator

Thank you for the information

minyk · 2023-10-23T01:31:55Z

minyk
Oct 23, 2023
Author

We could successfully handle this case with following configurations:

spark.hadoop.hive.metastore.client.socket.lifetime=3600
spark.hadoop.hive.metastore.client.socket.timeout=60

Thank you

0 replies

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Weird delay during SparkSession opens? #5461

{{title}}

{{editor}}'s edit

{{editor}}'s edit

Replies: 4 comments 4 replies

{{title}}

{{title}}

{{title}}

{{title}}

{{title}}

{{title}}

{{title}}

{{title}}

Select a reply

Weird delay during SparkSession opens? #5461

minyk Oct 18, 2023

Replies: 4 comments · 4 replies

yaooqinn Oct 18, 2023 Collaborator

minyk Oct 18, 2023 Author

minyk Oct 20, 2023 Author

minyk Oct 20, 2023 Author

yaooqinn Oct 20, 2023 Collaborator

minyk Oct 20, 2023 Author

yaooqinn Oct 23, 2023 Collaborator

minyk Oct 23, 2023 Author

minyk
Oct 18, 2023

Replies: 4 comments 4 replies

yaooqinn
Oct 18, 2023
Collaborator

minyk Oct 18, 2023
Author

minyk
Oct 20, 2023
Author

minyk
Oct 20, 2023
Author

yaooqinn Oct 20, 2023
Collaborator

minyk Oct 20, 2023
Author

yaooqinn Oct 23, 2023
Collaborator

minyk
Oct 23, 2023
Author