0

This code is a simplification of other code that does useful things. To track progress of a loop, I am accumulating a volatile var count inside the loop and reporting the value of the count using a scheduled thread from Java concurrent.

def foo {
  import java.util.concurrent._
  @volatile var count = 0l
  val reportRunner = new Runnable { def run() = println(s"report=$count") }
  val scheduledExecutorService = Executors.newSingleThreadScheduledExecutor()
  val reportRunnerHandle = scheduledExecutorService.scheduleAtFixedRate(reportRunner, 0,1000,TimeUnit.MILLISECONDS)

  val l = Stream.fill(100000000)(0)
  println(s"start count=$count")

  for(i <- 0 until l.size) {
    count = count + 1
  }

  println(s"end count=$count")

  reportRunnerHandle.cancel(true)
  scheduledExecutorService.shutdown()
}

It produced the following output for me:

report=0
start count=0
report=0
report=0
report=0
report=0
report=0
report=0
report=0
report=0
report=0
report=0
report=0
report=0
report=0
report=0
report=0
report=0
report=0
report=0
report=0
report=0
report=0
report=0
report=0
report=0
report=0
report=0
report=60019827
end count=100000000

Each of the report prints are suppose to occur every second but instead they occur in bursts and have the same count when they do. Feels like there is some fundamental JVM concurrency issue I am missing here. Or perhaps there are more reliable ways to do this besides ScheduledExecutorService?

Also not shown here, but I have tried this same code using AtomicLong and using Actors to accumulate the count instead of a volatile but I get the same results which makes me suspect the ScheduledExecutorService.

Lance Gatlin
  • 193
  • 2
  • 9
  • It behaves as expected for me if I use `while (true) { count = count + 1}`. I get a updates every second. Can you try using an iterator instead of a stream? – huynhjl Jul 18 '13 at 05:53

1 Answers1

1

You're doing something very weird with your loop. Almost all the time will be taken in the l.size call, as that is when the stream will be created (you need a fully-created stream to know its size). Then the loop itself will zip through really fast without referencing the stream at all, now that it knows the upper bound. And you probably have all sorts of garbage collection issues from allocating so much memory (in particular, the GC probably has to traverse the entire stream every time, and you're probably using a stop-the-world collector).

Try something like

@volatile var count = 0L
var accum = 0.0
for (i <- 0 until 1000000000) {
  accum += math.tan(i)
  count += 1
}

to get a loop that progresses at a steady (but not terribly fast) rate.

Rex Kerr
  • 166,841
  • 26
  • 322
  • 407
  • Thank you for your response! Yes, I understand the loop is "weird". In other code this loop does useful work, but I simplified here to the shortest form that reproduces the issue. Even if the loop is spending most of its time in l.size, the report running in a separate thread should fire once a second and not burst with what appears to be an invalid count as it does. – Lance Gatlin Jul 17 '13 at 14:05
  • The usage of stream is completely optional. It was an attempt to isolate memory issues. Stream can be replaced with any other collection and the same result will happen. – Lance Gatlin Jul 17 '13 at 14:14
  • @lancegatlin - Why don't you turn GC reporting on? `-verbose:gc -XX:+PrintGCTimeStamps -XX:+PrintGCDetails` or somesuch. Or turn on incremental GC: `-Xincgc`. GC supersedes all threaded activity, normally. So "once a second" is "once a second unless I'm doing GC" to the JVM. And 100M elements can make for expensive GC. – Rex Kerr Jul 17 '13 at 14:45
  • Thanks I will try that! I've read other places JVM not so great for real-time apps, but is there anyway that you know of to get a real-time report even with frequent GC? – Lance Gatlin Jul 17 '13 at 15:50
  • @lancegatlin - Look up "concurrent mark sweep garbage collector", which I think is what `-Xincgc` is these days. It greatly reduces the duration of pauses even if it doesn't eliminate them. – Rex Kerr Jul 17 '13 at 17:07