Ломается QueryPerformanceCounter. Как такое возможно?! , Странный эффект на пустом месте...

Привет!

Происходит какая-то фигня с QueryPerformanceCounter. У меня есть UtilsR1.dll, которая содержит функцию протоколирования отладочных строк. Эти строки сопровождаются метками времени в секундах с разрешением 10 мкс (показаны в квадратных скобках). Для получения меток времени как раз и используется эта самая QueryPerformanceCounter. Отсчет производится от момента запуска программы. Выглядит это дело примерно так:

[0.00000] UtilsR1.dll (Apr 27 2012 11:38:23): DLL_PROCESS_ATTACH
[0.00063] Debugger.dll (Apr 27 2012 11:30:12): DLL_PROCESS_ATTACH
[0.00182] [PlotEngineR2] CPlotEngine::CPlotEngine: Enter
[0.00204] PlotEngineR2.dll (Apr 27 2012 11:30:54): DLL_PROCESS_ATTACH
[0.00279] USB901R2.dll (Apr 27 2012 11:31:52): DLL_PROCESS_ATTACH
[0.00304] [USB901R2] USB901R2_SetDebugLevel: Set debug level to 0
[0.00333] SCUSBR2.dll (Apr 27 2012 11:31:38): DLL_PROCESS_ATTACH
[0.00355] TxRx64.dll (Mar  1 2011 11:02:06): DLL_PROCESS_ATTACH
[0.00381] Scanner_DRx64.dll (Apr 27 2012 11:28:38): DLL_PROCESS_ATTACH
[0.00401] Kbd801.dll (Apr 27 2012 11:30:25): DLL_PROCESS_ATTACH
[0.00420] [Kbd801] CThread2::CThread2: Shutdown event handle 0x00000174
[0.00442] Kbd1100.dll (Apr 27 2012 11:30:22): DLL_PROCESS_ATTACH
[0.00461] [Kbd1100] CThread2::CThread2: Shutdown event handle 0x00000178
[0.00481] KBDdllR1.dll (Apr 27 2012 11:30:28): DLL_PROCESS_ATTACH
[0.00510] Container.dll (Apr 27 2012 11:30:06): DLL_PROCESS_ATTACH
[0.00542] Ql.dll (Apr 27 2012 11:31:02): DLL_PROCESS_ATTACH
... и т.д.

Однако, после какого-то момента функция QueryPerformanceCounter начинает выдавать время очень грубыми шагами. Мало того, выдаваемое время даже скачет вперед/назад (из-за вывода из разных потоков)! Это можно увидеть в следующем фрагменте:

[0.15671] TRball.dll: DLL_PROCESS_ATTACH
[0.15998] [ScanR2_CFM_Start] CFMThreadReadData: Enter
[0.19485] [PlotEngineR2] CPlotEngine::Init: Enter
[0.19522] [PlotEngineR2] CRenderer::CRenderer: Enter
[0.19546] [PlotEngineR2] CRenderer::Init: Enter, HWND = 0x002906B8, width = 512, height = 512
[0.22257] [PlotEngineR2] CRenderer::Init: OK
[0.22257] [PlotEngineR2] CPaneB::CPaneB: Enter
[0.28507] [PlotEngineR2] CPaneM::CPaneM: Enter
[0.28507] [PlotEngineR2] CPaneG::CPaneG: Enter
[0.28507] [PlotEngineR2] CPaneGi::CPaneGi: Enter
[0.28507] Start system init sequence
[0.28507] Program file "C:\1my\_Work\Prog.exe"
[0.28507] Main ini file "C:\1my\_Work\Prog.ini"
[0.28507] TxRxControlR2.dll: Virtual mode disabled
[0.28507] [USB901R2] USB901R2_Init: hWnd = 0x00890584, VID = 0x04B4, PID = 0x8613, endpoints:
[0.28507] [USB901R2] USB901R2_Init: Ctrl OUT = 0x02 IN = 0x84, BData IN = 0x86, CfmData IN = 0x88
[0.28507] Signal "USB901R2_B_xfer_event" registered
[0.28507] Signal "USB901R2_B_frame_event" registered
[0.28507] Signal "USB901R2_M_beam_xfer" registered
[0.28507] Signal "USB901R2_M_beam_event" registered
[0.28507] Signal "USB901R2_CFM_xfer_event" registered
[0.28507] Signal "USB901R2_CFM_1st_block" registered
[0.28507] Signal "USB901R2_CFM_Nth_block" registered
[0.28507] Signal "USB901R2_CFM_frame_event" registered
[0.28507] Signal "USB901R2_D_beam_event" registered
[0.28507] Signal "USB901R2_D_beam_Nth_block" registered
[0.28507] [USB901R2] USB901R2_Init: EP1 present, EP1 OUT = 0x01 EP1 IN = 0x81
[0.28507] [USB901R2] CThread2::CThread2: Shutdown event handle 0x000002EC
[0.28507] [USB901R2] CThread2::CThread2: Shutdown event handle 0x000002F4
[0.29633] [USB901R2] US_data_reading_loop: Enter                          <---------- время больше
[0.29653] [USB901R2] CFM_data_reading_loop: Enter
[0.29671] [USB901R2] US_data_reading_loop: Shutdown event handle 0x000002EC
[0.29697] [USB901R2] CFM_data_reading_loop: Shutdown event handle 0x000002F4
[0.28507] [SCUSBR2] SCUSBR2_Init: Configure SCUSB PLD                     <---------- время опять меньше
[0.28507] [SCUSBR2] SCUSBR2_Init: File "SCUSBR2v28.rbf"
[0.28507] [SCUSBR2] SCUSBR2_PLD_loader_Load: PLD No 0
[0.28507] [SCUSBR2] _pld_loader_load: PLD No 0, data ptr 0x14860048, len 84539
[0.28507] [SCUSBR2] _pld_loader_reset: PLD No 0
[0.28507] [SCUSBR2] _pld_loader_reset: PLD No 0 reset OK
[1.78507] [SCUSBR2] _pld_loader_load: PLD No 0, Load OK (84539 bytes loaded)
[1.78507] [SCUSBR2] _pld_loader_load: SCUSB PLD revision No 28
...

