[HIVE-24552] Possible HMS connections leak or accumulation in loadDynamicPartitions

• Type: Bug
• Status: Closed
• Priority: Major
• Resolution: Fixed
• Fix Version/s: 4.0.0-alpha-1
• Component/s: Metastore
• Labels: pull-request-available
• Assignee: Yongzhi Chen
• Reporter: Yongzhi Chen
• Created: 20/Dec/20 14:12
• Updated: 17/Nov/22 08:48
• Resolved: 26/Feb/21 14:24

Description

When loadDynamicPartitions (Hive.java) is called, it generates several threads to handle FileMove. These threads may generate HiveMetaStore connections. These connections may not be closed in time and cause many accumulated connections. Following is the log got from running insert overwrites many times, you can see these threads created new HMS connections, and the total number of open connections is large. And the finalizer closes the connections and sometimes had errors:

<14>1 2020-12-15T17:06:15.894Z hiveserver2-0 hiveserver2 1 a3671b96-74fb-4ee9-b186-aeff0de0bbec [mdc@18060 class="metastore.HiveMetaStoreClient" level="INFO" thread="load-dynamic-partitionsToAdd-14"] Opened a connection to metastore, current connections: 44021
<14>1 2020-12-15T17:06:15.894Z hiveserver2-0 hiveserver2 1 a3671b96-74fb-4ee9-b186-aeff0de0bbec [mdc@18060 class="metastore.HiveMetaStoreClient" level="INFO" thread="load-dynamic-partitionsToAdd-14"] Connected to metastore.
<14>1 2020-12-15T17:06:15.894Z hiveserver2-0 hiveserver2 1 a3671b96-74fb-4ee9-b186-aeff0de0bbec [mdc@18060 class="metastore.RetryingMetaStoreClient" level="INFO" thread="load-dynamic-partitionsToAdd-14"] RetryingMetaStoreClient proxy=class org.apache.hadoop.hive.ql.metadata.SessionHiveMetaStoreClient ugi=hive/[e-mail] (auth:KERBEROS) retries=24 delay=5 lifetime=0
<14>1 2020-12-15T17:06:15.895Z hiveserver2-0 hiveserver2 1 a3671b96-74fb-4ee9-b186-aeff0de0bbec [mdc@18060 class="metastore.HiveMetaStoreClient" level="INFO" thread="load-dynamic-partitionsToAdd-5"] Opened a connection to metastore, current connections: 44022
<14>1 2020-12-15T17:06:15.895Z hiveserver2-0 hiveserver2 1 a3671b96-74fb-4ee9-b186-aeff0de0bbec [mdc@18060 class="metastore.HiveMetaStoreClient" level="INFO" thread="load-dynamic-partitionsToAdd-5"] Connected to metastore.
<14>1 2020-12-15T17:06:15.895Z hiveserver2-0 hiveserver2 1 a3671b96-74fb-4ee9-b186-aeff0de0bbec [mdc@18060 class="metastore.RetryingMetaStoreClient" level="INFO" thread="load-dynamic-partitionsToAdd-5"] RetryingMetaStoreClient proxy=class org.apache.hadoop.hive.ql.metadata.SessionHiveMetaStoreClient ugi=hive/[e-mail] (auth:KERBEROS) retries=24 delay=5 lifetime=0
<14>1 2020-12-15T17:06:15.895Z hiveserver2-0 hiveserver2 1 a3671b96-74fb-4ee9-b186-aeff0de0bbec [mdc@18060 class="metastore.HiveMetaStoreClient" level="INFO" thread="load-dynamic-partitionsToAdd-6"] Opened a connection to metastore, current connections: 44023
<14>1 2020-12-15T17:06:15.895Z hiveserver2-0 hiveserver2 1 a3671b96-74fb-4ee9-b186-aeff0de0bbec [mdc@18060 class="metastore.HiveMetaStoreClient" level="INFO" thread="load-dynamic-partitionsToAdd-6"] Connected to metastore.
<14>1 2020-12-15T17:06:15.895Z hiveserver2-0 hiveserver2 1 a3671b96-74fb-4ee9-b186-aeff0de0bbec [mdc@18060 class="metastore.RetryingMetaStoreClient" level="INFO" thread="load-dynamic-partitionsToAdd-6"] RetryingMetaStoreClient proxy=class org.apache.hadoop.hive.ql.metadata.SessionHiveMetaStoreClient ugi=hive/[e-mail] (auth:KERBEROS) retries=24 delay=5 lifetime=0
<14>1 2020-12-15T17:06:15.895Z hiveserver2-0 hiveserver2 1 a3671b96-74fb-4ee9-b186-aeff0de0bbec [mdc@18060 class="metastore.HiveMetaStoreClient" level="INFO" thread="load-dynamic-partitionsToAdd-3"] Opened a connection to metastore, current connections: 44024
....

