Yongzhi Chen created HIVE-24552:
-----------------------------------
Summary: Possible HMS connections leak or accumulation in
loadDynamicPartitions
Key: HIVE-24552
URL: https://issues.apache.org/jira/browse/HIVE-24552
Project: Hive
Issue Type: Bug
Components: Metastore
Reporter: Yongzhi Chen
Assignee: Yongzhi Chen
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:
{noformat}
<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/[email protected] (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/[email protected] (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/[email protected] (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)
{noformat}
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