Правда, строки с большим временем поступают из другого потока. Но выдача протокола закрыта критическими секциями и каждая строка записывается путем открытия/записи/закрытия файла протокола. Тут можно видеть и еще одну странность: в этих параллельных потоках QueryPerformanceCounter работает правильно, выдает время с верным разрешением.

И, наконец, последняя странность: после рестарта компьютера работа функции QueryPerformanceCounter снова восстанавливается, и строки протокола начинают опять выдаваться с правильным временем (с правильным временным разрешением). Выполнение Log Off/Log On не помогает. Вот те же места протокола после рестарта компьютера:

Первый кусок:
 
[0.00000] UtilsR1.dll (Apr 27 2012 11:38:23): DLL_PROCESS_ATTACH
[0.00060] Debugger.dll (Apr 27 2012 11:30:12): DLL_PROCESS_ATTACH
[0.00173] [PlotEngineR2] CPlotEngine::CPlotEngine: Enter
[0.00194] PlotEngineR2.dll (Apr 27 2012 11:30:54): DLL_PROCESS_ATTACH
[0.00266] USB901R2.dll (Apr 27 2012 11:31:52): DLL_PROCESS_ATTACH
[0.00292] [USB901R2] USB901R2_SetDebugLevel: Set debug level to 0
[0.00324] SCUSBR2.dll (Apr 27 2012 11:31:38): DLL_PROCESS_ATTACH
[0.00346] TxRx64.dll (Mar  1 2011 11:02:06): DLL_PROCESS_ATTACH
[0.00372] Scanner_DRx64.dll (Apr 27 2012 11:28:38): DLL_PROCESS_ATTACH
[0.00392] Kbd801.dll (Apr 27 2012 11:30:25): DLL_PROCESS_ATTACH
[0.00411] [Kbd801] CThread2::CThread2: Shutdown event handle 0x00000174
[0.00431] Kbd1100.dll (Apr 27 2012 11:30:22): DLL_PROCESS_ATTACH
[0.00449] [Kbd1100] CThread2::CThread2: Shutdown event handle 0x00000178
[0.00469] KBDdllR1.dll (Apr 27 2012 11:30:28): DLL_PROCESS_ATTACH
[0.00497] Container.dll (Apr 27 2012 11:30:06): DLL_PROCESS_ATTACH
[0.00528] Ql.dll (Apr 27 2012 11:31:02): DLL_PROCESS_ATTACH
...
 
Второй кусок:
 
[0.10455] TRball.dll: DLL_PROCESS_ATTACH
[0.10759] [ScanR2_CFM_Start] CFMThreadReadData: Enter
[0.11945] [PlotEngineR2] CPlotEngine::Init: Enter
[0.11980] [PlotEngineR2] CRenderer::CRenderer: Enter
[0.12006] [PlotEngineR2] CRenderer::Init: Enter, HWND = 0x00040470, width = 512, height = 512
[0.17464] [PlotEngineR2] CRenderer::Init: OK
[0.17513] [PlotEngineR2] CPaneB::CPaneB: Enter
[0.17550] [PlotEngineR2] CPaneM::CPaneM: Enter
[0.17574] [PlotEngineR2] CPaneG::CPaneG: Enter
[0.17599] [PlotEngineR2] CPaneGi::CPaneGi: Enter
[0.17733] Start system init sequence
[0.17867] Program file "C:\1my\_Work\Prog.exe"
[0.17940] Main ini file "C:\1my\_Work\Prog.ini"
[0.18014] TxRxControlR2.dll: Virtual mode disabled
[0.18148] [USB901R2] USB901R2_Init: hWnd = 0x000404A4, VID = 0x04B4, PID = 0x8613, endpoints:
[0.18172] [USB901R2] USB901R2_Init: Ctrl OUT = 0x02 IN = 0x84, BData IN = 0x86, CfmData IN = 0x88
[0.18197] Signal "USB901R2_B_xfer_event" registered
[0.18221] Signal "USB901R2_B_frame_event" registered
[0.18246] Signal "USB901R2_M_beam_xfer" registered
[0.18270] Signal "USB901R2_M_beam_event" registered
[0.18295] Signal "USB901R2_CFM_xfer_event" registered
[0.18319] Signal "USB901R2_CFM_1st_block" registered
[0.18343] Signal "USB901R2_CFM_Nth_block" registered
[0.18356] Signal "USB901R2_CFM_frame_event" registered
[0.18380] Signal "USB901R2_D_beam_event" registered
[0.18404] Signal "USB901R2_D_beam_Nth_block" registered
[0.19198] [USB901R2] USB901R2_Init: EP1 present, EP1 OUT = 0x01 EP1 IN = 0x81
[0.20052] [USB901R2] CThread2::CThread2: Shutdown event handle 0x000002EC
[0.20101] [USB901R2] CThread2::CThread2: Shutdown event handle 0x000002F4
[0.20185] [USB901R2] US_data_reading_loop: Enter                          <---------- время совершенно нормальное
[0.20199] [USB901R2] CFM_data_reading_loop: Enter
[0.20216] [USB901R2] US_data_reading_loop: Shutdown event handle 0x000002EC
[0.20249] [USB901R2] CFM_data_reading_loop: Shutdown event handle 0x000002F4
[0.20284] [SCUSBR2] SCUSBR2_Init: Configure SCUSB PLD
[0.20321] [SCUSBR2] SCUSBR2_Init: File "SCUSBR2v28.rbf"
[0.20382] [SCUSBR2] SCUSBR2_PLD_loader_Load: PLD No 0
[0.20406] [SCUSBR2] _pld_loader_load: PLD No 0, data ptr 0x14860048, len 84539
[0.20431] [SCUSBR2] _pld_loader_reset: PLD No 0
[0.20687] [SCUSBR2] _pld_loader_reset: PLD No 0 reset OK
[1.81783] [SCUSBR2] _pld_loader_load: PLD No 0, Load OK (84539 bytes loaded)
[1.81869] [SCUSBR2] _pld_loader_load: SCUSB PLD revision No 28
...

Тут можно видеть, что время в других потоках тоже совершенно нормальное.