<14>1 2020-12-15T17:05:38.485Z hiveserver2-0 hiveserver2 1 a3671b96-74fb-4ee9-b186-aeff0de0bbec [mdc@18060 class="metastore.HiveMetaStoreClient" level="INFO" thread="Finalizer"] Closed a connection to metastore, current connections: 43904
<14>1 2020-12-15T17:05:38.485Z hiveserver2-0 hiveserver2 1 a3671b96-74fb-4ee9-b186-aeff0de0bbec [mdc@18060 class="metastore.HiveMetaStoreClient" level="INFO" thread="Finalizer"] Closed a connection to metastore, current connections: 43903
<14>1 2020-12-15T17:05:38.485Z hiveserver2-0 hiveserver2 1 a3671b96-74fb-4ee9-b186-aeff0de0bbec [mdc@18060 class="metastore.HiveMetaStoreClient" level="INFO" thread="Finalizer"] Closed a connection to metastore, current connections: 43902
<14>1 2020-12-15T17:05:38.485Z hiveserver2-0 hiveserver2 1 a3671b96-74fb-4ee9-b186-aeff0de0bbec [mdc@18060 class="metastore.HiveMetaStoreClient" level="INFO" thread="Finalizer"] Closed a connection to metastore, current connections: 43901
<14>1 2020-12-15T17:05:38.485Z hiveserver2-0 hiveserver2 1 a3671b96-74fb-4ee9-b186-aeff0de0bbec [mdc@18060 class="metastore.HiveMetaStoreClient" level="INFO" thread="Finalizer"] Closed a connection to metastore, current connections: 43900
<14>1 2020-12-15T17:05:38.485Z hiveserver2-0 hiveserver2 1 a3671b96-74fb-4ee9-b186-aeff0de0bbec [mdc@18060 class="metastore.HiveMetaStoreClient" level="INFO" thread="Finalizer"] Closed a connection to metastore, current connections: 43899
<14>1 2020-12-15T17:05:38.485Z hiveserver2-0 hiveserver2 1 a3671b96-74fb-4ee9-b186-aeff0de0bbec [mdc@18060 class="metastore.HiveMetaStoreClient" level="INFO" thread="Finalizer"] Closed a connection to metastore, current connections: 43898
<14>1 2020-12-15T17:05:38.485Z hiveserver2-0 hiveserver2 1 a3671b96-74fb-4ee9-b186-aeff0de0bbec [mdc@18060 class="metastore.HiveMetaStoreClient" level="INFO" thread="Finalizer"] Closed a connection to metastore, current connections: 43897
<12>1 2020-12-15T17:05:38.485Z hiveserver2-0 hiveserver2 1 a3671b96-74fb-4ee9-b186-aeff0de0bbec [mdc@18060 class="transport.TIOStreamTransport" level="WARN" thread="Finalizer"] Error closing output stream.
java.net.SocketException: Socket closed
	at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:118)
	at java.net.SocketOutputStream.write(SocketOutputStream.java:155)
	at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:82)
	at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:140)
	at java.io.FilterOutputStream.close(FilterOutputStream.java:158)
	at org.apache.thrift.transport.TIOStreamTransport.close(TIOStreamTransport.java:110)
	at org.apache.thrift.transport.TSocket.close(TSocket.java:235)
	at org.apache.thrift.transport.TSaslTransport.close(TSaslTransport.java:400)
	at org.apache.thrift.transport.TSaslClientTransport.close(TSaslClientTransport.java:37)
	at org.apache.hadoop.hive.metastore.security.TFilterTransport.close(TFilterTransport.java:52)
	at org.apache.hadoop.hive.metastore.HiveMetaStoreClient.close(HiveMetaStoreClient.java:729)
	at sun.reflect.GeneratedMethodAccessor160.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at org.apache.hadoop.hive.metastore.RetryingMetaStoreClient.invoke(RetryingMetaStoreClient.java:212)
	at com.sun.proxy.$Proxy59.close(Unknown Source)
	at sun.reflect.GeneratedMethodAccessor160.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at org.apache.hadoop.hive.metastore.HiveMetaStoreClient$SynchronizedHandler.invoke(HiveMetaStoreClient.java:3411)
	at com.sun.proxy.$Proxy59.close(Unknown Source)
	at org.apache.hadoop.hive.ql.metadata.Hive.close(Hive.java:540)
	at org.apache.hadoop.hive.ql.metadata.Hive.finalize(Hive.java:512)
	at java.lang.System$2.invokeFinalize(System.java:1273)
	at java.lang.ref.Finalizer.runFinalizer(Finalizer.java:102)
	at java.lang.ref.Finalizer.access$100(Finalizer.java:34)
	at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:217)

Issue Links

• links to: GitHub Pull Request #1802