You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@reef.apache.org by "Tae-Geon Um (JIRA)" <ji...@apache.org> on 2015/05/11 17:59:01 UTC
[jira] [Updated] (REEF-319) Intermittent test failure of ClockTest.testAlarmOrder

     [ https://issues.apache.org/jira/browse/REEF-319?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]

Tae-Geon Um updated REEF-319:
-----------------------------
    Summary: Intermittent test failure of ClockTest.testAlarmOrder  (was: Intermittent ClockTest.testAlarmOrder test failure)

> Intermittent test failure of ClockTest.testAlarmOrder
> -----------------------------------------------------
>
>                 Key: REEF-319
>                 URL: https://issues.apache.org/jira/browse/REEF-319
>             Project: REEF
>          Issue Type: Bug
>          Components: REEF-Tests, Wake
>         Environment: Mac os x yosemite v10.10.1
>            Reporter: Tae-Geon Um
>
> ClockTest.testAlarmOrder test fails intermittently when I execute 'mvn clean package' ( about 1 failure per 5-10 executions ) 
> log: 
> {noformat}
> ...
> ...
> Running org.apache.reef.wake.test.time.ClockTest
> May 12, 2015 12:23:15 AM org.apache.reef.wake.time.runtime.RuntimeClock <init>
> FINE: RuntimeClock instantiated.
> May 12, 2015 12:23:15 AM org.apache.reef.wake.time.runtime.RuntimeClock run
> FINE: Subscribe event handlers
> May 12, 2015 12:23:15 AM org.apache.reef.wake.time.runtime.RuntimeClock run
> FINE: Initiate runtime start
> May 12, 2015 12:23:15 AM org.apache.reef.wake.impl.LoggingEventHandler onNext
> FINE: org.apache.reef.wake.time.runtime.event.RuntimeStart[0]
> May 12, 2015 12:23:15 AM org.apache.reef.wake.time.runtime.RuntimeClock run
> FINE: Initiate start time
> May 12, 2015 12:23:15 AM org.apache.reef.wake.impl.MissingStartHandlerHandler onNext
> WARNING: No binding to Clock.StartHandler. It is likely that the clock will immediately go idle and close.
> May 12, 2015 12:23:15 AM org.apache.reef.wake.impl.LoggingEventHandler onNext
> FINE: org.apache.reef.wake.time.runtime.event.IdleClock[0]
> May 12, 2015 12:23:15 AM org.apache.reef.wake.impl.LoggingEventHandler onNext
> FINE: org.apache.reef.wake.time.runtime.event.IdleClock[0]
> May 12, 2015 12:23:15 AM org.apache.reef.wake.impl.LoggingEventHandler onNext
> FINE: org.apache.reef.wake.time.runtime.event.IdleClock[100]
> May 12, 2015 12:23:15 AM org.apache.reef.wake.impl.LoggingEventHandler onNext
> FINE: org.apache.reef.wake.time.runtime.event.IdleClock[300]
> May 12, 2015 12:23:15 AM org.apache.reef.wake.impl.LoggingEventHandler onNext
> FINE: org.apache.reef.wake.time.runtime.event.IdleClock[600]
> May 12, 2015 12:23:15 AM org.apache.reef.wake.impl.LoggingEventHandler onNext
> FINE: org.apache.reef.wake.time.runtime.event.IdleClock[1000]
> May 12, 2015 12:23:15 AM org.apache.reef.wake.impl.LoggingEventHandler onNext
> FINE: org.apache.reef.wake.time.runtime.event.IdleClock[1500]
> May 12, 2015 12:23:15 AM org.apache.reef.wake.impl.LoggingEventHandler onNext
> FINE: org.apache.reef.wake.time.runtime.event.IdleClock[2100]
> May 12, 2015 12:23:15 AM org.apache.reef.wake.impl.LoggingEventHandler onNext
> FINE: org.apache.reef.wake.time.runtime.event.IdleClock[2800]
> May 12, 2015 12:23:15 AM org.apache.reef.wake.impl.LoggingEventHandler onNext
> FINE: org.apache.reef.wake.time.runtime.event.IdleClock[3600]
> May 12, 2015 12:23:15 AM org.apache.reef.wake.impl.LoggingEventHandler onNext
> FINE: org.apache.reef.wake.time.runtime.event.IdleClock[4500]
> May 12, 2015 12:23:17 AM org.apache.reef.wake.time.runtime.RuntimeClock close
> INFO: Clock.close()
> May 12, 2015 12:23:17 AM org.apache.reef.wake.impl.LoggingEventHandler onNext
> FINE: org.apache.reef.wake.time.event.StopTime[4501]
> May 12, 2015 12:23:17 AM org.apache.reef.wake.impl.LoggingEventHandler onNext
> FINE: org.apache.reef.wake.time.runtime.event.RuntimeStop[4501]
> May 12, 2015 12:23:17 AM org.apache.reef.wake.time.runtime.RuntimeClock logThreads
> FINE: Threads running after exiting the clock main loop: process reaper, pool-14-thread-1, Signal Dispatcher, pool-8-thread-2, pool-18-thread-7, pool-18-thread-6, pool-8-thread-4, Thread-2056, pool-18-thread-1, Submitter-pool-9-thread-1, pool-18-thread-3, main, pool-8-thread-5, Finalizer, pool-18-thread-4, ForkJoinPool-1-worker-2, SingleThreadStage<org.apache.reef.wake.test.ThreadPoolStageTest$TestEventHandlerA>, pool-18-thread-5, pool-8-thread-3, pool-8-thread-1, Submitter-pool-9-thread-2, Submitter-pool-9-thread-3, pool-9-thread-1, pool-13-thread-1, Reference Handler, pool-18-thread-2, 
> May 12, 2015 12:23:17 AM org.apache.reef.wake.time.runtime.RuntimeClock run
> FINE: Runtime clock exit
> May 12, 2015 12:23:17 AM org.apache.reef.wake.time.runtime.RuntimeClock <init>
> FINE: RuntimeClock instantiated.
> May 12, 2015 12:23:17 AM org.apache.reef.wake.time.runtime.RuntimeClock run
> FINE: Subscribe event handlers
> May 12, 2015 12:23:17 AM org.apache.reef.wake.time.runtime.RuntimeClock run
> FINE: Initiate runtime start
> May 12, 2015 12:23:17 AM org.apache.reef.wake.impl.LoggingEventHandler onNext
> FINE: org.apache.reef.wake.time.runtime.event.RuntimeStart[0]
> May 12, 2015 12:23:17 AM org.apache.reef.wake.time.runtime.RuntimeClock run
> FINE: Initiate start time
> May 12, 2015 12:23:17 AM org.apache.reef.wake.impl.MissingStartHandlerHandler onNext
> WARNING: No binding to Clock.StartHandler. It is likely that the clock will immediately go idle and close.
> May 12, 2015 12:23:17 AM org.apache.reef.wake.impl.LoggingEventHandler onNext
> FINE: org.apache.reef.wake.time.runtime.event.IdleClock[1000]
> May 12, 2015 12:23:19 AM org.apache.reef.wake.time.runtime.RuntimeClock close
> INFO: Clock.close()
> May 12, 2015 12:23:19 AM org.apache.reef.wake.impl.LoggingEventHandler onNext
> FINE: org.apache.reef.wake.time.event.StopTime[1001]
> May 12, 2015 12:23:19 AM org.apache.reef.wake.impl.LoggingEventHandler onNext
> FINE: org.apache.reef.wake.time.runtime.event.RuntimeStop[1001]
> May 12, 2015 12:23:19 AM org.apache.reef.wake.time.runtime.RuntimeClock <init>
> FINE: RuntimeClock instantiated.
> May 12, 2015 12:23:19 AM org.apache.reef.wake.time.runtime.RuntimeClock logThreads
> FINE: Threads running after exiting the clock main loop: process reaper, pool-14-thread-1, Signal Dispatcher, pool-8-thread-2, pool-18-thread-7, pool-18-thread-6, pool-8-thread-4, pool-18-thread-1, Submitter-pool-9-thread-1, pool-18-thread-3, main, pool-8-thread-5, Finalizer, pool-18-thread-4, Thread-2057, ForkJoinPool-1-worker-2, SingleThreadStage<org.apache.reef.wake.test.ThreadPoolStageTest$TestEventHandlerA>, pool-18-thread-5, pool-8-thread-3, pool-8-thread-1, Submitter-pool-9-thread-2, Submitter-pool-9-thread-3, pool-9-thread-1, pool-13-thread-1, Reference Handler, pool-18-thread-2, 
> May 12, 2015 12:23:19 AM org.apache.reef.wake.time.runtime.RuntimeClock run
> FINE: Runtime clock exit
> May 12, 2015 12:23:19 AM org.apache.reef.wake.time.runtime.RuntimeClock run
> FINE: Subscribe event handlers
> May 12, 2015 12:23:19 AM org.apache.reef.wake.time.runtime.RuntimeClock run
> FINE: Initiate runtime start
> May 12, 2015 12:23:19 AM org.apache.reef.wake.impl.LoggingEventHandler onNext
> FINE: org.apache.reef.wake.time.runtime.event.RuntimeStart[1431357799313]
> May 12, 2015 12:23:19 AM org.apache.reef.wake.time.runtime.RuntimeClock run
> FINE: Initiate start time
> May 12, 2015 12:23:19 AM org.apache.reef.wake.impl.MissingStartHandlerHandler onNext
> WARNING: No binding to Clock.StartHandler. It is likely that the clock will immediately go idle and close.
> May 12, 2015 12:23:24 AM org.apache.reef.wake.time.runtime.RuntimeClock close
> INFO: Clock.close()
> May 12, 2015 12:23:24 AM org.apache.reef.wake.impl.LoggingEventHandler onNext
> FINE: org.apache.reef.wake.time.event.StopTime[1431357804315]
> May 12, 2015 12:23:24 AM org.apache.reef.wake.impl.LoggingEventHandler onNext
> FINE: org.apache.reef.wake.time.runtime.event.RuntimeStop[1431357804316]
> May 12, 2015 12:23:24 AM org.apache.reef.wake.time.runtime.RuntimeClock <init>
> FINE: RuntimeClock instantiated.
> May 12, 2015 12:23:24 AM org.apache.reef.wake.time.runtime.RuntimeClock logThreads
> FINE: Threads running after exiting the clock main loop: pool-14-thread-1, Signal Dispatcher, pool-8-thread-2, pool-18-thread-7, pool-18-thread-6, pool-8-thread-4, pool-18-thread-1, Submitter-pool-9-thread-1, pool-18-thread-3, main, pool-8-thread-5, Finalizer, pool-18-thread-4, ForkJoinPool-1-worker-2, SingleThreadStage<org.apache.reef.wake.test.ThreadPoolStageTest$TestEventHandlerA>, pool-18-thread-5, pool-8-thread-3, pool-8-thread-1, Submitter-pool-9-thread-2, Submitter-pool-9-thread-3, pool-9-thread-1, Thread-2058, pool-13-thread-1, Reference Handler, pool-18-thread-2, 
> May 12, 2015 12:23:24 AM org.apache.reef.wake.time.runtime.RuntimeClock run
> FINE: Runtime clock exit
> May 12, 2015 12:23:24 AM org.apache.reef.wake.time.runtime.RuntimeClock run
> FINE: Subscribe event handlers
> May 12, 2015 12:23:24 AM org.apache.reef.wake.time.runtime.RuntimeClock run
> FINE: Initiate runtime start
> May 12, 2015 12:23:24 AM org.apache.reef.wake.impl.LoggingEventHandler onNext
> FINE: org.apache.reef.wake.time.runtime.event.RuntimeStart[1431357804321]
> May 12, 2015 12:23:24 AM org.apache.reef.wake.time.runtime.RuntimeClock run
> FINE: Initiate start time
> May 12, 2015 12:23:24 AM org.apache.reef.wake.impl.MissingStartHandlerHandler onNext
> WARNING: No binding to Clock.StartHandler. It is likely that the clock will immediately go idle and close.
> May 12, 2015 12:23:29 AM org.apache.reef.wake.impl.LoggingEventHandler onNext
> FINE: org.apache.reef.wake.time.runtime.event.IdleClock[1431357809322]
> May 12, 2015 12:23:29 AM org.apache.reef.wake.time.runtime.RuntimeClock close
> INFO: Clock.close()
> Tests run: 4, Failures: 1, Errors: 0, Skipped: 0, Time elapsed: 14.585 sec <<< FAILURE! - in org.apache.reef.wake.test.time.ClockTest
> testAlarmOrder(org.apache.reef.wake.test.time.ClockTest)  Time elapsed: 2.059 sec  <<< FAILURE!
> org.junit.internal.ArrayComparisonFailure: arrays first differed at element [2]; expected:<200> but was:<300>
> 	at org.junit.internal.ComparisonCriteria.arrayEquals(ComparisonCriteria.java:50)
> 	at org.junit.Assert.internalArrayEquals(Assert.java:473)
> 	at org.junit.Assert.assertArrayEquals(Assert.java:394)
> 	at org.junit.Assert.assertArrayEquals(Assert.java:405)
> 	at org.apache.reef.wake.test.time.ClockTest.testAlarmOrder(ClockTest.java:158)
> Running org.apache.reef.wake.test.TimerStageTest
> May 12, 2015 12:23:29 AM org.apache.reef.wake.impl.LoggingEventHandler onNext
> FINE: org.apache.reef.wake.time.event.StopTime[1431357809826]
> May 12, 2015 12:23:29 AM org.apache.reef.wake.impl.LoggingEventHandler onNext
> FINE: org.apache.reef.wake.time.runtime.event.RuntimeStop[1431357809826]
> TEST testTimerStage
> May 12, 2015 12:23:29 AM org.apache.reef.wake.time.runtime.RuntimeClock logThreads
> FINE: Threads running after exiting the clock main loop: pool-14-thread-1, Signal Dispatcher, pool-8-thread-2, pool-18-thread-7, pool-18-thread-6, pool-8-thread-4, pool-18-thread-1, Submitter-pool-9-thread-1, pool-18-thread-3, main, pool-8-thread-5, Finalizer, pool-18-thread-4, ForkJoinPool-1-worker-2, SingleThreadStage<org.apache.reef.wake.test.ThreadPoolStageTest$TestEventHandlerA>, pool-18-thread-5, pool-8-thread-3, pool-8-thread-1, Submitter-pool-9-thread-2, Submitter-pool-9-thread-3, pool-9-thread-1, Thread-2059, pool-13-thread-1, Reference Handler, pool-18-thread-2, 
> May 12, 2015 12:23:29 AM org.apache.reef.wake.time.runtime.RuntimeClock run
> FINE: Runtime clock exit
> 1 org.apache.reef.wake.impl.PeriodicEvent@1865b0e5 scheduled event at 1431357809928
> 2 org.apache.reef.wake.impl.PeriodicEvent@1865b0e5 scheduled event at 1431357810932
> 3 org.apache.reef.wake.impl.PeriodicEvent@1865b0e5 scheduled event at 1431357811933
> 4 org.apache.reef.wake.impl.PeriodicEvent@1865b0e5 scheduled event at 1431357812931
> 5 org.apache.reef.wake.impl.PeriodicEvent@1865b0e5 scheduled event at 1431357813930
> 6 org.apache.reef.wake.impl.PeriodicEvent@1865b0e5 scheduled event at 1431357814929
> 7 org.apache.reef.wake.impl.PeriodicEvent@1865b0e5 scheduled event at 1431357815932
> 8 org.apache.reef.wake.impl.PeriodicEvent@1865b0e5 scheduled event at 1431357816933
> 9 org.apache.reef.wake.impl.PeriodicEvent@1865b0e5 scheduled event at 1431357817932
> 10 org.apache.reef.wake.impl.PeriodicEvent@1865b0e5 scheduled event at 1431357818929
> Tests run: 1, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 9.081 sec - in org.apache.reef.wake.test.TimerStageTest
> May 12, 2015 12:23:38 AM org.apache.reef.wake.impl.WakeSharedPool close
> INFO: ending pool stage: java.util.concurrent.ForkJoinPool@41917d6d[Running, parallelism = 10, size = 1, active = 0, running = 0, steals = 1000000, tasks = 0, submissions = 0]
> Results :
> Failed tests: 
>   ClockTest.testAlarmOrder:158 arrays first differed at element [2]; expected:<200> but was:<300>
> Tests run: 66, Failures: 1, Errors: 0, Skipped: 0
> {noformat}



--
This message was sent by Atlassian JIRA
(v6.3.4#6332)