Как может сломаться функция QueryPerformanceCounter?! Она ведь оперирует аппаратным счетчиком в процессоре!

Я замечал этот дефект на 3-х аппаратных платформах, все они с Интеловскими процессорами (Core 2 Duo и одноядерный Celeron), на всех установлены 32-разрядные Win XP. Пробовал различные варианты доступа к RDTSC с помощью ассемблера или функции rdtsc() - все едино. Как такое возможно?!

Помогите, пожалуйста, побороть этот недуг!

P.S. Функция [0.19546] [PlotEngineR2] CRenderer::Init инициализирует DirectX с помощью функций Direct3DCreate9(D3D_SDK_VERSION), CreateDevice(), создания нужных текстур и т.п. Вот после нее QueryPerformanceCounter для текущего потока и ломается. Другие программы, не использующие DirectX, с помощью той же UtilsR1.dll выдают правильный протокол, без проблем с временем. Выходит, что DirectX портит работу QueryPerformanceCounter?... Не понимаю...

jur
К примеру виртуализация или SMM.

Цитата

Как может сломаться функция QueryPerformanceCounter?! Она ведь оперирует аппаратным счетчиком в процессоре!

QueryPerformanceCounter всего лишь абстракция. А значит подвержена корректировки, есть всякии ускорялки для игр.

Разные ядра имеют разные значения rdtsc.

Минздрав MSDN предупреждает:

Цитата

On a multiprocessor computer, it should not matter which processor is called. However, you can get different results on different processors due to bugs in the basic input/output system (BIOS) or the hardware abstraction layer (HAL). To specify processor affinity for a thread, use the SetThreadAffinityMask function.

Эх, не всё так просто. jur, может быть в этом проблема? На всякий случай у меня на машине GetSystemTimeAdjustment() для своих параметров выдаёт 156255 156250 0 соответственно.

Qraizer
Статья врёт.
Дело не в ошибках резонатора. А в том что кто-то захотел получить 10мс(в современных системах 15мс но не суть важно). А в наличии был таймер PIT с опорной частоты 1193181.(6) Гц и наличие делителя с коэфициентом в диапозоне 1-65536

10 мс =100Гц
100=1193181.(6)/х
х=11931.81

Расчёт для 15 мс
15мс=1000/15 Гц
1000/15=1193181.(6)/х
х=15/1000*1193181.(6)
х=17897,724999

А оно на цело и неделится и получилось бы тогда что таймер убегает или отстает. Вот и решили скорректировать хитрым образом.
Округлили х, а в таймере начали корректировать время.
Вот эту корректировку и зашили в GetTickCount. А реальные цифры в GetSystemTimeAdjustment.


На самом деле внутренний делитель в виндосе подобран так чтобы была частота 1024. А там ошибка как раз и большая.
А потом уже пропускается 15 интервалов таймера.
Да вот так вот все через Ж.. в виндоусе.
Подвиду итог PIT имеет частоту 1193181 делитель выбран как 1165
Итого имем частоту прерывания 1024,189
кант времени равен (16/1024,189)=0,015622




А по поводу ошибок резонатора, в любом генераторе или синтезаторе есть фазовая подстройка частоты. Она и недаёт делать скачки.
А во-вторых rdtsc получается умножением, а не делением. Поэтому тут проблемы с округлением нет.

В досе для time-of-day clock использовался RTC, а в виндоусе PIT
У RTC резонатор имеет частоту 32768 Гц и делитель 32768 Гц чтобы срабатывать раз в секунду. Поэтому время создания файлов в досе имела дискретность в 1 секунду и небыло проблем с делителем.
А в виндоусе использовали уже PIT и получалась разсинхронизация с которой и боролись боролись. А в итоге только хуже сделали.

Сообщение отредактировано: Pavia - 31.05.12, 17:57

Pavia, ты точно читал статью?

P.S. Под DOS я программил достаточно.

Добавлено 31.05.12, 18:41
В любом случае я предложил ещё один вариант, который может иметь место. Что там в коде у jur, мне неведомо.

А в boot.ini проблемной системы /usepmtimer не? По-моему, как раз похоже.

Кстати, да. Вот статья на эту тему.

Qraizer
Читал. Статья 100% ложь.


Vapaamies
По поводу /usepmtimer.
Qraizer дал статю. /usepmtimer это не проблемма а её решение. Как я уже писал QueryPerformanceCounter это абстракция. Для решения проблемы того что таймер HPET или rdtsc имеют разное начальное значения. Использовать один таймер PMTimer.

Меня смущают следующие моменты. Во-первых, как объяснить, что до "CRenderer::Init: OK" все хорошо, а после этого дискрет времени увеличивается на порядки? Как здесь:

[0.19485] [PlotEngineR2] CPlotEngine::Init: Enter
[0.19522] [PlotEngineR2] CRenderer::CRenderer: Enter
[0.19546] [PlotEngineR2] CRenderer::Init: Enter, HWND = 0x002906B8, width = 512, height = 512
 
до этого места хорошо, после - плохо...
 
[0.22257] [PlotEngineR2] CRenderer::Init: OK
[0.22257] [PlotEngineR2] CPaneB::CPaneB: Enter
[0.28507] [PlotEngineR2] CPaneM::CPaneM: Enter
[0.28507] [PlotEngineR2] CPaneG::CPaneG: Enter
[0.28507] [PlotEngineR2] CPaneGi::CPaneGi: Enter
[0.28507] Start system init sequence

Во-вторых, если QueryPerformanceCounter обращается к неправильному генератору, то почему в других потоках этот генератор становится правильным? Ведь в них время приращается верно, примерно на 100-200 (иногда чуть меньше) микросекунд за раз.

В-третьих, почему аппаратный 64-разрядный счетчик тиков процессора RDTSC выдает неправильные значения? Ведь он-то вообще ни от чего не зависит! В смысле, от каких-то резонаторов и т.п. Кроме того, этот дефект существует и на одноядерном простеньком Целероне.

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

