Проблема .NET System.Diagnostics.Stopwatch (возвращает слишком низкие значения)

На моем компьютере секундомер возвращает слишком низкие значения. Например, 200 мс, когда я указал Thread.Sleep(1000). Программа должна ждать 1 секунду. Я также тестировал ManualResetEvent.WaitOne(1000) и получил те же результаты. И фреймворк 2.0, и 3.0 демонстрируют такое странное поведение. Я использую Windows XP SP3 с .NET Framework 3.5 SP1.

Вот результат моих тестов (код ниже):

1000 ms for DateTime.Now.Ticks
0201 ms for Stopwatch.ElapsedTicks
0142 ms for Stopwatch.ElapsedMilliseconds
0139 ms for Stopwatch.ElapsedTicks after Reset
0264 ms for Stopwatch.ElapsedTicks setting ThreadAffinity
0151 ms for Stopwatch.ElapsedTicks setting ProcessorAffinity (and more)
0371 ms for Stopwatch.ElapsedTicks with Syncronized object
Done!

// Файл Program.cs

class Program
{
    static void Main(string[] args)
    {
        StopWatchTest.Go();
        Console.WriteLine("Done!");
        Console.ReadLine();
    }
}

// Класс StopWatchTest.cs

internal static class StopWatchTest
{
    public const int SleepTime = 1000;

    public static void Go()
    {
        #region Test #0 with DateTime.Now.Ticks
        long startTick = DateTime.Now.Ticks;
        Thread.Sleep(SleepTime);
        long stopTick = DateTime.Now.Ticks;
        long elapsedDt = (stopTick - startTick) * 100;
        Display((int)(elapsedDt / 1000 / 1000), "DateTime.Now.Ticks");
        #endregion Test #0 with DateTime.Now.Ticks

        Stopwatch watch = Stopwatch.StartNew();
        long frequency = Stopwatch.Frequency;
        double nanosecPerTick = (1000.0 * 1000.0 * 1000.0) / frequency;

        #region Test #1 with Stopwatch.ElapsedTicks
        startTick = watch.ElapsedTicks;
        Thread.Sleep(SleepTime);
        stopTick = watch.ElapsedTicks;
        double elapsedSw = (stopTick - startTick) * nanosecPerTick;
        Display((int)(elapsedSw / 1000 / 1000), "Stopwatch.ElapsedTicks");
        #endregion Test #1 with Stopwatch.ElapsedTicks

        #region Test #2 with Stopwatch.ElapsedMilliseconds
        startTick = watch.ElapsedMilliseconds;
        Thread.Sleep(SleepTime);
        stopTick = watch.ElapsedMilliseconds;
        Display((int)(stopTick - startTick), "Stopwatch.ElapsedMilliseconds");
        #endregion Test #2 with Stopwatch.ElapsedMilliseconds

        #region Test #3 with Stopwatch.ElapsedTicks after Reset
        watch.Stop();
        watch.Reset();
        watch.Start();
        startTick = watch.ElapsedTicks;
        Thread.Sleep(SleepTime);
        stopTick = watch.ElapsedTicks;
        elapsedSw = (stopTick - startTick) * nanosecPerTick;
        Display((int)(elapsedSw / 1000 / 1000), "Stopwatch.ElapsedTicks after Reset");
        #endregion Test #3 with Stopwatch.ElapsedTicks after Reset

        #region Test #4 with Stopwatch.ElapsedTicks and ThreadAffinity
        Thread.BeginThreadAffinity();
        startTick = watch.ElapsedTicks;
        Thread.Sleep(SleepTime);
        stopTick = watch.ElapsedTicks;
        elapsedSw = (stopTick - startTick) * nanosecPerTick;
        Display((int)(elapsedSw / 1000 / 1000), "Stopwatch.ElapsedTicks setting ThreadAffinity");
        Thread.EndThreadAffinity();
        #endregion Test #4 with Stopwatch.ElapsedTicks and ThreadAffinity

        #region Test #5 with Stopwatch.ElapsedTicks and ProcessorAffinity (and more)
        const int affinity = 0x0001;
        Process proc = Process.GetCurrentProcess();
        proc.ProcessorAffinity = new IntPtr(affinity);
        proc.PriorityClass = ProcessPriorityClass.High;
        ProcessThreadCollection ptc = proc.Threads;
        foreach (ProcessThread pt in ptc)
        {
            pt.IdealProcessor = 0;
            pt.ProcessorAffinity = new IntPtr(affinity);
        }
        Thread.CurrentThread.Priority = ThreadPriority.Highest;

        startTick = watch.ElapsedTicks;
        Thread.Sleep(SleepTime);
        stopTick = watch.ElapsedTicks;
        elapsedSw = (stopTick - startTick) * nanosecPerTick;
        Display((int)(elapsedSw / 1000 / 1000), "Stopwatch.ElapsedTicks setting ProcessorAffinity (and more)");
        #endregion Test #5 with ProcessorAffinity and more

        #region Test #6 with Syncronized object
        elapsedSw = new SyncTimer().Go();
        Display((int)(elapsedSw / 1000 / 1000), "Stopwatch.ElapsedTicks with Syncronized object");
        #endregion Test #6 with Syncronized object
    }

