AMRM Callback Handler Thread and Interrupted while waiting for queue

[#1]

hadoop version 2.6.0

hive version 2.1.0

tez version 0.8.4

in hive cli mode ，I use set hive.execution.engine=tez OR set hive.execution.engine=mr both work well ,

the same other config was

set hive.tez.container.size=2048;

set tez.task.resource.memory.mb=2048;

set hive.tez.java.opts=-Xmx1700m;

while connect hiveserver2 successfuly with pyhive :

set hive.execution.engine=mr can work well

but set hive.execution.engine=tez the python script hanging and the log as below:

INFO : Query ID = hive_20161212164426_9001f0fe-7189-47a2-a525-62dbd53913c4 INFO : Total jobs = 1 INFO : Launching Job 1 out of 1 INFO : Starting task [Stage-1:MAPRED] in parallel INFO : Tez session hasn't been created yet. Opening session

unitl I execute ctrl+c the log as below:

header = self._trans.readAll(4) File "/usr/local/python272/lib/python2.7/site-packages/thrift/transport/TTransport.py", line 58, in readAll chunk = self.read(sz - have) File "/usr/local/python272/lib/python2.7/site-packages/thrift/transport/TSocket.py", line 120, in read message='TSocket read 0 bytes') thrift.transport.TTransport.TTransportException: TSocket read 0 bytes Exception thrift.transport.TTransport.TTransportException: TTransportException('TSocket read 0 bytes',) in <bound method

the section logs of hiveserver2 as below:

2016-12-09T15:33:19,973 INFO [HiveServer2-Background-Pool: Thread-82]: ql.Driver (SessionState.java:printInfo(1054)) - Query ID = hive_20161209153319_d81caf71-f287-4105-aae2-d63418fdc74d 2016-12-09T15:33:19,973 INFO [HiveServer2-Background-Pool: Thread-82]: ql.Driver (SessionState.java:printInfo(1054)) - Total jobs = 1 2016-12-09T15:33:19,974 INFO [HiveServer2-Background-Pool: Thread-82]: ql.Driver (SessionState.java:printInfo(1054)) - Launching Job 1 out of 1 2016-12-09T15:33:19,974 INFO [HiveServer2-Background-Pool: Thread-82]: ql.Driver (Driver.java:launchTask(1850)) - Starting task [Stage-1:MAPRED] in parallel 2016-12-09T15:33:19,988 INFO [Thread-63]: tez.TezSessionPoolManager (TezSessionPoolManager.java:getSession(279)) - QueueName: null nonDefaultUser: true defaultQueuePool: null hasInitialSessions: false 2016-12-09T15:33:19,995 INFO [Thread-63]: tez.TezSessionPoolManager (TezSessionPoolManager.java:createAndInitSession(259)) - Created new tez session for queue: null with session id: cca34818-9463-4b84-97d9-68cd71a7242c 2016-12-09T15:33:20,076 INFO [Thread-63]: Configuration.deprecation (Configuration.java:warnOnceIfDeprecated(1174)) - mapred.committer.job.setup.cleanup.needed is deprecated. Instead, use mapreduce.job.committer.setup.cleanup.needed 2016-12-09T15:33:20,097 INFO [Thread-63]: ql.Context (Context.java:getMRScratchDir(340)) - New scratch dir is hdfs://nameservice1/tmp/hive/hive/3918bbd3-f9df-4487-b219-23545459b445/hive_2016-12-09_15-33-19_731_3044474760229019419-4 2016-12-09T15:33:20,118 INFO [Thread-63]: exec.Task (TezTask.java:updateSession(276)) - Tez session hasn't been created yet. Opening session 2016-12-09T15:33:20,118 INFO [Thread-63]: tez.TezSessionState (TezSessionState.java:openInternal(237)) - User of session id cca34818-9463-4b84-97d9-68cd71a7242c is hive 2016-12-09T15:33:20,140 INFO [Thread-63]: tez.DagUtils (DagUtils.java:getHiveJarDirectory(916)) - Jar dir is null / directory doesn't exist. Choosing HIVE_INSTALL_DIR - /user/hive/.hiveJars 2016-12-09T15:33:20,419 INFO [Thread-63]: tez.DagUtils (DagUtils.java:createLocalResource(758)) - Resource modification time: 1481106349834 for hdfs://nameservice1/user/hive/.hiveJars/hive-exec-2.1.0-f930d5a5e17a159094e7c7122753b81e1eab2a1516d3df982ed7b3b613da005f.jar 2016-12-09T15:33:20,462 INFO [Thread-63]: client.TezClient (TezClient.java:<init>(211)) - Tez Client Version: [ component=tez-api, version=0.8.4, revision=${buildNumber}, SCM-URL=scm:git:https://git-wip-us.apache.org/repos/asf/tez.git, buildTime=2016-12-08T02:12:16Z ] 2016-12-09T15:33:20,462 INFO [Thread-63]: tez.TezSessionState (TezSessionState.java:openInternal(315)) - Opening new Tez Session (id: cca34818-9463-4b84-97d9-68cd71a7242c, scratch dir: hdfs://nameservice1/tmp/hive/hive/_tez_session_dir/cca34818-9463-4b84-97d9-68cd71a7242c) 2016-12-09T15:33:20,490 INFO [Thread-63]: client.RMProxy (RMProxy.java:createRMProxy(98)) - Connecting to ResourceManager at GZHL-192-168-0-200.boyaa.com/192.168.0.200:8032 2016-12-09T15:33:20,491 INFO [Thread-63]: client.TezClient (TezClient.java:start(402)) - Using org.apache.tez.dag.history.ats.acls.ATSHistoryACLPolicyManager to manage Timeline ACLs 2016-12-09T15:33:20,494 WARN [Thread-63]: acls.ATSHistoryACLPolicyManager (ATSHistoryACLPolicyManager.java:initializeTimelineClient(74)) - org.apache.tez.dag.history.logging.ats.ATSHistoryLoggingService is disabled due to Timeline Service being disabled, yarn.timeline-service.enabled set to false 2016-12-09T15:33:20,495 INFO [Thread-63]: client.TezClient (TezClient.java:start(443)) - Session mode. Starting session. 2016-12-09T15:33:20,498 INFO [Thread-63]: client.TezClientUtils (TezClientUtils.java:setupTezJarsLocalResources(178)) - Using tez.lib.uris value from configuration: hdfs://nameservice1/apps/apache-tez-0.8.4-bin/tez-0.8.4-minimal.tar.gz 2016-12-09T15:33:20,498 INFO [Thread-63]: client.TezClientUtils (TezClientUtils.java:setupTezJarsLocalResources(180)) - Using tez.lib.uris.classpath value from configuration: null 2016-12-09T15:33:20,534 INFO [Thread-63]: client.TezClient (TezCommonUtils.java:createTezSystemStagingPath(122)) - Tez system stage directory hdfs://nameservice1/tmp/hive/hive/_tez_session_dir/cca34818-9463-4b84-97d9-68cd71a7242c/.tez/application_1479891196918_0199 doesn't exist and is created 2016-12-09T15:33:20,537 INFO [Thread-63]: acls.ATSHistoryACLPolicyManager (ATSHistoryACLPolicyManager.java:createSessionDomain(166)) - Created Timeline Domain for History ACLs, domainId=Tez_ATS_application_1479891196918_0199 2016-12-09T15:33:20,983 INFO [Thread-63]: impl.YarnClientImpl (YarnClientImpl.java:submitApplication(260)) - Submitted application application_1479891196918_0199 2016-12-09T15:33:20,986 INFO [Thread-63]: client.TezClient (TezClient.java:start(477)) - The url to track the Tez Session: http://GZHL-192-168-0-200.boyaa.com:8088/proxy/application_1479891196918_0199/ 2016-12-09T15:33:24,977 INFO [HiveServer2-Handler-Pool: Thread-79]: conf.HiveConf (HiveConf.java:getLogIdVar(3511)) - Using the default value passed in for log id: 3918bbd3-f9df-4487-b219-23545459b445 2016-12-09T15:33:24,978 INFO [HiveServer2-Handler-Pool: Thread-79]: session.SessionState (SessionState.java:updateThreadName(401)) - Updating thread name to 3918bbd3-f9df-4487-b219-23545459b445 HiveServer2-Handler-Pool: Thread-79 2016-12-09T15:33:24,978 INFO [3918bbd3-f9df-4487-b219-23545459b445 HiveServer2-Handler-Pool: Thread-79]: conf.HiveConf (HiveConf.java:getLogIdVar(3511)) - Using the default value passed in for log id: 3918bbd3-f9df-4487-b219-23545459b445 2016-12-09T15:33:24,978 INFO [3918bbd3-f9df-4487-b219-23545459b445 HiveServer2-Handler-Pool: Thread-79]: session.SessionState (SessionState.java:resetThreadName(412)) - Resetting thread name to HiveServer2-Handler-Pool: Thread-79 2016-12-09T15:33:26,385 INFO [Thread-63]: metastore.HiveMetaStore (HiveMetaStore.java:logInfo(734)) - 4: Metastore shutdown started... 2016-12-09T15:33:26,385 INFO [Thread-63]: HiveMetaStore.audit (HiveMetaStore.java:logAuditEvent(295)) - ugi=hiveip=unknown-ip-addrcmd=Metastore shutdown started... 2016-12-09T15:33:26,385 INFO [Thread-63]: metastore.HiveMetaStore (HiveMetaStore.java:logInfo(734)) - 4: Metastore shutdown complete. 2016-12-09T15:33:26,386 INFO [Thread-63]: HiveMetaStore.audit (HiveMetaStore.java:logAuditEvent(295)) - ugi=hiveip=unknown-ip-addrcmd=Metastore shutdown complete. 2016-12-09T15:33:28,445 INFO [HiveServer2-Background-Pool: Thread-82]: ql.Driver (Driver.java:execute(1729)) - Completed executing command(queryId=hive_20161209153319_d81caf71-f287-4105-aae2-d63418fdc74d); Time taken: 8.473 seconds 2016-12-09T15:33:28,985 INFO [HiveServer2-Handler-Pool: Thread-79]: thrift.ThriftCLIService (ThriftBinaryCLIService.java:deleteContext(136)) - Session disconnected without closing properly. 2016-12-09T15:33:28,985 INFO [HiveServer2-Handler-Pool: Thread-79]: thrift.ThriftCLIService (ThriftBinaryCLIService.java:deleteContext(140)) - Closing the session: SessionHandle [3918bbd3-f9df-4487-b219-23545459b445] 2016-12-09T15:33:28,986 INFO [HiveServer2-Handler-Pool: Thread-79]: conf.HiveConf (HiveConf.java:getLogIdVar(3511)) - Using the default value passed in for log id: 3918bbd3-f9df-4487-b219-23545459b445 2016-12-09T15:33:28,986 INFO [HiveServer2-Handler-Pool: Thread-79]: session.SessionState (SessionState.java:updateThreadName(401)) - Updating thread name to 3918bbd3-f9df-4487-b219-23545459b445 HiveServer2-Handler-Pool: Thread-79 2016-12-09T15:33:28,986 INFO [3918bbd3-f9df-4487-b219-23545459b445 HiveServer2-Handler-Pool: Thread-79]: conf.HiveConf (HiveConf.java:getLogIdVar(3511)) - Using the default value passed in for log id: 3918bbd3-f9df-4487-b219-23545459b445 2016-12-09T15:33:29,251 INFO [3918bbd3-f9df-4487-b219-23545459b445 HiveServer2-Handler-Pool: Thread-79]: conf.HiveConf (HiveConf.java:getLogIdVar(3511)) - Using the default value passed in for log id: 3918bbd3-f9df-4487-b219-23545459b445 2016-12-09T15:33:29,251 INFO [3918bbd3-f9df-4487-b219-23545459b445 HiveServer2-Handler-Pool: Thread-79]: session.SessionState (SessionState.java:resetThreadName(412)) - Resetting thread name to HiveServer2-Handler-Pool: Thread-79 2016-12-09T15:33:29,254 INFO [HiveServer2-Handler-Pool: Thread-79]: tez.TezSessionPoolManager (TezSessionPoolManager.java:closeIfNotDefault(336)) - Closing tez session default? false 2016-12-09T15:33:29,368 INFO [HiveServer2-Handler-Pool: Thread-79]: session.SessionState (SessionState.java:dropSessionPaths(786)) - Deleted HDFS directory: /tmp/hive/hive/3918bbd3-f9df-4487-b219-23545459b445 2016-12-09T15:33:29,368 INFO [HiveServer2-Handler-Pool: Thread-79]: session.SessionState (SessionState.java:dropSessionPaths(790)) - Deleted local directory: /tmp/hive/3918bbd3-f9df-4487-b219-23545459b445 2016-12-09T15:33:29,368 INFO [HiveServer2-Handler-Pool: Thread-79]: metastore.HiveMetaStore (HiveMetaStore.java:logInfo(734)) - 3: Metastore shutdown started... 2016-12-09T15:33:29,369 INFO [HiveServer2-Handler-Pool: Thread-79]: HiveMetaStore.audit (HiveMetaStore.java:logAuditEvent(295)) - ugi=hiveip=unknown-ip-addrcmd=Metastore shutdown started... 2016-12-09T15:33:29,369 INFO [HiveServer2-Handler-Pool: Thread-79]: metastore.HiveMetaStore (HiveMetaStore.java:logInfo(734)) - 3: Metastore shutdown complete. 2016-12-09T15:33:29,369 INFO [HiveServer2-Handler-Pool: Thread-79]: HiveMetaStore.audit (HiveMetaStore.java:logAuditEvent(295)) - ugi=hiveip=unknown-ip-addrcmd=Metastore shutdown complete. 2016-12-09T15:33:29,375 INFO [HiveServer2-Handler-Pool: Thread-79]: server.HiveServer2 (HiveServer2.java:stop(476)) - Shutting down HiveServer2 2016-12-09T15:33:29,376 INFO [HiveServer2-Handler-Pool: Thread-79]: thrift.ThriftCLIService (ThriftCLIService.java:stop(212)) - Thrift server has stopped 2016-12-09T15:33:29,376 INFO [HiveServer2-Handler-Pool: Thread-79]: service.AbstractService (AbstractService.java:stop(125)) - Service:ThriftBinaryCLIService is stopped. 2016-12-09T15:33:29,376 INFO [HiveServer2-Handler-Pool: Thread-79]: service.AbstractService (AbstractService.java:stop(125)) - Service:OperationManager is stopped. 2016-12-09T15:33:29,376 INFO [HiveServer2-Handler-Pool: Thread-79]: service.AbstractService (AbstractService.java:stop(125)) - Service:SessionManager is stopped. 2016-12-09T15:33:39,377 INFO [HiveServer2-Handler-Pool: Thread-79]: service.AbstractService (AbstractService.java:stop(125)) - Service:CLIService is stopped. 2016-12-09T15:33:39,377 INFO [HiveServer2-Handler-Pool: Thread-79]: service.AbstractService (AbstractService.java:stop(125)) - Service:HiveServer2 is stopped. 2016-12-09T15:33:39,399 INFO [HiveServer2-Handler-Pool: Thread-79]: handler.ContextHandler (ContextHandler.java:doStop(788)) - stopped o.e.j.s.ServletContextHandler{/logs,file:/var/log/hive/} 2016-12-09T15:33:39,400 INFO [HiveServer2-Handler-Pool: Thread-79]: handler.ContextHandler (ContextHandler.java:doStop(788)) - stopped o.e.j.s.ServletContextHandler{/static,jar:file:/usr/local/dist/hive-2.1.0/lib/hive-service-2.1.0.jar!/hive-webapps/static} 2016-12-09T15:33:39,650 INFO [HiveServer2-Handler-Pool: Thread-79]: handler.ContextHandler (ContextHandler.java:doStop(788)) - stopped o.e.j.w.WebAp