[0.11945] [PlotEngineR2] CPlotEngine::Init: Enter
[0.11980] [PlotEngineR2] CRenderer::CRenderer: Enter
[0.12006] [PlotEngineR2] CRenderer::Init: Enter, HWND = 0x00040470, width = 512, height = 512
[0.17464] [PlotEngineR2] CRenderer::Init: OK
[0.17513] [PlotEngineR2] CPaneB::CPaneB: Enter
[0.17550] [PlotEngineR2] CPaneM::CPaneM: Enter
[0.17574] [PlotEngineR2] CPaneG::CPaneG: Enter
[0.17599] [PlotEngineR2] CPaneGi::CPaneGi: Enter
[0.17733] Start system init sequence

Видно, что время отображается совершенно правильно. Поэтому представляется, что ключ /usepmtimer ничего не даст.

Для эксперимента я запускал параллельно две свои тестовые программки, представляющие собой пару клиент/сервер, для проверки передачи данных через механизм Memory mapped file. Эти программки используют все ту же UtilsR1.dll, ведающую выводом протокола. Так в их протоколе все хорошо, время отсчитывается нормально, каждая строка минимум на 100-200 микросекунд позже предыдущей. Разница в программах та, что не используется DirectX.

Темный лес... Всю голову сломал, а она у меня одна... :-)

P.S. Да, забыл сказать. Еще я пробовал SetProcessAffinityMask/SetThreadAffinityMask - все едино, времена вывода строк протокола как заколдованные...

Так и запишем, мол, Pavia за пояс заткнул системщиков из Microsoft.
jur, так ты попробуй. Сначала нужно найти причину, а потом уже искать пути решения.

Цитата Qraizer @ 01.06.12, 09:42

jur, так ты попробуй. Сначала нужно найти причину, а потом уже искать пути решения.

Обязательно попробую. Вот, уже перегрузил комп с этим ключом. Дело немножко осложняется тем, что после перезагрузки эта зараза работает правильно :-) Ну ничего, поковыряюсь, поисследую. (Интересно, вдруг получится?...)

Спасибо за помощь!

Не получилось, все то же самое... Оставил комп работать на ночь, теперь смотрю лог. Включил более детальный вывод протокола. Из него видно, что после инициализации DX Device отсчет времени ломается:

[0.07896] [PlotEngineR2] CPlotEngine::SetDebugLevel: Set debug level to 1
[0.07928] [PlotEngineR2] CPlotEngine::Init: Enter
[0.07949] [PlotEngineR2] CRenderer::CRenderer: Enter
[0.07969] [PlotEngineR2] CRenderer::Init: Enter, HWND = 0x001E060A, width = 512, height = 512
[0.08178] [PlotEngineR2] CRenderer::Init: DX Object   = 0x00173CA0
[0.08202] [PlotEngineR2] CRenderer::Init: GetAdapterDisplayMode() OK
[0.13258] [PlotEngineR2] CRenderer::Init: DX Device   = 0x0017FDC0
[0.14039] [PlotEngineR2] CRenderer::Init: B Texture   = 0x0016F320
[0.14039] [PlotEngineR2] CRenderer::Init: CFM Texture = 0x0020E460
[0.14039] [PlotEngineR2] CRenderer::Init: M Texture   = 0x0020E660
[0.14039] [PlotEngineR2] CRenderer::Init: G Texture   = 0x0020E840
[0.14039] [PlotEngineR2] CRenderer::Init: Gi Texture  = 0x0020EA20
[0.14039] [PlotEngineR2] CRenderer::Init: OK
[0.14039] [PlotEngineR2] CPaneB::CPaneB: Enter
[0.14820] [PlotEngineR2] CPaneB::_calc_convex: Scanning depth 120.0 mm, radius = 60.00 mm, angle = 42.69 deg
[0.14820] [PlotEngineR2] CPaneB::_calc_convex: Scanning depth 120.0 mm, radius = 60.00 mm, angle = 42.69 deg
[0.14820] [PlotEngineR2] CPaneM::CPaneM: Enter
[0.14820] [PlotEngineR2] CPaneG::CPaneG: Enter
[0.14820] [PlotEngineR2] CPaneGi::CPaneGi: Enter
[0.14820] Start system init sequence

В чем же может крыться причина поломки? Видно, что на это дело как-то влияет DirectX. Но как и почему?!

Ура! С помощью многоуважаемого коллеги Адамантэус наконец-то удалось достичь блистательной Виктории!

Дело оказалось в том, что, как предположил коллега Адамантэус, треклятая DirectX портит режим работы сопроцессора с плавающей точкой. Возможно кому-нибудь окажется полезной информация по преодолению данной проблемы. Ведь если в программе используются вычисления с плавающей точкой повышенной точности, то они будут выполняться неверно.

Вот что я сделал. Сначала я увеличил разрядность выводимого времени и добавил вывод значения счетчика RDTSC. Получил следующий протокол (детализацию для наглядности увеличил):

[0.210631519] 875788055576 [PlotEngineR2] CPlotEngine::Init: Enter
[0.210879316] 875788056462 [PlotEngineR2] CRenderer::CRenderer: Enter
[0.211111189] 875788057293 [PlotEngineR2] CRenderer::Init: Enter, HWND = 0x0007059E, width = 512, height = 512
[0.213896738] 875788067264 [PlotEngineR2] CRenderer::Init: DX Object   = 0x00173E20
[0.214174707] 875788068259 [PlotEngineR2] CRenderer::Init: GetAdapterDisplayMode() OK
 
с этого момента и до закрытия программы сопроцессор работает плохо:
 
