You are viewing a plain text version of this content. The canonical link for it is here.
Posted to user@hive.apache.org by Mich Talebzadeh <mi...@gmail.com> on 2016/05/24 17:31:01 UTC
Hive 2 loss of connection to metadstore and multiple
connections/disconnect in the same session
Hi,
I am seeing thie in hive.log. The job finishes OK but hive makes multiple
connection/disconnect to metastorte (in my case Oracle). in the same
session
It recovers from error but are these multiple connections and disconnects
necessary? Every time a Java thread tries to make a connection to database,
it has to deploy a file descriptor and context switch which is always
expensive. It is best to keep the connection/threads open during
the duration of session.
Anyway this is the log
2016-05-24T16:16:43,714 INFO [0deb842d-9b15-4dd9-8d60-0e198a9d3865
0deb842d-9b15-4dd9-8d60-0e198a9d3865 main]: hive.metastore
(HiveMetaStoreClient.java:isCompatibleWith(322)) - Mestastore configuration
hive.met
astore.filter.hook changed from
org.apache.hadoop.hive.metastore.DefaultMetaStoreFilterHookImpl to
org.apache.hadoop.hive.ql.security.authorization.plugin.AuthorizationMetaStoreFilterHook
2016-05-24T16:16:43,716 INFO [0deb842d-9b15-4dd9-8d60-0e198a9d3865
0deb842d-9b15-4dd9-8d60-0e198a9d3865 main]: hive.metastore
(HiveMetaStoreClient.java:close(534)) - Closed a connection to metastore,
current co
nnections: 0
2016-05-24T16:16:43,716 INFO [pool-5-thread-6]: metastore.HiveMetaStore
(HiveMetaStore.java:logInfo(669)) - 6: Shutting down the object store...
2016-05-24T16:16:43,717 INFO [pool-5-thread-6]: HiveMetaStore.audit
(HiveMetaStore.java:logAuditEvent(280)) - ugi=hduser
ip=50.140.197.217 cmd=Shutting down the object store...
2016-05-24T16:16:43,717 INFO [pool-5-thread-6]: metastore.HiveMetaStore
(HiveMetaStore.java:logInfo(669)) - 6: Metastore shutdown complete.
2016-05-24T16:16:43,717 INFO [pool-5-thread-6]: HiveMetaStore.audit
(HiveMetaStore.java:logAuditEvent(280)) - ugi=hduser
ip=50.140.197.217 cmd=Metastore shutdown complete.
2016-05-24T16:16:43,717 INFO [0deb842d-9b15-4dd9-8d60-0e198a9d3865
0deb842d-9b15-4dd9-8d60-0e198a9d3865 main]: hive.metastore
(HiveMetaStoreClient.java:open(408)) - Trying to connect to metastore with
URI thrif
t://rhes564:9083
2016-05-24T16:16:43,718 INFO [0deb842d-9b15-4dd9-8d60-0e198a9d3865
0deb842d-9b15-4dd9-8d60-0e198a9d3865 main]: hive.metastore
(HiveMetaStoreClient.java:open(453)) - Opened a connection to metastore,
current con
nections: 1
2016-05-24T16:16:43,718 INFO [0deb842d-9b15-4dd9-8d60-0e198a9d3865
0deb842d-9b15-4dd9-8d60-0e198a9d3865 main]: hive.metastore
(HiveMetaStoreClient.java:open(505)) - Connected to metastore.
2016-05-24T16:16:43,740 INFO [0deb842d-9b15-4dd9-8d60-0e198a9d3865
0deb842d-9b15-4dd9-8d60-0e198a9d3865 main]:
annotation.StatsRulesProcFactory
(StatsRulesProcFactory.java:updateStats(1851)) - STATS-GBY[4]: Equ
als 0 in number of rows.0 rows will be set to 1
2016-05-24T16:16:43,755 INFO [0deb842d-9b15-4dd9-8d60-0e198a9d3865
0deb842d-9b15-4dd9-8d60-0e198a9d3865 main]:
spark.SetSparkReducerParallelism
(SetSparkReducerParallelism.java:process(157)) - Number of reducer
s determined to be: 1
2016-05-24T16:16:43,791 INFO [0deb842d-9b15-4dd9-8d60-0e198a9d3865
0deb842d-9b15-4dd9-8d60-0e198a9d3865 main]: parse.CalcitePlanner
(SemanticAnalyzer.java:analyzeInternal(10198)) - Completed plan generation
2016-05-24T16:16:43,792 INFO [0deb842d-9b15-4dd9-8d60-0e198a9d3865
0deb842d-9b15-4dd9-8d60-0e198a9d3865
main]: ql.Driver (Driver.java:compile(485)) - Semantic Analysis Completed
2016-05-24T16:16:43,792 INFO [0deb842d-9b15-4dd9-8d60-0e198a9d3865
0deb842d-9b15-4dd9-8d60-0e198a9d3865 main]: ql.Driver
(Driver.java:getSchema(251)) - Returning Hive schema:
Schema(fieldSchemas:[FieldSchema(na
me:c0, type:double, comment:null)], properties:null)
2016-05-24T16:16:43,805 INFO [0deb842d-9b15-4dd9-8d60-0e198a9d3865
0deb842d-9b15-4dd9-8d60-0e198a9d3865 main]: exec.ListSinkOperator
(Operator.java:initialize(323)) - Initializing operator OP[7]
2016-05-24T16:16:43,810 INFO [0deb842d-9b15-4dd9-8d60-0e198a9d3865
0deb842d-9b15-4dd9-8d60-0e198a9d3865 main]: ql.Driver
(Driver.java:compile(557)) - Completed compiling
command(queryId=hduser_20160524161631_93
859db7-b4d8-42cf-b58c-e56691ae0529); Time taken: 1.165 seconds
2016-05-24T16:16:43,810 INFO [0deb842d-9b15-4dd9-8d60-0e198a9d3865
0deb842d-9b15-4dd9-8d60-0e198a9d3865 main]: lockmgr.DbTxnManager
(DbTxnManager.java:acquireLocks(152)) - Setting lock request transaction to
tx
nid:0 for queryId=hduser_20160524161631_93859db7-b4d8-42cf-b58c-e56691ae0529
2016-05-24T16:16:43,813 INFO [0deb842d-9b15-4dd9-8d60-0e198a9d3865
0deb842d-9b15-4dd9-8d60-0e198a9d3865 main]: lockmgr.DbLockManager
(DbLockManager.java:lock(85)) - Requesting:
queryId=hduser_20160524161631_938
59db7-b4d8-42cf-b58c-e56691ae0529
LockRequest(component:[LockComponent(type:SHARED_READ, level:TABLE,
dbname:oraclehadoop, tablename:channels)], txnid:0, user:hduser,
hostname:rhes564, agentInfo:Unknown)
2016-05-24T16:16:43,816 WARN [0deb842d-9b15-4dd9-8d60-0e198a9d3865
0deb842d-9b15-4dd9-8d60-0e198a9d3865 main]:
metastore.RetryingMetaStoreClient
(RetryingMetaStoreClient.java:invoke(199)) - MetaStoreClient lost
connection. Attempting to reconnect.
org.apache.thrift.transport.TTransportException: Cannot write to null
outputStream
at
org.apache.thrift.transport.TIOStreamTransport.write(TIOStreamTransport.java:142)
~[hive-exec-2.0.0.jar:2.0.0]
at
org.apache.thrift.protocol.TBinaryProtocol.writeI32(TBinaryProtocol.java:178)
~[hive-exec-2.0.0.jar:2.0.0]
at
org.apache.thrift.protocol.TBinaryProtocol.writeMessageBegin(TBinaryProtocol.java:106)
~[hive-exec-2.0.0.jar:2.0.0]
at
org.apache.thrift.TServiceClient.sendBase(TServiceClient.java:70)
~[hive-exec-2.0.0.jar:2.0.0]
at
org.apache.thrift.TServiceClient.sendBase(TServiceClient.java:62)
~[hive-exec-2.0.0.jar:2.0.0]
at
org.apache.hadoop.hive.metastore.api.ThriftHiveMetastore$Client.send_lock(ThriftHiveMetastore.java:4028)
~[hive-exec-2.0.0.jar:2.0.0]
at
org.apache.hadoop.hive.metastore.api.ThriftHiveMetastore$Client.lock(ThriftHiveMetastore.java:4020)
~[hive-exec-2.0.0.jar:2.0.0]
at
org.apache.hadoop.hive.metastore.HiveMetaStoreClient.lock(HiveMetaStoreClient.java:1967)
~[hive-exec-2.0.0.jar:2.0.0]
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
~[?:1.8.0_77]
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
~[?:1.8.0_77]
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
~[?:1.8.0_77]
at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_77]
at
org.apache.hadoop.hive.metastore.RetryingMetaStoreClient.invoke(RetryingMetaStoreClient.java:156)
[hive-exec-2.0.0.jar:2.0.0]
at com.sun.proxy.$Proxy21.lock(Unknown Source) [?:?]
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
~[?:1.8.0_77]
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
~[?:1.8.0_77]
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
~[?:1.8.0_77]
at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_77]
at
org.apache.hadoop.hive.metastore.HiveMetaStoreClient$SynchronizedHandler.invoke(HiveMetaStoreClient.java:2089)
[hive-exec-2.0.0.jar:2.0.0]
at com.sun.proxy.$Proxy21.lock(Unknown Source) [?:?]
at
org.apache.hadoop.hive.ql.lockmgr.DbLockManager.lock(DbLockManager.java:86)
[hive-exec-2.0.0.jar:2.0.0]
at
org.apache.hadoop.hive.ql.lockmgr.DbTxnManager.acquireLocks(DbTxnManager.java:273)
[hive-exec-2.0.0.jar:2.0.0]
at
org.apache.hadoop.hive.ql.lockmgr.DbTxnManager.acquireLocks(DbTxnManager.java:134)
[hive-exec-2.0.0.jar:2.0.0]
at
org.apache.hadoop.hive.ql.Driver.acquireLocksAndOpenTxn(Driver.java:1074)
[hive-exec-2.0.0.jar:2.0.0]
at org.apache.hadoop.hive.ql.Driver.runInternal(Driver.java:1356)
[hive-exec-2.0.0.jar:2.0.0]
at org.apache.hadoop.hive.ql.Driver.run(Driver.java:1184)
[hive-exec-2.0.0.jar:2.0.0]
at org.apache.hadoop.hive.ql.Driver.run(Driver.java:1172)
[hive-exec-2.0.0.jar:2.0.0]
at
org.apache.hadoop.hive.cli.CliDriver.processLocalCmd(CliDriver.java:233)
[hive-cli-2.0.0.jar:2.0.0]
at
org.apache.hadoop.hive.cli.CliDriver.processCmd(CliDriver.java:184)
[hive-cli-2.0.0.jar:2.0.0]
at
org.apache.hadoop.hive.cli.CliDriver.processLine(CliDriver.java:400)
[hive-cli-2.0.0.jar:2.0.0]
at
org.apache.hadoop.hive.cli.CliDriver.executeDriver(CliDriver.java:778)
[hive-cli-2.0.0.jar:2.0.0]
at org.apache.hadoop.hive.cli.CliDriver.run(CliDriver.java:717)
[hive-cli-2.0.0.jar:2.0.0]
at org.apache.hadoop.hive.cli.CliDriver.main(CliDriver.java:645)
[hive-cli-2.0.0.jar:2.0.0]
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
~[?:1.8.0_77]
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
~[?:1.8.0_77]
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
~[?:1.8.0_77]
at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_77]
at org.apache.hadoop.util.RunJar.run(RunJar.java:221)
[hadoop-common-2.6.0.jar:?]
at org.apache.hadoop.util.RunJar.main(RunJar.java:136)
[hadoop-common-2.6.0.jar:?]
2016-05-24T16:16:44,862 INFO [0deb842d-9b15-4dd9-8d60-0e198a9d3865
0deb842d-9b15-4dd9-8d60-0e198a9d3865 main]: hive.metastore
(HiveMetaStoreClient.java:open(408)) - Trying to connect to metastore with
URI thrif
t://rhes564:9083
2016-05-24T16:16:44,863 INFO [0deb842d-9b15-4dd9-8d60-0e198a9d3865
0deb842d-9b15-4dd9-8d60-0e198a9d3865 main]: hive.metastore
(HiveMetaStoreClient.java:open(453)) - Opened a connection to metastore,
current con
nections: 2
2016-05-24T16:16:44,864 INFO [0deb842d-9b15-4dd9-8d60-0e198a9d3865
0deb842d-9b15-4dd9-8d60-0e198a9d3865 main]: hive.metastore
(HiveMetaStoreClient.java:open(505)) - Connected to metastore.
Thanks
Dr Mich Talebzadeh
LinkedIn * https://www.linkedin.com/profile/view?id=AAEAAAAWh2gBxianrbJd6zP6AcPCCdOABUrV8Pw
<https://www.linkedin.com/profile/view?id=AAEAAAAWh2gBxianrbJd6zP6AcPCCdOABUrV8Pw>*
http://talebzadehmich.wordpress.com