    private static void Display(int milliseconds, string testName)
    {
        Console.WriteLine("{0:0000} ms for {1}", milliseconds, testName);
    }
}

[Synchronization]
internal class SyncTimer : ContextBoundObject
{
    [MethodImpl(MethodImplOptions.Synchronized)]
    public double Go()
    {
        Stopwatch.StartNew();
        long frequency = Stopwatch.Frequency;
        double nanosecPerTick = (1000.0 * 1000.0 * 1000.0) / frequency;

        long startTick = Stopwatch.GetTimestamp();
        Thread.Sleep(StopWatchTest.SleepTime);
        long stopTick = Stopwatch.GetTimestamp();
        return (stopTick - startTick) * nanosecPerTick;
    }
}

person Ducharme    schedule 25.02.2011    source источник
comment
@ user633578, в вашем коде ошибка. Вы должны использовать один экземпляр секундомера для каждого теста.   -  person acoolaum    schedule 25.02.2011
comment
Я не видел никаких ограничений относительно повторного использования одного и того же экземпляра Stopwatch. Кстати, первый тест не дает верного значения.   -  person Ducharme    schedule 25.02.2011
comment
У меня такая же проблема. Вы нашли причину? Мое измеренное время составляет половину реального времени.   -  person Michel    schedule 13.04.2011
comment
Мой секундомер тоже ведет себя странно. Я получаю правильный результат в ElapsedMilliseconds, но ElapsedTicks, кажется, дает около 2500 тиков / мс. Я предполагаю, что ElapsedTicks в основном недействителен.   -  person Kendall Frey    schedule 11.01.2012
comment
@KendallFrey: Нет, просто используется галочка другого размера. Сравните TimeSpan.TicksPerSecond с Stopwatch.Frequency. Различные размеры галочки четко указаны в разделе Секундомер. .ElapsedTicks, выделенный желтым.   -  person Allon Guralnek    schedule 05.06.2012


Ответы (7)


Взгляните на следующие ссылки:

https://connect.microsoft.com/VisualStudio/feedback/details/94083/stopwatch-returns-negative-elapsed-time

System.Diagnostics.Stopwatch возвращает отрицательные числа в свойствах Elapsed ...

Кажется, есть проблема с точностью секундомера, которая может привести к тому, что он вернет отрицательное прошедшее время, а также сильно различающееся время. Если вы посмотрите на проблему с подключением, большинство людей говорят о том, что видят проблему на виртуальной машине, и именно здесь мы наблюдаем проблему с отрицательными значениями Elapsed.