[0.250000000] 875788183770 [PlotEngineR2] CRenderer::Init: DX Device   = 0x0017D760
[0.250000000] 875788188668 [PlotEngineR2] CRenderer::Init: B Texture   = 0x0016D7C0
[0.250000000] 875788193673 [PlotEngineR2] CRenderer::Init: CFM Texture = 0x0020C660
[0.250000000] 875788200309 [PlotEngineR2] CRenderer::Init: M Texture   = 0x0020C840
[0.250000000] 875788208381 [PlotEngineR2] CRenderer::Init: G Texture   = 0x0020CA40
[0.250000000] 875788216458 [PlotEngineR2] CRenderer::Init: Gi Texture  = 0x0020CC20
[0.250000000] 875788217774 [PlotEngineR2] CRenderer::Init: OK
[0.250000000] 875788218817 [PlotEngineR2] CPaneB::CPaneB: Enter
[0.250000000] 875788219689 [PlotEngineR2] CPaneB::_calc_convex: Scanning depth 120.0 mm, radius = 60.00 mm, angle = 42.69 deg
[0.250000000] 875788220592 [PlotEngineR2] CPaneB::_calc_convex: Scanning depth 120.0 mm, radius = 60.00 mm, angle = 42.69 deg
[0.250000000] 875788221747 [PlotEngineR2] CPaneM::CPaneM: Enter
[0.250000000] 875788222600 [PlotEngineR2] CPaneG::CPaneG: Enter
[0.250000000] 875788223448 [PlotEngineR2] CPaneGi::CPaneGi: Enter
[0.250000000] 875788227792 Start system init sequence

Видно, что начиная с момента создания устройства DirecX ("DX Device") время портится. Однако, счетчик приращается нормально, как и раньше.

Это говорит о том, что предположение о влиянии DirecX на сопроцессор подтверждается. Тогда я после создания устройства DirecX вставил простую конструкцию:

  __asm {
    FINIT;
  }

Взглянул на протокол и понял: "Вот она, Виктория!" :-) Это можно видеть по следующему фрагменту:

[0.088878894] 881454515739 [PlotEngineR2] CPlotEngine::Init: Enter
[0.089127529] 881454516629 [PlotEngineR2] CRenderer::CRenderer: Enter
[0.089361078] 881454517465 [PlotEngineR2] CRenderer::Init: Enter, HWND = 0x0009059E, width = 512, height = 512
[0.091818094] 881454526260 [PlotEngineR2] CRenderer::Init: DX Object   = 0x00174040
[0.092081815] 881454527203 [PlotEngineR2] CRenderer::Init: GetAdapterDisplayMode() OK
[0.128233896] 881454656612 [PlotEngineR2] CRenderer::Init: DX Device   = 0x0017D9A0
[0.129625413] 881454661593 [PlotEngineR2] CRenderer::Init: B Texture   = 0x0016D7C0
[0.131077553] 881454666791 [PlotEngineR2] CRenderer::Init: CFM Texture = 0x0020C880
[0.132994836] 881454673654 [PlotEngineR2] CRenderer::Init: M Texture   = 0x0020CA80
[0.135265236] 881454681781 [PlotEngineR2] CRenderer::Init: G Texture   = 0x0020CC60
[0.137500716] 881454689783 [PlotEngineR2] CRenderer::Init: Gi Texture  = 0x0020CE40
[0.137878418] 881454691135 [PlotEngineR2] CRenderer::Init: OK
[0.138167002] 881454692168 [PlotEngineR2] CPaneB::CPaneB: Enter
[0.138410329] 881454693039 [PlotEngineR2] CPaneB::_calc_convex: Scanning depth 120.0 mm, radius = 60.00 mm, angle = 42.69 deg
[0.138659522] 881454693931 [PlotEngineR2] CPaneB::_calc_convex: Scanning depth 120.0 mm, radius = 60.00 mm, angle = 42.69 deg
[0.138992805] 881454695124 [PlotEngineR2] CPaneM::CPaneM: Enter
[0.139229707] 881454695972 [PlotEngineR2] CPaneG::CPaneG: Enter
[0.139470799] 881454696835 [PlotEngineR2] CPaneGi::CPaneGi: Enter
[0.140687713] 881454701191 Start system init sequence

Все, проблема благополучно решена! Всем спасибо за участие!

:-)

Сообщение отредактировано: jur - 04.06.12, 16:08

А видеодрова пробовал обновлять? Есть подозрение, что кривая инициализация D3D-минипорта может MMX-ом испортить FPU.

Цитата Qraizer @ 04.06.12, 16:18

А видеодрова пробовал обновлять? Есть подозрение, что кривая инициализация D3D-минипорта может MMX-ом испортить FPU.

За время борьбы с этой напастью я сменил два или три раза дрова на две разные видеокарты (обе NVIDIA, одна 8400, другая 9500, буквы запамятовал) на двух компьютерах. Кроме того пробовал на довольно слабом Целероне, где видеоподсистема вообще встроенная (если не путаю, на Интеловском ускорителе).

Все едино... Как только счетчик RDTSC достигает достаточно большой величины, время в протоколе портится. Это, кстати, объясняет, почему после перезагрузки компа все работает нормально. Просто значение счетчика еще маленькое, в мантиссу еще более-менее помещается! :-)

А у тебя случаем не float? Может банально переполняется и надо использовать double?

Ясно. Причина хоть и ясна, но не локализована.

Цитата Pavia @ 04.06.12, 17:47

А у тебя случаем не float? Может банально переполняется и надо использовать double?

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

  __int64 GetElapsedCount()
  {
    LARGE_INTEGER current_time;
    if( !QueryPerformanceCounter(&current_time) ) return 0;
    return current_time.QuadPart;
  }
 
  double GetElapsedSeconds()
  {
    return double(GetElapsedCount()) / double(_timer_frequency);
  }

где приватная переменная класса:

__int64 _timer_frequency;

устанавливается в конструкторе. Видать сопроцессор как-то так ломается, что даже double обрабатываются, как float. Без понятия, как и зачем это делается.

Цитата Qraizer @ 04.06.12, 19:45

Ясно. Причина хоть и ясна, но не локализована.

Не представляю, как ее локализовать. Ведь эта DirecX - черный Биллевский ящик :-)

P.S. Я вообще на OpenGL перехожу :-) Т.к. мне в приборе (в некоторых вариантах) нужно использовать OpenGL ES. Подозреваю, что там этой засады не будет. Обязательно проверю.

Цитата jur @ 04.06.12, 15:59

Тогда я после создания устройства DirecX вставил простую конструкцию FINIT

Цитата jur @ 04.06.12, 20:15

Видать сопроцессор как-то так ломается, что даже double обрабатываются, как float. Без понятия, как и зачем это делается.

