Почему так работает Stopwatch?

Question

[Jaguar_sea]

Есть вот такой код:

static void Main()
        {
            for (int i = 2; i <= 15; i++)
            {
                Stopwatch timerForRecursiveFactorial = Stopwatch.StartNew();
                int RecursiveFactorial = ComputeFactorialRecursive(i);
                timerForRecursiveFactorial.Stop();
                long ticksSpentOnRecursiveFactorial = timerForRecursiveFactorial.ElapsedTicks;
                Console.WriteLine("Факториал вычеслен рекурсивно. Результат = " + RecursiveFactorial + ". Затрачено " + ticksSpentOnRecursiveFactorial + " тиков");

                Stopwatch timerForInterativeFactorial = Stopwatch.StartNew();
                int IterativeFactorial = ComputeFactorialIterative(i);
                timerForInterativeFactorial.Stop();
                long ticksSpentOnIterativeFactorial = timerForInterativeFactorial.ElapsedTicks;
                Console.WriteLine("Факториал вычеслен итеративно. Результат = " + IterativeFactorial + ". Затрачено " + ticksSpentOnIterativeFactorial + " тиков");

                if (ticksSpentOnIterativeFactorial < ticksSpentOnRecursiveFactorial)
                    Console.WriteLine("Победил итеративный метод");
                else
                    Console.WriteLine("Победил рекурсивный метод");
            }

            Console.ReadKey();
        }

При этом результат получаю вот такой:

Факториал вычеслен рекурсивно. Результат = 2. Затрачено 471 тиков
Факториал вычеслен итеративно. Результат = 2. Затрачено 526 тиков
Победил рекурсивный метод
Факториал вычеслен рекурсивно. Результат = 6. Затрачено 1 тиков
Факториал вычеслен итеративно. Результат = 6. Затрачено 0 тиков
Победил итеративный метод
Факториал вычеслен рекурсивно. Результат = 24. Затрачено 0 тиков
Факториал вычеслен итеративно. Результат = 24. Затрачено 1 тиков
Победил рекурсивный метод
Факториал вычеслен рекурсивно. Результат = 120. Затрачено 1 тиков
Факториал вычеслен итеративно. Результат = 120. Затрачено 1 тиков
Победил рекурсивный метод
Факториал вычеслен рекурсивно. Результат = 720. Затрачено 1 тиков
Факториал вычеслен итеративно. Результат = 720. Затрачено 1 тиков
Победил рекурсивный метод
Факториал вычеслен рекурсивно. Результат = 5040. Затрачено 1 тиков
Факториал вычеслен итеративно. Результат = 5040. Затрачено 0 тиков
Победил итеративный метод
Факториал вычеслен рекурсивно. Результат = 40320. Затрачено 1 тиков
Факториал вычеслен итеративно. Результат = 40320. Затрачено 1 тиков
Победил рекурсивный метод
Факториал вычеслен рекурсивно. Результат = 362880. Затрачено 1 тиков
Факториал вычеслен итеративно. Результат = 362880. Затрачено 0 тиков
Победил итеративный метод

Почему правильное значение тиков я получаю только при первой итерации? Что я сделал не так?

Comments

[Jaguar_sea]

Ссылка на код - rextester.com/live/FMCPJ55540

Answer 1

[Михаил]

Это из-за JIT компилятора, который используется в .NET
Байт-код MSIL переводится в машинный код один раз JIT компилятором и последующее выполнение этого кода намного быстрее, потому что целевой код был сформирован и кэшируются

Comments

[Михаил]

Для тестов можно просто не брать в рассчёт первую итерацию, например

[Михаил]

И ещё можно покопать в сторону RuntimeHelpers.PrepareMethod, для предварительной компиляции

[Дмитрий Ковальский]

С одной стороны вы правы, а с другой какая-то хрень. Вы правы про JIT-компилятор, но это справедливо для каждого отдельного запуска приложения. На разных итерациях одного цикла таких проявлений быть не должно.

[Михаил]

Дмитрий Ковальский: Пробовали вынести 1 stopwatch за цикл, и делать start stop reset?

[Jaguar_sea]

Да, пробовал, не помогает.

[Larry Underwood]

Дмитрий Ковальский: флуктуация +-1 тик для разных итерации вполне допустима.

[Дмитрий Ковальский]

Максим Ванюшкин: Только в приведенном выводе флуктация - 1тик / 470 тиков. Тоже допустимо?

[Larry Underwood]

Дмитрий Ковальский: Вы неправильно поняли, методы ComputeFactorialRecursive и ComputeFactorialIterative скомпилируются в момент обращения к ним, а не при заходе в метод Main, обращение (и компиляция) происходит на первой итерации цикла, поэтому первая итерация долгая

Answer 2

[Станислав Макаров]

Вы что, шутите так время вычисления засекать?) Вы же не на Электронике считаете, несколько итераций/рекурсивных вызовов выполнятся настолько быстро, что вы даже не заметите. Михаил пожалуй назвал вероятную причину такого поведения, но это не отменяет того, что вы плохо ставите эксперимент.

При замере производительности одни и те же вычисления нужно проводить много раз, например по 100 тысяч раз на каждый вариант, а то и по миллиону. Тогда вы получите более-менее внятный результат для сравнения, и не будете натыкаться на всякие тонкости работы CLR.

Answer 3

[nirvimel]

Все правильно. ElapsedTicks показывает количество тиков таймера, но таймер не успевает тикнуть ни разу за время вычисления факториала или случайно происходит один тик. В первой итерации проходит много сотен тиков, так как при первом вызове работает компилятор JIT, время работы откомпилированного кода ничтожно по сравнению со временем компиляции.
Что делать:

1. Выполнять вызов измеряемой функции в цикле с глубиной в десятки или сотни тысяч итераций и делить полученный интервал на количество итераций. Точный подбор количества осуществляется вручную так, чтобы общая продолжительность всего теста составила несколько секунд.
   
2. Перед первым реальным замером необходимо сделать "прогрев" - несколько десятков тысяч итераций в холостую без замеров.
   

Answer 4

[Виталий Пухов]

Довольно странно, код выглядит правильным, в качестве "костыля" могу посоветовать делать reset обоих stopwatch периодически

Comments

[Jaguar_sea]

не. Не помогает.

[Jaguar_sea]

Помогает добавление Thread.Sleep(1); после выполнения каждого метода. Но я честно говоря не уверен что это можно применять хотя бы в качестве костыля.

Answer 5

[Дмитрий Ковальский]

А вы поставьте бряку на начало цикла и смотрите состояние объектов на каждой итерации. Так же проверьте что весь код на каждой итерации выполняется.

Comments

[Jaguar_sea]

Да, бряка дает нужный эффект. Т.е. на каждой итерации значения тиков такие, какие и должны быть.

[Дмитрий Ковальский]

Jaguar_sea: Бряка не останавливает секундомер. Так что то что вы считаете багом - по прежнему баг