временных функций парадоксальных

Question

У меня есть функция, чтобы вычислить время, проведенное в блоке:

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 

It означает, что общее время выполнения innerpos на 1000 меньше, чем у outpospos.

Что! между ними есть коэффициент 1000? И в нем говорится, что внешний вызов занимает в 1000 раз больше времени, чем все внутренние функции? я что-то упускаю или там где-то есть утечка памяти?

Update

Когда я сравниваю количество выполнения для каждого блока (numMap), я нахожу следующее:

outerpos -> 362878 
innerpos -> 21764 

Это парадоксальное. Даже если intersectPos вызывается где-то в другом месте, не должно ли количество раз, когда оно вызывается, так же велико, как количество раз, когда вызывается наружное слово?

EDIT

Если переместить линию numMap(key) = numMap.getOrElse(key, 0f) + 1 в верхней части времени functinon, то эти цифры становятся примерно равными.

Answer 1

nanoTime на JVM считается безопасным, но не очень точным. Вот некоторые хорошо читает:

Is System.nanoTime() completely useless?

System.currentTimeMillis vs System.nanoTime

В основном ваш тест будет страдать от неточностей таймера. Один из способов обойти это можно было бы назвать time("outerpos") в течение довольно долгого времени (обратите внимание, что оптимизация компилятора JIT может наступить в какой-то момент) и измерять время начала и окончания только один раз. Возьмите среднее и повторите с time("innerpos"). Это все, о чем я мог думать. Все еще не лучший тест когда-либо;)