FINIT это очень "грубо и невоспитанно", т.к. она не только устанавливает макс.точность вычислений, но и маскирует все исключения FPU - и то, и другое может аукнуться на работе того же DirectX или твоих собственных вычислениях. Открой для себя ф-ии controlfp\control87, которые позволяют проверять, сохранять и устанавливать управляющее слово FPU, как целиком так и отдельные биты\поля, в частности точность вычислений

Сообщение отредактировано: leo - 05.06.12, 03:46

Ну, странно, что проблема только у тебя, не правда ли?

Цитата jur @ 04.06.12, 20:15

Не представляю, как ее локализовать. Ведь эта DirecX - черный Биллевский ящик :-)

Это как ничто мотивирует читать документацию.

Цитата jur @ 04.06.12, 20:15

Цитата Pavia @ 04.06.12, 17:47

А у тебя случаем не float? Может банально переполняется и надо использовать double?

Не, все нормально, ...

Итог: о флаге D3DCREATE_FPU_PRESERVE ты впервые слышишь? Я признаться тоже, но я почитал документацию.

Сообщение отредактировано: Qraizer - 05.06.12, 09:34

Цитата Qraizer @ 05.06.12, 09:34

о флаге D3DCREATE_FPU_PRESERVE ты впервые слышишь? Я признаться тоже, но я почитал документацию

Угу, и если с reduce performance все понятно, то unmasking these exceptions may result in undefined behavior - как-то настораживает и заставляет задуматься, а нужно ли использовать этот флаг ради какой-то одной операции расчета времени в секундах, когда можно и целочисленным делением обойтись для получения микросекунд (а затем, если очень хочется поставить разделительную точку в строке в нужном месте), ну или дергать controlfp до и после вычисления секунд

Эти самые Portions of Direct3D, которые assume, что floating-point unit exceptions are masked, скорее всего тоже задокументированы. Но если и нет или не охота париться, можно и самому замаскировать той же _controlfp(), т.к. вряд ли они интересуют jur.

Цитата leo @ 05.06.12, 03:45

Открой для себя ф-ии controlfp\control87, которые позволяют проверять, сохранять и устанавливать управляющее слово FPU, как целиком так и отдельные биты\поля, в частности точность вычислений

Большое спасибо за толковую подсказку! (Я подозревал, что должна быть функция API для этого дела. Ведь не замыкаться же в Ассемблере...) Это как раз то, что нужно. А то я совсем растерялся, куды бечь - не знаю... :-)

Цитата Qraizer @ 05.06.12, 09:34

Итог: о флаге D3DCREATE_FPU_PRESERVE ты впервые слышишь? Я признаться тоже, но я почитал документацию.

Да, про этот флаг я не знал. И, честно говоря, не догадался поискать именно его. Т.к. за много лет привык, что в Винде "дело спасения утопающих - дело рук самих утопающих"... :-)

Подсказка уважаемого leo подтолкнула меня к дальнейшим действиям. Провел некоторые исследования. С помощью функции _controlfp_s() я прочитал слово состояния FPU перед инициализацией DirecX и после создания DX-устройства:

[0.09747] [PlotEngineR2] CRenderer::Init: Original FPU control word 0x9001F
[0.10028] [PlotEngineR2] CRenderer::Init: DX Object   = 0x00173E20
[0.10054] [PlotEngineR2] CRenderer::Init: GetAdapterDisplayMode() OK
[0.12500] [PlotEngineR2] CRenderer::Init: DX Device   = 0x0017D760
[0.12500] [PlotEngineR2] CRenderer::Init: Altered FPU control word 0xA001F, changed bits 0x30000

Посмотрел по битам - так и есть: точность вычислений ухудшается.

Ладно, думаю, а что делают FINIT/FNINIT и _clearfp()? Оказалось, что ассемблерная команда возвращает слово состояния в первоначальный вид, т.е. 0x9001F, а функция сброса - как раз в ДиректИксовский вид 0xA001F, во как!

Тогда я попробовал применить конструкцию, устанавливающую FPU в значение по умолчанию:

  _controlfp_s(&fpu_control_word, _CW_DEFAULT, MCW_PC);

Все OK. Стал размышлять, на каком именно варианте остановиться? Ведь можно также сохранять/восстанавливать слово состояния FPU. Получилось бы то же самое. Однако логичнее, IMHO, сохранять/восстанавливать, а не сбрасывать в дефолт. Ведь может быть какой-нибудь модуль установит свой, нужный ему, режим работы.

Большое спасибо за помощь, друзья! :-)

ИМХО самым правильным будет использовать D3DCREATE_FPU_PRESERVE, потому как ты явно говоришь DirectX-у, чтоб он не трогал FPU, и он становится в курсе происходящего. Если ты это сделаешь сохранением MCW с последующим его восстановлением, DirectX не будет в курсе этого, т.к. ты добился того же, но за его спиной. Это может повлечь ещё какие-нибудь грабли.
Что касается FPU-исключений, то их следует либо действительно запретить, раз того хотят Portions of Direct3D, либо, если они нужны программе, поставить "глобальный" SEH-кадр, который будет их ловить, в __except()-выражении фильтровать, и если вдруг они придут из недр DirectX-а, избавляться от них прям на месте и возвращать EXCEPTION_CONTINUE_EXECUTION. Избавляться, думаю, следует эмуляцией маскированной реакции FPU на это исключение.

Цитата Qraizer @ 06.06.12, 11:55

ИМХО самым правильным будет использовать D3DCREATE_FPU_PRESERVE, потому как ты явно говоришь DirectX-у, чтоб он не трогал FPU, и он становится в курсе происходящего

Это будет самым неправильным решением, т.к. раз DirectX используется, значит это нужно, и тормозить его работу ради вычисления какой-то одной цифирьки какого-то лога - выглядит просто глупо. Вот если в проге юзается еще куча каких-то реально нужных вычислений с double-точностью, тогда другое дело, тогда этой общий прокол с подключением DirectX и с этим нужно что-то делать. А если ради одной цифирьки в логе, то самое разумное просто добавить в GetElapsedSeconds несколько строчек для проверки, переустановки и восстановления значения MCW_PC