Глядя на документ QueryPerformanceCounter, кажется чтобы подразумевать, что эта проблема может произойти в многопроцессорных системах из-за ошибок BIOS или уровня аппаратной абстракции, но не дает дополнительной информации и не касается виртуализированных машин.

Что касается решения этой проблемы ... Я не нашел его во многих поисковых запросах. Вы можете игнорировать значения меньше нуля, что не идеально, но в некоторых случаях возможно. Но это не решает вашу проблему - как узнать, какие значения недействительны?

Надеюсь, это немного поможет.

person Niall Connaughton    schedule 27.10.2011

Я знаю, что это старый вопрос, но я подумал, что предоставлю свои 2 цента после того, как боролся с той же проблемой:

Я начал смотреть на частоту, предложенную @AllonGuralnek, и она показала точное время в секундах, но снизила оставшиеся миллисекунды, которые я также хотел зафиксировать.

В любом случае, после долгих перемоток взад и вперед я заметил, что sw.Elapsed имеет свойство Ticks, и оно предоставило мне точное количество тиков, а после обратного преобразования оно предоставило мне точное время.

С точки зрения кода, вот что у меня получилось:

Stopwatch sw = new Stopwatch();
sw.Start();

... DO WORK

sw.Stop();

long elapsedTicks = sw.Elapsed.Ticks;
Debug.WriteLine(TimeSpan.FromTicks(elapsedTicks).ToString());

При запуске теста вызов:

  • sw.Elapsed.ToString() : "00:00:11.6013029"

  • sw.ElapsedTicks: возвращает «40692243» и преобразует его в «00: 00: 04.0692243» при вызове TimeSpan.FromTicks(sw.ElapsedTicks).ToString(), который является неточным.

  • sw.Elapsed.Ticks: возвращает «116013029» и преобразует его в «00: 00: 11.6013029» при вызове TimeSpan.FromTicks(sw.Elapsed.Ticks).ToString(), который точен.

Хотя мне может чего-то не хватать, я чувствую, что не имеет смысла, что sw.ElaspedTicks возвращает другое значение, чем sw.Elapsed.Ticks, поэтому, если кто-то хочет пролить свет на это, сделайте это, пожалуйста, но с моей точки зрения , Я считаю это ошибкой, а если нет, то, по крайней мере, кажется, что это очень непоследовательно !.

ПРИМЕЧАНИЕ: вызов sw.ElapsedTicks / Stopwatch.Frequency возвращает 11 (то есть секунды), но, как я уже сказал, он отбрасывает миллисекунды, которые мне не нужны.

person Thierry    schedule 19.01.2017

Получил вот что:

1000 ms for DateTime.Now.Ticks
0999 ms for Stopwatch.ElapsedTicks
1000 ms for Stopwatch.ElapsedMilliseconds
0999 ms for Stopwatch.ElapsedTicks after Reset
0999 ms for Stopwatch.ElapsedTicks setting ThreadAffinity
0999 ms for Stopwatch.ElapsedTicks setting ProcessorAffinity (and more)

(Не удалось запустить последний тест)

На машине с четырехъядерным процессором i7 с .NET4 в Linqpad.

Я обычно использую только Stopwatch.ElapsedMilliseconds, но никогда не видел в этом ничего странного. Похоже, что что-то сломалось в вашей машине или платформе виртуализации.

person Will Dean    schedule 25.02.2011
comment
Большое Вам спасибо. Многие люди добиваются тех же результатов, что и вы. Следующий шаг: выяснить, что сломано и как это исправить ... - person Ducharme; 25.02.2011

Похоже, в некоторых случаях вы используете счетчик тиков. Помните, что по умолчанию, например, в современной Windows ОС экономит процессор. Это означает, что количество тиков и прошедшее время не находятся в линейной пропорции.

Я предлагаю вам попробовать использовать Stopwatch.ElapsedMilliseconds в самой простой форме:

