You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@tajo.apache.org by "Hyunsik Choi (JIRA)" <ji...@apache.org> on 2014/07/07 12:13:33 UTC
[jira] [Commented] (TAJO-869) Sometimes, the unit test of
testTaskRunnerHistory is failed.
[ https://issues.apache.org/jira/browse/TAJO-869?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14053523#comment-14053523 ]
Hyunsik Choi commented on TAJO-869:
-----------------------------------
Here is additional log.
{noformat}
2014-07-07 13:22:32,295 INFO: org.apache.tajo.master.TajoAsyncDispatcher (start(101)) - AsyncDispatcher started:q_1404706448574_0608
2014-07-07 13:22:32,295 INFO: org.apache.tajo.master.querymaster.Query (handle(688)) - Processing q_1404706448574_0608 of type START
2014-07-07 13:22:32,295 INFO: org.apache.tajo.master.querymaster.SubQuery (initTaskScheduler(677)) - org.apache.tajo.master.DefaultTaskScheduler is chosen for the task scheduling for eb_1404706448574_0608_000001
2014-07-07 13:22:32,297 INFO: org.apache.tajo.storage.AbstractStorageManager (listStatus(386)) - Total input paths to process : 1
2014-07-07 13:22:32,298 INFO: org.apache.tajo.storage.AbstractStorageManager (getSplits(615)) - Total # of splits: 1
2014-07-07 13:22:32,298 INFO: org.apache.tajo.master.querymaster.SubQuery (transition(647)) - 1 objects are scheduled
2014-07-07 13:22:32,298 INFO: org.apache.tajo.master.DefaultTaskScheduler (start(87)) - Start TaskScheduler
2014-07-07 13:22:32,298 INFO: org.apache.tajo.worker.TajoResourceAllocator (calculateNumRequestContainers(100)) - CalculateNumberRequestContainer - Number of Tasks=1, Number of Cluster Slots=1
2014-07-07 13:22:32,298 INFO: org.apache.tajo.master.querymaster.SubQuery (allocateContainers(888)) - Request Container for eb_1404706448574_0608_000001 containers=1
2014-07-07 13:22:32,298 INFO: org.apache.tajo.master.querymaster.Query (handle(705)) - q_1404706448574_0608 Query Transitioned from QUERY_NEW to QUERY_RUNNING
2014-07-07 13:22:32,299 INFO: org.apache.tajo.worker.TajoResourceAllocator (run(217)) - Start TajoWorkerAllocationThread
2014-07-07 13:22:32,299 INFO: org.apache.tajo.worker.TajoResourceAllocator (run(336)) - Stop TajoWorkerAllocationThread
2014-07-07 13:22:32,299 INFO: org.apache.tajo.master.querymaster.SubQuery (transition(997)) - SubQuery (eb_1404706448574_0608_000001) has 1 containers!
2014-07-07 13:22:32,300 INFO: org.apache.tajo.worker.TaskRunner (<init>(122)) - Tajo Root Dir: hdfs://localhost:62867/tajo
2014-07-07 13:22:32,300 INFO: org.apache.tajo.worker.TaskRunner (<init>(123)) - Worker Local Dir: file:///Users/hyunsik/Code/tajo/tajo-4/tajo-core/target/test-data/8be7ebd5-b545-434a-8e5b-cdcfc4060bc5/tajo-localdir
2014-07-07 13:22:32,300 INFO: org.apache.tajo.worker.TaskRunner (<init>(138)) - QueryMaster Address:192.168.0.118/192.168.0.118:27052
2014-07-07 13:22:32,300 INFO: org.apache.tajo.worker.TaskRunnerManager (run(156)) - Start TaskRunner:eb_1404706448574_0608_000001,container_1404706448574_0608_01_002422
2014-07-07 13:22:32,301 INFO: org.apache.tajo.worker.TaskRunner (init(191)) - TaskRunner basedir is created (q_1404706448574_0608/output/1)
2014-07-07 13:22:32,301 INFO: org.apache.tajo.worker.TaskRunner (run(327)) - TaskRunner startup
2014-07-07 13:22:32,302 INFO: org.apache.tajo.worker.TaskRunner (run(346)) - Request GetTask: eb_1404706448574_0608_000001,container_1404706448574_0608_01_002422
2014-07-07 13:22:32,303 INFO: org.apache.tajo.master.DefaultTaskScheduler (allocateRackTask(718)) - Assigned Local/Rack/Total: (0/1/1), Locality: 0.00%, Rack host: 192.168.0.118
2014-07-07 13:22:32,303 INFO: org.apache.tajo.worker.TaskRunner (run(385)) - Accumulated Received Task: 1
2014-07-07 13:22:32,303 INFO: org.apache.tajo.worker.TaskRunner (run(394)) - Initializing: ta_1404706448574_0608_000001_000000_00
2014-07-07 13:22:32,305 INFO: org.apache.tajo.worker.Task (<init>(184)) - Output File Path: hdfs://localhost:62867/tmp/tajo-hyunsik/staging/q_1404706448574_0608/RESULT/part-01-000000
2014-07-07 13:22:32,305 INFO: org.apache.tajo.worker.TaskAttemptContext (setState(115)) - Query status of ta_1404706448574_0608_000001_000000_00 is changed to TA_PENDING
2014-07-07 13:22:32,305 INFO: org.apache.tajo.worker.Task (<init>(189)) - ==================================
2014-07-07 13:22:32,305 INFO: org.apache.tajo.worker.Task (<init>(190)) - * Subquery ta_1404706448574_0608_000001_000000_00 is initialized
2014-07-07 13:22:32,305 INFO: org.apache.tajo.worker.Task (<init>(191)) - * InterQuery: false
2014-07-07 13:22:32,305 INFO: org.apache.tajo.worker.Task (<init>(194)) - * Fragments (num: 1)
2014-07-07 13:22:32,305 INFO: org.apache.tajo.worker.Task (<init>(195)) - * Fetches (total:0) :
2014-07-07 13:22:32,305 INFO: org.apache.tajo.worker.Task (<init>(199)) - * Local task dir: file:/Users/hyunsik/Code/tajo/tajo-4/tajo-core/target/test-data/8be7ebd5-b545-434a-8e5b-cdcfc4060bc5/tajo-localdir/q_1404706448574_0608/output/1/0_0
2014-07-07 13:22:32,305 INFO: org.apache.tajo.worker.Task (<init>(204)) - ==================================
2014-07-07 13:22:32,305 INFO: org.apache.tajo.worker.TaskAttemptContext (setState(115)) - Query status of ta_1404706448574_0608_000001_000000_00 is changed to TA_RUNNING
2014-07-07 13:22:33,199 INFO: BlockStateChange (logAddStoredBlock(2300)) - BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:62868 is added to blk_1073742813_1989{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, replicas=[ReplicaUnderConstruction[[DISK]DS-90a75377-221a-4eef-9c85-2a7e3f066ff0:NORMAL|RBW]]} size 0
2014-07-07 13:22:33,200 INFO: org.apache.tajo.worker.TaskAttemptContext (setState(115)) - Query status of ta_1404706448574_0606_000001_000000_00 is changed to TA_KILLED
2014-07-07 13:22:33,200 INFO: org.apache.tajo.worker.Task (run(464)) - Worker's task counter - total:1, succeeded: 0, killed: 2, failed: 0
2014-07-07 13:22:33,200 INFO: org.apache.tajo.worker.TaskRunner (run(346)) - Request GetTask: eb_1404706448574_0606_000001,container_1404706448574_0606_01_002418
2014-07-07 13:22:33,201 WARN: org.apache.tajo.master.querymaster.QueryMasterManagerService (statusUpdate(162)) - ta_1404706448574_0606_000001_000000_00 Killed
2014-07-07 13:22:33,201 INFO: org.apache.tajo.master.querymaster.QueryUnitAttempt (transition(343)) - ta_1404706448574_0606_000001_000000_00 Received TA_KILLED Status from LocalTask
2014-07-07 13:22:33,201 INFO: org.apache.tajo.worker.TaskRunner (run(376)) - Received ShouldDie flag:eb_1404706448574_0606_000001,container_1404706448574_0606_01_002418
2014-07-07 13:22:33,201 INFO: org.apache.tajo.worker.TaskRunner (stop(239)) - Stop TaskRunner: eb_1404706448574_0606_000001
2014-07-07 13:22:33,201 INFO: org.apache.tajo.worker.TaskRunnerManager (stopTask(89)) - Stop Task:eb_1404706448574_0606_000001,container_1404706448574_0606_01_002418
2014-07-07 13:22:33,946 INFO: org.apache.tajo.master.querymaster.QueryInProgress (heartbeat(265)) - Received QueryMaster heartbeat:q_1404706448574_0608,state=QUERY_RUNNING,progress=0.0, queryMaster=192.168.0.118
2014-07-07 13:22:35,947 INFO: org.apache.tajo.master.querymaster.QueryInProgress (heartbeat(265)) - Received QueryMaster heartbeat:q_1404706448574_0608,state=QUERY_RUNNING,progress=1.0, queryMaster=192.168.0.118
2014-07-07 13:22:37,326 INFO: BlockStateChange (logAddStoredBlock(2300)) - BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:62868 is added to blk_1073742814_1990{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, replicas=[ReplicaUnderConstruction[[DISK]DS-ce1eb997-27a6-4e8f-8bac-f59344d164d4:NORMAL|RBW]]} size 0
2014-07-07 13:22:37,327 INFO: org.apache.tajo.worker.TaskAttemptContext (setState(115)) - Query status of ta_1404706448574_0608_000001_000000_00 is changed to TA_SUCCEEDED
2014-07-07 13:22:37,327 INFO: org.apache.tajo.worker.Task (run(464)) - Worker's task counter - total:1, succeeded: 1, killed: 1, failed: 0
2014-07-07 13:22:37,327 INFO: org.apache.tajo.worker.TaskRunner (run(346)) - Request GetTask: eb_1404706448574_0608_000001,container_1404706448574_0608_01_002422
2014-07-07 13:22:37,328 INFO: org.apache.tajo.master.querymaster.SubQuery (transition(1074)) - [eb_1404706448574_0608_000001] Task Completion Event (Total: 1, Success: 1, Killed: 0, Failed: 0)
2014-07-07 13:22:37,328 INFO: org.apache.tajo.master.querymaster.SubQuery (transition(1114)) - subQuery completed - eb_1404706448574_0608_000001 (total=1, success=1, killed=0)
2014-07-07 13:22:37,328 INFO: org.apache.tajo.master.DefaultTaskScheduler (run(102)) - TaskScheduler schedulingThread stopped
2014-07-07 13:22:37,328 INFO: org.apache.tajo.master.DefaultTaskScheduler (stop(143)) - Task Scheduler stopped
2014-07-07 13:22:37,328 INFO: org.apache.tajo.worker.TaskRunner (run(376)) - Received ShouldDie flag:eb_1404706448574_0608_000001,container_1404706448574_0608_01_002422
2014-07-07 13:22:37,328 INFO: org.apache.tajo.worker.TaskRunner (stop(239)) - Stop TaskRunner: eb_1404706448574_0608_000001
2014-07-07 13:22:37,328 INFO: org.apache.tajo.worker.TaskRunnerManager (stopTask(89)) - Stop Task:eb_1404706448574_0608_000001,container_1404706448574_0608_01_002422
2014-07-07 13:22:37,328 INFO: org.apache.tajo.master.querymaster.Query (handle(688)) - Processing q_1404706448574_0608 of type SUBQUERY_COMPLETED
2014-07-07 13:22:37,328 INFO: org.apache.tajo.master.querymaster.Query (handle(688)) - Processing q_1404706448574_0608 of type QUERY_COMPLETED
2014-07-07 13:22:37,328 INFO: org.apache.tajo.master.rm.TajoWorkerResourceManager (releaseWorkerResource(519)) - Release Resource: 0.5,512
2014-07-07 13:22:37,329 INFO: org.apache.tajo.master.querymaster.Query (handle(705)) - q_1404706448574_0608 Query Transitioned from QUERY_RUNNING to QUERY_SUCCEEDED
2014-07-07 13:22:37,329 INFO: org.apache.tajo.master.querymaster.QueryMasterTask (handle(297)) - Query completion notified from q_1404706448574_0608
2014-07-07 13:22:37,329 INFO: org.apache.tajo.master.querymaster.QueryMasterTask (handle(308)) - Query final state: QUERY_SUCCEEDED
2014-07-07 13:22:37,329 INFO: org.apache.tajo.master.querymaster.QueryMasterTask (stop(187)) - Stopping QueryMasterTask:q_1404706448574_0608
2014-07-07 13:22:37,329 INFO: org.apache.tajo.master.querymaster.QueryInProgress (heartbeat(265)) - Received QueryMaster heartbeat:q_1404706448574_0608,state=QUERY_SUCCEEDED,progress=1.0, queryMaster=192.168.0.118
2014-07-07 13:22:37,329 INFO: org.apache.tajo.master.querymaster.QueryJobManager (stopQuery(203)) - Stop QueryInProgress:q_1404706448574_0608
2014-07-07 13:22:37,329 INFO: org.apache.tajo.master.querymaster.QueryInProgress (stop(116)) - =========================================================
2014-07-07 13:22:37,329 INFO: org.apache.tajo.master.querymaster.QueryInProgress (stop(117)) - Stop query:q_1404706448574_0608
2014-07-07 13:22:37,329 INFO: org.apache.tajo.master.rm.TajoWorkerResourceManager (releaseWorkerResource(519)) - Release Resource: 0.0,512
2014-07-07 13:22:37,329 WARN: org.apache.tajo.master.TajoAsyncDispatcher (stop(115)) - Interrupted Exception while stopping
2014-07-07 13:22:37,329 INFO: org.apache.tajo.master.rm.TajoWorkerResourceManager (stopQueryMaster(541)) - Released QueryMaster (q_1404706448574_0608) resource.
2014-07-07 13:22:37,330 INFO: org.apache.tajo.master.TajoAsyncDispatcher (stop(122)) - AsyncDispatcher stopped:q_1404706448574_0608
2014-07-07 13:22:37,330 INFO: org.apache.tajo.master.querymaster.QueryInProgress (stop(125)) - q_1404706448574_0608 QueryMaster stopped
2014-07-07 13:22:37,330 INFO: org.apache.tajo.master.querymaster.QueryMasterTask (stop(217)) - Stopped QueryMasterTask:q_1404706448574_0608
2014-07-07 13:22:37,330 INFO: org.apache.tajo.master.querymaster.QueryMaster (cleanup(166)) - cleanup query resources : q_1404706448574_0608
2014-07-07 13:22:37,330 WARN: org.apache.tajo.master.TajoAsyncDispatcher (stop(115)) - Interrupted Exception while stopping
2014-07-07 13:22:37,330 INFO: org.apache.tajo.master.TajoAsyncDispatcher (stop(122)) - AsyncDispatcher stopped:QueryInProgress:q_1404706448574_0608
2014-07-07 13:22:37,813 INFO: org.apache.tajo.master.session.SessionManager (removeSession(80)) - Session 69b7b393-512f-4184-b938-9c730a9cca47 is removed.
Tests run: 2, Failures: 1, Errors: 0, Skipped: 0, Time elapsed: 11.12 sec <<< FAILURE!
testTaskRunnerHistory(org.apache.tajo.worker.TestHistory) Time elapsed: 5.572 sec <<< FAILURE!
java.lang.AssertionError: expected: org.apache.tajo.worker.TaskRunnerHistory<or...@f9402a96> but was: org.apache.tajo.worker.TaskRunnerHistory<or...@f9402a96>
at org.junit.Assert.fail(Assert.java:88)
at org.junit.Assert.failNotEquals(Assert.java:743)
at org.junit.Assert.assertEquals(Assert.java:118)
at org.junit.Assert.assertEquals(Assert.java:144)
at org.apache.tajo.worker.TestHistory.testTaskRunnerHistory(TestHistory.java:80)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:47)
at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:44)
at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)
at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27)
at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:271)
at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:70)
at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:50)
at org.junit.runners.ParentRunner$3.run(ParentRunner.java:238)
at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:63)
at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:236)
at org.junit.runners.ParentRunner.access$000(ParentRunner.java:53)
at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:229)
at org.junit.runners.ParentRunner.run(ParentRunner.java:309)
at org.apache.maven.surefire.junit4.JUnit4Provider.execute(JUnit4Provider.java:252)
at org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:141)
at org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:112)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at org.apache.maven.surefire.util.ReflectionUtils.invokeMethodWithArray(ReflectionUtils.java:189)
at org.apache.maven.surefire.booter.ProviderFactory$ProviderProxy.invoke(ProviderFactory.java:165)
at org.apache.maven.surefire.booter.ProviderFactory.invokeProvider(ProviderFactory.java:85)
at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:115)
at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:75)
Running org.apache.tajo.worker.TestRangeRetrieverHandler
2014-07-07 13:22:37,838 INFO: org.apache.tajo.TajoTestingCluster (startCatalogCluster(241)) - Apache Derby repository is set to jdbc:derby:/Users/hyunsik/Code/tajo/tajo-4/tajo-core/target/test-data/8be7ebd5-b545-434a-8e5b-cdcfc4060bc5/774cc00b-f71c-4f49-90a0-0cca21e3544c/db
2014-07-07 13:22:37,838 INFO: org.apache.tajo.catalog.CatalogServer (serviceInit(128)) - Catalog Store Class: org.apache.tajo.catalog.store.MemStore
2014-07-07 13:22:37,838 INFO: org.apache.tajo.rpc.RpcChannelFactory (createServerChannelFactory(81)) - Create CatalogProtocol-87 ServerSocketChannelFactory. Worker:16
2014-07-07 13:22:37,841 INFO: org.apache.tajo.rpc.NettyServerBase (start(106)) - Rpc (CatalogProtocol) listens on /127.0.0.1:27132
2014-07-07 13:22:37,841 INFO: org.apache.tajo.catalog.CatalogServer (start(188)) - Catalog Server startup (127.0.0.1:27132)
2014-07-07 13:22:37,842 INFO: org.apache.tajo.catalog.CatalogServer (createTablespace(232)) - tablespace "default" (file:/Users/hyunsik/Code/tajo/tajo-4/tajo-core/target/test-data/905127ce-d7c5-4634-bcab-850485dd3273) is created
2014-07-07 13:22:37,842 INFO: org.apache.tajo.catalog.CatalogServer (createDatabase(357)) - database "default" is created
2014-07-07 13:22:37,893 INFO: org.apache.tajo.catalog.CatalogServer (createTable(523)) - relation "default.employee" is added to the catalog (127.0.0.1:27132)
2014-07-07 13:22:37,944 INFO: org.apache.tajo.engine.planner.physical.RangeShuffleFileWriteExec (init(76)) - Output data directory: file:/Users/hyunsik/Code/tajo/tajo-4/tajo-core/target/test-data/905127ce-d7c5-4634-bcab-850485dd3273/output
2014-07-07 13:22:37,987 INFO: org.apache.tajo.engine.planner.physical.ExternalSortExec (info(61)) - [ta_0000000000000_0073_000001_000076_42] Chunks creation time: 6 msec
2014-07-07 13:22:38,837 INFO: org.apache.tajo.worker.RangeRetrieverHandler (<init>(73)) - BSTIndex is loaded from disk ((0=>9999, 1=>10004), (0=>0, 1=>5)
2014-07-07 13:22:38,837 INFO: org.apache.tajo.worker.RangeRetrieverHandler (get(97)) - GET Request for /Users/hyunsik/Code/tajo/tajo-4/tajo-core/target/test-data/905127ce-d7c5-4634-bcab-850485dd3273/output/data/data (start=(0=>9599, 1=>10004), end=(0=>9999, 1=>10004), last=true)
2014-07-07 13:22:38,837 INFO: org.apache.tajo.worker.RangeRetrieverHandler (get(160)) - Retrieve File Chunk: (start=5200, length=-5200) /Users/hyunsik/Code/tajo/tajo-4/tajo-core/target/test-data/905127ce-d7c5-4634-bcab-850485dd3273/output/data/data
{noformat}
> Sometimes, the unit test of testTaskRunnerHistory is failed.
> ------------------------------------------------------------
>
> Key: TAJO-869
> URL: https://issues.apache.org/jira/browse/TAJO-869
> Project: Tajo
> Issue Type: Bug
> Reporter: Hyunsik Choi
> Priority: Critical
> Fix For: 0.9.0
>
>
> {noformat}
> Results :
> Failed tests: testTaskRunnerHistory(org.apache.tajo.worker.TestHistory): expected: org.apache.tajo.worker.TaskRunnerHistory<or...@63bec4ad> but was: org.apache.tajo.worker.TaskRunnerHistory<or...@63bec4ad>
> {noformat}
--
This message was sent by Atlassian JIRA
(v6.2#6252)