leo, ты снова нечётко формулируешь мысли. Твой ответ отвечает не на тот вопрос, который задан. Я бы не стал категорично утверждать, что FPU программе jur-а ограничивается исключительно вычислением циферки для лога. Учитывая формулировку вопроса, jur желает оставить для себя FPU.
jur, если есть возможность не использовать FPU вообще, имеет смысл посмотрить в сторону предложения leo.

Сообщение отредактировано: Qraizer - 06.06.12, 14:23

Не помню, говорил-ли я о решаемых мною задачах. Прошу меня простить, если уже говорил, а теперь повторяюсь.

Я работаю электронщиком-программистом, разрабатываю ультразвуковые медицинские сканеры (УЗИ). В нашем приборе установлена PC-совместимая материнка с Win XP, на которой и крутится приборная программа. В последнее время возникла необходимость освоить еще и не-Интеловскую платформу: довольно крутой DSP от фирмы TI, семейство OMAP. Хорош он тем, что имеет на кристалле два процессора (ARM для задач общего назначения и DSP для наших алгоритмов обработки сигнала) плюс графический ускоритель с отличной производительностью. Все это дело оснащено Windows CE 6.0, которую я постепенно осваиваю. Про Линукс - не говорите, не катит по множеству причин (главная - нулевой опыт применения).

Отображение УЗ-картинки осуществляется с помощью DirectX. Выбор этой графической библиотеки обусловлен рядом стародавних причин, многие из которых уже утратили актуальность. (Например, почти 2.5 кратная разница в скорости между DirectX и OpenGL.) Поэтому, а также из-за новой аппаратной платформы, я в ближайшее время полностью перейду на OpenGL. Надеюсь, что там моего вопроса вообще не возникнет.

Что касается математики, то в приборах без DSP довольно серьезные вычисления возлагаются на CPU со-товарищи. Поэтому мне важна точность сопроцессора (не фатально, но важно). А раз так, то я, конечно, попробую D3DCREATE_FPU_PRESERVE. Спасибо уважаемый Qraizer!

Ну вот примерно так, коротенько... :-)

Не могу назвать себя специалистом в OpenGL, но там тип float вроде бы обычное дело в отличие от double.
К слову, ARMы очень хорошо следуют IEEE-754.

Цитата jur @ 06.06.12, 14:57

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

Насколько помню там тоже самое.

Цитата Qraizer @ 31.05.12, 15:27

Эх, не всё так просто.

Автор рассказывает совершенно невероятные вещи.
При этом цифра 100 ррм (и даже больше - до 1000!) вполне возможна.
Но только не в связи с таинственным исчезновением прерываний,
а по более прозаичным причинам.
1. Всем наверно уже известно, что в ПК используются неудобные кварцы
для точного отсчёта времени. Отсюда и проблемы хода часов.
2. Дело в том, что качественные показатели кварца (допустим в 1ррм) не могут
быть практически достигнуты в обычном кварцевом мультивибраторе.
Качественные показатели - такие как точность начальной установки частоты,
температурная стабильность, временная стабильность зависят также и от
внешней обвязки - конденсаторов, вентилей цифровых микросхем, резисторов
и даже индуктивностей. Если они используются в данном узле.
В итоге, даже если мы подберём частоту(кварц+делитель) для часов теоретически
абсолютно точно, реальная ошибка может составить и 0.1% - запросто.
Для работы компа в целом это не страшно, а вот для часов это не здорово.
3. если использовать кварцевый генератор - отдельный электронный компонент - тогда "да".
Но его цена обычно на порядок (плюс-минус лапоть) выше стоимости обычных кварцев.

Извиняюсь, если мой вопрос покажется неуместным, но честно говоря после чтения первого поста я вообще не понял в чём проблема!
Я честно говоря не понял в чем виноват DirectX, QueryPerformanceCounter и самое главное каким образом FPU или DirectX может влиять на QueryPerformanceCounter? Если многоуважаемые коллеги объяснили бы поподробнее, был бы признателен. Единственно в чем может быть виновата QueryPerformanceCounter, на мой взгяд, так это выдавать разные значения для разных ядер и то не всегда, но для этого можно сделать элементарную синхронизацию значений счетчиков для всех ядер.

Во втором куске кода после рестарта компьютера(который автор приводит как пример нормальной работы) видно, что время также рассинхронно(сначала последовательно увеличивается, потом есть меньшие значения). Для того чтобы время в логе было более-менее синхронно необходимо делать один поток записывающий в лог-файл, он будет принимать данные от других потоков, сортировать и выводить в файл. А если просто закрыть вывод в файл критическими секциями и использовать буферизированный вывод, то в некоторые моменты будет происходить сброс кэша на диск и все остальные потоки будут ждать пока какой-то один из потоков не разгрузит дисковой и системный кеши. Из-за этого в файле протокола и будут появляться рассинхронные данные и задержки. Здесь была такая тема "Может ли критическая секция быть причиной тормозов".

Цитата jur @ 31.05.12, 14:12

Но выдача протокола закрыта критическими секциями и каждая строка записывается путем открытия/записи/закрытия файла протокола

Вот это вообще не понял, а зачем открывать и закрывать файл, если и так стоят критические секции?

p/s/ Ещё раз, прошу рассматривать мой пост только с точки зрения того, что я хотел бы лично для себя прояснить некоторые моменты которые не понял.

Сообщение отредактировано: neokoder - 07.06.12, 11:39

Цитата neokoder @ 07.06.12, 06:53

Я честно говоря не понял в чем виноват DirectX, QueryPerformanceCounter и самое главное каким образом FPU или DirectX может влиять на QueryPerformanceCounter? Если многоуважаемые коллеги объяснили бы поподробнее, был бы признателен

DirectX устанавливает пониженную точность FPU-вычислений и тем самым загрубляет результаты не самого QueryPerformanceCounter, а его деления на frequency для получения секунд. Отсюда, 1) чем больше времени прошло со старта системы, тем заметнее погрешность, 2) в других потоках результаты не загрубляются, т.к. у каждого потока свои настройки FPU.

