Member since
12-12-2016
2
Posts
0
Kudos Received
0
Solutions
12-26-2016
09:53 AM
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
... View more
12-12-2016
10:56 AM
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
... View more
Labels:
- Labels:
-
Apache Hive
-
Apache Tez