С++ std::chrono дает неправильный вывод в собственном примере

Поэтому я использовал класс профилировщика времени (см. Ниже). До какого-то момента он работал безупречно (под неработающим я подразумеваю, что я подозревал, что он выводит странные значения). Затем я создал новый пустой проект с нуля и скопировал пример отсюда: http://en.cppreference.com/w/cpp/chrono/duration/duration_cast. Вместо этого теперь он печатает 1014, когда явно должно быть 1000, точно так же, как это делалось до вчерашнего дня! Еще раз, тот же пример из приведенной выше ссылки работал до вчерашнего дня. Я понятия не имею, что произошло. Я перезапустил свою машину, но она все еще не работала.

Вот класс профилировщика времени:

#pragma once

#include <stdio.h>
#include <time.h>
#include <chrono> // C++11
#include <thread>
#include <string>

namespace profiler
{
// The time profiling class
class Time
{
public:
    Time(const std::string& str) 
        : m_str(str), m_start(std::chrono::system_clock::now()) { }

    virtual ~Time()
    {
        auto end = std::chrono::system_clock::now();
        auto duration = std::chrono::duration_cast<std::chrono::milliseconds>(end - m_start).count();

        printf("%s took %lli milliseconds\n", m_str.empty() ? "Block" : m_str.c_str(), duration);
    }

private:
    std::string m_str;
    std::chrono::system_clock::time_point m_start;
};
}

#ifdef _DEBUG
// Profile only if debugging. This profiles the time spent to process the block that this macro was called within
#ifndef TIME
#define TIME(str) profiler::Time timer__(str)
#endif // TIME
#else
// If not debugging, do nothing
#ifndef TIME
#define TIME(str) do { } while(0) // This avoids empty statements
#endif // TIME
#endif // _DEBUG

#ifndef SLEEP
#define SLEEP(ms) std::this_thread::sleep_for(std::chrono::milliseconds(ms));
#endif

// A working example of this profiler. Call EXAMPLE() and it should print 16 milliseconds
#ifndef EXAMPLE
#define EXAMPLE() \
    profiler::Time timer__("Example that takes 16 milliseconds (value should match)"); \
    std::this_thread::sleep_for(std::chrono::milliseconds(1)); \
    std::this_thread::sleep_for(std::chrono::milliseconds(2)); \
    std::this_thread::sleep_for(std::chrono::milliseconds(3)); \
    std::this_thread::sleep_for(std::chrono::milliseconds(10));
#endif

Вот код использования:

#include <stdio.h>
#include <chrono>
#include <thread>

int main()
{
    auto start = std::chrono::system_clock::now();

    std::this_thread::sleep_for(std::chrono::seconds(1));

    auto end = std::chrono::system_clock::now();
    auto duration = std::chrono::duration_cast<std::chrono::milliseconds>(end - start).count();

    printf("Block took %lli milliseconds\n", duration); 

    return getchar();
}

Я использую Visual Studio Ultimate 2012 в 64-разрядной версии Windows 7 Professional, если это поможет.


person Henri    schedule 20.10.2015    source источник
comment
Скриншот: postimg.org/image/7otdsxhnh   -  person Henri    schedule 20.10.2015
comment
Он работает, как и ожидалось. Здесь нужно учитывать 2 вещи. Во-первых, sleep_for будет спать в течение по крайней мере указанного времени ожидания. Есть также время, затраченное до и после метода сна.   -  person wendelbsilva    schedule 20.10.2015
comment
@wendelbsilva Я знаю, что эта функция сна может быть не очень точной и что SO может немного мешать, но я очень верю, что что-то не так. Я использовал его для измерения времени, затрачиваемого на разбор некоторого файла. Раньше среднее значение составляло от 10 до 15 миллисекунд, однако СЕЙЧАС иногда выводится НОЛЬ! Теперь этот синтаксический анализ не занимает 0 миллисекунд. Это так странно, что он даже печатает 15 миллисекунд, как раньше, а иногда и 0.   -  person Henri    schedule 20.10.2015
comment
Вызывало ли другое приложение на вашем компьютере timeBeginPeriod temporarilt, повышая ваше временное разрешение? В этом особенно виноваты игры (обратите внимание, что изменение периодов таймера, как правило, очень плохая идея).   -  person Mike Vine    schedule 20.10.2015
comment
@Майк, я не понял   -  person Henri    schedule 20.10.2015
comment
@Ив Анри. Прочитайте документы на timeBeginPeriod. Это заставляет расписание потоков Windows действовать в указанном такте. Обычно каждому потоку дается ~ 15 мс для выполнения, что означает, что любое измерение, вероятно, будет иметь ошибку около 15 мс. Если период планировщика установлен на что-то более низкое (например, игрой или мультимедийным приложением), то все измерения времени в системе становятся более точными, если вы используете системные часы (или GetTickCount или что-то еще). Используйте точный счетчик (QueryPerformanceCounter или аналогичный), чтобы сделать это правильно...   -  person Mike Vine    schedule 21.10.2015
comment
@Майк, я все еще в замешательстве. Я не использую timeBeginPeriod/timeEndPeriod (Windows.h). Вы имеете в виду, что std::chrono использует его внутри, и я могу каким-то образом изменить «период» функции time___Period для повышения точности (информация из документации)?!   -  person Henri    schedule 21.10.2015
comment
@Yves Henri Внимательно прочитайте документы. Если ЛЮБОЕ приложение на вашем компьютере вызывает timeBeingPeriod, это изменяет период времени для планировщика для всей системы. Например. если у вас неправильно работает медиаплеер, который вызывает эту функцию, работающую одновременно с выполнением тестов, это повлияет на ваше приложение. Может быть только так - планировщик в ОС всего один.   -  person Mike Vine    schedule 21.10.2015
comment
Поэтому я добавил ответ с примером этого события. Взгляните на это.   -  person Mike Vine    schedule 21.10.2015


