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

Strange behavior - by name

2 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?

Many thanks!

Jacques

extempore
Joined: 2008-12-17,
User offline. Last seen 35 weeks 3 days ago.
Re: Strange behavior - by name


On Tue, Jan 24, 2012 at 1:26 PM, jrlemieux <jacques [dot] lemieux [at] gmail [dot] com> wrote:
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.

The list of reasons these scenarios are not the same could literally fill a book.
You should do at least these things, at length:

 - examine the generated bytecode - read about how not to write a microbenchmark The presence of all these classes is a strong indicator everything is not the same:
Strange$$anonfun$go$1$1.classStrange$$anonfun$main$1$$anonfun$apply$mcVI$sp$1.classStrange$$anonfun$main$1.classStrange$$anonfun$main$10.classStrange$$anonfun$main$11.class Strange$$anonfun$main$12.classStrange$$anonfun$main$13.classStrange$$anonfun$main$14.classStrange$$anonfun$main$15.classStrange$$anonfun$main$2$$anonfun$apply$mcVI$sp$2.class Strange$$anonfun$main$2$$anonfun$apply$mcVI$sp$3.classStrange$$anonfun$main$2.classStrange$$anonfun$main$3$$anonfun$apply$mcVI$sp$4.classStrange$$anonfun$main$3$$anonfun$apply$mcVI$sp$5.class Strange$$anonfun$main$3$$anonfun$apply$mcVI$sp$6.classStrange$$anonfun$main$3.classStrange$$anonfun$main$4.classStrange$$anonfun$main$5.classStrange$$anonfun$main$6.class Strange$$anonfun$main$7.classStrange$$anonfun$main$8.classStrange$$anonfun$main$9.classStrange$.classStrange.class
Finally, this is a scala-user question: please leave scala-internals free for discussion of the scala implementation.
Emmanuel Castro
Joined: 2012-01-25,
User offline. Last seen 42 years 45 weeks ago.
Re: Strange behavior - by name

I've noted that the Java Server VM is able to remove small parts of
code that has no side effect when its result is not used, as it is the
case with your "1 + 1".
The Java Server VM is automatically selected if your machine has a big
memory and many cores, which is very common.

I guess that in your case, the 1+1 is not executed at all.

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