This page is no longer maintained — Please continue to the home page at www.scala-lang.org

Strange behavior - closures

No replies
Jacques Lemieux
Joined: 2011-10-11,
User offline. Last seen 42 years 45 weeks ago.

Hello all mystery lovers --

I have this small program (also available at https://gist.github.com/1665557)
:

object Strange {

def fmt(x: Double) = x.formatted("%.2f")

def run(f: => Any) = {
val n = 100000000L
val start = System.nanoTime
var i = 0L
while (i < n) {
f
i += 1
}
val stop = System.nanoTime
val delta = (stop - start).toDouble / 1000000000.0
val perSecond = n.toDouble / delta
val millionsPerSecond = perSecond / 1000000.0
println(fmt(millionsPerSecond) + " millions per second (for " +
fmt(delta) + " seconds).")
}

def main(args: Array[String]) = {
args match {
case Array("A") =>
for (i <- 0 until 12) {
run(1 + 1)
}
case Array("B") =>
for (i <- 0 until 6) {
run(1 + 1)
run(1 + 1)
}
case Array("C") =>
for (i <- 0 until 4) {
run(1 + 1)
run(1 + 1)
run(1 + 1)
}
case Array("D") =>
run(1 + 1)
run(1 + 1)
run(1 + 1)
run(1 + 1)
run(1 + 1)
run(1 + 1)
run(1 + 1)
run(1 + 1)
run(1 + 1)
run(1 + 1)
run(1 + 1)
run(1 + 1)
case Array("E") =>
def go = run(1 + 1)
go
go
go
go
go
go
go
go
go
go
go
go
case _ =>
println("Bad input, use A, B, C, D or E.")
}
}
}

I have these results at run-time :

$ scala Strange.scala A
1324,58 millions per second (for 0,08 seconds).
1357,07 millions per second (for 0,07 seconds).
1575,40 millions per second (for 0,06 seconds).
1579,85 millions per second (for 0,06 seconds).
1503,44 millions per second (for 0,07 seconds).
1575,36 millions per second (for 0,06 seconds).
1569,68 millions per second (for 0,06 seconds).
1541,08 millions per second (for 0,06 seconds).
1569,34 millions per second (for 0,06 seconds).
1570,11 millions per second (for 0,06 seconds).
1575,27 millions per second (for 0,06 seconds).
1577,83 millions per second (for 0,06 seconds).

$ scala Strange.scala B
1402,80 millions per second (for 0,07 seconds).
1345,69 millions per second (for 0,07 seconds).
1565,10 millions per second (for 0,06 seconds).
1575,55 millions per second (for 0,06 seconds).
1505,24 millions per second (for 0,07 seconds).
1571,79 millions per second (for 0,06 seconds).
1568,71 millions per second (for 0,06 seconds).
1563,86 millions per second (for 0,06 seconds).
1569,26 millions per second (for 0,06 seconds).
1533,93 millions per second (for 0,07 seconds).
1523,18 millions per second (for 0,07 seconds).
1428,25 millions per second (for 0,07 seconds).

$ scala Strange.scala C
1425,62 millions per second (for 0,07 seconds).
1340,70 millions per second (for 0,07 seconds).
341,66 millions per second (for 0,29 seconds).
215,57 millions per second (for 0,46 seconds).
394,21 millions per second (for 0,25 seconds).
209,61 millions per second (for 0,48 seconds).
225,85 millions per second (for 0,44 seconds).
242,30 millions per second (for 0,41 seconds).
240,44 millions per second (for 0,42 seconds).
242,94 millions per second (for 0,41 seconds).
241,68 millions per second (for 0,41 seconds).
242,52 millions per second (for 0,41 seconds).

$ scala Strange.scala D
1353,19 millions per second (for 0,07 seconds).
1231,97 millions per second (for 0,08 seconds).
343,77 millions per second (for 0,29 seconds).
215,23 millions per second (for 0,46 seconds).
311,08 millions per second (for 0,32 seconds).
208,06 millions per second (for 0,48 seconds).
233,26 millions per second (for 0,43 seconds).
240,24 millions per second (for 0,42 seconds).
240,23 millions per second (for 0,42 seconds).
240,53 millions per second (for 0,42 seconds).
240,55 millions per second (for 0,42 seconds).
239,52 millions per second (for 0,42 seconds).

$ scala Strange.scala E
1464,00 millions per second (for 0,07 seconds).
1262,13 millions per second (for 0,08 seconds).
1578,35 millions per second (for 0,06 seconds).
1574,25 millions per second (for 0,06 seconds).
1562,67 millions per second (for 0,06 seconds).
1569,63 millions per second (for 0,06 seconds).
1568,51 millions per second (for 0,06 seconds).
1569,95 millions per second (for 0,06 seconds).
1554,14 millions per second (for 0,06 seconds).
1416,29 millions per second (for 0,07 seconds).
1429,69 millions per second (for 0,07 seconds).
1545,42 millions per second (for 0,06 seconds).

For every test case A to E, 12 calls to "run(1 + 1) are made. At each
call of "run", I compute the execution time of 100,000,000 calls to
the by-name expression "f", here "1 + 1".

I do not understand why I do not get identical execution times for
every test case. Calling "run(1+1)" twice in a loop that is executed 6
times (case B) should be exactly the same as calling "run(1+1) three
times in a loop that is executed 4 times (case C). In both cases, the
call to "run(1+1) is performed 12 times. Even stranger is the
difference of timings between test cases D and E.

Does anyone have an explanation for this strange behavior?

Note that the behavior is the same whether I use the closure notation
"run (() => 1 + 1)" or the call-by-name notation "run(1 + 1)".

Many thanks!

Jacques

Copyright © 2012 École Polytechnique Fédérale de Lausanne (EPFL), Lausanne, Switzerland