You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@tajo.apache.org by Henry Saputra <he...@gmail.com> on 2013/05/20 09:20:40 UTC
Running sample query from sample external table from wiki never comeback
Something fishy, after building new Tajo from master today the simple query:
no longer working because
tajo> /d table1
table name: table1
table path: /home/hsaputra/tajo-install/sample_data/table1
store type: CSV
number of rows: 0
volume (bytes): 81 B
schema:
id type: INT4
name type: TEXT
score type: FLOAT8
type type: TEXT
tajo> select * from table1
Progress: 0%, response time: 2.993 sec
Progress: 0%, response time: 3.997 sec
Progress: 0%, response time: 5.0 sec
Progress: 0%, response time: 6.002 sec
Progress: 0%, response time: 7.003 sec
Progress: 0%, response time: 8.005 sec
Progress: 0%, response time: 9.008 sec
Progress: 0%, response time: 10.011 sec
Progress: 0%, response time: 11.014 sec
Progress: 0%, response time: 12.017 sec
Progress: 0%, response time: 13.02 sec
Progress: 0%, response time: 14.023 sec
Progress: 0%, response time: 15.026 sec
Here is the log entry:
2013-05-20 00:11:14,610 INFO master.GlobalEngine
(GlobalEngine.java:executeQuery(152)) - TQL: select * from table1
2013-05-20 00:11:14,787 INFO planner.LogicalPlanner
(LogicalPlanner.java:createPlanInternal(89)) - Planning select statement
2013-05-20 00:11:14,812 INFO master.GlobalEngine
(GlobalEngine.java:createLogicalPlan(243)) - LogicalPlan:
Logical Plan Root
"Scan" : {"table":"table1",
"out schema": {table1.id (INT4),table1.name (TEXT),table1.score
(FLOAT8),table1.type (TEXT)}
"in schema": {table1.id (INT4),table1.name (TEXT),table1.score
(FLOAT8),table1.type (TEXT)}
Get AppId: application_1369029921250_0003
2013-05-20 00:11:14,881 INFO master.GlobalEngine
(GlobalEngine.java:submitQuery(195)) - Setting up application submission
context for ASM
2013-05-20 00:11:14,899 INFO master.GlobalEngine
(GlobalEngine.java:submitQuery(220)) - Setting unmanaged AM
2013-05-20 00:11:14,900 INFO master.GlobalEngine
(GlobalEngine.java:submitQuery(223)) - Submitting application to ASM
2013-05-20 00:11:15,975 INFO master.GlobalEngine
(GlobalEngine.java:monitorApplication(323)) - Got application report from
ASM for, appId=3, appAttemptId=appattempt_1369029921250_0003_000001,
clientToken=null, appDiagnostics=, appMasterHost=N/A, appQueue=default,
appMasterRpcPort=0, appStartTime=1369033874909, yarnAppState=ACCEPTED,
distributedFinalState=UNDEFINED,
appTrackingUrl=hsaputra-x1-carbon:8088/proxy/application_1369029921250_0003/,
appUser=hsaputra
2013-05-20 00:11:15,976 INFO master.GlobalEngine
(GlobalEngine.java:submitQuery(232)) - Launching application with id:
appattempt_1369029921250_0003_000001
2013-05-20 00:11:16,099 INFO master.QueryMaster
(QueryMaster.java:<init>(102)) - Created Query Master for
appattempt_1369029921250_0003_000001
2013-05-20 00:11:16,128 INFO rpc.NettyServerBase
(NettyServerBase.java:start(84)) - RpcServer on /127.0.1.1:59941
2013-05-20 00:11:16,140 INFO event.AsyncDispatcher
(AsyncDispatcher.java:register(153)) - Registering class
tajo.master.event.ContainerAllocatorEventType for class
tajo.master.rm.RMContainerAllocator
2013-05-20 00:11:16,198 INFO master.QueryMaster
(QueryMaster.java:initStagingDir(463)) - Initialized Query Staging Dir:
hdfs://localhost:9000/user/hsaputra/tajo/q_1369029921250_0003_000001
2013-05-20 00:11:16,199 INFO event.AsyncDispatcher
(AsyncDispatcher.java:register(153)) - Registering class
tajo.master.event.QueryEventType for class tajo.master.Query
2013-05-20 00:11:16,201 INFO event.AsyncDispatcher
(AsyncDispatcher.java:register(153)) - Registering class
tajo.master.event.SubQueryEventType for class
tajo.master.QueryMaster$SubQueryEventDispatcher
2013-05-20 00:11:16,202 INFO event.AsyncDispatcher
(AsyncDispatcher.java:register(153)) - Registering class
tajo.master.event.TaskEventType for class
tajo.master.QueryMaster$TaskEventDispatcher
2013-05-20 00:11:16,204 INFO event.AsyncDispatcher
(AsyncDispatcher.java:register(153)) - Registering class
tajo.master.event.TaskAttemptEventType for class
tajo.master.QueryMaster$TaskAttemptEventDispatcher
2013-05-20 00:11:16,206 INFO event.AsyncDispatcher
(AsyncDispatcher.java:register(153)) - Registering class
tajo.master.event.QueryFinishEvent$EventType for class
tajo.master.QueryMaster$QueryFinishEventHandler
2013-05-20 00:11:16,208 INFO event.AsyncDispatcher
(AsyncDispatcher.java:register(153)) - Registering class
tajo.master.event.TaskSchedulerEvent$EventType for class
tajo.master.QueryMaster$TaskSchedulerDispatcher
2013-05-20 00:11:16,214 INFO event.AsyncDispatcher
(AsyncDispatcher.java:register(153)) - Registering class
tajo.master.TaskRunnerEvent$EventType for class
tajo.master.TaskRunnerLauncherImpl
2013-05-20 00:11:16,214 INFO service.AbstractService
(AbstractService.java:init(81)) - Service:Dispatcher is inited.
2013-05-20 00:11:16,217 INFO rpc.NettyServerBase
(NettyServerBase.java:start(84)) - RpcServer on /127.0.1.1:56434
2013-05-20 00:11:16,218 INFO cluster.WorkerListener
(TaskRunnerListener.java:init(102)) - WorkerListener is bind to
hsaputra-x1-carbon:56434
2013-05-20 00:11:16,218 INFO service.AbstractService
(AbstractService.java:init(81)) -
Service:tajo.master.cluster.WorkerListener is inited.
2013-05-20 00:11:16,219 INFO service.AbstractService
(AbstractService.java:init(81)) -
Service:org.apache.hadoop.yarn.client.AMRMClientImpl is inited.
2013-05-20 00:11:16,219 INFO service.AbstractService
(AbstractService.java:init(81)) -
Service:tajo.master.TaskRunnerLauncherImpl is inited.
2013-05-20 00:11:16,219 INFO service.AbstractService
(AbstractService.java:init(81)) - Service:tajo.master.QueryMaster is inited.
2013-05-20 00:11:16,220 INFO service.AbstractService
(AbstractService.java:start(94)) - Service:Dispatcher is started.
2013-05-20 00:11:16,220 INFO service.AbstractService
(AbstractService.java:start(94)) -
Service:tajo.master.cluster.WorkerListener is started.
2013-05-20 00:11:16,289 INFO service.AbstractService
(AbstractService.java:start(94)) -
Service:org.apache.hadoop.yarn.client.AMRMClientImpl is started.
2013-05-20 00:11:16,358 INFO service.AbstractService
(AbstractService.java:start(94)) -
Service:tajo.master.TaskRunnerLauncherImpl is started.
2013-05-20 00:11:16,359 INFO service.AbstractService
(AbstractService.java:start(94)) - Service:tajo.master.QueryMaster is
started.
2013-05-20 00:11:16,362 INFO rm.RMContainerAllocator
(RMContainerAllocator.java:heartbeat(157)) - Available Cluster Nodes: 1
2013-05-20 00:11:16,363 INFO master.ClientService
(ClientService.java:submitQuery(143)) - Query q_1369029921250_0003_000001
is submitted
2013-05-20 00:11:16,363 INFO rm.RMContainerAllocator
(RMContainerAllocator.java:heartbeat(158)) - Available Resource: <memory:0,
vCores:0>
2013-05-20 00:11:16,364 INFO master.Query (Query.java:handle(384)) -
Processing q_1369029921250_0003_000001 of type INIT
2013-05-20 00:11:16,365 INFO rm.RMContainerAllocator
(RMContainerAllocator.java:heartbeat(159)) - Num of Allocated Containers: 0
2013-05-20 00:11:16,366 INFO master.Query (Query.java:handle(398)) -
q_1369029921250_0003_000001 Query Transitioned from QUERY_NEW to QUERY_INIT
2013-05-20 00:11:16,367 INFO master.Query (Query.java:handle(384)) -
Processing q_1369029921250_0003_000001 of type START
2013-05-20 00:11:16,381 INFO master.Query (Query.java:transition(282)) -
Schedule unit plan:
"Store": {"table": "sq_1369029921250_0003_000001_00, storage: CSV, partnum:
0},
"out schema": {table1.id (INT4),table1.name (TEXT),table1.score
(FLOAT8),table1.type (TEXT)},
"in schema": {table1.id (INT4),table1.name (TEXT),table1.score
(FLOAT8),table1.type (TEXT)}}
"Scan" : {"table":"table1",
"out schema": {table1.id (INT4),table1.name (TEXT),table1.score
(FLOAT8),table1.type (TEXT)}
"in schema": {table1.id (INT4),table1.name (TEXT),table1.score
(FLOAT8),table1.type (TEXT)}
2013-05-20 00:11:16,446 INFO storage.StorageManager
(StorageManager.java:listStatus(417)) - Total input paths to process : 1
2013-05-20 00:11:16,469 INFO master.SubQuery
(SubQuery.java:createTasks(570)) - Create 1 Tasks
2013-05-20 00:11:16,513 INFO event.AsyncDispatcher
(AsyncDispatcher.java:register(153)) - Registering class
tajo.master.event.TaskRequestEvent$TaskRequestEventType for class
tajo.master.TaskSchedulerImpl$TaskRequests
2013-05-20 00:11:16,514 INFO service.AbstractService
(AbstractService.java:init(81)) - Service:tajo.master.TaskSchedulerImpl is
inited.
2013-05-20 00:11:16,515 INFO event.TaskScheduleEvent
(TaskSchedulerImpl.java:start(89)) - Start TaskScheduler
2013-05-20 00:11:16,517 INFO service.AbstractService
(AbstractService.java:start(94)) - Service:tajo.master.TaskSchedulerImpl is
started.
2013-05-20 00:11:16,521 INFO master.Query (Query.java:handle(398)) -
q_1369029921250_0003_000001 Query Transitioned from QUERY_INIT to
QUERY_RUNNING
2013-05-20 00:11:16,521 INFO rm.RMContainerAllocator
(RMContainerAllocator.java:handle(206)) - EventType: CONTAINER_REQ
2013-05-20 00:11:17,371 INFO rm.RMContainerAllocator
(RMContainerAllocator.java:heartbeat(157)) - Available Cluster Nodes: 1
2013-05-20 00:11:17,371 INFO rm.RMContainerAllocator
(RMContainerAllocator.java:heartbeat(158)) - Available Resource: <memory:0,
vCores:0>
2013-05-20 00:11:17,372 INFO rm.RMContainerAllocator
(RMContainerAllocator.java:heartbeat(159)) - Num of Allocated Containers: 0
2013-05-20 00:11:18,386 INFO rm.RMContainerAllocator
(RMContainerAllocator.java:heartbeat(157)) - Available Cluster Nodes: 1
2013-05-20 00:11:18,387 INFO rm.RMContainerAllocator
(RMContainerAllocator.java:heartbeat(158)) - Available Resource: <memory:0,
vCores:0>
2013-05-20 00:11:18,387 INFO rm.RMContainerAllocator
(RMContainerAllocator.java:heartbeat(159)) - Num of Allocated Containers: 1
2013-05-20 00:11:18,387 INFO rm.RMContainerAllocator
(RMContainerAllocator.java:heartbeat(161)) -
================================================================
2013-05-20 00:11:18,391 INFO rm.RMContainerAllocator
(RMContainerAllocator.java:heartbeat(163)) - > Container Id:
container_1369029921250_0003_01_000001
2013-05-20 00:11:18,392 INFO rm.RMContainerAllocator
(RMContainerAllocator.java:heartbeat(164)) - > Node Id:
hsaputra-x1-carbon:37192
2013-05-20 00:11:18,392 INFO rm.RMContainerAllocator
(RMContainerAllocator.java:heartbeat(165)) - > Resource (Mem): 8192
2013-05-20 00:11:18,393 INFO rm.RMContainerAllocator
(RMContainerAllocator.java:heartbeat(166)) - > State : NEW
2013-05-20 00:11:18,394 INFO rm.RMContainerAllocator
(RMContainerAllocator.java:heartbeat(167)) - > Priority: 100
2013-05-20 00:11:18,394 INFO rm.RMContainerAllocator
(RMContainerAllocator.java:heartbeat(169)) -
================================================================
2013-05-20 00:11:18,397 INFO master.SubQuery
(SubQuery.java:transition(694)) - SubQuery
(sq_1369029921250_0003_000001_01) has 1 containers!
2013-05-20 00:11:18,403 INFO master.TaskRunnerLauncherImpl
(TaskRunnerLauncherImpl.java:launch(395)) - Launching Container with Id:
container_1369029921250_0003_01_000001
2013-05-20 00:11:18,433 INFO master.TaskRunnerLauncherImpl
(TaskRunnerLauncherImpl.java:createCommonContainerLaunchContext(157)) - Set
the environment for the application master
2013-05-20 00:11:18,435 WARN conf.Configuration
(Configuration.java:warnOnceIfDeprecated(817)) - fs.default.name is
deprecated. Instead, use fs.defaultFS
2013-05-20 00:11:18,435 INFO master.TaskRunnerLauncherImpl
(TaskRunnerLauncherImpl.java:createCommonContainerLaunchContext(208)) -
defaultFS: hdfs://localhost:9000
2013-05-20 00:11:18,435 INFO master.TaskRunnerLauncherImpl
(TaskRunnerLauncherImpl.java:createCommonContainerLaunchContext(209)) -
defaultFS: hdfs://localhost:9000
2013-05-20 00:11:18,457 INFO master.TaskRunnerLauncherImpl
(TaskRunnerLauncherImpl.java:createCommonContainerLaunchContext(223)) -
Writing a QueryConf to HDFS and add to local environment
2013-05-20 00:11:19,118 INFO master.TaskRunnerLauncherImpl
(TaskRunnerLauncherImpl.java:createContainerLaunchContext(303)) - Completed
setting up taskrunner command ${JAVA_HOME}/bin/java -Xmx2000m
tajo.worker.TaskRunner hsaputra-x1-carbon 59941
sq_1369029921250_0003_000001_01 hsaputra-x1-carbon:37192
container_1369029921250_0003_01_000001 1><LOG_DIR>/stdout
2><LOG_DIR>/stderr
2013-05-20 00:11:19,157 INFO master.TaskRunnerLauncherImpl
(TaskRunnerLauncherImpl.java:launch(426)) - PullServer port returned by
ContainerManager for container_1369029921250_0003_01_000001 : 42921
2013-05-20 00:11:19,161 INFO master.Query (Query.java:handle(384)) -
Processing q_1369029921250_0003_000001 of type INIT_COMPLETED
2013-05-20 00:11:19,399 INFO rm.RMContainerAllocator
(RMContainerAllocator.java:heartbeat(157)) - Available Cluster Nodes: 1
2013-05-20 00:11:19,399 INFO rm.RMContainerAllocator
(RMContainerAllocator.java:heartbeat(158)) - Available Resource: <memory:0,
vCores:0>
2013-05-20 00:11:19,400 INFO rm.RMContainerAllocator
(RMContainerAllocator.java:heartbeat(159)) - Num of Allocated Containers: 0
2013-05-20 00:11:20,404 INFO rm.RMContainerAllocator
(RMContainerAllocator.java:heartbeat(157)) - Available Cluster Nodes: 1
2013-05-20 00:11:20,405 INFO rm.RMContainerAllocator
(RMContainerAllocator.java:heartbeat(158)) - Available Resource: <memory:0,
vCores:0>
2013-05-20 00:11:20,405 INFO rm.RMContainerAllocator
(RMContainerAllocator.java:heartbeat(159)) - Num of Allocated Containers: 0
2013-05-20 00:11:21,407 INFO rm.RMContainerAllocator
(RMContainerAllocator.java:heartbeat(157)) - Available Cluster Nodes: 1
2013-05-20 00:11:21,407 INFO rm.RMContainerAllocator
(RMContainerAllocator.java:heartbeat(158)) - Available Resource: <memory:0,
vCores:0>
2013-05-20 00:11:21,407 INFO rm.RMContainerAllocator
(RMContainerAllocator.java:heartbeat(159)) - Num of Allocated Containers: 0
2013-05-20 00:11:22,411 INFO rm.RMContainerAllocator
(RMContainerAllocator.java:heartbeat(157)) - Available Cluster Nodes: 1
2013-05-20 00:11:22,411 INFO rm.RMContainerAllocator
(RMContainerAllocator.java:heartbeat(158)) - Available Resource: <memory:0,
vCores:0>
2013-05-20 00:11:22,411 INFO rm.RMContainerAllocator
(RMContainerAllocator.java:heartbeat(159)) - Num of Allocated Containers: 0
2013-05-20 00:11:22,518 INFO event.TaskScheduleEvent
(TaskSchedulerImpl.java:schedule(173)) - Try to schedule tasks with
taskRequestEvents: 1, LeafTask Schedule Request: 1
2013-05-20 00:11:22,519 INFO event.TaskScheduleEvent
(TaskSchedulerImpl.java:schedule(178)) - Get 1 taskRequestEvents
2013-05-20 00:11:22,519 INFO event.TaskScheduleEvent
(TaskSchedulerImpl.java:assignToLeafTasks(298)) - Got task requests 1
2013-05-20 00:11:22,520 INFO util.RackResolver
(RackResolver.java:coreResolve(100)) - Resolved hsaputra-x1-carbon to
/default-rack
2013-05-20 00:11:22,670 INFO event.TaskScheduleEvent
(TaskSchedulerImpl.java:assignToLeafTasks(373)) - HostLocalAssigned /
Total: 0 / 1
2013-05-20 00:11:22,671 INFO event.TaskScheduleEvent
(TaskSchedulerImpl.java:assignToLeafTasks(374)) - RackLocalAssigned: 0 / 1
2013-05-20 00:11:23,415 INFO rm.RMContainerAllocator
(RMContainerAllocator.java:heartbeat(157)) - Available Cluster Nodes: 1
2013-05-20 00:11:23,415 INFO rm.RMContainerAllocator
(RMContainerAllocator.java:heartbeat(158)) - Available Resource: <memory:0,
vCores:0>
2013-05-20 00:11:23,415 INFO rm.RMContainerAllocator
(RMContainerAllocator.java:heartbeat(159)) - Num of Allocated Containers: 0
2013-05-20 00:11:24,419 INFO rm.RMContainerAllocator
(RMContainerAllocator.java:heartbeat(157)) - Available Cluster Nodes: 1
2013-05-20 00:11:24,419 INFO rm.RMContainerAllocator
(RMContainerAllocator.java:heartbeat(158)) - Available Resource: <memory:0,
vCores:0>
2013-05-20 00:11:24,420 INFO rm.RMContainerAllocator
(RMContainerAllocator.java:heartbeat(159)) - Num of Allocated Containers: 0
2013-05-20 00:11:25,423 INFO rm.RMContainerAllocator
(RMContainerAllocator.java:heartbeat(157)) - Available Cluster Nodes: 1
2013-05-20 00:11:25,424 INFO rm.RMContainerAllocator
(RMContainerAllocator.java:heartbeat(158)) - Available Resource: <memory:0,
vCores:0>
2013-05-20 00:11:25,424 INFO rm.RMContainerAllocator
(RMContainerAllocator.java:heartbeat(159)) - Num of Allocated Containers: 0
2013-05-20 00:11:26,428 INFO rm.RMContainerAllocator
(RMContainerAllocator.java:heartbeat(157)) - Available Cluster Nodes: 1
and repeating entry waiting for task to finish.
I saw directory created in my HDFS for the new query but looks like its
empty.
Looking at the Java process looks like YARN is executing a TaskRunner but
somehow never complete the query.
Any tips how to figure out what went wrong?
Thanks,
Henry
Re: Running sample query from sample external table from wiki never comeback
Posted by Hyunsik Choi <hy...@apache.org>.
Hi Henry,
I also suspect that TaskRunner causes this problem. The easiest way to dig
into such a problem is to see TaskRunner's log. You can see TaskRunner's
stdout/stderr logs in
${YARN_LOGS}/userlogs/application_xxxxx/container_xxxx_xxxx. Usually,
${YARN_LOGS} is located in /tmp/logs.
In addition, you can also use remote debug. For this, please take a look at
TaskLauncherImpl.java. In this class, you can find where you should put
remote debug option.
Thanks,
Hyunsik
On Mon, May 20, 2013 at 4:20 PM, Henry Saputra <he...@gmail.com>wrote:
> Something fishy, after building new Tajo from master today the simple
> query:
>
> no longer working because
>
> tajo> /d table1
>
> table name: table1
> table path: /home/hsaputra/tajo-install/sample_data/table1
> store type: CSV
> number of rows: 0
> volume (bytes): 81 B
> schema:
> id type: INT4
>
> name type: TEXT
>
> score type: FLOAT8
>
> type type: TEXT
>
>
> tajo> select * from table1
> Progress: 0%, response time: 2.993 sec
> Progress: 0%, response time: 3.997 sec
> Progress: 0%, response time: 5.0 sec
> Progress: 0%, response time: 6.002 sec
> Progress: 0%, response time: 7.003 sec
> Progress: 0%, response time: 8.005 sec
> Progress: 0%, response time: 9.008 sec
> Progress: 0%, response time: 10.011 sec
> Progress: 0%, response time: 11.014 sec
> Progress: 0%, response time: 12.017 sec
> Progress: 0%, response time: 13.02 sec
> Progress: 0%, response time: 14.023 sec
> Progress: 0%, response time: 15.026 sec
>
>
> Here is the log entry:
>
> 2013-05-20 00:11:14,610 INFO master.GlobalEngine
> (GlobalEngine.java:executeQuery(152)) - TQL: select * from table1
> 2013-05-20 00:11:14,787 INFO planner.LogicalPlanner
> (LogicalPlanner.java:createPlanInternal(89)) - Planning select statement
> 2013-05-20 00:11:14,812 INFO master.GlobalEngine
> (GlobalEngine.java:createLogicalPlan(243)) - LogicalPlan:
> Logical Plan Root
>
> "Scan" : {"table":"table1",
> "out schema": {table1.id (INT4),table1.name (TEXT),table1.score
> (FLOAT8),table1.type (TEXT)}
> "in schema": {table1.id (INT4),table1.name (TEXT),table1.score
> (FLOAT8),table1.type (TEXT)}
> Get AppId: application_1369029921250_0003
> 2013-05-20 00:11:14,881 INFO master.GlobalEngine
> (GlobalEngine.java:submitQuery(195)) - Setting up application submission
> context for ASM
> 2013-05-20 00:11:14,899 INFO master.GlobalEngine
> (GlobalEngine.java:submitQuery(220)) - Setting unmanaged AM
> 2013-05-20 00:11:14,900 INFO master.GlobalEngine
> (GlobalEngine.java:submitQuery(223)) - Submitting application to ASM
> 2013-05-20 00:11:15,975 INFO master.GlobalEngine
> (GlobalEngine.java:monitorApplication(323)) - Got application report from
> ASM for, appId=3, appAttemptId=appattempt_1369029921250_0003_000001,
> clientToken=null, appDiagnostics=, appMasterHost=N/A, appQueue=default,
> appMasterRpcPort=0, appStartTime=1369033874909, yarnAppState=ACCEPTED,
> distributedFinalState=UNDEFINED,
>
> appTrackingUrl=hsaputra-x1-carbon:8088/proxy/application_1369029921250_0003/,
> appUser=hsaputra
> 2013-05-20 00:11:15,976 INFO master.GlobalEngine
> (GlobalEngine.java:submitQuery(232)) - Launching application with id:
> appattempt_1369029921250_0003_000001
> 2013-05-20 00:11:16,099 INFO master.QueryMaster
> (QueryMaster.java:<init>(102)) - Created Query Master for
> appattempt_1369029921250_0003_000001
> 2013-05-20 00:11:16,128 INFO rpc.NettyServerBase
> (NettyServerBase.java:start(84)) - RpcServer on /127.0.1.1:59941
> 2013-05-20 00:11:16,140 INFO event.AsyncDispatcher
> (AsyncDispatcher.java:register(153)) - Registering class
> tajo.master.event.ContainerAllocatorEventType for class
> tajo.master.rm.RMContainerAllocator
> 2013-05-20 00:11:16,198 INFO master.QueryMaster
> (QueryMaster.java:initStagingDir(463)) - Initialized Query Staging Dir:
> hdfs://localhost:9000/user/hsaputra/tajo/q_1369029921250_0003_000001
> 2013-05-20 00:11:16,199 INFO event.AsyncDispatcher
> (AsyncDispatcher.java:register(153)) - Registering class
> tajo.master.event.QueryEventType for class tajo.master.Query
> 2013-05-20 00:11:16,201 INFO event.AsyncDispatcher
> (AsyncDispatcher.java:register(153)) - Registering class
> tajo.master.event.SubQueryEventType for class
> tajo.master.QueryMaster$SubQueryEventDispatcher
> 2013-05-20 00:11:16,202 INFO event.AsyncDispatcher
> (AsyncDispatcher.java:register(153)) - Registering class
> tajo.master.event.TaskEventType for class
> tajo.master.QueryMaster$TaskEventDispatcher
> 2013-05-20 00:11:16,204 INFO event.AsyncDispatcher
> (AsyncDispatcher.java:register(153)) - Registering class
> tajo.master.event.TaskAttemptEventType for class
> tajo.master.QueryMaster$TaskAttemptEventDispatcher
> 2013-05-20 00:11:16,206 INFO event.AsyncDispatcher
> (AsyncDispatcher.java:register(153)) - Registering class
> tajo.master.event.QueryFinishEvent$EventType for class
> tajo.master.QueryMaster$QueryFinishEventHandler
> 2013-05-20 00:11:16,208 INFO event.AsyncDispatcher
> (AsyncDispatcher.java:register(153)) - Registering class
> tajo.master.event.TaskSchedulerEvent$EventType for class
> tajo.master.QueryMaster$TaskSchedulerDispatcher
> 2013-05-20 00:11:16,214 INFO event.AsyncDispatcher
> (AsyncDispatcher.java:register(153)) - Registering class
> tajo.master.TaskRunnerEvent$EventType for class
> tajo.master.TaskRunnerLauncherImpl
> 2013-05-20 00:11:16,214 INFO service.AbstractService
> (AbstractService.java:init(81)) - Service:Dispatcher is inited.
> 2013-05-20 00:11:16,217 INFO rpc.NettyServerBase
> (NettyServerBase.java:start(84)) - RpcServer on /127.0.1.1:56434
> 2013-05-20 00:11:16,218 INFO cluster.WorkerListener
> (TaskRunnerListener.java:init(102)) - WorkerListener is bind to
> hsaputra-x1-carbon:56434
> 2013-05-20 00:11:16,218 INFO service.AbstractService
> (AbstractService.java:init(81)) -
> Service:tajo.master.cluster.WorkerListener is inited.
> 2013-05-20 00:11:16,219 INFO service.AbstractService
> (AbstractService.java:init(81)) -
> Service:org.apache.hadoop.yarn.client.AMRMClientImpl is inited.
> 2013-05-20 00:11:16,219 INFO service.AbstractService
> (AbstractService.java:init(81)) -
> Service:tajo.master.TaskRunnerLauncherImpl is inited.
> 2013-05-20 00:11:16,219 INFO service.AbstractService
> (AbstractService.java:init(81)) - Service:tajo.master.QueryMaster is
> inited.
> 2013-05-20 00:11:16,220 INFO service.AbstractService
> (AbstractService.java:start(94)) - Service:Dispatcher is started.
> 2013-05-20 00:11:16,220 INFO service.AbstractService
> (AbstractService.java:start(94)) -
> Service:tajo.master.cluster.WorkerListener is started.
> 2013-05-20 00:11:16,289 INFO service.AbstractService
> (AbstractService.java:start(94)) -
> Service:org.apache.hadoop.yarn.client.AMRMClientImpl is started.
> 2013-05-20 00:11:16,358 INFO service.AbstractService
> (AbstractService.java:start(94)) -
> Service:tajo.master.TaskRunnerLauncherImpl is started.
> 2013-05-20 00:11:16,359 INFO service.AbstractService
> (AbstractService.java:start(94)) - Service:tajo.master.QueryMaster is
> started.
> 2013-05-20 00:11:16,362 INFO rm.RMContainerAllocator
> (RMContainerAllocator.java:heartbeat(157)) - Available Cluster Nodes: 1
> 2013-05-20 00:11:16,363 INFO master.ClientService
> (ClientService.java:submitQuery(143)) - Query q_1369029921250_0003_000001
> is submitted
> 2013-05-20 00:11:16,363 INFO rm.RMContainerAllocator
> (RMContainerAllocator.java:heartbeat(158)) - Available Resource: <memory:0,
> vCores:0>
> 2013-05-20 00:11:16,364 INFO master.Query (Query.java:handle(384)) -
> Processing q_1369029921250_0003_000001 of type INIT
> 2013-05-20 00:11:16,365 INFO rm.RMContainerAllocator
> (RMContainerAllocator.java:heartbeat(159)) - Num of Allocated Containers: 0
> 2013-05-20 00:11:16,366 INFO master.Query (Query.java:handle(398)) -
> q_1369029921250_0003_000001 Query Transitioned from QUERY_NEW to QUERY_INIT
> 2013-05-20 00:11:16,367 INFO master.Query (Query.java:handle(384)) -
> Processing q_1369029921250_0003_000001 of type START
> 2013-05-20 00:11:16,381 INFO master.Query (Query.java:transition(282)) -
> Schedule unit plan:
> "Store": {"table": "sq_1369029921250_0003_000001_00, storage: CSV, partnum:
> 0},
> "out schema": {table1.id (INT4),table1.name (TEXT),table1.score
> (FLOAT8),table1.type (TEXT)},
> "in schema": {table1.id (INT4),table1.name (TEXT),table1.score
> (FLOAT8),table1.type (TEXT)}}
> "Scan" : {"table":"table1",
> "out schema": {table1.id (INT4),table1.name (TEXT),table1.score
> (FLOAT8),table1.type (TEXT)}
> "in schema": {table1.id (INT4),table1.name (TEXT),table1.score
> (FLOAT8),table1.type (TEXT)}
> 2013-05-20 00:11:16,446 INFO storage.StorageManager
> (StorageManager.java:listStatus(417)) - Total input paths to process : 1
> 2013-05-20 00:11:16,469 INFO master.SubQuery
> (SubQuery.java:createTasks(570)) - Create 1 Tasks
> 2013-05-20 00:11:16,513 INFO event.AsyncDispatcher
> (AsyncDispatcher.java:register(153)) - Registering class
> tajo.master.event.TaskRequestEvent$TaskRequestEventType for class
> tajo.master.TaskSchedulerImpl$TaskRequests
> 2013-05-20 00:11:16,514 INFO service.AbstractService
> (AbstractService.java:init(81)) - Service:tajo.master.TaskSchedulerImpl is
> inited.
> 2013-05-20 00:11:16,515 INFO event.TaskScheduleEvent
> (TaskSchedulerImpl.java:start(89)) - Start TaskScheduler
> 2013-05-20 00:11:16,517 INFO service.AbstractService
> (AbstractService.java:start(94)) - Service:tajo.master.TaskSchedulerImpl is
> started.
> 2013-05-20 00:11:16,521 INFO master.Query (Query.java:handle(398)) -
> q_1369029921250_0003_000001 Query Transitioned from QUERY_INIT to
> QUERY_RUNNING
> 2013-05-20 00:11:16,521 INFO rm.RMContainerAllocator
> (RMContainerAllocator.java:handle(206)) - EventType: CONTAINER_REQ
> 2013-05-20 00:11:17,371 INFO rm.RMContainerAllocator
> (RMContainerAllocator.java:heartbeat(157)) - Available Cluster Nodes: 1
> 2013-05-20 00:11:17,371 INFO rm.RMContainerAllocator
> (RMContainerAllocator.java:heartbeat(158)) - Available Resource: <memory:0,
> vCores:0>
> 2013-05-20 00:11:17,372 INFO rm.RMContainerAllocator
> (RMContainerAllocator.java:heartbeat(159)) - Num of Allocated Containers: 0
> 2013-05-20 00:11:18,386 INFO rm.RMContainerAllocator
> (RMContainerAllocator.java:heartbeat(157)) - Available Cluster Nodes: 1
> 2013-05-20 00:11:18,387 INFO rm.RMContainerAllocator
> (RMContainerAllocator.java:heartbeat(158)) - Available Resource: <memory:0,
> vCores:0>
> 2013-05-20 00:11:18,387 INFO rm.RMContainerAllocator
> (RMContainerAllocator.java:heartbeat(159)) - Num of Allocated Containers: 1
> 2013-05-20 00:11:18,387 INFO rm.RMContainerAllocator
> (RMContainerAllocator.java:heartbeat(161)) -
> ================================================================
> 2013-05-20 00:11:18,391 INFO rm.RMContainerAllocator
> (RMContainerAllocator.java:heartbeat(163)) - > Container Id:
> container_1369029921250_0003_01_000001
> 2013-05-20 00:11:18,392 INFO rm.RMContainerAllocator
> (RMContainerAllocator.java:heartbeat(164)) - > Node Id:
> hsaputra-x1-carbon:37192
> 2013-05-20 00:11:18,392 INFO rm.RMContainerAllocator
> (RMContainerAllocator.java:heartbeat(165)) - > Resource (Mem): 8192
> 2013-05-20 00:11:18,393 INFO rm.RMContainerAllocator
> (RMContainerAllocator.java:heartbeat(166)) - > State : NEW
> 2013-05-20 00:11:18,394 INFO rm.RMContainerAllocator
> (RMContainerAllocator.java:heartbeat(167)) - > Priority: 100
> 2013-05-20 00:11:18,394 INFO rm.RMContainerAllocator
> (RMContainerAllocator.java:heartbeat(169)) -
> ================================================================
> 2013-05-20 00:11:18,397 INFO master.SubQuery
> (SubQuery.java:transition(694)) - SubQuery
> (sq_1369029921250_0003_000001_01) has 1 containers!
> 2013-05-20 00:11:18,403 INFO master.TaskRunnerLauncherImpl
> (TaskRunnerLauncherImpl.java:launch(395)) - Launching Container with Id:
> container_1369029921250_0003_01_000001
> 2013-05-20 00:11:18,433 INFO master.TaskRunnerLauncherImpl
> (TaskRunnerLauncherImpl.java:createCommonContainerLaunchContext(157)) - Set
> the environment for the application master
> 2013-05-20 00:11:18,435 WARN conf.Configuration
> (Configuration.java:warnOnceIfDeprecated(817)) - fs.default.name is
> deprecated. Instead, use fs.defaultFS
> 2013-05-20 00:11:18,435 INFO master.TaskRunnerLauncherImpl
> (TaskRunnerLauncherImpl.java:createCommonContainerLaunchContext(208)) -
> defaultFS: hdfs://localhost:9000
> 2013-05-20 00:11:18,435 INFO master.TaskRunnerLauncherImpl
> (TaskRunnerLauncherImpl.java:createCommonContainerLaunchContext(209)) -
> defaultFS: hdfs://localhost:9000
> 2013-05-20 00:11:18,457 INFO master.TaskRunnerLauncherImpl
> (TaskRunnerLauncherImpl.java:createCommonContainerLaunchContext(223)) -
> Writing a QueryConf to HDFS and add to local environment
> 2013-05-20 00:11:19,118 INFO master.TaskRunnerLauncherImpl
> (TaskRunnerLauncherImpl.java:createContainerLaunchContext(303)) - Completed
> setting up taskrunner command ${JAVA_HOME}/bin/java -Xmx2000m
> tajo.worker.TaskRunner hsaputra-x1-carbon 59941
> sq_1369029921250_0003_000001_01 hsaputra-x1-carbon:37192
> container_1369029921250_0003_01_000001 1><LOG_DIR>/stdout
> 2><LOG_DIR>/stderr
> 2013-05-20 00:11:19,157 INFO master.TaskRunnerLauncherImpl
> (TaskRunnerLauncherImpl.java:launch(426)) - PullServer port returned by
> ContainerManager for container_1369029921250_0003_01_000001 : 42921
> 2013-05-20 00:11:19,161 INFO master.Query (Query.java:handle(384)) -
> Processing q_1369029921250_0003_000001 of type INIT_COMPLETED
> 2013-05-20 00:11:19,399 INFO rm.RMContainerAllocator
> (RMContainerAllocator.java:heartbeat(157)) - Available Cluster Nodes: 1
> 2013-05-20 00:11:19,399 INFO rm.RMContainerAllocator
> (RMContainerAllocator.java:heartbeat(158)) - Available Resource: <memory:0,
> vCores:0>
> 2013-05-20 00:11:19,400 INFO rm.RMContainerAllocator
> (RMContainerAllocator.java:heartbeat(159)) - Num of Allocated Containers: 0
> 2013-05-20 00:11:20,404 INFO rm.RMContainerAllocator
> (RMContainerAllocator.java:heartbeat(157)) - Available Cluster Nodes: 1
> 2013-05-20 00:11:20,405 INFO rm.RMContainerAllocator
> (RMContainerAllocator.java:heartbeat(158)) - Available Resource: <memory:0,
> vCores:0>
> 2013-05-20 00:11:20,405 INFO rm.RMContainerAllocator
> (RMContainerAllocator.java:heartbeat(159)) - Num of Allocated Containers: 0
> 2013-05-20 00:11:21,407 INFO rm.RMContainerAllocator
> (RMContainerAllocator.java:heartbeat(157)) - Available Cluster Nodes: 1
> 2013-05-20 00:11:21,407 INFO rm.RMContainerAllocator
> (RMContainerAllocator.java:heartbeat(158)) - Available Resource: <memory:0,
> vCores:0>
> 2013-05-20 00:11:21,407 INFO rm.RMContainerAllocator
> (RMContainerAllocator.java:heartbeat(159)) - Num of Allocated Containers: 0
> 2013-05-20 00:11:22,411 INFO rm.RMContainerAllocator
> (RMContainerAllocator.java:heartbeat(157)) - Available Cluster Nodes: 1
> 2013-05-20 00:11:22,411 INFO rm.RMContainerAllocator
> (RMContainerAllocator.java:heartbeat(158)) - Available Resource: <memory:0,
> vCores:0>
> 2013-05-20 00:11:22,411 INFO rm.RMContainerAllocator
> (RMContainerAllocator.java:heartbeat(159)) - Num of Allocated Containers: 0
> 2013-05-20 00:11:22,518 INFO event.TaskScheduleEvent
> (TaskSchedulerImpl.java:schedule(173)) - Try to schedule tasks with
> taskRequestEvents: 1, LeafTask Schedule Request: 1
> 2013-05-20 00:11:22,519 INFO event.TaskScheduleEvent
> (TaskSchedulerImpl.java:schedule(178)) - Get 1 taskRequestEvents
> 2013-05-20 00:11:22,519 INFO event.TaskScheduleEvent
> (TaskSchedulerImpl.java:assignToLeafTasks(298)) - Got task requests 1
> 2013-05-20 00:11:22,520 INFO util.RackResolver
> (RackResolver.java:coreResolve(100)) - Resolved hsaputra-x1-carbon to
> /default-rack
> 2013-05-20 00:11:22,670 INFO event.TaskScheduleEvent
> (TaskSchedulerImpl.java:assignToLeafTasks(373)) - HostLocalAssigned /
> Total: 0 / 1
> 2013-05-20 00:11:22,671 INFO event.TaskScheduleEvent
> (TaskSchedulerImpl.java:assignToLeafTasks(374)) - RackLocalAssigned: 0 / 1
> 2013-05-20 00:11:23,415 INFO rm.RMContainerAllocator
> (RMContainerAllocator.java:heartbeat(157)) - Available Cluster Nodes: 1
> 2013-05-20 00:11:23,415 INFO rm.RMContainerAllocator
> (RMContainerAllocator.java:heartbeat(158)) - Available Resource: <memory:0,
> vCores:0>
> 2013-05-20 00:11:23,415 INFO rm.RMContainerAllocator
> (RMContainerAllocator.java:heartbeat(159)) - Num of Allocated Containers: 0
> 2013-05-20 00:11:24,419 INFO rm.RMContainerAllocator
> (RMContainerAllocator.java:heartbeat(157)) - Available Cluster Nodes: 1
> 2013-05-20 00:11:24,419 INFO rm.RMContainerAllocator
> (RMContainerAllocator.java:heartbeat(158)) - Available Resource: <memory:0,
> vCores:0>
> 2013-05-20 00:11:24,420 INFO rm.RMContainerAllocator
> (RMContainerAllocator.java:heartbeat(159)) - Num of Allocated Containers: 0
> 2013-05-20 00:11:25,423 INFO rm.RMContainerAllocator
> (RMContainerAllocator.java:heartbeat(157)) - Available Cluster Nodes: 1
> 2013-05-20 00:11:25,424 INFO rm.RMContainerAllocator
> (RMContainerAllocator.java:heartbeat(158)) - Available Resource: <memory:0,
> vCores:0>
> 2013-05-20 00:11:25,424 INFO rm.RMContainerAllocator
> (RMContainerAllocator.java:heartbeat(159)) - Num of Allocated Containers: 0
> 2013-05-20 00:11:26,428 INFO rm.RMContainerAllocator
> (RMContainerAllocator.java:heartbeat(157)) - Available Cluster Nodes: 1
>
> and repeating entry waiting for task to finish.
>
>
> I saw directory created in my HDFS for the new query but looks like its
> empty.
>
> Looking at the Java process looks like YARN is executing a TaskRunner but
> somehow never complete the query.
>
> Any tips how to figure out what went wrong?
>
>
> Thanks,
>
> Henry
>