the section logs of yarn as below:

LogType:stderr Log Upload Time:Fri Dec 09 15:38:32 +0800 2016 LogLength:513 Log Contents: SLF4J: Class path contains multiple SLF4J bindings. SLF4J: Found binding in [jar:file:/disk1/yarn/nm/filecache/11/tez-0.8.4-minimal.tar.gz/lib/slf4j-log4j12-1.7.10.jar!/org/slf4j/impl/StaticLoggerBinder.class] SLF4J: Found binding in [jar:file:/opt/cloudera/parcels/CDH-5.8.2-1.cdh5.8.2.p0.3/jars/slf4j-log4j12-1.7.5.jar!/org/slf4j/impl/StaticLoggerBinder.class] SLF4J: See http://www.slf4j.org/codes.html#multiple_bindings for an explanation. SLF4J: Actual binding is of type [org.slf4j.impl.Log4jLoggerFactory] LogType:stdout Log Upload Time:Fri Dec 09 15:38:32 +0800 2016 LogLength:1363 Log Contents: 1.377: [GC [PSYoungGen: 113357K->12592K(244736K)] 113357K->12664K(803840K), 0.0137860 secs] [Times: user=0.20 sys=0.06, real=0.01 secs] 1.921: [GC [PSYoungGen: 122451K->13162K(244736K)] 122523K->13242K(803840K), 0.0183000 secs] [Times: user=0.35 sys=0.08, real=0.02 secs] 2.501: [GC [PSYoungGen: 127119K->12174K(244736K)] 127199K->12262K(803840K), 0.0101060 secs] [Times: user=0.20 sys=0.00, real=0.01 secs] Heap PSYoungGen total 244736K, used 56631K [0x00000000eee80000, 0x0000000100000000, 0x0000000100000000) eden space 209920K, 21% used [0x00000000eee80000,0x00000000f5f08460,0x00000000fbb80000) lgrp 0 space 104960K, 32% used [0x00000000eee80000,0x00000000f0fe1f68,0x00000000f5500000) lgrp 1 space 104960K, 9% used [0x00000000f5500000,0x00000000f5f08460,0x00000000fbb80000) from space 34816K, 34% used [0x00000000fbb80000,0x00000000fc763bc8,0x00000000fdd80000) to space 34816K, 0% used [0x00000000fde00000,0x00000000fde00000,0x0000000100000000) ParOldGen total 559104K, used 88K [0x00000000ccc00000, 0x00000000eee00000, 0x00000000eee80000) object space 559104K, 0% used [0x00000000ccc00000,0x00000000ccc16010,0x00000000eee00000) PSPermGen total 28672K, used 28205K [0x00000000c7a00000, 0x00000000c9600000, 0x00000000ccc00000) object space 28672K, 98% used [0x00000000c7a00000,0x00000000c958b488,0x00000000c9600000) LogType:syslog Log Upload Time:Fri Dec 09 15:38:32 +0800 2016 LogLength:20945 Log Contents: 2016-12-09 15:33:23,336 [INFO] [main] |app.DAGAppMaster|: Creating DAGAppMaster for applicationId=application_1479891196918_0199, attemptNum=1, AMContainerId=container_1479891196918_0199_01_000001, jvmPid=170033, userFromEnv=hive, cliSessionOption=true, pwd=/disk10/yarn/nm/usercache/hive/appcache/application_1479891196918_0199/container_1479891196918_0199_01_000001, localDirs=/disk1/yarn/nm/usercache/hive/appcache/application_1479891196918_0199,/disk10/yarn/nm/usercache/hive/appcache/application_1479891196918_0199,/disk11/yarn/nm/usercache/hive/appcache/application_1479891196918_0199,/disk12/yarn/nm/usercache/hive/appcache/application_1479891196918_0199,/disk2/yarn/nm/usercache/hive/appcache/application_1479891196918_0199,/disk3/yarn/nm/usercache/hive/appcache/application_1479891196918_0199,/disk4/yarn/nm/usercache/hive/appcache/application_1479891196918_0199,/disk5/yarn/nm/usercache/hive/appcache/application_1479891196918_0199,/disk6/yarn/nm/usercache/hive/appcache/application_1479891196918_0199,/disk7/yarn/nm/usercache/hive/appcache/application_1479891196918_0199,/disk8/yarn/nm/usercache/hive/appcache/application_1479891196918_0199,/disk9/yarn/nm/usercache/hive/appcache/application_1479891196918_0199, logDirs=/data/yarn/container-logs/application_1479891196918_0199/container_1479891196918_0199_01_000001,/disk1/yarn/container-logs/application_1479891196918_0199/container_1479891196918_0199_01_000001,/disk10/yarn/container-logs/application_1479891196918_0199/container_1479891196918_0199_01_000001,/disk11/yarn/container-logs/application_1479891196918_0199/container_1479891196918_0199_01_000001,/disk12/yarn/container-logs/application_1479891196918_0199/container_1479891196918_0199_01_000001,/disk2/yarn/container-logs/application_1479891196918_0199/container_1479891196918_0199_01_000001,/disk3/yarn/container-logs/application_1479891196918_0199/container_1479891196918_0199_01_000001,/disk4/yarn/container-logs/application_1479891196918_0199/container_1479891196918_0199_01_000001,/disk5/yarn/container-logs/application_1479891196918_0199/container_1479891196918_0199_01_000001,/disk6/yarn/container-logs/application_1479891196918_0199/container_1479891196918_0199_01_000001,/disk7/yarn/container-logs/application_1479891196918_0199/container_1479891196918_0199_01_000001,/disk8/yarn/container-logs/application_1479891196918_0199/container_1479891196918_0199_01_000001,/disk9/yarn/container-logs/application_1479891196918_0199/container_1479891196918_0199_01_000001 2016-12-09 15:33:23,823 [INFO] [main] |app.DAGAppMaster|: Created DAGAppMaster for application appattempt_1479891196918_0199_000001, versionInfo=[ component=tez-dag, version=0.8.4, revision=${buildNumber}, SCM-URL=scm:git:https://git-wip-us.apache.org/repos/asf/tez.git, buildTime=2016-12-08T02:12:16Z ] 2016-12-09 15:33:23,841 [INFO] [main] |shim.HadoopShimsLoader|: Trying to locate HadoopShimProvider for hadoopVersion=2.6.0-cdh5.8.2, majorVersion=2, minorVersion=6 2016-12-09 15:33:23,843 [INFO] [main] |shim.HadoopShimsLoader|: Picked HadoopShim org.apache.tez.hadoop.shim.HadoopShim26, providerName=org.apache.tez.hadoop.shim.HadoopShim25_26_27Provider, overrideProviderViaConfig=null, hadoopVersion=2.6.0-cdh5.8.2, majorVersion=2, minorVersion=6 2016-12-09 15:33:23,875 [INFO] [main] |app.DAGAppMaster|: AM Level configured TaskSchedulers: [0:TezYarn:null],[1:TezUber:null] 2016-12-09 15:33:23,875 [INFO] [main] |app.DAGAppMaster|: AM Level configured ContainerLaunchers: [0:TezYarn:null],[1:TezUber:null] 2016-12-09 15:33:23,875 [INFO] [main] |app.DAGAppMaster|: AM Level configured TaskCommunicators: [0:TezYarn:null],[1:TezUber:null] 2016-12-09 15:33:23,876 [INFO] [main] |app.DAGAppMaster|: Comparing client version with AM version, clientVersion=0.8.4, AMVersion=0.8.4 2016-12-09 15:33:24,540 [INFO] [main] |app.TaskCommunicatorManager|: Creating Default Task Communicator 2016-12-09 15:33:24,558 [INFO] [main] |Configuration.deprecation|: io.bytes.per.checksum is deprecated. Instead, use dfs.bytes-per-checksum 2016-12-09 15:33:24,561 [INFO] [main] |Configuration.deprecation|: mapred.input.dir.recursive is deprecated. Instead, use mapreduce.input.fileinputformat.input.dir.recursive 2016-12-09 15:33:24,564 [INFO] [main] |app.TaskCommunicatorManager|: Creating Default Local Task Communicator 2016-12-09 15:33:24,579 [INFO] [main] |common.AsyncDispatcher|: Registering class org.apache.tez.dag.app.rm.container.AMContainerEventType for class org.apache.tez.dag.app.rm.container.AMContainerMap 2016-12-09 15:33:24,580 [INFO] [main] |common.AsyncDispatcher|: Registering class org.apache.tez.dag.app.rm.node.AMNodeEventType for class org.apache.tez.dag.app.rm.node.AMNodeTracker 2016-12-09 15:33:24,581 [INFO] [main] |common.AsyncDispatcher|: Registering class org.apache.tez.dag.app.dag.event.DAGAppMasterEventType for class org.apache.tez.dag.app.DAGAppMaster$DAGAppMasterEventHandler 2016-12-09 15:33:24,581 [INFO] [main] |common.AsyncDispatcher|: Registering class org.apache.tez.dag.app.dag.event.DAGEventType for class org.apache.tez.dag.app.DAGAppMaster$DagEventDispatcher 2016-12-09 15:33:24,582 [INFO] [main] |common.AsyncDispatcher|: Registering class org.apache.tez.dag.app.dag.event.VertexEventType for class org.apache.tez.dag.app.DAGAppMaster$VertexEventDispatcher 2016-12-09 15:33:24,582 [INFO] [main] |app.DAGAppMaster|: Using concurrent dispatcher: false 2016-12-09 15:33:24,582 [INFO] [main] |common.AsyncDispatcher|: Registering class org.apache.tez.dag.app.dag.event.TaskEventType for class org.apache.tez.dag.app.DAGAppMaster$TaskEventDispatcher 2016-12-09 15:33:24,583 [INFO] [main] |common.AsyncDispatcher|: Registering class org.apache.tez.dag.app.dag.event.TaskAttemptEventType for class org.apache.tez.dag.app.DAGAppMaster$TaskAttemptEventDispatcher 2016-12-09 15:33:24,583 [INFO] [main] |common.AsyncDispatcher|: Registering class org.apache.tez.dag.app.dag.event.SpeculatorEventType for independent dispatch using: class org.apache.tez.dag.app.DAGAppMaster$SpeculatorEventHandler 2016-12-09 15:33:24,583 [INFO] [main] |common.AsyncDispatcher|: Registering class org.apache.tez.dag.app.dag.event.SpeculatorEventType for class org.apache.tez.dag.app.DAGAppMaster$SpeculatorEventHandler 2016-12-09 15:33:24,597 [INFO] [main] |common.AsyncDispatcher|: Registering class org.apache.tez.dag.app.rm.AMSchedulerEventType for class org.apache.tez.dag.app.rm.TaskSchedulerManager 2016-12-09 15:33:24,599 [INFO] [main] |launcher.TezContainerLauncherImpl|: Creating DefaultContainerLauncher 2016-12-09 15:33:24,610 [INFO] [main] |launcher.TezContainerLauncherImpl|: Upper limit on the thread pool size is 500 2016-12-09 15:33:24,610 [INFO] [main] |launcher.TezContainerLauncherImpl|: Creating LocalContainerLauncher 2016-12-09 15:33:24,619 [INFO] [main] |common.AsyncDispatcher|: Registering class org.apache.tez.dag.app.rm.ContainerLauncherEventType for class org.apache.tez.dag.app.launcher.ContainerLauncherManager 2016-12-09 15:33:24,686 [INFO] [main] |node.AMNodeTracker|: blacklistDisablePercent is 33, blacklistingEnabled: true, maxTaskFailuresPerNode: 10, nodeUpdatesRescheduleEnabled: false 2016-12-09 15:33:24,688 [INFO] [main] |web.WebUIService|: Tez UI History URL: http://tez.oa.com/#/main/views/TEZ/0.7.0.0-SNAPSHOT/TEZUI/#/tez-app/application_1479891196918_0199 2016-12-09 15:33:24,688 [INFO] [main] |history.HistoryEventHandler|: Initializing HistoryEventHandler withrecoveryEnabled=true, historyServiceClassName=org.apache.tez.dag.history.logging.ats.ATSHistoryLoggingService 2016-12-09 15:33:24,692 [WARN] [main] |ats.ATSHistoryLoggingService|: org.apache.tez.dag.history.logging.ats.ATSHistoryLoggingService is disabled due to Timeline Service being disabled, yarn.timeline-service.enabled set to false 2016-12-09 15:33:24,692 [INFO] [main] |ats.ATSHistoryLoggingService|: Initializing ATSHistoryLoggingService with maxEventsPerBatch=5, maxPollingTime(ms)=10, waitTimeForShutdown(ms)=-1, TimelineACLManagerClass=org.apache.tez.dag.history.ats.acls.ATSHistoryACLPolicyManager 2016-12-09 15:33:24,693 [WARN] [main] |acls.ATSHistoryACLPolicyManager|: org.apache.tez.dag.history.logging.ats.ATSHistoryLoggingService is disabled due to Timeline Service being disabled, yarn.timeline-service.enabled set to false 2016-12-09 15:33:24,694 [INFO] [main] |recovery.RecoveryService|: RecoveryService initialized with recoveryPath=hdfs://nameservice1/tmp/hive/hive/_tez_session_dir/cca34818-9463-4b84-97d9-68cd71a7242c/.tez/application_1479891196918_0199/recovery/1, bufferSize(bytes)=8192, flushInterval(s)=30, maxUnflushedEvents=100 2016-12-09 15:33:24,694 [INFO] [main] |history.HistoryEventHandler|: [HISTORY][DAG:N/A][Event:APP_LAUNCHED]: applicationId=application_1479891196918_0199, appSubmitTime=1481268800980, launchTime=1481268803821 2016-12-09 15:33:24,695 [INFO] [main] |history.HistoryEventHandler|: [HISTORY][DAG:N/A][Event:AM_LAUNCHED]: appAttemptId=appattempt_1479891196918_0199_000001, appSubmitTime=1481268800980, launchTime=1481268803821 2016-12-09 15:33:24,698 [INFO] [ServiceThread:org.apache.tez.dag.app.launcher.ContainerLauncherManager] |impl.ContainerManagementProtocolProxy|: yarn.client.max-cached-nodemanagers-proxies : 0 2016-12-09 15:33:24,702 [INFO] [ServiceThread:org.apache.tez.dag.app.TaskCommunicatorManager] |ipc.CallQueueManager|: Using callQueue class java.util.concurrent.LinkedBlockingQueue 2016-12-09 15:33:24,702 [INFO] [ServiceThread:DAGClientRPCServer] |ipc.CallQueueManager|: Using callQueue class java.util.concurrent.LinkedBlockingQueue 2016-12-09 15:33:24,729 [INFO] [Socket Reader #1 for port 35001] |ipc.Server|: Starting Socket Reader #1 for port 35001 2016-12-09 15:33:24,729 [INFO] [Socket Reader #1 for port 42744] |ipc.Server|: Starting Socket Reader #1 for port 42744 2016-12-09 15:33:24,746 [INFO] [IPC Server Responder] |ipc.Server|: IPC Server Responder: starting 2016-12-09 15:33:24,746 [INFO] [IPC Server listener on 42744] |ipc.Server|: IPC Server listener on 42744: starting 2016-12-09 15:33:24,747 [INFO] [IPC Server Responder] |ipc.Server|: IPC Server Responder: starting 2016-12-09 15:33:24,747 [INFO] [IPC Server listener on 35001] |ipc.Server|: IPC Server listener on 35001: starting 2016-12-09 15:33:24,748 [INFO] [ServiceThread:DAGClientRPCServer] |client.DAGClientServer|: Instantiated DAGClientRPCServer at GZHL-192-168-0-205.boyaa.com/192.168.0.205:42744 2016-12-09 15:33:24,751 [INFO] [ServiceThread:org.apache.tez.dag.app.TaskCommunicatorManager] |app.TezTaskCommunicatorImpl|: Instantiated TezTaskCommunicator RPC at GZHL-192-168-0-205.boyaa.com/192.168.0.205:35001 2016-12-09 15:33:24,768 [INFO] [ServiceThread:org.apache.tez.dag.app.web.WebUIService] |mortbay.log|: Logging to org.slf4j.impl.Log4jLoggerAdapter(org.mortbay.log) via org.mortbay.log.Slf4jLog 2016-12-09 15:33:24,773 [INFO] [ServiceThread:org.apache.tez.dag.app.web.WebUIService] |server.AuthenticationFilter|: Unable to initialize FileSignerSecretProvider, falling back to use random secrets. 2016-12-09 15:33:24,778 [INFO] [ServiceThread:org.apache.tez.dag.app.web.WebUIService] |http.HttpRequestLog|: Http request log for http.requests. is not defined 2016-12-09 15:33:24,786 [INFO] [ServiceThread:org.apache.tez.dag.app.web.WebUIService] |http.HttpServer2|: Added global filter 'safety' (class=org.apache.hadoop.http.HttpServer2$QuotingInputFilter) 2016-12-09 15:33:24,792 [INFO] [ServiceThread:org.apache.tez.dag.app.web.WebUIService] |http.HttpServer2|: Added filter AM_PROXY_FILTER (class=org.apache.hadoop.yarn.server.webproxy.amfilter.AmIpFilter) to context 2016-12-09 15:33:24,792 [INFO] [ServiceThread:org.apache.tez.dag.app.web.WebUIService] |http.HttpServer2|: Added filter AM_PROXY_FILTER (class=org.apache.hadoop.yarn.server.webproxy.amfilter.AmIpFilter) to context static 2016-12-09 15:33:24,795 [INFO] [ServiceThread:org.apache.tez.dag.app.web.WebUIService] |http.HttpServer2|: adding path spec: /* 2016-12-09 15:33:24,802 [INFO] [ServiceThread:org.apache.tez.dag.app.web.WebUIService] |http.HttpServer2|: Jetty bound to port 47406 2016-12-09 15:33:24,802 [INFO] [ServiceThread:org.apache.tez.dag.app.web.WebUIService] |mortbay.log|: jetty-6.1.26 2016-12-09 15:33:24,828 [INFO] [ServiceThread:org.apache.tez.dag.app.web.WebUIService] |mortbay.log|: Extract jar:file:/opt/cloudera/parcels/CDH-5.8.2-1.cdh5.8.2.p0.3/jars/hadoop-common-2.6.0-cdh5.8.2-tests.jar!/webapps/ to /disk10/yarn/nm/usercache/hive/appcache/application_1479891196918_0199/container_1479891196918_0199_01_000001/tmp/Jetty_0_0_0_0_47406_webapps____.1zqaki/webapp 2016-12-09 15:33:25,043 [INFO] [ServiceThread:org.apache.tez.dag.app.web.WebUIService] |mortbay.log|: Started HttpServer2$SelectChannelConnectorWithSafeStartup@0.0.0.0:47406 2016-12-09 15:33:25,043 [INFO] [ServiceThread:org.apache.tez.dag.app.web.WebUIService] |webapp.WebApps|: Web app / started at 47406 2016-12-09 15:33:25,278 [INFO] [ServiceThread:org.apache.tez.dag.app.web.WebUIService] |webapp.WebApps|: Registered webapp guice modules 2016-12-09 15:33:25,279 [INFO] [ServiceThread:org.apache.tez.dag.app.web.WebUIService] |web.WebUIService|: Instantiated WebUIService at http://GZHL-192-168-0-205.boyaa.com:47406/ui/ 2016-12-09 15:33:25,281 [INFO] [ServiceThread:org.apache.tez.dag.app.rm.TaskSchedulerManager] |rm.TaskSchedulerManager|: Creating TaskScheduler: YarnTaskSchedulerService 2016-12-09 15:33:25,315 [INFO] [ServiceThread:org.apache.tez.dag.app.rm.TaskSchedulerManager] |Configuration.deprecation|: io.bytes.per.checksum is deprecated. Instead, use dfs.bytes-per-checksum 2016-12-09 15:33:25,318 [INFO] [ServiceThread:org.apache.tez.dag.app.rm.TaskSchedulerManager] |rm.TaskSchedulerManager|: Creating TaskScheduler: Local TaskScheduler with clusterIdentifier=111101111 2016-12-09 15:33:25,331 [INFO] [ServiceThread:org.apache.tez.dag.app.rm.TaskSchedulerManager] |rm.YarnTaskSchedulerService|: YarnTaskScheduler initialized with configuration: maxRMHeartbeatInterval: 1000, containerReuseEnabled: true, reuseRackLocal: true, reuseNonLocal: false, localitySchedulingDelay: 250, preemptionPercentage: 10, preemptionMaxWaitTime: 60000, numHeartbeatsBetweenPreemptions: 3, idleContainerMinTimeout: 5000, idleContainerMaxTimeout: 10000, sessionMinHeldContainers: 0 2016-12-09 15:33:25,341 [INFO] [ServiceThread:org.apache.tez.dag.app.rm.TaskSchedulerManager] |client.RMProxy|: Connecting to ResourceManager at GZHL-192-168-0-200.boyaa.com/192.168.0.200:8030 2016-12-09 15:33:25,397 [INFO] [main] |history.HistoryEventHandler|: [HISTORY][DAG:N/A][Event:AM_STARTED]: appAttemptId=appattempt_1479891196918_0199_000001, startTime=1481268805397 2016-12-09 15:33:25,397 [INFO] [main] |app.DAGAppMaster|: In Session mode. Waiting for DAG over RPC 2016-12-09 15:33:25,424 [INFO] [AMRM Callback Handler Thread] |rm.YarnTaskSchedulerService|: App total resource memory: 187405 cpu: 236 taskAllocations: 0 2016-12-09 15:33:25,424 [INFO] [AMRM Callback Handler Thread] |rm.YarnTaskSchedulerService|: Allocated: <memory:0, vCores:0> Free: <memory:187405, vCores:236> pendingRequests: 0 delayedContainers: 0 heartbeats: 1 lastPreemptionHeartbeat: 0 2016-12-09 15:33:25,427 [INFO] [Dispatcher thread {Central}] |node.PerSourceNodeTracker|: Num cluster nodes = 5 2016-12-09 15:34:15,494 [INFO] [AMRM Callback Handler Thread] |rm.YarnTaskSchedulerService|: Allocated: <memory:0, vCores:0> Free: <memory:187405, vCores:236> pendingRequests: 0 delayedContainers: 0 heartbeats: 51 lastPreemptionHeartbeat: 50 2016-12-09 15:35:05,558 [INFO] [AMRM Callback Handler Thread] |rm.YarnTaskSchedulerService|: Allocated: <memory:0, vCores:0> Free: <memory:187405, vCores:236> pendingRequests: 0 delayedContainers: 0 heartbeats: 101 lastPreemptionHeartbeat: 100 2016-12-09 15:35:55,626 [INFO] [AMRM Callback Handler Thread] |rm.YarnTaskSchedulerService|: Allocated: <memory:0, vCores:0> Free: <memory:187405, vCores:236> pendingRequests: 0 delayedContainers: 0 heartbeats: 151 lastPreemptionHeartbeat: 150 2016-12-09 15:36:45,688 [INFO] [AMRM Callback Handler Thread] |rm.YarnTaskSchedulerService|: Allocated: <memory:0, vCores:0> Free: <memory:187405, vCores:236> pendingRequests: 0 delayedContainers: 0 heartbeats: 201 lastPreemptionHeartbeat: 200 2016-12-09 15:37:35,758 [INFO] [AMRM Callback Handler Thread] |rm.YarnTaskSchedulerService|: Allocated: <memory:0, vCores:0> Free: <memory:187405, vCores:236> pendingRequests: 0 delayedContainers: 0 heartbeats: 251 lastPreemptionHeartbeat: 250 2016-12-09 15:38:25,398 [INFO] [Timer-1] |rm.TaskSchedulerManager|: TaskScheduler notified that it should unregister from RM 2016-12-09 15:38:25,398 [INFO] [Timer-1] |app.DAGAppMaster|: No current running DAG, shutting down the AM 2016-12-09 15:38:25,398 [INFO] [Timer-1] |app.DAGAppMaster|: DAGAppMasterShutdownHandler invoked 2016-12-09 15:38:25,398 [INFO] [Timer-1] |app.DAGAppMaster|: Handling DAGAppMaster shutdown 2016-12-09 15:38:25,399 [INFO] [AMShutdownThread] |app.DAGAppMaster|: Sleeping for 5 seconds before shutting down 2016-12-09 15:38:25,826 [INFO] [AMRM Callback Handler Thread] |rm.YarnTaskSchedulerService|: Allocated: <memory:0, vCores:0> Free: <memory:187405, vCores:236> pendingRequests: 0 delayedContainers: 0 heartbeats: 301 lastPreemptionHeartbeat: 300 2016-12-09 15:38:30,399 [INFO] [AMShutdownThread] |app.DAGAppMaster|: Calling stop for all the services 2016-12-09 15:38:30,399 [INFO] [AMShutdownThread] |rm.YarnTaskSchedulerService|: Initiating stop of YarnTaskScheduler 2016-12-09 15:38:30,400 [INFO] [AMShutdownThread] |rm.YarnTaskSchedulerService|: Releasing held containers 2016-12-09 15:38:30,400 [INFO] [AMShutdownThread] |rm.YarnTaskSchedulerService|: Removing all pending taskRequests 2016-12-09 15:38:30,400 [INFO] [AMShutdownThread] |history.HistoryEventHandler|: Stopping HistoryEventHandler 2016-12-09 15:38:30,400 [INFO] [AMShutdownThread] |recovery.RecoveryService|: Stopping RecoveryService 2016-12-09 15:38:30,400 [INFO] [AMShutdownThread] |recovery.RecoveryService|: Handle the remaining events in queue, queue size=0 2016-12-09 15:38:30,401 [INFO] [RecoveryEventHandlingThread] |recovery.RecoveryService|: EventQueue take interrupted. Returning 2016-12-09 15:38:30,401 [INFO] [DelayedContainerManager] |rm.YarnTaskSchedulerService|: AllocatedContainerManager Thread interrupted 2016-12-09 15:38:30,404 [INFO] [AMShutdownThread] |rm.YarnTaskSchedulerService|: Unregistering application from RM, exitStatus=SUCCEEDED, exitMessage=Session stats:submittedDAGs=0, successfulDAGs=0, failedDAGs=0, killedDAGs=0 , trackingURL=http://tez.oa.com/#/main/views/TEZ/0.7.0.0-SNAPSHOT/TEZUI/#/tez-app/application_1479891196918_0199 2016-12-09 15:38:30,408 [INFO] [AMShutdownThread] |impl.AMRMClientImpl|: Waiting for application to be successfully unregistered. 2016-12-09 15:38:30,510 [INFO] [AMShutdownThread] |rm.YarnTaskSchedulerService|: Successfully unregistered application from RM 2016-12-09 15:38:30,510 [INFO] [AMShutdownThread] |rm.TaskSchedulerManager|: Shutting down AppCallbackExecutor 2016-12-09 15:38:30,510 [INFO] [AMRM Callback Handler Thread] |impl.AMRMClientAsyncImpl|: Interrupted while waiting for queue java.lang.InterruptedException at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.reportInterruptAfterWait(AbstractQueuedSynchronizer.java:2017) at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2052) at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442) at org.apache.hadoop.yarn.client.api.async.impl.AMRMClientAsyncImpl$CallbackHandlerThread.run(AMRMClientAsyncImpl.java:274) 2016-12-09 15:38:30,513 [INFO] [AMShutdownThread] |mortbay.log|: Stopped HttpServer2$SelectChannelConnectorWithSafeStartup@0.0.0.0:0 2016-12-09 15:38:30,613 [INFO] [AMShutdownThread] |ipc.Server|: Stopping server on 35001 2016-12-09 15:38:30,613 [INFO] [IPC Server listener on 35001] |ipc.Server|: Stopping IPC Server listener on 35001 2016-12-09 15:38:30,613 [INFO] [AMShutdownThread] |ipc.Server|: Stopping server on 42744 2016-12-09 15:38:30,614 [INFO] [IPC Server Responder] |ipc.Server|: Stopping IPC Server Responder 2016-12-09 15:38:30,614 [INFO] [IPC Server listener on 42744] |ipc.Server|: Stopping IPC Server listener on 42744 2016-12-09 15:38:30,615 [INFO] [IPC Server Responder] |ipc.Server|: Stopping IPC Server Responder 2016-12-09 15:38:30,617 [INFO] [Thread-2] |app.DAGAppMaster|: DAGAppMasterShutdownHook invoked 2016-12-09 15:38:30,617 [INFO] [Thread-2] |app.DAGAppMaster|: The shutdown handler is still running, waiting for it to complete 2016-12-09 15:38:30,630 [WARN] [AMShutdownThread] |app.DAGAppMaster|: Failed to delete tez scratch data dir, path=hdfs://nameservice1/tmp/hive/hive/_tez_session_dir/cca34818-9463-4b84-97d9-68cd71a7242c/.tez/application_1479891196918_0199 2016-12-09 15:38:30,630 [INFO] [AMShutdownThread] |app.DAGAppMaster|: Exiting DAGAppMaster..GoodBye! 2016-12-09 15:38:30,630 [INFO] [Thread-2] |app.DAGAppMaster|: The shutdown handler has completed

from the yarn logs , DAGAppMaster looks like Abnormal exit

Does anybody know what happening ，and how to config tez

[#2]

@jiang zhixingwith the logs

Unregistering application from RM, exitStatus=SUCCEEDED, exitMessage=Session stats:submittedDAGs=0, successfulDAGs=0, failedDAGs=0, killedDAGs=0

it seems that your dag was completed successfully so need not to worry, for interrupt yarn community(https://issues.apache.org/jira/browse/YARN-1022) decided to to change logging level for it to DEBUG but the issue is reproducible

[#3]

thanks,

actually, i had forgot start metastore service ,so the hiveserver started the metastore thread self, with many problems.

while i started metastore service and hiveserver service successively,

my problems disappeared