矛盾的计时功能(Paradoxal timing functions)

 我有一个函数来计算块中花费的时间： 
 
import collection.mutable.{Map => MMap}
var timeTotalMap = MMap[String, Long]()
var numMap = MMap[String, Float]()
var averageMsMap = MMap[String, Float]()
def time[T](key: String)(block: =>T): T = {
  val start = System.nanoTime()
  val res = block
  val total = System.nanoTime - start
  timeTotalMap(key) = timeTotalMap.getOrElse(key, 0L) + total
  numMap(key) = numMap.getOrElse(key, 0f) + 1
  averageMsMap(key) = timeTotalMap(key)/1000000000f/numMap(key)
  res
}
 
 我正在计算一个函数以及在一个地方调用它的地方。 
 
time("outerpos") { intersectPos(a, b) }
 
 并且函数本身以： 
 
def intersectPos(p1: SPosition, p2: SPosition)(implicit unify: Option[Identifier] =None): SPosition
    = time("innerpos") {(p1, p2) match {
   ...
}
 
 当我为每个键显示纳米时间（ timeTotalMap ）时，我得到（为lisibility添加空格） 
 
outerpos->  37 870 034 714
innerpos->      53 647 956
 
 这意味着innerpos的总执行时间比外包的总执行时间少1000。 
 
 什么 ！ 两者之间有一个因素1000？ 它说外部呼叫比所有内部功能多花费1000倍？ 我错过了什么，或者某处是否存在泄漏鬼魂？ 
 
 更新 
 
 当我比较每个块的执行次数（ numMap ）时，我发现以下内容： 
 
outerpos -> 362878
innerpos -> 21764
 
 这是矛盾的。 即使在其他地方调用intersectPos ，它的调用次数是否应该与外部调用的次数一样大？ 
 
 编辑 
 
 如果我将行numMap(key) = numMap.getOrElse(key, 0f) + 1到时间函数的顶部，那么这些数字大致相等。 

I have a function to compute the time spent in a block:
 
import collection.mutable.{Map => MMap}
var timeTotalMap = MMap[String, Long]()
var numMap = MMap[String, Float]()
var averageMsMap = MMap[String, Float]()
def time[T](key: String)(block: =>T): T = {
  val start = System.nanoTime()
  val res = block
  val total = System.nanoTime - start
  timeTotalMap(key) = timeTotalMap.getOrElse(key, 0L) + total
  numMap(key) = numMap.getOrElse(key, 0f) + 1
  averageMsMap(key) = timeTotalMap(key)/1000000000f/numMap(key)
  res
}
 
I am timing a function and the place where it is called in one place.
 
time("outerpos") { intersectPos(a, b) }
 
and the function itself starts with:
 
def intersectPos(p1: SPosition, p2: SPosition)(implicit unify: Option[Identifier] =None): SPosition
    = time("innerpos") {(p1, p2) match {
   ...
}
 
When I display the nano times for each key (timeTotalMap), I get (added spaces for lisibility)
 
outerpos->  37 870 034 714
innerpos->      53 647 956
 
It means that the total execution time of innerpos is 1000 less than the one of outerpos.
 
What ! there is a factor 1000 between the two ? And its says that the outer call takes 1000x more time than all the inner functions? am I missing something or is there a memory leaking ghost somewhere ?
 
Update
 
When I compare the number of execution for each block (numMap), I find the following:
 
outerpos -> 362878
innerpos -> 21764
 
This is paradoxal. Even if intersectPos is called somewhere else, shouldn't the number of times it is called be as great as the number of times outerpos is called?
 
EDIT
 
If I move the line numMap(key) = numMap.getOrElse(key, 0f) + 1 to the top of the time functinon, then these numbers become approximately equal.

原文：https://stackoverflow.com/questions/21241079