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