PS: Основной вопрос был не о "рассинхронизации", а о том, что происходит заметное загрубление выдачи времени - сначала все строки имеют различающиеся значения, а потом идут пачками с одним и тем же значением

Сообщение отредактировано: leo - 07.06.12, 14:44

Цитата leo @ 07.06.12, 14:36

DirectX устанавливает пониженную точность FPU-вычислений и тем самым загрубляет результаты не самого QueryPerformanceCounter, а его деления на frequency для получения секунд. Отсюда, 1) чем больше времени прошло со старта системы, тем заметнее погрешность, 2) в других потоках результаты не загрубляются, т.к. у каждого потока свои настройки FPU.

PS: Основной вопрос был не о "рассинхронизации", а о том, что происходит заметное загрубление выдачи времени - сначала все строки имеют различающиеся значения, а потом идут пачками с одним и тем же значением

Понятно, leo. Но так можно вообще отказаться от деления, а переведение в секунды организовать самому, минуя FPU. Это же проще гораздо чем что-то там ещё придумывать.

Я уже на это намекал, но в #29 автор заявил, что ему "важна точность сопроцессора (не фатально, но важно)" и для других расчетов

Цитата neokoder @ 07.06.12, 06:53

Я честно говоря не понял в чем виноват DirectX, QueryPerformanceCounter и самое главное каким образом FPU или DirectX может влиять на QueryPerformanceCounter?

Тут все просто. DirectX портила точность вычислений с плавающей точкой, что косвенно проявляется в протоколе :-) Я сначала подумал, что строки с одинаковым временем получаются из-за сломавшегося QueryPerformanceCounter, но уважаемый коллега Адамантэус помог понять, в чем дело.

Что касается разных ядер, то мне в общем-то до лампочки синхронизм между потоками. Тем более, что рассинхронизация, наверное, невелика.

Цитата neokoder @ 07.06.12, 06:53

Цитата jur @ 31.05.12, 14:12

Но выдача протокола закрыта критическими секциями и каждая строка записывается путем открытия/записи/закрытия файла протокола

Вот это вообще не понял, а зачем открывать и закрывать файл, если и так стоят критические секции?

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

Цитата jur @ 07.06.12, 16:50

Я так сделал потому, что раньше получал пустой файл, если программа "вылетала". Ведь данные накапливаются в буфере, а в файл они не попадают.

Сделайте лучше небуферизированный ввод/вывод. Открытие/закрытие файла отнимает кучу лишнего времени.

Сообщение отредактировано: neokoder - 07.06.12, 17:11

Цитата leo @ 07.06.12, 14:36

DirectX устанавливает пониженную точность FPU-вычислений и тем самым загрубляет результаты не самого QueryPerformanceCounter, а его деления на frequency для получения секунд. Отсюда, 1) чем больше времени прошло со старта системы, тем заметнее погрешность, 2) в других потоках результаты не загрубляются, т.к. у каждого потока свои настройки FPU.

А что, автор делил именно так? Не дельту двух значений (которые целочисленные) делил на частоту, а сначала делил и потом вычислял дельту? Ой, мамочки

Цитата Pacific @ 08.06.12, 09:50

А что, автор делил именно так? Не дельту двух значений (которые целочисленные) делил на частоту, а сначала делил и потом вычислял дельту? Ой, мамочки

Вряд ли. Думаю должен быть где-то код типа такого:

double GetElapsedSeconds(__int64 c1,__int64 c2)
{
   return ((double)(c2-c1)/double(_timer_frequency);
}

Да нет, вот тут: Ломается QueryPerformanceCounter. Как такое возможно?! (сообщение #3149130)
Такой код:

__int64 GetElapsedCount()
  {
    LARGE_INTEGER current_time;
    if( !QueryPerformanceCounter(&current_time) ) return 0;
    return current_time.QuadPart;
  }
 
  double GetElapsedSeconds()
  {
    return double(GetElapsedCount()) / double(_timer_frequency);
  }

Цитата Pacific @ 08.06.12, 09:50

А что, автор делил именно так? Не дельту двух значений (которые целочисленные) делил на частоту, а сначала делил и потом вычислял дельту? Ой, мамочки

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

Цитата leo @ 08.06.12, 13:11

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

НЕ БЫЛО БЫ СЧАСТЬЯ, ДА НЕСЧАСТЬЕ ПОМОГЛО

Цитата neokoder @ 07.06.12, 17:10

Сделайте лучше небуферизированный ввод/вывод. Открытие/закрытие файла отнимает кучу лишнего времени.

Да, спасибо, я именно так и сделал. Уже не помню, почему раньше этот момент мне не понравился. Спасибо за полезную подсказку!

Цитата Pacific @ 08.06.12, 09:50

А что, автор делил именно так? Не дельту двух значений (которые целочисленные) делил на частоту, а сначала делил и потом вычислял дельту? Ой, мамочки

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

Но! Этот момент вскрыл гораздо более важную вещь. А именно, ухудшение точности вычислений с плавающей точкой. На эти треклятые времена в протоколе можно наплевать, но удалось понять гораздо более важный вопрос. Поэтому Ваши слова: "... сначала делил и потом вычислял дельту", - это стирание двойки в дневнике, или, что намного хуже, исправление данных в анализе. Я очень рад, что анализ не исправлял, а с помощью друзей обнаружил источник болезни и нашел действенный метод ее лечения! :-)

Цитата neokoder @ 08.06.12, 10:01

Думаю должен быть где-то код типа такого:

Точно! Стопроцентное попадание :-) Вот мой нынешний код:

  __int64 GetElapsedCount()
  {
    LARGE_INTEGER current_time;
    if( !QueryPerformanceCounter(&current_time) ) return 0;
    return current_time.QuadPart;
  }
 
  double GetElapsedSeconds()
  {
    return double(GetElapsedCount()-_start_ticks) / _timer_frequency;
  }

Правда, раньше я _start_ticks не вычитал, из-за причины, изложенной выше.

Цитата neokoder @ 08.06.12, 18:41

НЕ БЫЛО БЫ СЧАСТЬЯ, ДА НЕСЧАСТЬЕ ПОМОГЛО

Именно так :-)

Сообщение отредактировано: jur - 09.06.12, 19:01