*** ВНИМАНИЕ: Блог переехал на другой адрес - demin.ws ***

четверг, 5 марта 2009 г.

QueryPerformanceCounter() на мультиядерных и виртуальных системах

Как я обещал, рассказываю про мои приключения с классом PreciseTimer.

Мой класс PreciseTimer предназначен для работы с миллисекундными интервалами времени. Реализация под Windows основана на использовании функций QueryPerformanceFrequency() и QueryPerformanceCounter().

Этот класс активно используется в некоторых наших проектах. Также, в силу некоторых обстоятельств, мы активно используем виртуальные машины для тестовых сборок. И, например, сборка под Windows 64-бита производится под VirtualBox. И вот очередной релиз-кандидат ушел в тестирование. Немедленно мне посыпались жалобы, что сборка не работает под 64-битным Windows под виртуальной машиной.

Я запретил тестерам временно отключать тест и начал проверять все сам. На реальных машинах все работает. Начал гонять на виртуальных. На VMWare тоже глючит. Тест PreciseTimer.MeasurementAccuracy выдает ошибку типа:
c:\sandbox\test\PreTimer_unittest.cpp(22): error: Value of: delta <= allowed_delta_ms
Actual: false
Expected: true
Delta (100) > than 10
[ FAILED ] PreciseTimer.MeasurementAccuracy (110 ms)
Получается, что задержка в 100 миллисекунд была измерена практически как нулевая.

Я заподозрил функцию QueryPerformanceCounter(). Написал еще один кондовый тест:
TEST(PreciseTimer, MillisecCounter) {
monitor::PreciseTimer timer;
monitor::PreciseTimer::Counter a = timer.millisec();
timer.sleepMs(10000);
monitor::PreciseTimer::Counter b = timer.millisec();
EXPECT_EQ(10000, b - a);
}
Этот тест делает видную глазом задержку в 10 секунд (чтобы исключить проблему в самой задержке) и затем проверят показания таймера.

Итак, на реальной машине тест выдает следующее:
[==========] Running 1 test from 1 test case.
[----------] Global test environment set-up.
[----------] 1 test from PreciseTimer
[ RUN ] PreciseTimer.MillisecCounter
c:\sandbox\test\PreTimer_unittest.cpp(17): error: Value of: b - a

Actual: 9995
Expected: 10000
[ FAILED ] PreciseTimer.MillisecCounter
[----------] Global test environment tear-down
[==========] 1 test from 1 test case ran.
[ PASSED ] 0 tests.
[ FAILED ] 1 test, listed below:
[ FAILED ] PreciseTimer.MillisecCounter

1 FAILED TEST
Тест, конечно, сбоит, но тут четко видно, что требуемая задержка в 10000 миллисекунд (10 секунд) измерена как 9995 миллисекунд. Понятно, тут невозможно измерить точь в точь, но суть работает верно.

А вот, что я получил на виртуальное машине:
[==========] Running 1 test from 1 test case.
[----------] Global test environment set-up.
[----------] 1 test from PreciseTimer
[ RUN ] PreciseTimer.MillisecCounter
c:\sandbox\test\PreTimer_unittest.cpp(17): error: Value of: b - a
Actual: 90
Expected: 10000
[ FAILED ] PreciseTimer.MillisecCounter
[----------] Global test environment tear-down
[==========] 1 test from 1 test case ran.
[ PASSED ] 0 tests.
[ FAILED ] 1 test, listed below:
[ FAILED ] PreciseTimer.MillisecCounter

1 FAILED TEST
Задержка в 10000 миллисекунд была измерена всего как 90. Вот и причина сбоя — функция QueryPerformanceCounter(). Полчаса работы.

Затем я поискал в интернете на тему проблем у функции QueryPerformanceCounter() на виртуальных машинах и нашел объяснение в MSDN. Корень проблемы, как оказалось, был не конкретно в виртуальных машинах, а в "старом" биосе и в использовании мультиядерных систем. На наших реальных мультиядерных машинах все работало, так как, видимо их биос был "нормальным".

В итоге проблема решилась добавлением параметра /usepmtimer в файл c:\boot.ini, как рекомендуется в найденной статье. После этого все тесты заработали как положено.

Я включил подробное описание проблемы в Release Notes, чтобы клиенты не наступили на эти грабли, и инцидент был исчерпан. Еще полчаса работы. Итого час на все.

А теперь вдумайтесь в произошедшее. Проблема была локализована и исправлена не то, чтобы до релиза. Она была локализована даже до тестового запуска. Лично я вот ну ни как не ожидал, что в Windows функция QueryPerformanceCounter() почему-то как-то особенно работает на мультиядерных системах со "старым" биосом (видимо биосы VMWare и VirtualBox как раз подходят под эту категорию). А вот как бы искал эту проблему потом? уже на реальной работающей системе. Одно из применений этого класса у нас, это измерения временных данных по транзакциям. Да я потратил был потом полжизни для поиска этой "маленькой проблемки", случись она у реального клиента.

Пишите тесты! Это экономит не только деньги, но самое драгоценное — ваши нервы.


Другие посты по теме:

2 комментария:

  1. Про QueryPerormanceCounter я писал небольшую статью, видел?
    Очень уж он тормозной.

    ОтветитьУдалить
  2. Да, я читал про твои опыты. Так как мне все-таки нужны миллисекунды, то timeGetTime немного неудобен. RDTSC хорош, но имеет проблемы на многопроцессорных системах. Сейчас я понимаю, что QueryPerformanceCounter тоже их имеет ;-), но тут винды хотя бы дают способ с этим справиться. К тому же RDTSC - это однозначно Intel, а для меня это табу. ;-)

    ОтветитьУдалить