Ответы (2)


По всей вероятности, это другое приложение, вызывающее timeBeginPeriod, которое искажает ваши измерения. Вот пример:

Вот приложение, которое измеряет 1000 мс сна, а затем порождает другое приложение, которое вызывает timeBeingPeriod(1) и timeEndPeriod(1). Обратите внимание, как второе приложение, вызывающее timeBeginPeriod, влияет на измерение времени этого приложения:

#include <Windows.h>
#include <chrono>
#include <iostream>

int main(int nArgs, char**args)
{
    if (nArgs <= 1)
    {
        // if we're spawned normally measure sleeping for 1000ms 30 times
        for (int i = 0; i < 30; ++i)
        {
            auto timeBegin = std::chrono::system_clock::now();
            Sleep(1000);
            auto timeEnd = std::chrono::system_clock::now();
            auto duration = std::chrono::duration_cast<std::chrono::milliseconds>(timeEnd - timeBegin);
            std::cout << "Iteration " << i << ", sleeping for 1000ms took " << duration.count() << "ms..." << std::endl;
            // On the 10th iteration spawn a bad app which calls timeBeginPeriod(1)
            if (i == 10)
            {
                std::cout << "Spawning bad process" << std::endl;
                PROCESS_INFORMATION pi = {};
                STARTUPINFOA si = { sizeof(STARTUPINFOA) };
                CreateProcessA("..\\Debug\\Timer.exe", "be a bad process", nullptr, nullptr, FALSE, 0, nullptr, nullptr, &si, &pi);
            }
        }
    }
    else
    {
        // If we're spawned with some arguments pretend to be a bad app that calls timeBeginPeriod(1)
        std::cout << "Bad process calling timeBeginPeriod(1)" << std::endl;
        timeBeginPeriod(1);
        Sleep(10 * 1000);
        std::cout << "Bad process calling timeEndPeriod(1)" << std::endl;
        timeEndPeriod(1);
    }

}

Дает:

Iteration 0, sleeping for 1000ms took 1015ms...
Iteration 1, sleeping for 1000ms took 1015ms...
Iteration 2, sleeping for 1000ms took 1015ms...
Iteration 3, sleeping for 1000ms took 1015ms...
Iteration 4, sleeping for 1000ms took 1015ms...
Iteration 5, sleeping for 1000ms took 1015ms...
Iteration 6, sleeping for 1000ms took 1015ms...
Iteration 7, sleeping for 1000ms took 1015ms...
Iteration 8, sleeping for 1000ms took 1015ms...
Iteration 9, sleeping for 1000ms took 1015ms...
Iteration 10, sleeping for 1000ms took 1015ms...
Spawning bad process
Bad process calling timeBeginPeriod(1)
Iteration 11, sleeping for 1000ms took 1011ms...
Iteration 12, sleeping for 1000ms took 1001ms...
Iteration 13, sleeping for 1000ms took 1001ms...
Iteration 14, sleeping for 1000ms took 1001ms...
Iteration 15, sleeping for 1000ms took 1000ms...
Iteration 16, sleeping for 1000ms took 1000ms...
Iteration 17, sleeping for 1000ms took 1001ms...
Iteration 18, sleeping for 1000ms took 1001ms...
Iteration 19, sleeping for 1000ms took 1001ms...
Bad process calling timeEndPeriod(1)
Iteration 20, sleeping for 1000ms took 1008ms...
Iteration 21, sleeping for 1000ms took 1011ms...
Iteration 22, sleeping for 1000ms took 1015ms...
Iteration 23, sleeping for 1000ms took 1015ms...
Iteration 24, sleeping for 1000ms took 1016ms...
Iteration 25, sleeping for 1000ms took 1015ms...
Iteration 26, sleeping for 1000ms took 1015ms...
Iteration 27, sleeping for 1000ms took 1015ms...
Iteration 28, sleeping for 1000ms took 1015ms...
Iteration 29, sleeping for 1000ms took 1015ms...