var sw = new Stopwatch();
sw.Start();
Thread.Sleep(1000);
var elpased = sw.Elapsed;
person Wernight    schedule 25.02.2011
comment
Не повезло! В моем тесте он возвращает 127 мс. ‹Br /› 1000 мс для DateTime.Now.Ticks ‹br /› 0127 мс для секундомера. Истекло ‹br /› Готово! ‹code› Секундомер sw = new Секундомер(); sw.Start (); Thread.Sleep (1000); Display ((int) sw.Elapsed.TotalMilliseconds, Stopwatch.Elapsed); - person Ducharme; 25.02.2011
comment
Вы работаете на виртуальной машине? Обеспечивает ли хост гостевой машины максимальную производительность ЦП в панели управления? - person Wernight; 25.02.2011
comment
Если да, то пропорционально ли возвращаемое значение времени сна? - person Wernight; 25.02.2011

Если секундомер не работает, вы можете использовать QueryPerformanceCounter в Windows.

См. Этот небольшой класс на http://www.windojitsu.com/code/hirestimer.cs.html

person Wernight    schedule 25.02.2011
comment
Тот же результат. Я провожу несколько тестов после того, как убиваю как можно больше процессов на компьютере. Может кто-то из них меняет системные часы ... - person Ducharme; 25.02.2011
comment
Класс Stopwatch реализуется с помощью P / Invoke для вызова собственной функции QueryPerformanceCounter, и выполнение этого самостоятельно вместо использования класса Stopwatch не должно иметь никакого значения. - person Martin Liversage; 17.04.2013
comment
@Martin: Я так и не узнал, почему на этой машине (которая была настроена корпорацией путем копирования файлов и настроек реестра) секундомер был неправильным на милю. - person Wernight; 26.04.2013

Вы можете использовать этот код, чтобы исправить проблему с методом Stopwatch.Elapsed:

using System;
using System.Diagnostics;

namespace HQ.Util.General
{
    public static class StopWatchExtension
    {
        public static TimeSpan ToTimeSpan(this Stopwatch stopWatch)
        {
            return TimeSpan.FromTicks(stopWatch.ElapsedTicks);
        }
    }
}

Использование:

using HQ.Util.General;

Debug.Print($"Elapsed millisec: { stopWatch.ToTimeSpan().TotalMilliseconds}");
person Eric Ouellet    schedule 19.03.2018

Думаю, вы найдете здесь ответ: http://social.msdn.microsoft.com/Forums/en-US/netfxbcl/thread/eec73d6e-f597-4342-be48-5d2ce30202f0/

но для получения дополнительных сведений и объяснений см. также: http://msdn.microsoft.com/en-us/magazine/cc163996.aspx http://stackoverflow.com/questions/394020/stopwatch-accuracy http://msdn.microsoft.com/en-us/library/system.diagnostics.stopwatch.aspx

person Elroy Flynn    schedule 25.02.2011
comment
Упомянутые вами ссылки касаются точности разрешения счетчиков. Моя проблема не в том, что класс дает несколько миллисекунд больше, чем ожидалось, а в том, что у него намного меньше! Полезен только раздел ПРИМЕЧАНИЕ в MSDN, и я тестировал с помощью ProcessThread.ProcessorAffinity, как это было предложено Microsoft. - person Ducharme; 25.02.2011
comment
Я нашел эту статью support.microsoft.com/kb/896256 и проверил версию библиотеки на своем компьютер. Это 5.1.2600.6055, более поздняя, ​​чем в патче (5.1.2600.3023). Я добавил раздел реестра [HKEY_LOCAL_MACHINE \ SYSTEM \ CurrentControlSet \ Control \ Session Manager \ Throttle] и снова провел тесты с PerfEnablePackageIdle = dword: 00000000 и PerfEnablePackageIdle = dword: 00000001 (после каждой перезагрузки компьютера). У меня такие же результаты ... - person Ducharme; 25.02.2011