Log Type: syslog Log Upload Time: Tue Dec 13 09:10:55 +0200 2016 Log Length: 30335 2016-12-13 09:00:40,963 [INFO] [main] |app.DAGAppMaster|: Creating DAGAppMaster for applicationId=application_1474363291123_59008, attemptNum=1, AMContainerId=container_e24_1474363291123_59008_01_000001, jvmPid=6259, userFromEnv=hdfs, cliSessionOption=true, pwd=/grid/2/hadoop/yarn/local/usercache/hdfs/appcache/application_1474363291123_59008/container_e24_1474363291123_59008_01_000001, localDirs=/grid/4/hadoop/yarn/local/usercache/hdfs/appcache/application_1474363291123_59008,/grid/9/hadoop/yarn/local/usercache/hdfs/appcache/application_1474363291123_59008,/grid/11/hadoop/yarn/local/usercache/hdfs/appcache/application_1474363291123_59008,/grid/3/hadoop/yarn/local/usercache/hdfs/appcache/application_1474363291123_59008,/grid/8/hadoop/yarn/local/usercache/hdfs/appcache/application_1474363291123_59008,/grid/6/hadoop/yarn/local/usercache/hdfs/appcache/application_1474363291123_59008,/grid/7/hadoop/yarn/local/usercache/hdfs/appcache/application_1474363291123_59008,/grid/2/hadoop/yarn/local/usercache/hdfs/appcache/application_1474363291123_59008,/grid/1/hadoop/yarn/local/usercache/hdfs/appcache/application_1474363291123_59008,/grid/5/hadoop/yarn/local/usercache/hdfs/appcache/application_1474363291123_59008,/grid/10/hadoop/yarn/local/usercache/hdfs/appcache/application_1474363291123_59008,/grid/0/hadoop/yarn/local/usercache/hdfs/appcache/application_1474363291123_59008, logDirs=/opt/hadoop/yarn/log/application_1474363291123_59008/container_e24_1474363291123_59008_01_000001,/tmp/hadoop/yarn/log/application_1474363291123_59008/container_e24_1474363291123_59008_01_000001,/usr/hadoop/yarn/log/application_1474363291123_59008/container_e24_1474363291123_59008_01_000001,/var/hadoop/yarn/log/application_1474363291123_59008/container_e24_1474363291123_59008_01_000001,/var/log/hadoop/yarn/log/application_1474363291123_59008/container_e24_1474363291123_59008_01_000001,/grid/4/hadoop/yarn/log/application_1474363291123_59008/container_e24_1474363291123_59008_01_000001,/grid/6/hadoop/yarn/log/application_1474363291123_59008/container_e24_1474363291123_59008_01_000001,/grid/8/hadoop/yarn/log/application_1474363291123_59008/container_e24_1474363291123_59008_01_000001,/grid/11/hadoop/yarn/log/application_1474363291123_59008/container_e24_1474363291123_59008_01_000001,/grid/7/hadoop/yarn/log/application_1474363291123_59008/container_e24_1474363291123_59008_01_000001,/grid/9/hadoop/yarn/log/application_1474363291123_59008/container_e24_1474363291123_59008_01_000001,/grid/3/hadoop/yarn/log/application_1474363291123_59008/container_e24_1474363291123_59008_01_000001,/grid/2/hadoop/yarn/log/application_1474363291123_59008/container_e24_1474363291123_59008_01_000001,/grid/1/hadoop/yarn/log/application_1474363291123_59008/container_e24_1474363291123_59008_01_000001,/grid/10/hadoop/yarn/log/application_1474363291123_59008/container_e24_1474363291123_59008_01_000001,/grid/5/hadoop/yarn/log/application_1474363291123_59008/container_e24_1474363291123_59008_01_000001,/grid/0/hadoop/yarn/log/application_1474363291123_59008/container_e24_1474363291123_59008_01_000001 2016-12-13 09:00:41,596 [INFO] [main] |app.DAGAppMaster|: Created DAGAppMaster for application appattempt_1474363291123_59008_000001, versionInfo=[ component=tez-dag, version=0.7.0.2.4.0.0-169, revision=3c1431f45faaca982ecc8dad13a107787b834696, SCM-URL=scm:git:https://git-wip-us.apache.org/repos/asf/tez.git, buildTime=20160210-0711 ] 2016-12-13 09:00:41,609 [INFO] [main] |app.DAGAppMaster|: Comparing client version with AM version, clientVersion=0.7.0.2.4.0.0-169, AMVersion=0.7.0.2.4.0.0-169 2016-12-13 09:00:44,488 [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-13 09:00:44,489 [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-13 09:00:44,490 [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-13 09:00:44,490 [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-13 09:00:44,491 [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-13 09:00:44,491 [INFO] [main] |app.DAGAppMaster|: Using concurrent dispatcher: false 2016-12-13 09:00:44,491 [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-13 09:00:44,492 [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-13 09:00:44,492 [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-13 09:00:44,493 [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-13 09:00:44,588 [INFO] [main] |common.AsyncDispatcher|: Registering class org.apache.tez.dag.app.rm.AMSchedulerEventType for class org.apache.tez.dag.app.rm.TaskSchedulerEventHandler 2016-12-13 09:00:44,590 [INFO] [main] |common.AsyncDispatcher|: Registering class org.apache.tez.dag.app.rm.NMCommunicatorEventType for class org.apache.tez.dag.app.launcher.ContainerLauncherImpl 2016-12-13 09:00:44,688 [INFO] [main] |node.AMNodeTracker|: blacklistDisablePercent is 33, blacklistingEnabled: true, maxTaskFailuresPerNode: 10 2016-12-13 09:00:44,689 [INFO] [main] |web.WebUIService|: Tez UI History URL: http://nn:8080/#/main/views/TEZ/0.7.0.2.3.4.0-161/TEZ_CLUSTER_INSTANCE?viewPath=%2F%23%2Ftez-app%2Fapplication_1474363291123_59008 2016-12-13 09:00:44,696 [INFO] [main] |launcher.ContainerLauncherImpl|: Upper limit on the thread pool size is 500 2016-12-13 09:00:44,696 [INFO] [main] |history.HistoryEventHandler|: Initializing HistoryEventHandler withrecoveryEnabled=true, historyServiceClassName=org.apache.tez.dag.history.logging.ats.ATSV15HistoryLoggingService 2016-12-13 09:00:45,107 [INFO] [main] |impl.TimelineClientImpl|: Timeline service address: http://nn:8188/ws/v1/timeline/ 2016-12-13 09:00:45,108 [INFO] [main] |ats.ATSV15HistoryLoggingService|: Initializing ATSV15HistoryLoggingService with , maxPollingTime(ms)=10, waitTimeForShutdown(ms)=-1, TimelineACLManagerClass=org.apache.tez.dag.history.ats.acls.ATSV15HistoryACLPolicyManager 2016-12-13 09:00:45,181 [INFO] [main] |impl.TimelineClientImpl|: Timeline service address: http://nn:8188/ws/v1/timeline/ 2016-12-13 09:00:45,300 [INFO] [main] |recovery.RecoveryService|: RecoveryService initialized with recoveryPath=hdfs://nn:8020/tmp/hive/hdfs/_tez_session_dir/0cb424f8-88dd-4614-9a2e-97846dc820b3/.tez/application_1474363291123_59008/recovery/1, bufferSize(bytes)=8192, flushInterval(s)=30, maxUnflushedEvents=100 2016-12-13 09:00:45,302 [INFO] [main] |history.HistoryEventHandler|: [HISTORY][DAG:N/A][Event:APP_LAUNCHED]: applicationId=application_1474363291123_59008, appSubmitTime=1481612438103, launchTime=1481612441595 2016-12-13 09:00:45,302 [INFO] [main] |history.HistoryEventHandler|: [HISTORY][DAG:N/A][Event:AM_LAUNCHED]: appAttemptId=appattempt_1474363291123_59008_000001, appSubmitTime=1481612438103, launchTime=1481612441595 2016-12-13 09:00:45,312 [INFO] [ServiceThread:org.apache.tez.dag.app.launcher.ContainerLauncherImpl] |impl.ContainerManagementProtocolProxy|: yarn.client.max-cached-nodemanagers-proxies : 0 2016-12-13 09:00:45,354 [INFO] [ServiceThread:DAGClientRPCServer] |ipc.CallQueueManager|: Using callQueue class java.util.concurrent.LinkedBlockingQueue 2016-12-13 09:00:45,354 [INFO] [ServiceThread:org.apache.tez.dag.app.TaskAttemptListenerImpTezDag] |ipc.CallQueueManager|: Using callQueue class java.util.concurrent.LinkedBlockingQueue 2016-12-13 09:00:45,356 [INFO] [HistoryEventHandlingThread] |impl.TimelineClientImpl|: Writing summary log for appattempt_1474363291123_59008_000001 to /ats/active/application_1474363291123_59008/appattempt_1474363291123_59008_000001/summarylog-appattempt_1474363291123_59008_000001 2016-12-13 09:00:45,371 [INFO] [Socket Reader #1 for port 46176] |ipc.Server|: Starting Socket Reader #1 for port 46176 2016-12-13 09:00:45,371 [INFO] [Socket Reader #1 for port 35501] |ipc.Server|: Starting Socket Reader #1 for port 35501 2016-12-13 09:00:45,397 [INFO] [IPC Server Responder] |ipc.Server|: IPC Server Responder: starting 2016-12-13 09:00:45,397 [INFO] [IPC Server listener on 46176] |ipc.Server|: IPC Server listener on 46176: starting 2016-12-13 09:00:45,399 [INFO] [IPC Server Responder] |ipc.Server|: IPC Server Responder: starting 2016-12-13 09:00:45,399 [INFO] [IPC Server listener on 35501] |ipc.Server|: IPC Server listener on 35501: starting 2016-12-13 09:00:45,400 [INFO] [ServiceThread:DAGClientRPCServer] |client.DAGClientServer|: Instantiated DAGClientRPCServer at node 2016-12-13 09:00:45,404 [INFO] [ServiceThread:org.apache.tez.dag.app.TaskAttemptListenerImpTezDag] |app.TaskAttemptListenerImpTezDag|: Instantiated TaskAttemptListener RPC at node 2016-12-13 09:00:45,448 [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-13 09:00:45,458 [INFO] [ServiceThread:org.apache.tez.dag.app.web.WebUIService] |server.AuthenticationFilter|: Unable to initialize FileSignerSecretProvider, falling back to use random secrets. 2016-12-13 09:00:45,463 [INFO] [ServiceThread:org.apache.tez.dag.app.web.WebUIService] |http.HttpRequestLog|: Http request log for http.requests. is not defined 2016-12-13 09:00:45,485 [INFO] [ServiceThread:org.apache.tez.dag.app.web.WebUIService] |http.HttpServer2|: Added global filter 'safety' (class=org.apache.hadoop.http.HttpServer2$QuotingInputFilter) 2016-12-13 09:00:45,491 [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-13 09:00:45,491 [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-13 09:00:45,495 [INFO] [ServiceThread:org.apache.tez.dag.app.web.WebUIService] |http.HttpServer2|: adding path spec: /* 2016-12-13 09:00:45,539 [INFO] [HistoryEventHandlingThread] |impl.TimelineClientImpl|: Writing summary log for appattempt_1474363291123_59008_000001 to /ats/active/application_1474363291123_59008/appattempt_1474363291123_59008_000001/summarylog-appattempt_1474363291123_59008_000001 2016-12-13 09:00:47,231 [INFO] [ServiceThread:org.apache.tez.dag.app.web.WebUIService] |webapp.WebApps|: Registered webapp guice modules 2016-12-13 09:00:47,233 [INFO] [ServiceThread:org.apache.tez.dag.app.web.WebUIService] |http.HttpServer2|: Jetty bound to port 49384 2016-12-13 09:00:47,233 [INFO] [ServiceThread:org.apache.tez.dag.app.web.WebUIService] |mortbay.log|: jetty-6.1.26.hwx 2016-12-13 09:00:48,544 [INFO] [ServiceThread:org.apache.tez.dag.app.web.WebUIService] |mortbay.log|: Extract jar:file:/grid/11/hadoop/yarn/local/filecache/293/tez.tar.gz/lib/hadoop-yarn-common-2.7.1.2.4.0.0-169.jar!/webapps/ to /grid/2/hadoop/yarn/local/usercache/hdfs/appcache/application_1474363291123_59008/container_e24_1474363291123_59008_01_000001/tmp/Jetty_0_0_0_0_49384_webapps____d576ej/webapp 2016-12-13 09:00:48,863 [INFO] [ServiceThread:org.apache.tez.dag.app.web.WebUIService] |mortbay.log|: Started HttpServer2$SelectChannelConnectorWithSafeStartup@0.0.0.0:49384 2016-12-13 09:00:48,864 [INFO] [ServiceThread:org.apache.tez.dag.app.web.WebUIService] |webapp.WebApps|: Web app started at 49384 2016-12-13 09:00:48,865 [INFO] [ServiceThread:org.apache.tez.dag.app.web.WebUIService] |web.WebUIService|: Instantiated WebUIService at http://nn:49384/ui/ 2016-12-13 09:00:48,999 [INFO] [ServiceThread:org.apache.tez.dag.app.rm.TaskSchedulerEventHandler] |rm.YarnTaskSchedulerService|: YarnTaskScheduler initialized with configuration: maxRMHeartbeatInterval: 250, containerReuseEnabled: true, reuseRackLocal: true, reuseNonLocal: false, localitySchedulingDelay: 250, preemptionPercentage: 10, preemptionMaxWaitTime: 60000, numHeartbeatsBetweenPreemptions: 3, idleContainerMinTimeout: 10000, idleContainerMaxTimeout: 20000, sessionMinHeldContainers: 0 2016-12-13 09:00:49,037 [INFO] [ServiceThread:org.apache.tez.dag.app.rm.TaskSchedulerEventHandler] |client.RMProxy|: Connecting to ResourceManager:8030 2016-12-13 09:00:49,110 [INFO] [main] |history.HistoryEventHandler|: [HISTORY][DAG:N/A][Event:AM_STARTED]: appAttemptId=appattempt_1474363291123_59008_000001, startTime=1481612449109 2016-12-13 09:00:49,110 [INFO] [main] |app.DAGAppMaster|: In Session mode. Waiting for DAG over RPC 2016-12-13 09:00:49,112 [INFO] [HistoryEventHandlingThread] |impl.TimelineClientImpl|: Writing summary log for appattempt_1474363291123_59008_000001 to /ats/active/application_1474363291123_59008/appattempt_1474363291123_59008_000001/summarylog-appattempt_1474363291123_59008_000001 2016-12-13 09:00:49,160 [INFO] [AMRM Callback Handler Thread] |rm.YarnTaskSchedulerService|: App total resource memory: 168960 cpu: 1 taskAllocations: 0 2016-12-13 09:00:49,160 [INFO] [AMRM Callback Handler Thread] |rm.YarnTaskSchedulerService|: Allocated: Free: pendingRequests: 0 delayedContainers: 0 heartbeats: 1 lastPreemptionHeartbeat: 0 2016-12-13 09:00:49,162 [INFO] [Dispatcher thread {Central}] |node.AMNodeTracker|: Num cluster nodes = 8 2016-12-13 09:01:01,740 [INFO] [AMRM Callback Handler Thread] |rm.YarnTaskSchedulerService|: Allocated: Free: pendingRequests: 0 delayedContainers: 0 heartbeats: 51 lastPreemptionHeartbeat: 50 2016-12-13 09:01:14,306 [INFO] [AMRM Callback Handler Thread] |rm.YarnTaskSchedulerService|: Allocated: Free: pendingRequests: 0 delayedContainers: 0 heartbeats: 101 lastPreemptionHeartbeat: 100 2016-12-13 09:01:26,866 [INFO] [AMRM Callback Handler Thread] |rm.YarnTaskSchedulerService|: Allocated: Free: pendingRequests: 0 delayedContainers: 0 heartbeats: 151 lastPreemptionHeartbeat: 150 2016-12-13 09:01:39,426 [INFO] [AMRM Callback Handler Thread] |rm.YarnTaskSchedulerService|: Allocated: Free: pendingRequests: 0 delayedContainers: 0 heartbeats: 201 lastPreemptionHeartbeat: 200 2016-12-13 09:01:52,078 [INFO] [AMRM Callback Handler Thread] |rm.YarnTaskSchedulerService|: Allocated: Free: pendingRequests: 0 delayedContainers: 0 heartbeats: 251 lastPreemptionHeartbeat: 250 2016-12-13 09:02:04,625 [INFO] [AMRM Callback Handler Thread] |rm.YarnTaskSchedulerService|: Allocated: Free: pendingRequests: 0 delayedContainers: 0 heartbeats: 301 lastPreemptionHeartbeat: 300 2016-12-13 09:02:17,172 [INFO] [AMRM Callback Handler Thread] |rm.YarnTaskSchedulerService|: Allocated: Free: pendingRequests: 0 delayedContainers: 0 heartbeats: 351 lastPreemptionHeartbeat: 350 2016-12-13 09:02:29,717 [INFO] [AMRM Callback Handler Thread] |rm.YarnTaskSchedulerService|: Allocated: Free: pendingRequests: 0 delayedContainers: 0 heartbeats: 401 lastPreemptionHeartbeat: 400 2016-12-13 09:02:42,258 [INFO] [AMRM Callback Handler Thread] |rm.YarnTaskSchedulerService|: Allocated: Free: pendingRequests: 0 delayedContainers: 0 heartbeats: 451 lastPreemptionHeartbeat: 450 2016-12-13 09:02:54,800 [INFO] [AMRM Callback Handler Thread] |rm.YarnTaskSchedulerService|: Allocated: Free: pendingRequests: 0 delayedContainers: 0 heartbeats: 501 lastPreemptionHeartbeat: 500 2016-12-13 09:03:07,342 [INFO] [AMRM Callback Handler Thread] |rm.YarnTaskSchedulerService|: Allocated: Free: pendingRequests: 0 delayedContainers: 0 heartbeats: 551 lastPreemptionHeartbeat: 550 2016-12-13 09:03:19,886 [INFO] [AMRM Callback Handler Thread] |rm.YarnTaskSchedulerService|: Allocated: Free: pendingRequests: 0 delayedContainers: 0 heartbeats: 601 lastPreemptionHeartbeat: 600 2016-12-13 09:03:32,430 [INFO] [AMRM Callback Handler Thread] |rm.YarnTaskSchedulerService|: Allocated: Free: pendingRequests: 0 delayedContainers: 0 heartbeats: 651 lastPreemptionHeartbeat: 650 2016-12-13 09:03:44,977 [INFO] [AMRM Callback Handler Thread] |rm.YarnTaskSchedulerService|: Allocated: Free: pendingRequests: 0 delayedContainers: 0 heartbeats: 701 lastPreemptionHeartbeat: 700 2016-12-13 09:03:57,525 [INFO] [AMRM Callback Handler Thread] |rm.YarnTaskSchedulerService|: Allocated: Free: pendingRequests: 0 delayedContainers: 0 heartbeats: 751 lastPreemptionHeartbeat: 750 2016-12-13 09:04:10,089 [INFO] [AMRM Callback Handler Thread] |rm.YarnTaskSchedulerService|: Allocated: Free: pendingRequests: 0 delayedContainers: 0 heartbeats: 801 lastPreemptionHeartbeat: 800 2016-12-13 09:04:22,676 [INFO] [AMRM Callback Handler Thread] |rm.YarnTaskSchedulerService|: Allocated: Free: pendingRequests: 0 delayedContainers: 0 heartbeats: 851 lastPreemptionHeartbeat: 850 2016-12-13 09:04:35,228 [INFO] [AMRM Callback Handler Thread] |rm.YarnTaskSchedulerService|: Allocated: Free: pendingRequests: 0 delayedContainers: 0 heartbeats: 901 lastPreemptionHeartbeat: 900 2016-12-13 09:04:47,779 [INFO] [AMRM Callback Handler Thread] |rm.YarnTaskSchedulerService|: Allocated: Free: pendingRequests: 0 delayedContainers: 0 heartbeats: 951 lastPreemptionHeartbeat: 950 2016-12-13 09:05:00,360 [INFO] [AMRM Callback Handler Thread] |rm.YarnTaskSchedulerService|: Allocated: Free: pendingRequests: 0 delayedContainers: 0 heartbeats: 1001 lastPreemptionHeartbeat: 1000 2016-12-13 09:05:12,913 [INFO] [AMRM Callback Handler Thread] |rm.YarnTaskSchedulerService|: Allocated: Free: pendingRequests: 0 delayedContainers: 0 heartbeats: 1051 lastPreemptionHeartbeat: 1050 2016-12-13 09:05:25,495 [INFO] [AMRM Callback Handler Thread] |rm.YarnTaskSchedulerService|: Allocated: Free: pendingRequests: 0 delayedContainers: 0 heartbeats: 1101 lastPreemptionHeartbeat: 1100 2016-12-13 09:05:38,046 [INFO] [AMRM Callback Handler Thread] |rm.YarnTaskSchedulerService|: Allocated: Free: pendingRequests: 0 delayedContainers: 0 heartbeats: 1151 lastPreemptionHeartbeat: 1150 2016-12-13 09:05:50,606 [INFO] [AMRM Callback Handler Thread] |rm.YarnTaskSchedulerService|: Allocated: Free: pendingRequests: 0 delayedContainers: 0 heartbeats: 1201 lastPreemptionHeartbeat: 1200 2016-12-13 09:06:03,162 [INFO] [AMRM Callback Handler Thread] |rm.YarnTaskSchedulerService|: Allocated: Free: pendingRequests: 0 delayedContainers: 0 heartbeats: 1251 lastPreemptionHeartbeat: 1250 2016-12-13 09:06:15,713 [INFO] [AMRM Callback Handler Thread] |rm.YarnTaskSchedulerService|: Allocated: Free: pendingRequests: 0 delayedContainers: 0 heartbeats: 1301 lastPreemptionHeartbeat: 1300 2016-12-13 09:06:28,266 [INFO] [AMRM Callback Handler Thread] |rm.YarnTaskSchedulerService|: Allocated: Free: pendingRequests: 0 delayedContainers: 0 heartbeats: 1351 lastPreemptionHeartbeat: 1350 2016-12-13 09:06:40,812 [INFO] [AMRM Callback Handler Thread] |rm.YarnTaskSchedulerService|: Allocated: Free: pendingRequests: 0 delayedContainers: 0 heartbeats: 1401 lastPreemptionHeartbeat: 1400 2016-12-13 09:06:53,359 [INFO] [AMRM Callback Handler Thread] |rm.YarnTaskSchedulerService|: Allocated: Free: pendingRequests: 0 delayedContainers: 0 heartbeats: 1451 lastPreemptionHeartbeat: 1450 2016-12-13 09:07:05,900 [INFO] [AMRM Callback Handler Thread] |rm.YarnTaskSchedulerService|: Allocated: Free: pendingRequests: 0 delayedContainers: 0 heartbeats: 1501 lastPreemptionHeartbeat: 1500 2016-12-13 09:07:18,443 [INFO] [AMRM Callback Handler Thread] |rm.YarnTaskSchedulerService|: Allocated: Free: pendingRequests: 0 delayedContainers: 0 heartbeats: 1551 lastPreemptionHeartbeat: 1550 2016-12-13 09:07:30,991 [INFO] [AMRM Callback Handler Thread] |rm.YarnTaskSchedulerService|: Allocated: Free: pendingRequests: 0 delayedContainers: 0 heartbeats: 1601 lastPreemptionHeartbeat: 1600 2016-12-13 09:07:43,538 [INFO] [AMRM Callback Handler Thread] |rm.YarnTaskSchedulerService|: Allocated: Free: pendingRequests: 0 delayedContainers: 0 heartbeats: 1651 lastPreemptionHeartbeat: 1650 2016-12-13 09:07:56,104 [INFO] [AMRM Callback Handler Thread] |rm.YarnTaskSchedulerService|: Allocated: Free: pendingRequests: 0 delayedContainers: 0 heartbeats: 1701 lastPreemptionHeartbeat: 1700 2016-12-13 09:08:08,653 [INFO] [AMRM Callback Handler Thread] |rm.YarnTaskSchedulerService|: Allocated: Free: pendingRequests: 0 delayedContainers: 0 heartbeats: 1751 lastPreemptionHeartbeat: 1750 2016-12-13 09:08:21,202 [INFO] [AMRM Callback Handler Thread] |rm.YarnTaskSchedulerService|: Allocated: Free: pendingRequests: 0 delayedContainers: 0 heartbeats: 1801 lastPreemptionHeartbeat: 1800 2016-12-13 09:08:33,746 [INFO] [AMRM Callback Handler Thread] |rm.YarnTaskSchedulerService|: Allocated: Free: pendingRequests: 0 delayedContainers: 0 heartbeats: 1851 lastPreemptionHeartbeat: 1850 2016-12-13 09:08:46,292 [INFO] [AMRM Callback Handler Thread] |rm.YarnTaskSchedulerService|: Allocated: Free: pendingRequests: 0 delayedContainers: 0 heartbeats: 1901 lastPreemptionHeartbeat: 1900 2016-12-13 09:08:58,837 [INFO] [AMRM Callback Handler Thread] |rm.YarnTaskSchedulerService|: Allocated: Free: pendingRequests: 0 delayedContainers: 0 heartbeats: 1951 lastPreemptionHeartbeat: 1950 2016-12-13 09:09:11,382 [INFO] [AMRM Callback Handler Thread] |rm.YarnTaskSchedulerService|: Allocated: Free: pendingRequests: 0 delayedContainers: 0 heartbeats: 2001 lastPreemptionHeartbeat: 2000 2016-12-13 09:09:23,928 [INFO] [AMRM Callback Handler Thread] |rm.YarnTaskSchedulerService|: Allocated: Free: pendingRequests: 0 delayedContainers: 0 heartbeats: 2051 lastPreemptionHeartbeat: 2050 2016-12-13 09:09:36,471 [INFO] [AMRM Callback Handler Thread] |rm.YarnTaskSchedulerService|: Allocated: Free: pendingRequests: 0 delayedContainers: 0 heartbeats: 2101 lastPreemptionHeartbeat: 2100 2016-12-13 09:09:49,015 [INFO] [AMRM Callback Handler Thread] |rm.YarnTaskSchedulerService|: Allocated: Free: pendingRequests: 0 delayedContainers: 0 heartbeats: 2151 lastPreemptionHeartbeat: 2150 2016-12-13 09:10:01,558 [INFO] [AMRM Callback Handler Thread] |rm.YarnTaskSchedulerService|: Allocated: Free: pendingRequests: 0 delayedContainers: 0 heartbeats: 2201 lastPreemptionHeartbeat: 2200 2016-12-13 09:10:14,104 [INFO] [AMRM Callback Handler Thread] |rm.YarnTaskSchedulerService|: Allocated: Free: pendingRequests: 0 delayedContainers: 0 heartbeats: 2251 lastPreemptionHeartbeat: 2250 2016-12-13 09:10:26,648 [INFO] [AMRM Callback Handler Thread] |rm.YarnTaskSchedulerService|: Allocated: Free: pendingRequests: 0 delayedContainers: 0 heartbeats: 2301 lastPreemptionHeartbeat: 2300 2016-12-13 09:10:39,195 [INFO] [AMRM Callback Handler Thread] |rm.YarnTaskSchedulerService|: Allocated: Free: pendingRequests: 0 delayedContainers: 0 heartbeats: 2351 lastPreemptionHeartbeat: 2350 2016-12-13 09:10:49,110 [INFO] [Timer-1] |app.DAGAppMaster|: Session timed out, lastDAGCompletionTime=1481612449110 ms, sessionTimeoutInterval=600000 ms 2016-12-13 09:10:49,111 [INFO] [Timer-1] |rm.TaskSchedulerEventHandler|: TaskScheduler notified that it should unregister from RM 2016-12-13 09:10:49,111 [INFO] [Timer-1] |app.DAGAppMaster|: No current running DAG, shutting down the AM 2016-12-13 09:10:49,111 [INFO] [Timer-1] |app.DAGAppMaster|: DAGAppMasterShutdownHandler invoked 2016-12-13 09:10:49,111 [INFO] [Timer-1] |app.DAGAppMaster|: Handling DAGAppMaster shutdown 2016-12-13 09:10:49,113 [INFO] [AMShutdownThread] |app.DAGAppMaster|: Sleeping for 5 seconds before shutting down 2016-12-13 09:10:51,742 [INFO] [AMRM Callback Handler Thread] |rm.YarnTaskSchedulerService|: Allocated: Free: pendingRequests: 0 delayedContainers: 0 heartbeats: 2401 lastPreemptionHeartbeat: 2400 2016-12-13 09:10:54,113 [INFO] [AMShutdownThread] |app.DAGAppMaster|: Calling stop for all the services 2016-12-13 09:10:54,113 [INFO] [AMShutdownThread] |rm.YarnTaskSchedulerService|: Initiating stop of YarnTaskScheduler 2016-12-13 09:10:54,113 [INFO] [AMShutdownThread] |rm.YarnTaskSchedulerService|: Releasing held containers 2016-12-13 09:10:54,113 [INFO] [AMShutdownThread] |rm.YarnTaskSchedulerService|: Removing all pending taskRequests 2016-12-13 09:10:54,114 [INFO] [AMShutdownThread] |history.HistoryEventHandler|: Stopping HistoryEventHandler 2016-12-13 09:10:54,115 [INFO] [AMShutdownThread] |recovery.RecoveryService|: Stopping RecoveryService 2016-12-13 09:10:54,115 [INFO] [AMShutdownThread] |recovery.RecoveryService|: Handle the remaining events in queue, queue size=0 2016-12-13 09:10:54,115 [INFO] [RecoveryEventHandlingThread] |recovery.RecoveryService|: EventQueue take interrupted. Returning 2016-12-13 09:10:54,115 [INFO] [AMShutdownThread] |ats.ATSV15HistoryLoggingService|: Stopping ATSService, eventQueueBacklog=0 2016-12-13 09:10:54,117 [INFO] [DelayedContainerManager] |rm.YarnTaskSchedulerService|: AllocatedContainerManager Thread interrupted 2016-12-13 09:10:54,119 [INFO] [AMShutdownThread] |rm.YarnTaskSchedulerService|: Unregistering application from RM, exitStatus=SUCCEEDED, exitMessage=Session stats:submittedDAGs=0, successfulDAGs=0, failedDAGs=0, killedDAGs=0 , trackingURL=http://nn:8080/#/main/views/TEZ/0.7.0.2.3.4.0-161/TEZ_CLUSTER_INSTANCE?viewPath=%2F%23%2Ftez-app%2Fapplication_1474363291123_59008 2016-12-13 09:10:54,136 [INFO] [AMShutdownThread] |impl.AMRMClientImpl|: Waiting for application to be successfully unregistered. 2016-12-13 09:10:54,237 [INFO] [AMShutdownThread] |rm.YarnTaskSchedulerService|: Successfully unregistered application from RM 2016-12-13 09:10:54,239 [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:2014) at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2048) at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442) at org.apache.hadoop.yarn.client.api.async.impl.AMRMClientAsyncImpl$CallbackHandlerThread.run(AMRMClientAsyncImpl.java:287) 2016-12-13 09:10:54,336 [INFO] [AMShutdownThread] |mortbay.log|: Stopped HttpServer2$SelectChannelConnectorWithSafeStartup@0.0.0.0:0 2016-12-13 09:10:54,437 [INFO] [AMShutdownThread] |ipc.Server|: Stopping server on 35501 2016-12-13 09:10:54,441 [INFO] [IPC Server listener on 35501] |ipc.Server|: Stopping IPC Server listener on 35501 2016-12-13 09:10:54,442 [INFO] [AMShutdownThread] |ipc.Server|: Stopping server on 46176 2016-12-13 09:10:54,442 [INFO] [IPC Server Responder] |ipc.Server|: Stopping IPC Server Responder 2016-12-13 09:10:54,443 [INFO] [IPC Server listener on 46176] |ipc.Server|: Stopping IPC Server listener on 46176 2016-12-13 09:10:54,444 [INFO] [IPC Server Responder] |ipc.Server|: Stopping IPC Server Responder 2016-12-13 09:10:54,452 [WARN] [AMShutdownThread] |app.DAGAppMaster|: Failed to delete tez scratch data dir, path=hdfs://nn:8020/tmp/hive/hdfs/_tez_session_dir/0cb424f8-88dd-4614-9a2e-97846dc820b3/.tez/application_1474363291123_59008 2016-12-13 09:10:54,452 [INFO] [AMShutdownThread] |app.DAGAppMaster|: Exiting DAGAppMaster..GoodBye! 2016-12-13 09:10:54,463 [INFO] [Thread-3] |app.DAGAppMaster|: DAGAppMasterShutdownHook invoked