Обратите внимание, что в общем случае мы измеряем 15 мс слишком долго, но пока работает «плохое» приложение, мы намного точнее.

Вы должны использовать более точные часы для измерения времени. QueryPerformanceCounter/QueryPerformanceFrequency или GetSystemTimeAsFileTimePrecise или std::chrono::high_resolution_clock будет работать ТОЛЬКО В VS2015. std::chrono::high_resolution_clock на vs2013 немного хреновый и все еще имеет эту проблему.

Однако это объясняет только то, что вы видите, в общем случае sleep(xxx) будет спать для xxx и некоторых дополнительных — он снова запустится только тогда, когда появится свободное ядро ​​ЦП для его запуска на или следующий по расписанию. Пожалуйста, не используйте timeBeginPeriod самостоятельно, так как это плохо, просто напишите свою логику, чтобы обработать тот факт, что вы не работаете в системе реального времени, поэтому любое измерение будет иметь некоторую ошибку.

person Mike Vine    schedule 21.10.2015
comment
Нелегко определить, какие приложения вызывают функции timePeriods, верно? Существуют ли варианты включения этих функций timePeriods без проблем с переносимостью для улучшения этого класса профилирования? Между прочим, high_resolution_clock — это просто определение типа system_clock. - person Henri; 22.10.2015
comment
@Yves Henri Если это для класса профилирования, учтите, что, во-первых, вы должны использовать рекомендуемую функцию синхронизации высокого качества. Ни один из часов в хроно не является таким (по крайней мере, на VS2012). Во-вторых, этот сон известен своей неточностью - если бы вы действительно измеряли какой-то реальный код, ваше время было бы более точным. Но самое главное, вы не работаете в ОС реального времени, поэтому ваши потоки будут упреждающими, что создаст проблему воспроизводимости. Вот почему вы должны использовать профилировщик, который находится в сговоре с планировщиком, поскольку он может быть точным, или просто жить с неточностью, которую вы получаете. - person Mike Vine; 22.10.2015
comment
И msdn.microsoft.com/ en-gb/library/windows/desktop/ является обязательным для чтения, если вы хотите знать, какие таймеры хороши для Windows. - person Mike Vine; 22.10.2015
comment
Я просто подумал, что хроно (тот, что поставляется с компилятором C++11 из VS2012) — это самые точные часы, которые я мог использовать, поэтому я нашел этот класс и внес несколько корректировок. Он работал гладко и все такое, но в какой-то момент он начал выдавать 0 мс для той же задачи, которая раньше составляла 10–15 мс (это не был спящий вызов. Для полноты картины это была функция разбора файла). Знаете ли вы какой-нибудь бесплатный профилировщик точного времени, который я мог бы использовать для тестирования на своих окнах? - person Henri; 22.10.2015

std::this_thread::sleep_for(std::chrono::seconds(1)); никоим образом не гарантирует, что он будет спать ровно 1 секунду.

Использование 1,014 секунды, включая второй вызов now(), должно считаться достаточным.

person Bo Persson    schedule 20.10.2015
comment
Я использовал его для измерения времени, затрачиваемого на разбор некоторого файла. Раньше среднее значение составляло от 10 до 15 мс, однако иногда СЕЙЧАС печатает НОЛЬ! Не может быть, чтобы этот синтаксический анализ занимал 0 мс. Я могу заверить вас, основываясь на стресс-тестах, которые я провел вчера, что вызов now() не занимает 14 мс. Однако это может быть связано с SO. Что действительно любопытно, так это то, что к тому времени, когда я отвечал на ваши комментарии, я снова запускал приложение несколько раз, и теперь оно печатает правильное значение даже для очень коротких снов, например, 3 мс. - person Henri; 20.10.2015
comment
Это СОВЕРШЕННО другой вопрос. Если бенчмарк занимает 0 раз, это обычно означает, что оптимизатор удалил весь код. Синтетические тесты - это сложно! - person Bo Persson; 20.10.2015
comment
Смотрите мой комментарий. Точность system_clock в Windows составляет около 15 мс, поэтому вы увидите либо 0, либо 15, если что-то достаточно быстро - person Mike Vine; 21.10.2015