See <https://builds.apache.org/job/Tajo-master-nightly/388/changes>
Changes:
[hyunsik] TAJO-894: Left outer join with partitioned large table and small
table returns empty result. (Hyoungjun Kim via hyunsik)
------------------------------------------
[...truncated 177244 lines...]
=> in schema: {(16) default.lineitem.l_orderkey
(INT4),default.lineitem.l_partkey (INT4),default.lineitem.l_suppkey
(INT4),default.lineitem.l_linenumber (INT4),default.lineitem.l_quantity
(FLOAT8),default.lineitem.l_extendedprice (FLOAT8),default.lineitem.l_discount
(FLOAT8),default.lineitem.l_tax (FLOAT8),default.lineitem.l_returnflag
(TEXT),default.lineitem.l_linestatus (TEXT),default.lineitem.l_shipdate
(TEXT),default.lineitem.l_commitdate (TEXT),default.lineitem.l_receiptdate
(TEXT),default.lineitem.l_shipinstruct (TEXT),default.lineitem.l_shipmode
(TEXT),default.lineitem.l_comment (TEXT)}
2014-07-01 02:16:38,727 INFO: org.apache.tajo.master.GlobalEngine
(createLogicalPlan(477)) - =============================================
2014-07-01 02:16:38,728 INFO: org.apache.tajo.master.GlobalEngine
(executeQueryInternal(285)) - Query is forwarded to :0
2014-07-01 02:16:38,728 INFO: org.apache.tajo.master.TajoAsyncDispatcher
(start(101)) - AsyncDispatcher started:QueryInProgress:q_1404180576016_0512
2014-07-01 02:16:38,728 INFO:
org.apache.tajo.master.querymaster.QueryInProgress (startQueryMaster(165)) -
Initializing QueryInProgress for QueryID=q_1404180576016_0512
2014-07-01 02:16:38,728 INFO:
org.apache.tajo.master.querymaster.QueryInProgress (connectQueryMaster(209)) -
Connect to QueryMaster:asf001.sp2.ygridcore.net/67.195.138.31:16359
2014-07-01 02:16:38,729 INFO:
org.apache.tajo.master.querymaster.QueryInProgress (submmitQueryToMaster(229))
- Call executeQuery to :asf001.sp2.ygridcore.net:16359,q_1404180576016_0512
2014-07-01 02:16:38,731 INFO:
org.apache.tajo.master.querymaster.QueryMasterManagerService
(executeQuery(236)) - Receive executeQuery request:q_1404180576016_0512
2014-07-01 02:16:38,732 INFO: org.apache.tajo.master.querymaster.QueryMaster
(handle(374)) - Start QueryStartEventHandler:q_1404180576016_0512
2014-07-01 02:16:38,735 INFO:
org.apache.tajo.master.querymaster.QueryMasterTask (initStagingDir(380)) - The
staging dir
'hdfs://localhost:59625/tmp/tajo-jenkins/staging/q_1404180576016_0512' is
created.
2014-07-01 02:16:38,772 INFO:
org.apache.tajo.engine.planner.global.GlobalPlanner (build(116)) -
-----------------------------
Query Block Graph
-----------------------------
|-#ROOT
-----------------------------
Optimization Log:
-----------------------------
INSERT(2) INTO default.testcolumnpartitionedtablebyonecolumn
=> {(3) default.testcolumnpartitionedtablebyonecolumn.col1
(INT4),default.testcolumnpartitionedtablebyonecolumn.col2
(INT4),default.testcolumnpartitionedtablebyonecolumn.key (FLOAT8)}
PROJECTION(1)
=> Targets: default.lineitem.l_orderkey (INT4), default.lineitem.l_partkey
(INT4), NULL as null_col, default.lineitem.l_quantity (FLOAT8)
=> out schema: {(4) default.lineitem.l_orderkey
(INT4),default.lineitem.l_partkey (INT4),null_col
(NULL_TYPE),default.lineitem.l_quantity (FLOAT8)}
=> in schema: {(3) default.lineitem.l_orderkey
(INT4),default.lineitem.l_partkey (INT4),default.lineitem.l_quantity (FLOAT8)}
SCAN(0) on default.lineitem
=> target list: default.lineitem.l_orderkey (INT4),
default.lineitem.l_partkey (INT4), default.lineitem.l_quantity (FLOAT8)
=> out schema: {(3) default.lineitem.l_orderkey
(INT4),default.lineitem.l_partkey (INT4),default.lineitem.l_quantity (FLOAT8)}
=> in schema: {(16) default.lineitem.l_orderkey
(INT4),default.lineitem.l_partkey (INT4),default.lineitem.l_suppkey
(INT4),default.lineitem.l_linenumber (INT4),default.lineitem.l_quantity
(FLOAT8),default.lineitem.l_extendedprice (FLOAT8),default.lineitem.l_discount
(FLOAT8),default.lineitem.l_tax (FLOAT8),default.lineitem.l_returnflag
(TEXT),default.lineitem.l_linestatus (TEXT),default.lineitem.l_shipdate
(TEXT),default.lineitem.l_commitdate (TEXT),default.lineitem.l_receiptdate
(TEXT),default.lineitem.l_shipinstruct (TEXT),default.lineitem.l_shipmode
(TEXT),default.lineitem.l_comment (TEXT)}
2014-07-01 02:16:38,773 INFO:
org.apache.tajo.engine.planner.global.GlobalPlanner (build(154)) -
-------------------------------------------------------------------------------
Execution Block Graph (TERMINAL - eb_1404180576016_0512_000003)
-------------------------------------------------------------------------------
|-eb_1404180576016_0512_000003
|-eb_1404180576016_0512_000002
|-eb_1404180576016_0512_000001
-------------------------------------------------------------------------------
=======================================================
Block Id: eb_1404180576016_0512_000001 [LEAF]
=======================================================
[Outgoing]
[q_1404180576016_0512] 1 => 2 (type=HASH_SHUFFLE,
key=default.lineitem.l_quantity (FLOAT8), num=32)
PROJECTION(1)
=> Targets: default.lineitem.l_orderkey (INT4), default.lineitem.l_partkey
(INT4), NULL as null_col, default.lineitem.l_quantity (FLOAT8)
=> out schema: {(4) default.lineitem.l_orderkey
(INT4),default.lineitem.l_partkey (INT4),null_col
(NULL_TYPE),default.lineitem.l_quantity (FLOAT8)}
=> in schema: {(3) default.lineitem.l_orderkey
(INT4),default.lineitem.l_partkey (INT4),default.lineitem.l_quantity (FLOAT8)}
SCAN(0) on default.lineitem
=> target list: default.lineitem.l_orderkey (INT4),
default.lineitem.l_partkey (INT4), default.lineitem.l_quantity (FLOAT8)
=> out schema: {(3) default.lineitem.l_orderkey
(INT4),default.lineitem.l_partkey (INT4),default.lineitem.l_quantity (FLOAT8)}
=> in schema: {(16) default.lineitem.l_orderkey
(INT4),default.lineitem.l_partkey (INT4),default.lineitem.l_suppkey
(INT4),default.lineitem.l_linenumber (INT4),default.lineitem.l_quantity
(FLOAT8),default.lineitem.l_extendedprice (FLOAT8),default.lineitem.l_discount
(FLOAT8),default.lineitem.l_tax (FLOAT8),default.lineitem.l_returnflag
(TEXT),default.lineitem.l_linestatus (TEXT),default.lineitem.l_shipdate
(TEXT),default.lineitem.l_commitdate (TEXT),default.lineitem.l_receiptdate
(TEXT),default.lineitem.l_shipinstruct (TEXT),default.lineitem.l_shipmode
(TEXT),default.lineitem.l_comment (TEXT)}
=======================================================
Block Id: eb_1404180576016_0512_000002 [ROOT]
=======================================================
[Incoming]
[q_1404180576016_0512] 1 => 2 (type=HASH_SHUFFLE,
key=default.lineitem.l_quantity (FLOAT8), num=32)
INSERT(2) INTO default.testcolumnpartitionedtablebyonecolumn
=> {(3) default.testcolumnpartitionedtablebyonecolumn.col1
(INT4),default.testcolumnpartitionedtablebyonecolumn.col2
(INT4),default.testcolumnpartitionedtablebyonecolumn.key (FLOAT8)}
SCAN(5) on eb_1404180576016_0512_000001
=> out schema: {(4) default.lineitem.l_orderkey
(INT4),default.lineitem.l_partkey (INT4),null_col
(NULL_TYPE),default.lineitem.l_quantity (FLOAT8)}
=> in schema: {(4) default.lineitem.l_orderkey
(INT4),default.lineitem.l_partkey (INT4),null_col
(NULL_TYPE),default.lineitem.l_quantity (FLOAT8)}
=======================================================
Block Id: eb_1404180576016_0512_000003 [TERMINAL]
=======================================================
2014-07-01 02:16:38,774 INFO: org.apache.tajo.master.TajoAsyncDispatcher
(start(101)) - AsyncDispatcher started:q_1404180576016_0512
2014-07-01 02:16:38,774 INFO: org.apache.tajo.master.querymaster.Query
(handle(688)) - Processing q_1404180576016_0512 of type START
2014-07-01 02:16:38,774 INFO: org.apache.tajo.master.querymaster.SubQuery
(calculateShuffleOutputNum(801)) - ============>>>>> Unexpected Case!
<<<<<================
2014-07-01 02:16:38,774 INFO: org.apache.tajo.master.querymaster.SubQuery
(calculateShuffleOutputNum(805)) - eb_1404180576016_0512_000001, Table's volume
is approximately 1 MB
2014-07-01 02:16:38,774 INFO: org.apache.tajo.master.querymaster.SubQuery
(calculateShuffleOutputNum(808)) - eb_1404180576016_0512_000001, The determined
number of partitions is 1
2014-07-01 02:16:38,775 INFO: org.apache.tajo.master.querymaster.SubQuery
(initTaskScheduler(677)) - org.apache.tajo.master.DefaultTaskScheduler is
chosen for the task scheduling for eb_1404180576016_0512_000001
2014-07-01 02:16:38,776 INFO: org.apache.tajo.storage.AbstractStorageManager
(listStatus(386)) - Total input paths to process : 1
2014-07-01 02:16:38,777 INFO: org.apache.tajo.storage.AbstractStorageManager
(getSplits(615)) - Total # of splits: 1
2014-07-01 02:16:38,777 INFO: org.apache.tajo.master.querymaster.SubQuery
(transition(647)) - 1 objects are scheduled
2014-07-01 02:16:38,777 INFO: org.apache.tajo.master.DefaultTaskScheduler
(start(87)) - Start TaskScheduler
2014-07-01 02:16:38,778 INFO: org.apache.tajo.worker.TajoResourceAllocator
(calculateNumRequestContainers(100)) - CalculateNumberRequestContainer - Number
of Tasks=1, Number of Cluster Slots=1
2014-07-01 02:16:38,778 INFO: org.apache.tajo.master.querymaster.SubQuery
(allocateContainers(888)) - Request Container for eb_1404180576016_0512_000001
containers=1
2014-07-01 02:16:38,778 INFO: org.apache.tajo.master.querymaster.Query
(handle(705)) - q_1404180576016_0512 Query Transitioned from QUERY_NEW to
QUERY_RUNNING
2014-07-01 02:16:38,778 INFO: org.apache.tajo.worker.TajoResourceAllocator
(run(217)) - Start TajoWorkerAllocationThread
2014-07-01 02:16:38,779 INFO: org.apache.tajo.worker.TajoResourceAllocator
(run(336)) - Stop TajoWorkerAllocationThread
2014-07-01 02:16:38,779 INFO: org.apache.tajo.master.querymaster.SubQuery
(transition(997)) - SubQuery (eb_1404180576016_0512_000001) has 1 containers!
2014-07-01 02:16:38,780 INFO: org.apache.tajo.worker.TaskRunner (<init>(122)) -
Tajo Root Dir: hdfs://localhost:59625/tajo
2014-07-01 02:16:38,780 INFO: org.apache.tajo.worker.TaskRunner (<init>(123)) -
Worker Local Dir:
file://<https://builds.apache.org/job/Tajo-master-nightly/ws/tajo-core/target/test-data/f4cedba3-ec41-47f9-bbe4-99d57f7b0726/tajo-localdir>
2014-07-01 02:16:38,781 INFO: org.apache.tajo.worker.TaskRunner (<init>(138)) -
QueryMaster Address:asf001.sp2.ygridcore.net/67.195.138.31:16359
2014-07-01 02:16:38,782 INFO: org.apache.tajo.worker.TaskRunnerManager
(run(156)) - Start
TaskRunner:eb_1404180576016_0512_000001,container_1404180576016_0512_01_001838
2014-07-01 02:16:38,782 INFO: org.apache.tajo.worker.TaskRunner (init(191)) -
TaskRunner basedir is created (q_1404180576016_0512/output/1)
2014-07-01 02:16:38,783 INFO: org.apache.tajo.worker.TaskRunner (run(327)) -
TaskRunner startup
2014-07-01 02:16:38,783 INFO: org.apache.tajo.worker.TaskRunner (run(346)) -
Request GetTask:
eb_1404180576016_0512_000001,container_1404180576016_0512_01_001838
2014-07-01 02:16:38,784 INFO: org.apache.tajo.master.DefaultTaskScheduler
(allocateRackTask(707)) - Assigned Local/Rack/Total: (0/1/1), Locality: 0.00%,
Rack host: 67.195.138.31
2014-07-01 02:16:38,785 INFO: org.apache.tajo.worker.TaskRunner (run(385)) -
Accumulated Received Task: 1
2014-07-01 02:16:38,785 INFO: org.apache.tajo.worker.TaskRunner (run(394)) -
Initializing: ta_1404180576016_0512_000001_000000_00
2014-07-01 02:16:38,786 INFO: org.apache.tajo.worker.TaskAttemptContext
(setState(115)) - Query status of ta_1404180576016_0512_000001_000000_00 is
changed to TA_PENDING
2014-07-01 02:16:38,787 INFO: org.apache.tajo.worker.Task (<init>(188)) -
==================================
2014-07-01 02:16:38,787 INFO: org.apache.tajo.worker.Task (<init>(189)) - *
Subquery ta_1404180576016_0512_000001_000000_00 is initialized
2014-07-01 02:16:38,787 INFO: org.apache.tajo.worker.Task (<init>(190)) - *
InterQuery: true, Use HASH_SHUFFLE shuffle
2014-07-01 02:16:38,787 INFO: org.apache.tajo.worker.Task (<init>(193)) - *
Fragments (num: 1)
2014-07-01 02:16:38,787 INFO: org.apache.tajo.worker.Task (<init>(194)) - *
Fetches (total:0) :
2014-07-01 02:16:38,787 INFO: org.apache.tajo.worker.Task (<init>(198)) - *
Local task dir:
<https://builds.apache.org/job/Tajo-master-nightly/ws/tajo-core/target/test-data/f4cedba3-ec41-47f9-bbe4-99d57f7b0726/tajo-localdir/q_1404180576016_0512/output/1/0_0>
2014-07-01 02:16:38,787 INFO: org.apache.tajo.worker.Task (<init>(203)) -
==================================
2014-07-01 02:16:38,788 INFO: org.apache.tajo.worker.TaskAttemptContext
(setState(115)) - Query status of ta_1404180576016_0512_000001_000000_00 is
changed to TA_RUNNING
2014-07-01 02:16:38,792 INFO: org.apache.tajo.worker.TaskAttemptContext
(setState(115)) - Query status of ta_1404180576016_0512_000001_000000_00 is
changed to TA_SUCCEEDED
2014-07-01 02:16:38,792 INFO: org.apache.tajo.worker.Task (run(452)) - Worker's
task counter - total:1, succeeded: 1, killed: 1, failed: 0
2014-07-01 02:16:38,792 INFO: org.apache.tajo.worker.TaskRunner (run(346)) -
Request GetTask:
eb_1404180576016_0512_000001,container_1404180576016_0512_01_001838
2014-07-01 02:16:38,792 INFO: org.apache.tajo.master.querymaster.SubQuery
(transition(1074)) - [eb_1404180576016_0512_000001] Task Completion Event
(Total: 1, Success: 1, Killed: 0, Failed: 0)
2014-07-01 02:16:38,793 INFO: org.apache.tajo.master.querymaster.SubQuery
(transition(1114)) - subQuery completed - eb_1404180576016_0512_000001
(total=1, success=1, killed=0)
2014-07-01 02:16:38,793 INFO: org.apache.tajo.master.DefaultTaskScheduler
(run(102)) - TaskScheduler schedulingThread stopped
2014-07-01 02:16:38,793 INFO: org.apache.tajo.master.DefaultTaskScheduler
(stop(143)) - Task Scheduler stopped
2014-07-01 02:16:38,793 INFO: org.apache.tajo.worker.TaskRunner (run(376)) -
Received ShouldDie
flag:eb_1404180576016_0512_000001,container_1404180576016_0512_01_001838
2014-07-01 02:16:38,793 INFO: org.apache.tajo.master.querymaster.Query
(handle(688)) - Processing q_1404180576016_0512 of type SUBQUERY_COMPLETED
2014-07-01 02:16:38,793 INFO: org.apache.tajo.worker.TaskRunner (stop(239)) -
Stop TaskRunner: eb_1404180576016_0512_000001
2014-07-01 02:16:38,793 INFO: org.apache.tajo.master.querymaster.SubQuery
(initTaskScheduler(677)) - org.apache.tajo.master.DefaultTaskScheduler is
chosen for the task scheduling for eb_1404180576016_0512_000002
2014-07-01 02:16:38,794 INFO: org.apache.tajo.master.querymaster.SubQuery
(getNonLeafTaskNum(837)) - Table's volume is approximately 1 MB
2014-07-01 02:16:38,794 INFO: org.apache.tajo.master.querymaster.SubQuery
(getNonLeafTaskNum(840)) - The determined number of non-leaf tasks is 1
2014-07-01 02:16:38,794 INFO:
org.apache.tajo.master.rm.TajoWorkerResourceManager
(releaseWorkerResource(519)) - Release Resource: 0.5,512
2014-07-01 02:16:38,794 INFO: org.apache.tajo.worker.TaskRunnerManager
(stopTask(89)) - Stop
Task:eb_1404180576016_0512_000001,container_1404180576016_0512_01_001838
2014-07-01 02:16:38,794 INFO: org.apache.tajo.master.querymaster.Repartitioner
(scheduleHashShuffledFetches(575)) - eb_1404180576016_0512_000002,
ScheduleHashShuffledFetches - Max num=1, finalFetchURI=1
2014-07-01 02:16:38,795 INFO: org.apache.tajo.master.querymaster.Repartitioner
(scheduleHashShuffledFetches(591)) - eb_1404180576016_0512_000002,
DeterminedTaskNum : 1
2014-07-01 02:16:38,795 INFO: org.apache.tajo.master.querymaster.SubQuery
(transition(647)) - 1 objects are scheduled
2014-07-01 02:16:38,795 INFO: org.apache.tajo.master.DefaultTaskScheduler
(start(87)) - Start TaskScheduler
2014-07-01 02:16:38,795 INFO: org.apache.tajo.worker.TajoResourceAllocator
(calculateNumRequestContainers(100)) - CalculateNumberRequestContainer - Number
of Tasks=1, Number of Cluster Slots=1
2014-07-01 02:16:38,795 INFO: org.apache.tajo.master.querymaster.SubQuery
(allocateContainers(888)) - Request Container for eb_1404180576016_0512_000002
containers=1
2014-07-01 02:16:38,795 INFO: org.apache.tajo.master.querymaster.Query
(executeNextBlock(609)) - Scheduling SubQuery:eb_1404180576016_0512_000002
2014-07-01 02:16:38,795 INFO: org.apache.tajo.worker.TajoResourceAllocator
(run(217)) - Start TajoWorkerAllocationThread
2014-07-01 02:16:38,796 INFO: org.apache.tajo.worker.TajoResourceAllocator
(run(336)) - Stop TajoWorkerAllocationThread
2014-07-01 02:16:38,796 INFO: org.apache.tajo.master.querymaster.SubQuery
(transition(997)) - SubQuery (eb_1404180576016_0512_000002) has 1 containers!
2014-07-01 02:16:38,797 INFO: org.apache.tajo.worker.TaskRunner (<init>(122)) -
Tajo Root Dir: hdfs://localhost:59625/tajo
2014-07-01 02:16:38,798 INFO: org.apache.tajo.worker.TaskRunner (<init>(123)) -
Worker Local Dir:
file://<https://builds.apache.org/job/Tajo-master-nightly/ws/tajo-core/target/test-data/f4cedba3-ec41-47f9-bbe4-99d57f7b0726/tajo-localdir>
2014-07-01 02:16:38,798 INFO: org.apache.tajo.worker.TaskRunner (<init>(138)) -
QueryMaster Address:asf001.sp2.ygridcore.net/67.195.138.31:16359
2014-07-01 02:16:38,798 INFO: org.apache.tajo.worker.TaskRunnerManager
(run(156)) - Start
TaskRunner:eb_1404180576016_0512_000002,container_1404180576016_0512_01_001839
2014-07-01 02:16:38,799 INFO: org.apache.tajo.worker.TaskRunner (init(191)) -
TaskRunner basedir is created (q_1404180576016_0512/output/2)
2014-07-01 02:16:38,799 INFO: org.apache.tajo.worker.TaskRunner (run(327)) -
TaskRunner startup
2014-07-01 02:16:38,799 INFO: org.apache.tajo.worker.TaskRunner (run(346)) -
Request GetTask:
eb_1404180576016_0512_000002,container_1404180576016_0512_01_001839
2014-07-01 02:16:38,801 INFO: org.apache.tajo.worker.TaskRunner (run(385)) -
Accumulated Received Task: 1
2014-07-01 02:16:38,801 INFO: org.apache.tajo.worker.TaskRunner (run(394)) -
Initializing: ta_1404180576016_0512_000002_000000_00
2014-07-01 02:16:38,802 INFO: org.apache.tajo.worker.Task (<init>(183)) -
Output File Path:
hdfs://localhost:59625/tmp/tajo-jenkins/staging/q_1404180576016_0512/RESULT/part-02-000000
2014-07-01 02:16:38,802 INFO: org.apache.tajo.worker.TaskAttemptContext
(setState(115)) - Query status of ta_1404180576016_0512_000002_000000_00 is
changed to TA_PENDING
2014-07-01 02:16:38,802 INFO: org.apache.tajo.worker.Task (<init>(188)) -
==================================
2014-07-01 02:16:38,802 INFO: org.apache.tajo.worker.Task (<init>(189)) - *
Subquery ta_1404180576016_0512_000002_000000_00 is initialized
2014-07-01 02:16:38,802 INFO: org.apache.tajo.worker.Task (<init>(190)) - *
InterQuery: false
2014-07-01 02:16:38,802 INFO: org.apache.tajo.worker.Task (<init>(193)) - *
Fragments (num: 1)
2014-07-01 02:16:38,802 INFO: org.apache.tajo.worker.Task (<init>(194)) - *
Fetches (total:1) :
2014-07-01 02:16:38,802 INFO: org.apache.tajo.worker.Task (<init>(196)) - Table
Id: eb_1404180576016_0512_000001, Simple URIs:
[http://67.195.138.31:46064/?qid=q_1404180576016_0512&sid=1&p=0&type=h]
2014-07-01 02:16:38,802 INFO: org.apache.tajo.worker.Task (<init>(198)) - *
Local task dir:
<https://builds.apache.org/job/Tajo-master-nightly/ws/tajo-core/target/test-data/f4cedba3-ec41-47f9-bbe4-99d57f7b0726/tajo-localdir/q_1404180576016_0512/output/2/0_0>
2014-07-01 02:16:38,803 INFO: org.apache.tajo.worker.Task (<init>(203)) -
==================================
2014-07-01 02:16:38,804 INFO: org.apache.tajo.worker.Task (init(219)) - the
directory is created
<https://builds.apache.org/job/Tajo-master-nightly/ws/tajo-core/target/test-data/f4cedba3-ec41-47f9-bbe4-99d57f7b0726/tajo-localdir/q_1404180576016_0512/in/eb_1404180576016_0512_000002/0/0/eb_1404180576016_0512_000001>
2014-07-01 02:16:38,806 INFO: org.apache.tajo.worker.TaskAttemptContext
(setState(115)) - Query status of ta_1404180576016_0512_000002_000000_00 is
changed to TA_RUNNING
2014-07-01 02:16:38,806 INFO: org.apache.tajo.pullserver.TajoPullServerService
(channelOpen(349)) - Current number of shuffle connections (2)
2014-07-01 02:16:38,806 INFO: org.apache.tajo.worker.Fetcher (get(126)) -
Fetch:
http://67.195.138.31:46064/?qid=q_1404180576016_0512&sid=1&p=0&type=h&ta=0_0
2014-07-01 02:16:38,807 INFO: org.apache.tajo.pullserver.TajoPullServerService
(messageReceived(394)) - PullServer request param: shuffleType=h, sid=1,
partId=0, taskIds=[0_0]
2014-07-01 02:16:38,807 INFO: org.apache.tajo.pullserver.TajoPullServerService
(messageReceived(400)) - PullServer baseDir:
file://<https://builds.apache.org/job/Tajo-master-nightly/ws/tajo-core/target/test-data/f4cedba3-ec41-47f9-bbe4-99d57f7b0726/tajo-localdir/q_1404180576016_0512/output>
2014-07-01 02:16:38,808 INFO: org.apache.tajo.worker.Task (waitForFetch(360)) -
ta_1404180576016_0512_000002_000000_00 All fetches are done!
2014-07-01 02:16:38,809 INFO:
org.apache.tajo.engine.planner.PhysicalPlannerImpl
(createSortBasedColumnPartitionStorePlan(826)) - The planner chooses
[Sort-based Column Partitioned Store] algorithm
2014-07-01 02:16:38,810 INFO:
org.apache.tajo.engine.planner.physical.ExternalSortExec (info(61)) -
[ta_1404180576016_0512_000002_000000_00] Chunks creation time: 0 msec
2014-07-01 02:16:38,812 INFO:
org.apache.tajo.engine.planner.physical.SortBasedColPartitionStoreExec
(getAppender(74)) - Add subpartition path directory
:hdfs://localhost:59625/tmp/tajo-jenkins/staging/q_1404180576016_0512/RESULT/key=17.0
2014-07-01 02:16:38,819 INFO: BlockStateChange (logAddStoredBlock(2300)) -
BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39643 is added to
blk_1073742653_1829{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1,
replicas=[ReplicaUnderConstruction[[DISK]DS-09593d91-2ecd-47fd-b1cb-5ee09c8257b0:NORMAL|RBW]]}
size 0
2014-07-01 02:16:38,824 INFO:
org.apache.tajo.engine.planner.physical.SortBasedColPartitionStoreExec
(getAppender(74)) - Add subpartition path directory
:hdfs://localhost:59625/tmp/tajo-jenkins/staging/q_1404180576016_0512/RESULT/key=36.0
2014-07-01 02:16:38,833 INFO: BlockStateChange (logAddStoredBlock(2300)) -
BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39643 is added to
blk_1073742654_1830{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1,
replicas=[ReplicaUnderConstruction[[DISK]DS-9e0aefb3-e358-4388-98b1-81e7288c67ee:NORMAL|RBW]]}
size 0
2014-07-01 02:16:38,836 INFO:
org.apache.tajo.engine.planner.physical.SortBasedColPartitionStoreExec
(getAppender(74)) - Add subpartition path directory
:hdfs://localhost:59625/tmp/tajo-jenkins/staging/q_1404180576016_0512/RESULT/key=38.0
2014-07-01 02:16:38,844 INFO: BlockStateChange (logAddStoredBlock(2300)) -
BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39643 is added to
blk_1073742655_1831{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1,
replicas=[ReplicaUnderConstruction[[DISK]DS-09593d91-2ecd-47fd-b1cb-5ee09c8257b0:NORMAL|RBW]]}
size 0
2014-07-01 02:16:38,847 INFO:
org.apache.tajo.engine.planner.physical.SortBasedColPartitionStoreExec
(getAppender(74)) - Add subpartition path directory
:hdfs://localhost:59625/tmp/tajo-jenkins/staging/q_1404180576016_0512/RESULT/key=45.0
2014-07-01 02:16:38,855 INFO: BlockStateChange (logAddStoredBlock(2300)) -
BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39643 is added to
blk_1073742656_1832{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1,
replicas=[ReplicaUnderConstruction[[DISK]DS-9e0aefb3-e358-4388-98b1-81e7288c67ee:NORMAL|RBW]]}
size 0
2014-07-01 02:16:38,859 INFO:
org.apache.tajo.engine.planner.physical.SortBasedColPartitionStoreExec
(getAppender(74)) - Add subpartition path directory
:hdfs://localhost:59625/tmp/tajo-jenkins/staging/q_1404180576016_0512/RESULT/key=49.0
2014-07-01 02:16:38,866 INFO: BlockStateChange (logAddStoredBlock(2300)) -
BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39643 is added to
blk_1073742657_1833{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1,
replicas=[ReplicaUnderConstruction[[DISK]DS-09593d91-2ecd-47fd-b1cb-5ee09c8257b0:NORMAL|RBW]]}
size 0
2014-07-01 02:16:38,867 INFO: org.apache.tajo.worker.TaskAttemptContext
(setState(115)) - Query status of ta_1404180576016_0512_000002_000000_00 is
changed to TA_SUCCEEDED
2014-07-01 02:16:38,867 INFO: org.apache.tajo.worker.Task (run(452)) - Worker's
task counter - total:1, succeeded: 1, killed: 1, failed: 0
2014-07-01 02:16:38,867 INFO: org.apache.tajo.worker.TaskRunner (run(346)) -
Request GetTask:
eb_1404180576016_0512_000002,container_1404180576016_0512_01_001839
2014-07-01 02:16:38,868 INFO: org.apache.tajo.master.querymaster.SubQuery
(transition(1074)) - [eb_1404180576016_0512_000002] Task Completion Event
(Total: 1, Success: 1, Killed: 0, Failed: 0)
2014-07-01 02:16:38,868 INFO: org.apache.tajo.master.querymaster.SubQuery
(transition(1114)) - subQuery completed - eb_1404180576016_0512_000002
(total=1, success=1, killed=0)
2014-07-01 02:16:38,868 INFO: org.apache.tajo.master.DefaultTaskScheduler
(stop(143)) - Task Scheduler stopped
2014-07-01 02:16:38,868 INFO: org.apache.tajo.master.DefaultTaskScheduler
(run(102)) - TaskScheduler schedulingThread stopped
2014-07-01 02:16:38,868 INFO: org.apache.tajo.master.querymaster.Query
(handle(688)) - Processing q_1404180576016_0512 of type SUBQUERY_COMPLETED
2014-07-01 02:16:38,868 INFO: org.apache.tajo.master.querymaster.Query
(handle(688)) - Processing q_1404180576016_0512 of type QUERY_COMPLETED
2014-07-01 02:16:38,868 INFO: org.apache.tajo.worker.TaskRunner (run(376)) -
Received ShouldDie
flag:eb_1404180576016_0512_000002,container_1404180576016_0512_01_001839
2014-07-01 02:16:38,869 INFO:
org.apache.tajo.master.rm.TajoWorkerResourceManager
(releaseWorkerResource(519)) - Release Resource: 0.5,512
2014-07-01 02:16:38,869 INFO: org.apache.tajo.worker.TaskRunner (stop(239)) -
Stop TaskRunner: eb_1404180576016_0512_000002
2014-07-01 02:16:38,869 INFO: org.apache.tajo.worker.TaskRunnerManager
(stopTask(89)) - Stop
Task:eb_1404180576016_0512_000002,container_1404180576016_0512_01_001839
2014-07-01 02:16:38,873 INFO: org.apache.tajo.catalog.CatalogServer
(dropTable(554)) - relation "default.testcolumnpartitionedtablebyonecolumn" is
deleted from the catalog (127.0.0.1:16355)
2014-07-01 02:16:38,874 INFO: org.apache.tajo.catalog.CatalogServer
(createTable(523)) - relation "default.testcolumnpartitionedtablebyonecolumn"
is added to the catalog (127.0.0.1:16355)
2014-07-01 02:16:38,874 INFO: org.apache.tajo.master.querymaster.Query
(handle(705)) - q_1404180576016_0512 Query Transitioned from QUERY_RUNNING to
QUERY_SUCCEEDED
2014-07-01 02:16:38,874 INFO:
org.apache.tajo.master.querymaster.QueryMasterTask (handle(297)) - Query
completion notified from q_1404180576016_0512
2014-07-01 02:16:38,874 INFO:
org.apache.tajo.master.querymaster.QueryMasterTask (handle(308)) - Query final
state: QUERY_SUCCEEDED
2014-07-01 02:16:38,874 INFO:
org.apache.tajo.master.querymaster.QueryMasterTask (stop(187)) - Stopping
QueryMasterTask:q_1404180576016_0512
2014-07-01 02:16:38,875 INFO:
org.apache.tajo.master.querymaster.QueryInProgress (heartbeat(265)) - Received
QueryMaster heartbeat:q_1404180576016_0512,state=QUERY_SUCCEEDED,progress=1.0,
queryMaster=asf001.sp2.ygridcore.net
2014-07-01 02:16:38,875 INFO:
org.apache.tajo.master.querymaster.QueryJobManager (stopQuery(203)) - Stop
QueryInProgress:q_1404180576016_0512
2014-07-01 02:16:38,875 INFO:
org.apache.tajo.master.querymaster.QueryInProgress (stop(116)) -
=========================================================
2014-07-01 02:16:38,875 INFO:
org.apache.tajo.master.querymaster.QueryInProgress (stop(117)) - Stop
query:q_1404180576016_0512
2014-07-01 02:16:38,875 WARN: org.apache.tajo.master.TajoAsyncDispatcher
(stop(115)) - Interrupted Exception while stopping
2014-07-01 02:16:38,875 INFO: org.apache.tajo.master.TajoAsyncDispatcher
(stop(122)) - AsyncDispatcher stopped:q_1404180576016_0512
2014-07-01 02:16:38,875 INFO:
org.apache.tajo.master.rm.TajoWorkerResourceManager
(releaseWorkerResource(519)) - Release Resource: 0.0,512
2014-07-01 02:16:38,875 INFO:
org.apache.tajo.master.rm.TajoWorkerResourceManager (stopQueryMaster(541)) -
Released QueryMaster (q_1404180576016_0512) resource.
2014-07-01 02:16:38,876 INFO:
org.apache.tajo.master.querymaster.QueryInProgress (stop(125)) -
q_1404180576016_0512 QueryMaster stopped
2014-07-01 02:16:38,876 INFO:
org.apache.tajo.master.querymaster.QueryMasterTask (stop(217)) - Stopped
QueryMasterTask:q_1404180576016_0512
2014-07-01 02:16:38,876 INFO: org.apache.tajo.master.querymaster.QueryMaster
(cleanup(166)) - cleanup query resources : q_1404180576016_0512
2014-07-01 02:16:38,876 WARN: org.apache.tajo.master.TajoAsyncDispatcher
(stop(115)) - Interrupted Exception while stopping
2014-07-01 02:16:38,876 INFO: org.apache.tajo.master.TajoAsyncDispatcher
(stop(122)) - AsyncDispatcher stopped:QueryInProgress:q_1404180576016_0512
Killed
Results :
Tests run: 878, Failures: 0, Errors: 0, Skipped: 0
[INFO] ------------------------------------------------------------------------
[INFO] Reactor Summary:
[INFO]
[INFO] Tajo Main ......................................... SUCCESS [55.731s]
[INFO] Tajo Project POM .................................. SUCCESS [3.038s]
[INFO] Tajo Maven Plugins ................................ SUCCESS [8.134s]
[INFO] Tajo Common ....................................... SUCCESS [1:16.656s]
[INFO] Tajo Algebra ...................................... SUCCESS [5.211s]
[INFO] Tajo Catalog Common ............................... SUCCESS [6.835s]
[INFO] Tajo Rpc .......................................... SUCCESS [23.148s]
[INFO] Tajo Catalog Client ............................... SUCCESS [1.130s]
[INFO] Tajo Catalog Server ............................... SUCCESS [6.977s]
[INFO] Tajo Storage ...................................... SUCCESS [56.128s]
[INFO] Tajo Core PullServer .............................. SUCCESS [1.390s]
[INFO] Tajo Client ....................................... SUCCESS [4.296s]
[INFO] Tajo JDBC Driver .................................. SUCCESS [2.001s]
[INFO] Tajo Catalog Drivers HCatalog ..................... SUCCESS [13.821s]
[INFO] Tajo Core ......................................... FAILURE [7:31.612s]
[INFO] Tajo Catalog Drivers .............................. SKIPPED
[INFO] Tajo Catalog ...................................... SKIPPED
[INFO] Tajo Distribution ................................. SKIPPED
[INFO] ------------------------------------------------------------------------
[INFO] BUILD FAILURE
[INFO] ------------------------------------------------------------------------
[INFO] Total time: 11:57.721s
[INFO] Finished at: Tue Jul 01 02:16:39 UTC 2014
[INFO] Final Memory: 50M/406M
[INFO] ------------------------------------------------------------------------
[ERROR] Failed to execute goal
org.apache.maven.plugins:maven-surefire-plugin:2.12.4:test (default-test) on
project tajo-core: Execution default-test of goal
org.apache.maven.plugins:maven-surefire-plugin:2.12.4:test failed: The forked
VM terminated without saying properly goodbye. VM crash or System.exit called ?
-> [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/PluginExecutionException
[ERROR]
[ERROR] After correcting the problems, you can resume the build with the command
[ERROR] mvn <goals> -rf :tajo-core
Build step 'Execute shell' marked build as failure
Recording test results
