Uploaded image for project: 'Spark'
  1. Spark
  2. SPARK-23504

Flaky test: RateSourceV2Suite.basic microbatch execution

    XMLWordPrintableJSON

Details

    • Bug
    • Status: Resolved
    • Major
    • Resolution: Cannot Reproduce
    • 2.4.0
    • None
    • SQL, Tests
    • None

    Description

      Seen on an unrelated change:
      https://amplab.cs.berkeley.edu/jenkins/job/SparkPullRequestBuilder/87635/testReport/org.apache.spark.sql.execution.streaming/RateSourceV2Suite/basic_microbatch_execution/

      Error Message
org.scalatest.exceptions.TestFailedException:   == Results == !== Correct Answer - 10 ==     == Spark Answer - 0 == !struct<_1:timestamp,_2:int>   struct<> ![1969-12-31 16:00:00.0,0]      ![1969-12-31 16:00:00.1,1]      ![1969-12-31 16:00:00.2,2]      ![1969-12-31 16:00:00.3,3]      ![1969-12-31 16:00:00.4,4]      ![1969-12-31 16:00:00.5,5]      ![1969-12-31 16:00:00.6,6]      ![1969-12-31 16:00:00.7,7]      ![1969-12-31 16:00:00.8,8]      ![1969-12-31 16:00:00.9,9]            == Progress ==    AdvanceRateManualClock(1) => CheckLastBatch: [1969-12-31 16:00:00.0,0],[1969-12-31 16:00:00.1,1],[1969-12-31 16:00:00.2,2],[1969-12-31 16:00:00.3,3],[1969-12-31 16:00:00.4,4],[1969-12-31 16:00:00.5,5],[1969-12-31 16:00:00.6,6],[1969-12-31 16:00:00.7,7],[1969-12-31 16:00:00.8,8],[1969-12-31 16:00:00.9,9]    StopStream    StartStream(ProcessingTime(0),org.apache.spark.util.SystemClock@22bc97a,Map(),null)    AdvanceRateManualClock(2)    CheckLastBatch: [1969-12-31 16:00:01.0,10],[1969-12-31 16:00:01.1,11],[1969-12-31 16:00:01.2,12],[1969-12-31 16:00:01.3,13],[1969-12-31 16:00:01.4,14],[1969-12-31 16:00:01.5,15],[1969-12-31 16:00:01.6,16],[1969-12-31 16:00:01.7,17],[1969-12-31 16:00:01.8,18],[1969-12-31 16:00:01.9,19]  == Stream == Output Mode: Append Stream state: {org.apache.spark.sql.execution.streaming.sources.RateStreamMicroBatchReader@75b88292: {"0":{"value":-1,"runTimeMs":0}}} Thread state: alive Thread stack trace: sun.misc.Unsafe.park(Native Method) java.util.concurrent.locks.LockSupport.park(LockSupport.java:175) java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836) java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(AbstractQueuedSynchronizer.java:997) java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1304) scala.concurrent.impl.Promise$DefaultPromise.tryAwait(Promise.scala:202) scala.concurrent.impl.Promise$DefaultPromise.ready(Promise.scala:218) scala.concurrent.impl.Promise$DefaultPromise.ready(Promise.scala:153) org.apache.spark.util.ThreadUtils$.awaitReady(ThreadUtils.scala:222) org.apache.spark.scheduler.DAGScheduler.runJob(DAGScheduler.scala:633) org.apache.spark.SparkContext.runJob(SparkContext.scala:2030) org.apache.spark.sql.execution.datasources.v2.WriteToDataSourceV2Exec.doExecute(WriteToDataSourceV2.scala:84) org.apache.spark.sql.execution.SparkPlan$$anonfun$execute$1.apply(SparkPlan.scala:131) org.apache.spark.sql.execution.SparkPlan$$anonfun$execute$1.apply(SparkPlan.scala:127) org.apache.spark.sql.execution.SparkPlan$$anonfun$executeQuery$1.apply(SparkPlan.scala:155) org.apache.spark.rdd.RDDOperationScope$.withScope(RDDOperationScope.scala:151) org.apache.spark.sql.execution.SparkPlan.executeQuery(SparkPlan.scala:152) org.apache.spark.sql.execution.SparkPlan.execute(SparkPlan.scala:127) org.apache.spark.sql.execution.SparkPlan.getByteArrayRdd(SparkPlan.scala:247) org.apache.spark.sql.execution.SparkPlan.executeCollect(SparkPlan.scala:294) org.apache.spark.sql.Dataset.org$apache$spark$sql$Dataset$$collectFromPlan(Dataset.scala:3272) org.apache.spark.sql.Dataset$$anonfun$collect$1.apply(Dataset.scala:2722) org.apache.spark.sql.Dataset$$anonfun$collect$1.apply(Dataset.scala:2722) org.apache.spark.sql.Dataset$$anonfun$52.apply(Dataset.scala:3253) org.apache.spark.sql.execution.SQLExecution$.withNewExecutionId(SQLExecution.scala:77) org.apache.spark.sql.Dataset.withAction(Dataset.scala:3252) org.apache.spark.sql.Dataset.collect(Dataset.scala:2722) org.apache.spark.sql.execution.streaming.MicroBatchExecution$$anonfun$org$apache$spark$sql$execution$streaming$MicroBatchExecution$$runBatch$3$$anonfun$apply$18.apply(MicroBatchExecution.scala:493) org.apache.spark.sql.execution.SQLExecution$.withNewExecutionId(SQLExecution.scala:77) org.apache.spark.sql.execution.streaming.MicroBatchExecution$$anonfun$org$apache$spark$sql$execution$streaming$MicroBatchExecution$$runBatch$3.apply(MicroBatchExecution.scala:488) org.apache.spark.sql.execution.streaming.ProgressReporter$class.reportTimeTaken(ProgressReporter.scala:271) org.apache.spark.sql.execution.streaming.StreamExecution.reportTimeTaken(StreamExecution.scala:58) org.apache.spark.sql.execution.streaming.MicroBatchExecution.org$apache$spark$sql$execution$streaming$MicroBatchExecution$$runBatch(MicroBatchExecution.scala:487) org.apache.spark.sql.execution.streaming.MicroBatchExecution$$anonfun$runActivatedStream$1$$anonfun$apply$mcZ$sp$1.apply$mcV$sp(MicroBatchExecution.scala:143) org.apache.spark.sql.execution.streaming.MicroBatchExecution$$anonfun$runActivatedStream$1$$anonfun$apply$mcZ$sp$1.apply(MicroBatchExecution.scala:131) org.apache.spark.sql.execution.streaming.MicroBatchExecution$$anonfun$runActivatedStream$1$$anonfun$apply$mcZ$sp$1.apply(MicroBatchExecution.scala:131) org.apache.spark.sql.execution.streaming.ProgressReporter$class.reportTimeTaken(ProgressReporter.scala:271) org.apache.spark.sql.execution.streaming.StreamExecution.reportTimeTaken(StreamExecution.scala:58) org.apache.spark.sql.execution.streaming.MicroBatchExecution$$anonfun$runActivatedStream$1.apply$mcZ$sp(MicroBatchExecution.scala:131) org.apache.spark.sql.execution.streaming.ProcessingTimeExecutor.execute(TriggerExecutor.scala:56) org.apache.spark.sql.execution.streaming.MicroBatchExecution.runActivatedStream(MicroBatchExecution.scala:127) org.apache.spark.sql.execution.streaming.StreamExecution.org$apache$spark$sql$execution$streaming$StreamExecution$$runStream(StreamExecution.scala:279) org.apache.spark.sql.execution.streaming.StreamExecution$$anon$1.run(StreamExecution.scala:189)   == Sink == 0:    == Plan == == Parsed Logical Plan == WriteToDataSourceV2 org.apache.spark.sql.execution.streaming.sources.MicroBatchWriter@36f7e778 +- Project [timestamp#421856 AS timestamp#421823, value#421857L AS value#421824L]    +- StreamingDataSourceV2Relation [timestamp#421856, value#421857L], org.apache.spark.sql.execution.streaming.sources.RateStreamMicroBatchReader@75b88292  == Analyzed Logical Plan == WriteToDataSourceV2 org.apache.spark.sql.execution.streaming.sources.MicroBatchWriter@36f7e778 +- Project [timestamp#421856 AS timestamp#421823, value#421857L AS value#421824L]    +- StreamingDataSourceV2Relation [timestamp#421856, value#421857L], org.apache.spark.sql.execution.streaming.sources.RateStreamMicroBatchReader@75b88292  == Optimized Logical Plan == WriteToDataSourceV2 org.apache.spark.sql.execution.streaming.sources.MicroBatchWriter@36f7e778 +- StreamingDataSourceV2Relation [timestamp#421856, value#421857L], org.apache.spark.sql.execution.streaming.sources.RateStreamMicroBatchReader@75b88292  == Physical Plan == WriteToDataSourceV2 org.apache.spark.sql.execution.streaming.sources.MicroBatchWriter@36f7e778 +- *(1) DataSourceV2Scan [timestamp#421856, value#421857L], org.apache.spark.sql.execution.streaming.sources.RateStreamMicroBatchReader@75b88292                    
Stacktrace
sbt.ForkMain$ForkError: org.scalatest.exceptions.TestFailedException: 

== Results ==
!== Correct Answer - 10 ==     == Spark Answer - 0 ==
!struct<_1:timestamp,_2:int>   struct<>
![1969-12-31 16:00:00.0,0]     
![1969-12-31 16:00:00.1,1]     
![1969-12-31 16:00:00.2,2]     
![1969-12-31 16:00:00.3,3]     
![1969-12-31 16:00:00.4,4]     
![1969-12-31 16:00:00.5,5]     
![1969-12-31 16:00:00.6,6]     
![1969-12-31 16:00:00.7,7]     
![1969-12-31 16:00:00.8,8]     
![1969-12-31 16:00:00.9,9]     
    

== Progress ==
   AdvanceRateManualClock(1)
=> CheckLastBatch: [1969-12-31 16:00:00.0,0],[1969-12-31 16:00:00.1,1],[1969-12-31 16:00:00.2,2],[1969-12-31 16:00:00.3,3],[1969-12-31 16:00:00.4,4],[1969-12-31 16:00:00.5,5],[1969-12-31 16:00:00.6,6],[1969-12-31 16:00:00.7,7],[1969-12-31 16:00:00.8,8],[1969-12-31 16:00:00.9,9]
   StopStream
   StartStream(ProcessingTime(0),org.apache.spark.util.SystemClock@22bc97a,Map(),null)
   AdvanceRateManualClock(2)
   CheckLastBatch: [1969-12-31 16:00:01.0,10],[1969-12-31 16:00:01.1,11],[1969-12-31 16:00:01.2,12],[1969-12-31 16:00:01.3,13],[1969-12-31 16:00:01.4,14],[1969-12-31 16:00:01.5,15],[1969-12-31 16:00:01.6,16],[1969-12-31 16:00:01.7,17],[1969-12-31 16:00:01.8,18],[1969-12-31 16:00:01.9,19]

== Stream ==
Output Mode: Append
Stream state: {org.apache.spark.sql.execution.streaming.sources.RateStreamMicroBatchReader@75b88292: {"0":{"value":-1,"runTimeMs":0}}}
Thread state: alive
Thread stack trace: sun.misc.Unsafe.park(Native Method)
java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)
java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(AbstractQueuedSynchronizer.java:997)
java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1304)
scala.concurrent.impl.Promise$DefaultPromise.tryAwait(Promise.scala:202)
scala.concurrent.impl.Promise$DefaultPromise.ready(Promise.scala:218)
scala.concurrent.impl.Promise$DefaultPromise.ready(Promise.scala:153)
org.apache.spark.util.ThreadUtils$.awaitReady(ThreadUtils.scala:222)
org.apache.spark.scheduler.DAGScheduler.runJob(DAGScheduler.scala:633)
org.apache.spark.SparkContext.runJob(SparkContext.scala:2030)
org.apache.spark.sql.execution.datasources.v2.WriteToDataSourceV2Exec.doExecute(WriteToDataSourceV2.scala:84)
org.apache.spark.sql.execution.SparkPlan$$anonfun$execute$1.apply(SparkPlan.scala:131)
org.apache.spark.sql.execution.SparkPlan$$anonfun$execute$1.apply(SparkPlan.scala:127)
org.apache.spark.sql.execution.SparkPlan$$anonfun$executeQuery$1.apply(SparkPlan.scala:155)
org.apache.spark.rdd.RDDOperationScope$.withScope(RDDOperationScope.scala:151)
org.apache.spark.sql.execution.SparkPlan.executeQuery(SparkPlan.scala:152)
org.apache.spark.sql.execution.SparkPlan.execute(SparkPlan.scala:127)
org.apache.spark.sql.execution.SparkPlan.getByteArrayRdd(SparkPlan.scala:247)
org.apache.spark.sql.execution.SparkPlan.executeCollect(SparkPlan.scala:294)
org.apache.spark.sql.Dataset.org$apache$spark$sql$Dataset$$collectFromPlan(Dataset.scala:3272)
org.apache.spark.sql.Dataset$$anonfun$collect$1.apply(Dataset.scala:2722)
org.apache.spark.sql.Dataset$$anonfun$collect$1.apply(Dataset.scala:2722)
org.apache.spark.sql.Dataset$$anonfun$52.apply(Dataset.scala:3253)
org.apache.spark.sql.execution.SQLExecution$.withNewExecutionId(SQLExecution.scala:77)
org.apache.spark.sql.Dataset.withAction(Dataset.scala:3252)
org.apache.spark.sql.Dataset.collect(Dataset.scala:2722)
org.apache.spark.sql.execution.streaming.MicroBatchExecution$$anonfun$org$apache$spark$sql$execution$streaming$MicroBatchExecution$$runBatch$3$$anonfun$apply$18.apply(MicroBatchExecution.scala:493)
org.apache.spark.sql.execution.SQLExecution$.withNewExecutionId(SQLExecution.scala:77)
org.apache.spark.sql.execution.streaming.MicroBatchExecution$$anonfun$org$apache$spark$sql$execution$streaming$MicroBatchExecution$$runBatch$3.apply(MicroBatchExecution.scala:488)
org.apache.spark.sql.execution.streaming.ProgressReporter$class.reportTimeTaken(ProgressReporter.scala:271)
org.apache.spark.sql.execution.streaming.StreamExecution.reportTimeTaken(StreamExecution.scala:58)
org.apache.spark.sql.execution.streaming.MicroBatchExecution.org$apache$spark$sql$execution$streaming$MicroBatchExecution$$runBatch(MicroBatchExecution.scala:487)
org.apache.spark.sql.execution.streaming.MicroBatchExecution$$anonfun$runActivatedStream$1$$anonfun$apply$mcZ$sp$1.apply$mcV$sp(MicroBatchExecution.scala:143)
org.apache.spark.sql.execution.streaming.MicroBatchExecution$$anonfun$runActivatedStream$1$$anonfun$apply$mcZ$sp$1.apply(MicroBatchExecution.scala:131)
org.apache.spark.sql.execution.streaming.MicroBatchExecution$$anonfun$runActivatedStream$1$$anonfun$apply$mcZ$sp$1.apply(MicroBatchExecution.scala:131)
org.apache.spark.sql.execution.streaming.ProgressReporter$class.reportTimeTaken(ProgressReporter.scala:271)
org.apache.spark.sql.execution.streaming.StreamExecution.reportTimeTaken(StreamExecution.scala:58)
org.apache.spark.sql.execution.streaming.MicroBatchExecution$$anonfun$runActivatedStream$1.apply$mcZ$sp(MicroBatchExecution.scala:131)
org.apache.spark.sql.execution.streaming.ProcessingTimeExecutor.execute(TriggerExecutor.scala:56)
org.apache.spark.sql.execution.streaming.MicroBatchExecution.runActivatedStream(MicroBatchExecution.scala:127)
org.apache.spark.sql.execution.streaming.StreamExecution.org$apache$spark$sql$execution$streaming$StreamExecution$$runStream(StreamExecution.scala:279)
org.apache.spark.sql.execution.streaming.StreamExecution$$anon$1.run(StreamExecution.scala:189)


