See <https://builds.apache.org/job/Tajo-master-nightly/300/changes>
Changes: [jinossy] TAJO-647: Work unbalance on disk scheduling of DefaultScheduler. (jinho) [jinossy] TAJO-651: HcatalogStore should support (de)serialization of RCFile. (jinho) [jinossy] TAJO-686: Integration test aborted. (jinho) ------------------------------------------ [...truncated 61780 lines...] ======================================================= 2014-03-14 03:17:51,659 INFO master.TajoAsyncDispatcher (TajoAsyncDispatcher.java:start(101)) - AsyncDispatcher started:q_1394766883591_0196 2014-03-14 03:17:51,659 INFO querymaster.Query (Query.java:handle(641)) - Processing q_1394766883591_0196 of type START 2014-03-14 03:17:51,659 INFO querymaster.SubQuery (SubQuery.java:calculateShuffleOutputNum(755)) - Table's volume is approximately 1 MB 2014-03-14 03:17:51,660 INFO querymaster.SubQuery (SubQuery.java:calculateShuffleOutputNum(762)) - Total memory of cluster is 1024 MB 2014-03-14 03:17:51,660 INFO querymaster.SubQuery (SubQuery.java:calculateShuffleOutputNum(765)) - The determined number of aggregation partitions is 1 2014-03-14 03:17:51,661 INFO querymaster.SubQuery (SubQuery.java:initTaskScheduler(668)) - org.apache.tajo.master.DefaultTaskScheduler is chosen for the task scheduling 2014-03-14 03:17:51,664 INFO storage.AbstractStorageManager (AbstractStorageManager.java:listStatus(382)) - Total input paths to process : 1 2014-03-14 03:17:51,667 INFO storage.AbstractStorageManager (AbstractStorageManager.java:getSplits(607)) - Total # of splits: 1 2014-03-14 03:17:51,667 INFO querymaster.SubQuery (SubQuery.java:transition(638)) - 1 objects are scheduled 2014-03-14 03:17:51,667 INFO master.DefaultTaskScheduler (DefaultTaskScheduler.java:start(88)) - Start TaskScheduler 2014-03-14 03:17:51,668 INFO worker.TajoResourceAllocator (TajoResourceAllocator.java:calculateNumRequestContainers(99)) - CalculateNumberRequestContainer - Number of Tasks=1, Number of Cluster Slots=1 2014-03-14 03:17:51,668 INFO querymaster.SubQuery (SubQuery.java:allocateContainers(850)) - Request Container for eb_1394766883591_0196_000001 containers=1 2014-03-14 03:17:51,668 INFO querymaster.Query (Query.java:handle(654)) - q_1394766883591_0196 Query Transitioned from QUERY_NEW to QUERY_RUNNING 2014-03-14 03:17:51,668 INFO worker.TajoResourceAllocator (TajoResourceAllocator.java:run(216)) - Start TajoWorkerAllocationThread 2014-03-14 03:17:51,670 INFO worker.TajoResourceAllocator (TajoResourceAllocator.java:run(334)) - Stop TajoWorkerAllocationThread 2014-03-14 03:17:51,671 INFO querymaster.SubQuery (SubQuery.java:transition(957)) - SubQuery (eb_1394766883591_0196_000001) has 1 containers! 2014-03-14 03:17:51,674 INFO worker.TaskRunner (TaskRunner.java:<init>(121)) - Tajo Root Dir: hdfs://localhost:59092/tajo 2014-03-14 03:17:51,675 INFO worker.TaskRunner (TaskRunner.java:<init>(122)) - Worker Local Dir: file://<https://builds.apache.org/job/Tajo-master-nightly/ws/tajo-core/tajo-core-backend/target/test-data/da2d8c89-0dac-4d78-b3d2-13e4ab245dde/tajo-localdir> 2014-03-14 03:17:51,675 INFO worker.TaskRunner (TaskRunner.java:<init>(136)) - QueryMaster Address:asf002.sp2.ygridcore.net/67.195.138.30:18805 2014-03-14 03:17:51,675 INFO worker.TaskRunnerManager (TaskRunnerManager.java:run(188)) - Start TaskRunner:eb_1394766883591_0196_000001,container_1394766883591_0196_01_000745 2014-03-14 03:17:51,676 INFO worker.TaskRunner (TaskRunner.java:init(183)) - TaskRunner basedir is created (q_1394766883591_0196/output/1) 2014-03-14 03:17:51,677 INFO worker.TaskRunner (TaskRunner.java:run(316)) - TaskRunner startup 2014-03-14 03:17:51,679 INFO worker.TaskRunner (TaskRunner.java:run(336)) - Request GetTask: eb_1394766883591_0196_000001,container_1394766883591_0196_01_000745 2014-03-14 03:17:51,680 INFO master.DefaultTaskScheduler (DefaultTaskScheduler.java:allocateRackTask(701)) - Assigned Local/Rack/Total: (0/1/1), Locality: 0.00%, Rack host: 67.195.138.30 2014-03-14 03:17:51,683 INFO worker.TaskRunner (TaskRunner.java:run(374)) - Accumulated Received Task: 1 2014-03-14 03:17:51,684 INFO worker.TaskRunner (TaskRunner.java:run(383)) - Initializing: ta_1394766883591_0196_000001_000000_00 2014-03-14 03:17:51,686 INFO worker.TaskAttemptContext (TaskAttemptContext.java:setState(110)) - Query status of ta_1394766883591_0196_000001_000000_00 is changed to TA_PENDING 2014-03-14 03:17:51,686 INFO worker.Task (Task.java:<init>(188)) - ================================== 2014-03-14 03:17:51,686 INFO worker.Task (Task.java:<init>(189)) - * Subquery ta_1394766883591_0196_000001_000000_00 is initialized 2014-03-14 03:17:51,686 INFO worker.Task (Task.java:<init>(190)) - * InterQuery: true, Use HASH_SHUFFLE shuffle 2014-03-14 03:17:51,686 INFO worker.Task (Task.java:<init>(193)) - * Fragments (num: 1) 2014-03-14 03:17:51,686 INFO worker.Task (Task.java:<init>(194)) - * Fetches (total:0) : 2014-03-14 03:17:51,686 INFO worker.Task (Task.java:<init>(198)) - * Local task dir: <https://builds.apache.org/job/Tajo-master-nightly/ws/tajo-core/tajo-core-backend/target/test-data/da2d8c89-0dac-4d78-b3d2-13e4ab245dde/tajo-localdir/q_1394766883591_0196/output/1/0_0> 2014-03-14 03:17:51,687 INFO worker.Task (Task.java:<init>(203)) - ================================== 2014-03-14 03:17:51,687 INFO worker.TaskAttemptContext (TaskAttemptContext.java:setState(110)) - Query status of ta_1394766883591_0196_000001_000000_00 is changed to TA_RUNNING 2014-03-14 03:17:51,687 INFO planner.PhysicalPlannerImpl (PhysicalPlannerImpl.java:createBestAggregationPlan(955)) - The planner chooses [Hash Aggregation] 2014-03-14 03:17:51,688 INFO planner.PhysicalPlannerImpl (PhysicalPlannerImpl.java:createInMemoryHashAggregation(898)) - The planner chooses [Hash Aggregation] 2014-03-14 03:17:51,697 INFO worker.TaskAttemptContext (TaskAttemptContext.java:setState(110)) - Query status of ta_1394766883591_0196_000001_000000_00 is changed to TA_SUCCEEDED 2014-03-14 03:17:51,697 INFO worker.Task (Task.java:run(447)) - Task Counter - total:450, succeeded: 446, killed: 1, failed: 3 2014-03-14 03:17:51,698 INFO worker.TaskRunner (TaskRunner.java:run(336)) - Request GetTask: eb_1394766883591_0196_000001,container_1394766883591_0196_01_000745 2014-03-14 03:17:51,699 INFO querymaster.SubQuery (SubQuery.java:transition(1032)) - [eb_1394766883591_0196_000001] Task Completion Event (Total: 1, Success: 1, Killed: 0, Failed: 0 2014-03-14 03:17:51,699 INFO querymaster.SubQuery (SubQuery.java:transition(1072)) - subQuery completed - eb_1394766883591_0196_000001 (total=1, success=1, killed=0) 2014-03-14 03:17:51,699 INFO master.DefaultTaskScheduler (DefaultTaskScheduler.java:stop(144)) - Task Scheduler stopped 2014-03-14 03:17:51,700 INFO master.DefaultTaskScheduler (DefaultTaskScheduler.java:run(103)) - TaskScheduler schedulingThread stopped 2014-03-14 03:17:51,700 INFO worker.TaskRunner (TaskRunner.java:run(366)) - Received ShouldDie flag:eb_1394766883591_0196_000001,container_1394766883591_0196_01_000745 2014-03-14 03:17:51,700 INFO worker.TaskRunner (TaskRunner.java:stop(227)) - Stop TaskRunner: eb_1394766883591_0196_000001 2014-03-14 03:17:51,700 INFO worker.TaskRunnerManager (TaskRunnerManager.java:stopTask(89)) - Stop Task:eb_1394766883591_0196_000001,container_1394766883591_0196_01_000745 2014-03-14 03:17:51,700 INFO querymaster.Query (Query.java:handle(641)) - Processing q_1394766883591_0196 of type SUBQUERY_COMPLETED 2014-03-14 03:17:51,700 INFO querymaster.SubQuery (SubQuery.java:calculateShuffleOutputNum(769)) - ============>>>>> Unexpected Case! <<<<<================ 2014-03-14 03:17:51,701 INFO querymaster.SubQuery (SubQuery.java:calculateShuffleOutputNum(773)) - Table's volume is approximately 1 MB 2014-03-14 03:17:51,701 INFO querymaster.SubQuery (SubQuery.java:calculateShuffleOutputNum(776)) - The determined number of partitions is 1 2014-03-14 03:17:51,701 INFO querymaster.SubQuery (SubQuery.java:initTaskScheduler(668)) - org.apache.tajo.master.DefaultTaskScheduler is chosen for the task scheduling 2014-03-14 03:17:51,701 INFO rm.TajoWorkerResourceManager (TajoWorkerResourceManager.java:releaseWorkerResource(512)) - Release Resource: 1.0,512 2014-03-14 03:17:51,701 INFO querymaster.SubQuery (SubQuery.java:getNonLeafTaskNum(805)) - Table's volume is approximately 1 MB 2014-03-14 03:17:51,701 INFO querymaster.SubQuery (SubQuery.java:getNonLeafTaskNum(808)) - The determined number of non-leaf tasks is 1 2014-03-14 03:17:51,702 INFO querymaster.Repartitioner (Repartitioner.java:scheduleHashShuffledFetches(482)) - ScheduleHashShuffledFetches - Max num=1, finalFetchURI=1 2014-03-14 03:17:51,702 INFO querymaster.Repartitioner (Repartitioner.java:scheduleHashShuffledFetches(492)) - DeterminedTaskNum : 1 2014-03-14 03:17:51,702 INFO querymaster.SubQuery (SubQuery.java:transition(638)) - 1 objects are scheduled 2014-03-14 03:17:51,702 INFO master.DefaultTaskScheduler (DefaultTaskScheduler.java:start(88)) - Start TaskScheduler 2014-03-14 03:17:51,702 INFO worker.TajoResourceAllocator (TajoResourceAllocator.java:calculateNumRequestContainers(99)) - CalculateNumberRequestContainer - Number of Tasks=1, Number of Cluster Slots=1 2014-03-14 03:17:51,702 INFO querymaster.SubQuery (SubQuery.java:allocateContainers(850)) - Request Container for eb_1394766883591_0196_000002 containers=1 2014-03-14 03:17:51,703 INFO querymaster.Query (Query.java:executeNextBlock(562)) - Scheduling SubQuery:eb_1394766883591_0196_000002 2014-03-14 03:17:51,703 INFO worker.TajoResourceAllocator (TajoResourceAllocator.java:run(216)) - Start TajoWorkerAllocationThread 2014-03-14 03:17:51,704 INFO worker.TajoResourceAllocator (TajoResourceAllocator.java:run(334)) - Stop TajoWorkerAllocationThread 2014-03-14 03:17:51,704 INFO querymaster.SubQuery (SubQuery.java:transition(957)) - SubQuery (eb_1394766883591_0196_000002) has 1 containers! 2014-03-14 03:17:51,706 INFO worker.TaskRunner (TaskRunner.java:<init>(121)) - Tajo Root Dir: hdfs://localhost:59092/tajo 2014-03-14 03:17:51,706 INFO worker.TaskRunner (TaskRunner.java:<init>(122)) - Worker Local Dir: file://<https://builds.apache.org/job/Tajo-master-nightly/ws/tajo-core/tajo-core-backend/target/test-data/da2d8c89-0dac-4d78-b3d2-13e4ab245dde/tajo-localdir> 2014-03-14 03:17:51,706 INFO worker.TaskRunner (TaskRunner.java:<init>(136)) - QueryMaster Address:asf002.sp2.ygridcore.net/67.195.138.30:18805 2014-03-14 03:17:51,707 INFO worker.TaskRunnerManager (TaskRunnerManager.java:run(188)) - Start TaskRunner:eb_1394766883591_0196_000002,container_1394766883591_0196_01_000746 2014-03-14 03:17:51,707 INFO worker.TaskRunner (TaskRunner.java:init(183)) - TaskRunner basedir is created (q_1394766883591_0196/output/2) 2014-03-14 03:17:51,708 INFO worker.TaskRunner (TaskRunner.java:run(316)) - TaskRunner startup 2014-03-14 03:17:51,708 INFO worker.TaskRunner (TaskRunner.java:run(336)) - Request GetTask: eb_1394766883591_0196_000002,container_1394766883591_0196_01_000746 2014-03-14 03:17:51,710 INFO worker.TaskRunner (TaskRunner.java:run(374)) - Accumulated Received Task: 1 2014-03-14 03:17:51,711 INFO worker.TaskRunner (TaskRunner.java:run(383)) - Initializing: ta_1394766883591_0196_000002_000000_00 2014-03-14 03:17:51,712 INFO worker.TaskAttemptContext (TaskAttemptContext.java:setState(110)) - Query status of ta_1394766883591_0196_000002_000000_00 is changed to TA_PENDING 2014-03-14 03:17:51,712 INFO worker.Task (Task.java:<init>(188)) - ================================== 2014-03-14 03:17:51,713 INFO worker.Task (Task.java:<init>(189)) - * Subquery ta_1394766883591_0196_000002_000000_00 is initialized 2014-03-14 03:17:51,713 INFO worker.Task (Task.java:<init>(190)) - * InterQuery: true, Use RANGE_SHUFFLE shuffle 2014-03-14 03:17:51,713 INFO worker.Task (Task.java:<init>(193)) - * Fragments (num: 1) 2014-03-14 03:17:51,713 INFO worker.Task (Task.java:<init>(194)) - * Fetches (total:1) : 2014-03-14 03:17:51,713 INFO worker.Task (Task.java:<init>(196)) - Table Id: eb_1394766883591_0196_000001, url: http://67.195.138.30:36598/?qid=q_1394766883591_0196&sid=1&p=0&type=h&ta=0_0 2014-03-14 03:17:51,713 INFO worker.Task (Task.java:<init>(198)) - * Local task dir: <https://builds.apache.org/job/Tajo-master-nightly/ws/tajo-core/tajo-core-backend/target/test-data/da2d8c89-0dac-4d78-b3d2-13e4ab245dde/tajo-localdir/q_1394766883591_0196/output/2/0_0> 2014-03-14 03:17:51,713 INFO worker.Task (Task.java:<init>(203)) - ================================== 2014-03-14 03:17:51,715 INFO worker.Task (Task.java:init(219)) - the directory is created <https://builds.apache.org/job/Tajo-master-nightly/ws/tajo-core/tajo-core-backend/target/test-data/da2d8c89-0dac-4d78-b3d2-13e4ab245dde/tajo-localdir/q_1394766883591_0196/in/eb_1394766883591_0196_000002/0/0/eb_1394766883591_0196_000001> 2014-03-14 03:17:51,717 INFO worker.TaskAttemptContext (TaskAttemptContext.java:setState(110)) - Query status of ta_1394766883591_0196_000002_000000_00 is changed to TA_RUNNING 2014-03-14 03:17:51,718 INFO pullserver.TajoPullServerService (TajoPullServerService.java:channelOpen(346)) - Current number of shuffle connections (2) 2014-03-14 03:17:51,719 INFO worker.Fetcher (Fetcher.java:get(129)) - Fetch: http://67.195.138.30:36598/?qid=q_1394766883591_0196&sid=1&p=0&type=h&ta=0_0 2014-03-14 03:17:51,719 INFO pullserver.TajoPullServerService (TajoPullServerService.java:messageReceived(391)) - PullServer request param: shuffleType=h, sid=1, partId=0, taskIds=[0_0] 2014-03-14 03:17:51,719 INFO pullserver.TajoPullServerService (TajoPullServerService.java:messageReceived(397)) - PullServer baseDir: file://<https://builds.apache.org/job/Tajo-master-nightly/ws/tajo-core/tajo-core-backend/target/test-data/da2d8c89-0dac-4d78-b3d2-13e4ab245dde/tajo-localdir/q_1394766883591_0196/output> 2014-03-14 03:17:51,720 INFO worker.Task (Task.java:waitForFetch(356)) - ta_1394766883591_0196_000002_000000_00 All fetches are done! 2014-03-14 03:17:51,722 INFO planner.PhysicalPlannerImpl (PhysicalPlannerImpl.java:createBestAggregationPlan(955)) - The planner chooses [Hash Aggregation] 2014-03-14 03:17:51,722 INFO planner.PhysicalPlannerImpl (PhysicalPlannerImpl.java:createInMemoryHashAggregation(898)) - The planner chooses [Hash Aggregation] 2014-03-14 03:17:51,723 INFO physical.RangeShuffleFileWriteExec (RangeShuffleFileWriteExec.java:init(76)) - Output data directory: <https://builds.apache.org/job/Tajo-master-nightly/ws/tajo-core/tajo-core-backend/target/test-data/da2d8c89-0dac-4d78-b3d2-13e4ab245dde/tajo-localdir/q_1394766883591_0196/output/2/0_0/output> 2014-03-14 03:17:51,748 INFO physical.ExternalSortExec (PhysicalExec.java:info(61)) - [ta_1394766883591_0196_000002_000000_00] Chunks creation time: 0 msec 2014-03-14 03:17:51,757 INFO worker.TaskAttemptContext (TaskAttemptContext.java:setState(110)) - Query status of ta_1394766883591_0196_000002_000000_00 is changed to TA_SUCCEEDED 2014-03-14 03:17:51,757 INFO worker.Task (Task.java:run(447)) - Task Counter - total:451, succeeded: 447, killed: 1, failed: 3 2014-03-14 03:17:51,757 INFO worker.TaskRunner (TaskRunner.java:run(336)) - Request GetTask: eb_1394766883591_0196_000002,container_1394766883591_0196_01_000746 2014-03-14 03:17:51,758 INFO querymaster.SubQuery (SubQuery.java:transition(1032)) - [eb_1394766883591_0196_000002] Task Completion Event (Total: 1, Success: 1, Killed: 0, Failed: 0 2014-03-14 03:17:51,758 INFO querymaster.SubQuery (SubQuery.java:transition(1072)) - subQuery completed - eb_1394766883591_0196_000002 (total=1, success=1, killed=0) 2014-03-14 03:17:51,758 INFO master.DefaultTaskScheduler (DefaultTaskScheduler.java:run(103)) - TaskScheduler schedulingThread stopped 2014-03-14 03:17:51,758 INFO master.DefaultTaskScheduler (DefaultTaskScheduler.java:stop(144)) - Task Scheduler stopped 2014-03-14 03:17:51,759 INFO worker.TaskRunner (TaskRunner.java:run(366)) - Received ShouldDie flag:eb_1394766883591_0196_000002,container_1394766883591_0196_01_000746 2014-03-14 03:17:51,759 INFO querymaster.Query (Query.java:handle(641)) - Processing q_1394766883591_0196 of type SUBQUERY_COMPLETED 2014-03-14 03:17:51,759 INFO worker.TaskRunner (TaskRunner.java:stop(227)) - Stop TaskRunner: eb_1394766883591_0196_000002 2014-03-14 03:17:51,759 INFO worker.TaskRunnerManager (TaskRunnerManager.java:stopTask(89)) - Stop Task:eb_1394766883591_0196_000002,container_1394766883591_0196_01_000746 2014-03-14 03:17:51,759 INFO querymaster.SubQuery (SubQuery.java:initTaskScheduler(668)) - org.apache.tajo.master.DefaultTaskScheduler is chosen for the task scheduling 2014-03-14 03:17:51,760 INFO querymaster.SubQuery (SubQuery.java:getNonLeafTaskNum(805)) - Table's volume is approximately 1 MB 2014-03-14 03:17:51,760 INFO querymaster.SubQuery (SubQuery.java:getNonLeafTaskNum(808)) - The determined number of non-leaf tasks is 1 2014-03-14 03:17:51,760 INFO rm.TajoWorkerResourceManager (TajoWorkerResourceManager.java:releaseWorkerResource(512)) - Release Resource: 1.0,512 2014-03-14 03:17:51,760 INFO querymaster.Repartitioner (Repartitioner.java:scheduleRangeShuffledFetches(352)) - Try to divide [(0=>N, 1=>F), (0=>R, 1=>O)) into 1 sub ranges (total units: 1) 2014-03-14 03:17:51,761 INFO querymaster.SubQuery (SubQuery.java:transition(638)) - 1 objects are scheduled 2014-03-14 03:17:51,761 INFO master.DefaultTaskScheduler (DefaultTaskScheduler.java:start(88)) - Start TaskScheduler 2014-03-14 03:17:51,762 INFO worker.TajoResourceAllocator (TajoResourceAllocator.java:calculateNumRequestContainers(99)) - CalculateNumberRequestContainer - Number of Tasks=1, Number of Cluster Slots=1 2014-03-14 03:17:51,762 INFO querymaster.SubQuery (SubQuery.java:allocateContainers(850)) - Request Container for eb_1394766883591_0196_000003 containers=1 2014-03-14 03:17:51,762 INFO querymaster.Query (Query.java:executeNextBlock(562)) - Scheduling SubQuery:eb_1394766883591_0196_000003 2014-03-14 03:17:51,762 INFO worker.TajoResourceAllocator (TajoResourceAllocator.java:run(216)) - Start TajoWorkerAllocationThread 2014-03-14 03:17:51,763 INFO worker.TajoResourceAllocator (TajoResourceAllocator.java:run(334)) - Stop TajoWorkerAllocationThread 2014-03-14 03:17:51,763 INFO querymaster.SubQuery (SubQuery.java:transition(957)) - SubQuery (eb_1394766883591_0196_000003) has 1 containers! 2014-03-14 03:17:51,764 INFO worker.TaskRunner (TaskRunner.java:<init>(121)) - Tajo Root Dir: hdfs://localhost:59092/tajo 2014-03-14 03:17:51,765 INFO worker.TaskRunner (TaskRunner.java:<init>(122)) - Worker Local Dir: file://<https://builds.apache.org/job/Tajo-master-nightly/ws/tajo-core/tajo-core-backend/target/test-data/da2d8c89-0dac-4d78-b3d2-13e4ab245dde/tajo-localdir> 2014-03-14 03:17:51,765 INFO worker.TaskRunner (TaskRunner.java:<init>(136)) - QueryMaster Address:asf002.sp2.ygridcore.net/67.195.138.30:18805 2014-03-14 03:17:51,765 INFO worker.TaskRunnerManager (TaskRunnerManager.java:run(188)) - Start TaskRunner:eb_1394766883591_0196_000003,container_1394766883591_0196_01_000747 2014-03-14 03:17:51,766 INFO worker.TaskRunner (TaskRunner.java:init(183)) - TaskRunner basedir is created (q_1394766883591_0196/output/3) 2014-03-14 03:17:51,766 INFO worker.TaskRunner (TaskRunner.java:run(316)) - TaskRunner startup 2014-03-14 03:17:51,766 INFO worker.TaskRunner (TaskRunner.java:run(336)) - Request GetTask: eb_1394766883591_0196_000003,container_1394766883591_0196_01_000747 2014-03-14 03:17:51,768 INFO worker.TaskRunner (TaskRunner.java:run(374)) - Accumulated Received Task: 1 2014-03-14 03:17:51,768 INFO worker.TaskRunner (TaskRunner.java:run(383)) - Initializing: ta_1394766883591_0196_000003_000000_00 2014-03-14 03:17:51,769 INFO worker.Task (Task.java:<init>(183)) - Output File Path: hdfs://localhost:59092/tmp/tajo-jenkins/staging/q_1394766883591_0196/RESULT/part-03-000000 2014-03-14 03:17:51,769 INFO worker.TaskAttemptContext (TaskAttemptContext.java:setState(110)) - Query status of ta_1394766883591_0196_000003_000000_00 is changed to TA_PENDING 2014-03-14 03:17:51,769 INFO worker.Task (Task.java:<init>(188)) - ================================== 2014-03-14 03:17:51,770 INFO worker.Task (Task.java:<init>(189)) - * Subquery ta_1394766883591_0196_000003_000000_00 is initialized 2014-03-14 03:17:51,770 INFO worker.Task (Task.java:<init>(190)) - * InterQuery: false 2014-03-14 03:17:51,770 INFO worker.Task (Task.java:<init>(193)) - * Fragments (num: 1) 2014-03-14 03:17:51,770 INFO worker.Task (Task.java:<init>(194)) - * Fetches (total:1) : 2014-03-14 03:17:51,770 INFO worker.Task (Task.java:<init>(196)) - Table Id: eb_1394766883591_0196_000002, url: http://asf002.sp2.ygridcore.net:36598/?qid=q_1394766883591_0196&sid=2&ta=0_0&p=0&type=r&start=AAAAAU4AAAABRg%3D%3D&end=AAAAAVIAAAABTw%3D%3D&final=true 2014-03-14 03:17:51,770 INFO worker.Task (Task.java:<init>(198)) - * Local task dir: <https://builds.apache.org/job/Tajo-master-nightly/ws/tajo-core/tajo-core-backend/target/test-data/da2d8c89-0dac-4d78-b3d2-13e4ab245dde/tajo-localdir/q_1394766883591_0196/output/3/0_0> 2014-03-14 03:17:51,770 INFO worker.Task (Task.java:<init>(203)) - ================================== 2014-03-14 03:17:51,772 INFO worker.Task (Task.java:init(219)) - the directory is created <https://builds.apache.org/job/Tajo-master-nightly/ws/tajo-core/tajo-core-backend/target/test-data/da2d8c89-0dac-4d78-b3d2-13e4ab245dde/tajo-localdir/q_1394766883591_0196/in/eb_1394766883591_0196_000003/0/0/eb_1394766883591_0196_000002> 2014-03-14 03:17:51,774 INFO worker.TaskAttemptContext (TaskAttemptContext.java:setState(110)) - Query status of ta_1394766883591_0196_000003_000000_00 is changed to TA_RUNNING 2014-03-14 03:17:51,775 INFO pullserver.TajoPullServerService (TajoPullServerService.java:channelOpen(346)) - Current number of shuffle connections (2) 2014-03-14 03:17:51,775 INFO worker.Fetcher (Fetcher.java:get(129)) - Fetch: http://asf002.sp2.ygridcore.net:36598/?qid=q_1394766883591_0196&sid=2&ta=0_0&p=0&type=r&start=AAAAAU4AAAABRg%3D%3D&end=AAAAAVIAAAABTw%3D%3D&final=true 2014-03-14 03:17:51,775 INFO pullserver.TajoPullServerService (TajoPullServerService.java:messageReceived(391)) - PullServer request param: shuffleType=r, sid=2, partId=0, taskIds=[0_0] 2014-03-14 03:17:51,776 INFO pullserver.TajoPullServerService (TajoPullServerService.java:messageReceived(397)) - PullServer baseDir: file://<https://builds.apache.org/job/Tajo-master-nightly/ws/tajo-core/tajo-core-backend/target/test-data/da2d8c89-0dac-4d78-b3d2-13e4ab245dde/tajo-localdir/q_1394766883591_0196/output> 2014-03-14 03:17:51,796 INFO pullserver.TajoPullServerService (TajoPullServerService.java:getFileCunks(556)) - BSTIndex is loaded from disk ((0=>N, 1=>O), (0=>R, 1=>F) 2014-03-14 03:17:51,796 INFO pullserver.TajoPullServerService (TajoPullServerService.java:getFileCunks(579)) - GET Request for <https://builds.apache.org/job/Tajo-master-nightly/ws/tajo-core/tajo-core-backend/target/test-data/da2d8c89-0dac-4d78-b3d2-13e4ab245dde/tajo-localdir/q_1394766883591_0196/output/2/0_0/output/output> (start=(0=>N, 1=>F), end=(0=>R, 1=>O), last=true) 2014-03-14 03:17:51,796 INFO pullserver.TajoPullServerService (TajoPullServerService.java:getFileCunks(648)) - Retrieve File Chunk: (start=0, length=24) <https://builds.apache.org/job/Tajo-master-nightly/ws/tajo-core/tajo-core-backend/target/test-data/da2d8c89-0dac-4d78-b3d2-13e4ab245dde/tajo-localdir/q_1394766883591_0196/output/2/0_0/output/output> 2014-03-14 03:17:51,798 INFO worker.Task (Task.java:waitForFetch(356)) - ta_1394766883591_0196_000003_000000_00 All fetches are done! 2014-03-14 03:17:51,804 INFO physical.ExternalSortExec (PhysicalExec.java:info(61)) - [ta_1394766883591_0196_000003_000000_00] Total merge time: 0 msec 2014-03-14 03:17:51,810 INFO BlockStateChange (BlockManager.java:logAddStoredBlock(2237)) - BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:47468 is added to blk_1073742100_1276{blockUCState=COMMITTED, primaryNodeIndex=-1, replicas=[ReplicaUnderConstruction[127.0.0.1:47468|RBW]]} size 12 2014-03-14 03:17:52,223 INFO worker.TaskAttemptContext (TaskAttemptContext.java:setState(110)) - Query status of ta_1394766883591_0196_000003_000000_00 is changed to TA_SUCCEEDED 2014-03-14 03:17:52,224 INFO worker.Task (Task.java:run(447)) - Task Counter - total:452, succeeded: 448, killed: 1, failed: 3 2014-03-14 03:17:52,224 INFO worker.TaskRunner (TaskRunner.java:run(336)) - Request GetTask: eb_1394766883591_0196_000003,container_1394766883591_0196_01_000747 2014-03-14 03:17:52,225 INFO querymaster.SubQuery (SubQuery.java:transition(1032)) - [eb_1394766883591_0196_000003] Task Completion Event (Total: 1, Success: 1, Killed: 0, Failed: 0 2014-03-14 03:17:52,225 INFO querymaster.SubQuery (SubQuery.java:transition(1072)) - subQuery completed - eb_1394766883591_0196_000003 (total=1, success=1, killed=0) 2014-03-14 03:17:52,225 INFO master.DefaultTaskScheduler (DefaultTaskScheduler.java:run(103)) - TaskScheduler schedulingThread stopped 2014-03-14 03:17:52,225 INFO worker.TaskRunner (TaskRunner.java:run(366)) - Received ShouldDie flag:eb_1394766883591_0196_000003,container_1394766883591_0196_01_000747 2014-03-14 03:17:52,225 INFO master.DefaultTaskScheduler (DefaultTaskScheduler.java:stop(144)) - Task Scheduler stopped 2014-03-14 03:17:52,225 INFO worker.TaskRunner (TaskRunner.java:stop(227)) - Stop TaskRunner: eb_1394766883591_0196_000003 2014-03-14 03:17:52,226 INFO worker.TaskRunnerManager (TaskRunnerManager.java:stopTask(89)) - Stop Task:eb_1394766883591_0196_000003,container_1394766883591_0196_01_000747 2014-03-14 03:17:52,226 INFO querymaster.Query (Query.java:handle(641)) - Processing q_1394766883591_0196 of type SUBQUERY_COMPLETED 2014-03-14 03:17:52,226 INFO querymaster.Query (Query.java:handle(641)) - Processing q_1394766883591_0196 of type QUERY_COMPLETED 2014-03-14 03:17:52,226 INFO rm.TajoWorkerResourceManager (TajoWorkerResourceManager.java:releaseWorkerResource(512)) - Release Resource: 1.0,512 2014-03-14 03:17:52,227 INFO querymaster.Query (Query.java:handle(654)) - q_1394766883591_0196 Query Transitioned from QUERY_RUNNING to QUERY_SUCCEEDED 2014-03-14 03:17:52,227 INFO querymaster.QueryMasterTask (QueryMasterTask.java:handle(266)) - Query completion notified from q_1394766883591_0196 2014-03-14 03:17:52,227 INFO querymaster.QueryMasterTask (QueryMasterTask.java:handle(277)) - Query final state: QUERY_SUCCEEDED 2014-03-14 03:17:52,228 INFO querymaster.QueryMasterTask (QueryMasterTask.java:stop(172)) - Stopping QueryMasterTask:q_1394766883591_0196 2014-03-14 03:17:52,228 INFO querymaster.QueryJobManager (QueryJobManager.java:stopQuery(138)) - Stop QueryInProgress:q_1394766883591_0196 2014-03-14 03:17:52,228 INFO querymaster.QueryInProgress (QueryInProgress.java:heartbeat(257)) - Received QueryMaster heartbeat:q_1394766883591_0196state=QUERY_SUCCEEDED,progress=1.0, queryMaster=asf002.sp2.ygridcore.net 2014-03-14 03:17:52,228 INFO querymaster.QueryInProgress (QueryInProgress.java:stop(108)) - ========================================================= 2014-03-14 03:17:52,228 INFO querymaster.QueryInProgress (QueryInProgress.java:stop(109)) - Stop query:q_1394766883591_0196 2014-03-14 03:17:52,229 INFO rm.TajoWorkerResourceManager (TajoWorkerResourceManager.java:releaseWorkerResource(512)) - Release Resource: 0.0,512 2014-03-14 03:17:52,229 INFO rm.TajoWorkerResourceManager (TajoWorkerResourceManager.java:stopQueryMaster(534)) - Released QueryMaster (q_1394766883591_0196) resource:null 2014-03-14 03:17:52,229 INFO querymaster.QueryInProgress (QueryInProgress.java:stop(117)) - q_1394766883591_0196 QueryMaster stopped 2014-03-14 03:17:52,230 INFO master.TajoAsyncDispatcher (TajoAsyncDispatcher.java:stop(122)) - AsyncDispatcher stopped:QueryInProgress:q_1394766883591_0196 2014-03-14 03:17:52,231 WARN master.TajoAsyncDispatcher (TajoAsyncDispatcher.java:stop(115)) - Interrupted Exception while stopping 2014-03-14 03:17:52,231 INFO master.TajoAsyncDispatcher (TajoAsyncDispatcher.java:stop(122)) - AsyncDispatcher stopped:q_1394766883591_0196 2014-03-14 03:17:52,231 INFO querymaster.QueryMasterTask (QueryMasterTask.java:stop(200)) - Stopped QueryMasterTask:q_1394766883591_0196 2014-03-14 03:17:52,584 INFO worker.TajoWorkerClientService (TajoWorkerClientService.java:closeQuery(211)) - Stop Query:q_1394766883591_0196 Tests run: 6, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 4.522 sec Running org.apache.tajo.jdbc.TestResultSet 2014-03-14 03:17:52,651 INFO BlockStateChange (BlockManager.java:logAddStoredBlock(2237)) - BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:47468 is added to blk_1073742101_1277{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, replicas=[ReplicaUnderConstruction[127.0.0.1:47468|RBW]]} size 0 Tests run: 1, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.133 sec 2014-03-14 03:17:52,729 INFO worker.TajoWorker (TajoWorker.java:run(492)) - ============================================ 2014-03-14 03:17:52,729 INFO worker.TajoWorker (TajoWorker.java:run(493)) - TajoWorker received SIGINT Signal 2014-03-14 03:17:52,729 INFO worker.TajoWorker (TajoWorker.java:run(494)) - ============================================ 2014-03-14 03:17:52,734 INFO worker.WorkerHeartbeatService (WorkerHeartbeatService.java:run(251)) - Worker Resource Heartbeat Thread stopped. 2014-03-14 03:17:52,750 INFO rpc.NettyServerBase (NettyServerBase.java:shutdown(127)) - Rpc (TajoWorkerProtocol) listened on 0:0:0:0:0:0:0:0:18806) shutdown 2014-03-14 03:17:52,751 INFO worker.TajoWorkerManagerService (TajoWorkerManagerService.java:stop(95)) - TajoWorkerManagerService stopped 2014-03-14 03:17:52,753 INFO rpc.NettyServerBase (NettyServerBase.java:shutdown(127)) - Rpc (QueryMasterProtocol) listened on 0:0:0:0:0:0:0:0:18805) shutdown 2014-03-14 03:17:52,753 INFO querymaster.QueryMasterManagerService (QueryMasterManagerService.java:stop(110)) - QueryMasterManagerService stopped 2014-03-14 03:17:52,753 INFO querymaster.QueryMaster (QueryMaster.java:run(423)) - QueryMaster heartbeat thread stopped 2014-03-14 03:17:52,756 INFO master.TajoAsyncDispatcher (TajoAsyncDispatcher.java:stop(122)) - AsyncDispatcher stopped:querymaster_1394766884228 2014-03-14 03:17:52,756 INFO querymaster.QueryMaster (QueryMaster.java:stop(160)) - QueryMaster stop 2014-03-14 03:17:52,756 INFO worker.TajoWorkerClientService (TajoWorkerClientService.java:stop(107)) - TajoWorkerClientService stopping 2014-03-14 03:17:52,758 INFO rpc.NettyServerBase (NettyServerBase.java:shutdown(127)) - Rpc (QueryMasterClientProtocol) listened on 0:0:0:0:0:0:0:0:18804) shutdown 2014-03-14 03:17:52,758 INFO worker.TajoWorkerClientService (TajoWorkerClientService.java:stop(111)) - TajoWorkerClientService stopped 2014-03-14 03:17:52,758 INFO worker.TajoWorker (TajoWorker.java:stop(334)) - TajoWorker main thread exiting Results : Failed tests: testUnion7(org.apache.tajo.engine.query.TestUnionQuery): Result Verification expected:<[orderkey(..) Tests run: 578, Failures: 1, Errors: 0, Skipped: 0 [INFO] ------------------------------------------------------------------------ [INFO] Reactor Summary: [INFO] [INFO] Tajo Main ......................................... SUCCESS [16.746s] [INFO] Tajo Project POM .................................. SUCCESS [5.060s] [INFO] Tajo Common ....................................... SUCCESS [10.507s] [INFO] Tajo Algebra ...................................... SUCCESS [3.497s] [INFO] Tajo Rpc .......................................... SUCCESS [19.885s] [INFO] Tajo Catalog Common ............................... SUCCESS [5.866s] [INFO] Tajo Catalog Client ............................... SUCCESS [1.216s] [INFO] Tajo Catalog Server ............................... SUCCESS [12.640s] [INFO] Tajo Storage ...................................... SUCCESS [45.447s] [INFO] Tajo Core PullServer .............................. SUCCESS [1.840s] [INFO] Tajo Client ....................................... SUCCESS [3.932s] [INFO] Tajo JDBC Driver .................................. SUCCESS [0.671s] [INFO] Tajo Core Backend ................................. FAILURE [3:35.648s] [INFO] Tajo Core ......................................... SKIPPED [INFO] Tajo Catalog Drivers HCatalog ..................... SKIPPED [INFO] Tajo Catalog Drivers .............................. SKIPPED [INFO] Tajo Catalog ...................................... SKIPPED [INFO] Tajo Distribution ................................. SKIPPED [INFO] ------------------------------------------------------------------------ [INFO] BUILD FAILURE [INFO] ------------------------------------------------------------------------ [INFO] Total time: 5:43.922s [INFO] Finished at: Fri Mar 14 03:17:53 UTC 2014 [INFO] Final Memory: 41M/359M [INFO] ------------------------------------------------------------------------ [ERROR] Failed to execute goal org.apache.maven.plugins:maven-surefire-plugin:2.12.4:test (default-test) on project tajo-core-backend: There are test failures. [ERROR] [ERROR] Please refer to <https://builds.apache.org/job/Tajo-master-nightly/ws/tajo-core/tajo-core-backend/target/surefire-reports> for the individual test results. [ERROR] -> [Help 1] [ERROR] [ERROR] To see the full stack trace of the errors, re-run Maven with the -e switch. [ERROR] Re-run Maven using the -X switch to enable full debug logging. [ERROR] [ERROR] For more information about the errors and possible solutions, please read the following articles: [ERROR] [Help 1] http://cwiki.apache.org/confluence/display/MAVEN/MojoFailureException [ERROR] [ERROR] After correcting the problems, you can resume the build with the command [ERROR] mvn <goals> -rf :tajo-core-backend Build step 'Execute shell' marked build as failure Recording test results
