Ломается QueryPerformanceCounter. Хочу починить.

[jur]

Привет!

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

Код:

[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?! Она ведь оперирует аппаратным счетчиком в процессоре!

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

P.S. Функция CRenderer::Init инициализирует DirectX с помощью функций Direct3DCreate9(D3D_SDK_VERSION), CreateDevice(), создания нужных текстур и т.п.

[Ochkarik]

два ядра + функция снижения тактовой частоты ядер при простое.
попробуйте на эту тему поискать. или попробуйте отключить.
ЗЫ это просто мысль на вскидку... не факт что правильная)

[Вад]

Но выдача протокола закрыта критическими секциями

Запрос значения счётчика защищён той же критической секцией?

[jur]

два ядра + функция снижения тактовой частоты ядер при простое.
попробуйте на эту тему поискать. или попробуйте отключить.
ЗЫ это просто мысль на вскидку... не факт что правильная)

Не помогает... Через какое-то время все-равно ломается...

Запрос значения счётчика защищён той же критической секцией?

Нет. Я подумал, что QueryPerformanceCounter - достаточно атомарная операция, поэтому дополнительно защищать ее не стал.

Я работаю с точным таймером посредством очень простого класса. Получение текущего времени происходит с помощью этого метода:

Код:

  double GetElapsedSeconds()
  {
    LARGE_INTEGER current_time;

    if(!_timer_operable) return 0.0;
    if(!QueryPerformanceCounter(&current_time)) return 0.0;
    return double(current_time.QuadPart) / _timer_frequency;
  }

Приватная переменная класса double   _timer_frequency инициализируется в конструкторе и проверяется, чтобы не была равна нулю. А переменная BOOL   _timer_operable - просто флаг, который возвращает функция QueryPerformanceFrequency.

Сейчас пытаюсь понять, когда же и после чего эта поломка происходит. Запустил IE, Opera, Firefox, Студию. Покомпилировал, походил по сайтам, закрыл IE с Opera-ой. При этом периодически проверял, что там с протоколом. Добился того, что QueryPerformanceCounter начала деградировать, но постепенно. Сейчас она выдает не по 10-15 одинаковых времён, а только по несколько:

Код:

[837.63342] [SCUSBR2] SCUSBR2_PLD_regs_class::Preset: reg 0x16 data 0xFF index = 24
[837.63342] [SCUSBR2] SCUSBR2_PLD_regs_class::Preset: reg 0x17 data 0x00 index = 26
[837.63391] [SCUSBR2] SCUSBR2_PLD_regs_class::Preset: reg 0x18 data 0x16 index = 28
[837.63391] [SCUSBR2] SCUSBR2_PLD_regs_class::Preset: reg 0x19 data 0x38 index = 30
[837.63391] [SCUSBR2] SCUSBR2_PLD_regs_class::Preset: reg 0x1A data 0x38 index = 32
[837.63440] [SCUSBR2] SCUSBR2_PLD_regs_class::Preset: reg 0x1B data 0x38 index = 34
[837.63440] [SCUSBR2] SCUSBR2_PLD_regs_class::Preset: reg 0x1C data 0x38 index = 36
[837.63489] [SCUSBR2] SCUSBR2_PLD_regs_class::Preset: reg 0x1D data 0xFF index = 38
[837.63489] [SCUSBR2] SCUSBR2_PLD_regs_class::Preset: reg 0x1E data 0x7F index = 40
[837.63489] [SCUSBR2] SCUSBR2_PLD_regs_class::Preset: reg 0x20 data 0xFF index = 42

При нормальной работе время между очередными строками как минимум 100-200 микросекунд.

Фигня какая-то... Мистика...

P.S. При последующих измываниях над компьютером дальнейшая деградация не происходит, по-прежнему выдает только две/три строки с одинаковыми временами.

P.P.S. Поработал несколько часов - снова по 10+ строк с одинаковым временем. Гулял в Интернете (читал о лишении приватной невинности программы Skype ), немножко покомпилировал - и каюк... Черт...

[jur]

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

Дело оказалось в том, что, как предположил коллега Адамантэус, треклятая 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

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

:-)

[RXL]

Полистал справочник команд: думаю стоит заменить на FNINIT. На всякий пожарный.

[jur]

Полистал справочник команд: думаю стоит заменить на FNINIT. На всякий пожарный.

Да, я тоже думаю, что FNINIT получше будет. Я сначала подумал, что может какая-нить функция API для этого дела имеется. Но сходу не нашел, а долго и нудно разбираться поленился. Из меня эта проблема и так уже достаточно крови высосала :-)

Спасибо за подсказку!