== Sink ==
0: 


== Plan ==
== Parsed Logical Plan ==
WriteToDataSourceV2 org.apache.spark.sql.execution.streaming.sources.MicroBatchWriter@36f7e778
+- Project [timestamp#421856 AS timestamp#421823, value#421857L AS value#421824L]
   +- StreamingDataSourceV2Relation [timestamp#421856, value#421857L], org.apache.spark.sql.execution.streaming.sources.RateStreamMicroBatchReader@75b88292

== Analyzed Logical Plan ==
WriteToDataSourceV2 org.apache.spark.sql.execution.streaming.sources.MicroBatchWriter@36f7e778
+- Project [timestamp#421856 AS timestamp#421823, value#421857L AS value#421824L]
   +- StreamingDataSourceV2Relation [timestamp#421856, value#421857L], org.apache.spark.sql.execution.streaming.sources.RateStreamMicroBatchReader@75b88292

== Optimized Logical Plan ==
WriteToDataSourceV2 org.apache.spark.sql.execution.streaming.sources.MicroBatchWriter@36f7e778
+- StreamingDataSourceV2Relation [timestamp#421856, value#421857L], org.apache.spark.sql.execution.streaming.sources.RateStreamMicroBatchReader@75b88292

== Physical Plan ==
WriteToDataSourceV2 org.apache.spark.sql.execution.streaming.sources.MicroBatchWriter@36f7e778
+- *(1) DataSourceV2Scan [timestamp#421856, value#421857L], org.apache.spark.sql.execution.streaming.sources.RateStreamMicroBatchReader@75b88292
         
         
	at org.scalatest.Assertions$class.newAssertionFailedException(Assertions.scala:528)
	at org.scalatest.FunSuite.newAssertionFailedException(FunSuite.scala:1560)
	at org.scalatest.Assertions$class.fail(Assertions.scala:1089)
	at org.scalatest.FunSuite.fail(FunSuite.scala:1560)
	at org.apache.spark.sql.streaming.StreamTest$class.failTest$1(StreamTest.scala:430)
	at org.apache.spark.sql.streaming.StreamTest$$anonfun$executeAction$1$18.apply(StreamTest.scala:669)
	at org.apache.spark.sql.streaming.StreamTest$$anonfun$executeAction$1$18.apply(StreamTest.scala:669)
	at scala.Option.foreach(Option.scala:257)
	at org.apache.spark.sql.streaming.StreamTest$class.executeAction$1(StreamTest.scala:668)
	at org.apache.spark.sql.streaming.StreamTest$$anonfun$liftedTree1$1$1.apply(StreamTest.scala:704)
	at org.apache.spark.sql.streaming.StreamTest$$anonfun$liftedTree1$1$1.apply(StreamTest.scala:693)
	at scala.collection.mutable.ResizableArray$class.foreach(ResizableArray.scala:59)
	at scala.collection.mutable.ArrayBuffer.foreach(ArrayBuffer.scala:48)
	at org.apache.spark.sql.streaming.StreamTest$class.liftedTree1$1(StreamTest.scala:693)
	at org.apache.spark.sql.streaming.StreamTest$class.testStream(StreamTest.scala:692)
	at org.apache.spark.sql.execution.streaming.RateSourceV2Suite.testStream(RateSourceV2Suite.scala:34)
	at org.apache.spark.sql.execution.streaming.RateSourceV2Suite$$anonfun$1.apply$mcV$sp(RateSourceV2Suite.scala:66)
	at org.apache.spark.sql.execution.streaming.RateSourceV2Suite$$anonfun$1.apply(RateSourceV2Suite.scala:59)
	at org.apache.spark.sql.execution.streaming.RateSourceV2Suite$$anonfun$1.apply(RateSourceV2Suite.scala:59)

      Attachments

        Issue Links

          blocks

          Umbrella - An overarching type made of sub-tasks SPARK-24139 Fix Flaky Tests

          • Major - Major loss of function.
          • Resolved

          Activity

            People

              Unassigned Unassigned
              vanzin Marcelo Masiero Vanzin
              Votes:
              1 Vote for this issue
              Watchers:
              5 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved: