Измерение времени выполнения

Выполняю такой код:
.data
first dd 1
second dd 1
.code
_start:
invoke timeBeginPeriod, first
invoke timeGetTime
push eax
push edx
mov ebx, 5
xor ebx, ebx
mov ebx, 45
mov ebx, 55
xor ebx, ebx
invoke timeGetTime
invoke timeEndPeriod, second
pop edx
pop eax
ret
end _start
после срабатывания второго вызова функции timeGetTime, смотрю значение eax и получается, что сохранённое и вновь полученное полностью совпадают, такое возможно?
(промежуточные функции вставлены от балды)
что не так?

 

Все так. timeGetTime измеряет время с дискретом в 1 мс, что на частоте в несколько ГГц составляет несколько миллионов тактов процессора, а твой кусок кода выполняется всего лишь несколько тактов.

Для измерения малых задержек нужно юзать rdtsc, да и то получить результаты с точностью до тика не всегда возможно.
Например, дискретность rdtsc равна 1 такту только в AMD и классических P6, а вот в P4\P4E\PentiumD она составляет 4\8\15 тактов соотв-но, в Core2 вроде как тоже дискретность = 8 тактов. Поэтому на P4 и Core2 можно сравнивать задержки только циклов или сравнительно больших кусков кода в несколько деятков или сотен тактов (причем нужно учитывать, что если просто заключить кусок кода в цикл, то общая задержка цикла может оказаться существенно меньше задержки куска * на число повторений из-за частичного перекрытия циклов во время исполнения). Ну и при включенном Hiper Threading на P4 вообще ловить нечего - его нужно отключать.
Затем сама инструкция rdtsc не является "серийной" и может выполняться праллельно с предшествующим или последующим кодом, что тоже может вносить погрешности. Поэтому для ловли блох нужно сериализовать измерения с помощью cpuid и делать поправку на задержку cpuid. Но это нормально работает только при отсутствии в тестируемом коде записей в память, т.к. при наличии записи задержка cpuid возрастает примерно на число тактов = 0.5-1 от длины конвеера - ожидание сброса всех буферов записи в кэш).
Ну и ес-но нужно проводить не одно измерение, а серию из 8-10 измерений и отбрасывать первые два, которые всегда являются завышенными, а также возможные выбросы из-за виндовых прерываний

В аттаче тестилка wintest на фасме:

 

leo
Чему равен один отсчёт в QueryPerformanceFrequency или это и есть такт?
Архив повреждён скинь ещё раз пожалуйста.

 

Всё получилось, скидывать не надо)))

 

leo

Ну так мы как раз это и ловим? Если инструкции спариваются значит хорошо. Значит на самом деле инструкции заканчивают обработку раньше. Существенные различия будут если у нас цикл состоит из малого числа инструкций 1-4 . Дискретность rdtsc может изменяться из за наличия цикла.

Это в мануэлах несказанно, точно так же как и cpuid.

А не эффект ли это того что cpuid может спариваться?

Я бы проводил бы по 100 измерений. Лучше всего 1000 и усреднить результат. Точнее будут измерения.

Пусть участок кода занимает 100 тактов при дискретности 15 и 10 измерениях (100*10+15)/10=101,5 имеем ошибку порядка 2 тактов.

Если уж нужно вычислять с точностью до блохи предлагаю к коду добавлять несколько нопов. У пентиума nop занимает процессорное время. Нужно учитывать, что она может быть вычислена любым ALU.
А вот у AMD ноп не занимает процессорного времени.

Посмотрел твой код, а как насчет многоядерных систем? В них есть возможность выполнения кода поочередно на разных процессорах. Надо бы пофиксить багу. добавить выбор процессора.

SloT
QueryPerformanceFrequency зависит от установленного в компьютер таймера.
1,19318 МГц – не встречал возможно на 486 такое и будет.
3,579545 МГц - такое значение часто встречается это ACPI Timer(APM Timer)
14,31818 МГц - Тоже возможно значение это APIC TIMER (HPET) не знаю, не встречал
Частота rdtsc. Это встречается в новых системах. Походу это вызвано тем что в новых моделях таймер имеет фиксированную частоту и "не зависит" от частоты процессора которая может меняться. А в старых системах таймер зависел от частоты процессора. Вернее частота rdtsc может выбираться при старте системы в зависимости от множителя(т.е в зависимости от частоты процессора.).

PS. Вопрос насколько секунд в сутки убигают/отстают часы компьютера?

 

SloT

QueryPerformanceFrequency выдает частоту счетчика в герцах. Если это значение примерно равно частоте проца (в герцах), значит юзается rdtsc и разность двух QueryPerformanceCounter будет соответствовать числу тактов процессора
PS: Для сравнения скорости выполнения небольших кусков кода лучше использовать именно такты процесора, а не время, т.к.число тактов не зависит от конкретной частоты, поэтому для процев одного модельного ряда, но с разными частотами, число тиков будет одинаковым.

Pavia

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

?! Сказано и в официальных манах Intel и AMD, и у А.Фога

Нет, спариваться с пред.кодом может только xor eax,eax перед cpuid.
В обычном режиме сброс буферов записи в кэш происходит с некоторой задержкой (для обеспечения store-to-load forwarding-а) и выполняется в фоновом режиме одновременно с исполнением следующего куска кода и поэтому не вносит задержки в исполняемый код. Но cpuid должна гарантировать полное завершение всех операций, включая операции записи, поэтому при наличии данных в буферах записи она вынуждена ждать пока они не будут записаны в кэш - отсюда и доп.задержка (т.к. при расчете оверхеда буферы пусты и cpuid отрабатывает быстрее, а во время теста дольше за счет ожидания сброса буферов)

wintest предназначен не просто для измерения времени выполнения, а для сравнительного анализа разных вариантов\алгоритмов реализации. Для этого нужно, чтобы измерения производились в одинаковых условиях - если условия одинаковы, то результаты разных проходов совпадают "тик в тик" и поэтому усреднять их бессмысленно. А несколько проходов делается, во-первых, для того чтобы исключить начальные погрешности, связанные с загрузкой кода и данных в кэш (плюс преддекодирование команд в атлонах и P4) и настройки предсказателя переходов, во-вторых, контроля повторяемости результатов и отбрасывания хотя и редких, но возможных выбросов из-за виндовых прерываний. Причем чем больше повторений мы накручиваем, тем дольше работает тест и тем больше вероятность прерывания потока. Какой смысл усреднять 100 результатов, если из них 99 равны скажем 100 тикам, а один сбойный = 1000 тиков ? А при выводе 10 результатов сразу видно какие значения соответствуют реальности, а какие выбиты

В АМД нопы "не занимают исполнительных ресурсов", но занимают ресурсы и время in-order стадий декодирования, диспатча и отставки, а посему съедают условную 1/3 тика на один ноп (реальный тик на 3 мопа)

Распространенное заблуждение\предостережение Переключение процессоров нужно учитывать только при измерении больших интервалов времени в десятки-сотни милисекунд и более. Однако при этом о высоких точностях вообще говорить не приходится, т.к. никому не известно насколько часто и на какое время винда будет усыплять поток. А wintest предназначена для точных измерений небольших задержек, когда код выполняется на одном процессоре и не прерывается виндой. Если прерывание все же происходит, то мы это видим по завышенному значению из серии 10 измерений и просто его не учитываем. Поэтому если не накручивать километровые циклы и не усреднять все подряд, то как раз с многоядерными процами проблем нет. А вот дебильный HT портит все результаты и бороться с ним привязкой к процессору невозможно - нужно только отключать

 

Давно реверсил хал, тока не помню что по fs:[0xAC], текущее значение счётчика производительности вроде.

Код (Text):

1. ULONG_PTR
2. HalSetProfileInterval (
3.     IN ULONG_PTR Interval
4.     );
5.  
6. HalSetProfileInterval:
7.     mov ecx,dword ptr ss:[esp+4]    ;Interval
8.     and ecx,7FFFFFFFh
9.     cmp ecx,989680h
10.     jle short 002624AB
11.     mov ecx,989680h
12. 002624AB:
13.     push ecx
14.     mov eax,dword ptr fs:[KPCR.HalReserved.ProfileScaleFactor]
15.     xor edx,edx
16.     mul ecx
17.     mov ecx,989680h
18.     div ecx
19.     mov dword ptr fs:[KPCR.HalReserved.HalProfileInterval],eax
20.     mov edx,dword ptr ds:[LAPIC_CCT]
21.     mov dword ptr ds:[PLAPIC_ICT],eax
22.     pop eax
23.     ret 4
24. ;---------------------------------------------------------------------------------------------------------
25. LARGE_INTEGER
26. KeQueryPerformanceCounter (
27.    OUT PLARGE_INTEGER PerformanceFrequency OPTIONAL
28.    );
29.  
30. KeQueryPerformanceCounter:
31.     mov edi,edi
32.     push ebp
33.     mov ebp,esp
34.     pop ebp
35.     jmp dword ptr ds:[KepQueryPerformanceCounter]   ;00260C78->26D4C8
36.  
37. extern KepQueryPerformanceCounter   ;Указатель на HalQueryPerformanceCounter ;26D4C8
38.  
39. HalQueryPerformanceCounter:
40.     mov al,byte ptr ds:[26905C]
41.     or al,al
42.     jnz short 00260CAE      ;Initialize PIT
43.     mov ecx,dword ptr ss:[esp+4]    ;PerformanceFrequency
44.     or ecx,ecx
45.     je short 00260C9B
46.     mov eax,dword ptr fs:[KPCR.KernelReserved.PerformanceFrequency]
47.     mov edx,dword ptr fs:[KPCR.KernelReserved.PerformanceFrequency+4]
48.     mov dword ptr ds:[ecx],eax  ;PerformanceFrequency + 0
49.     mov dword ptr ds:[ecx+4],edx    ;PerformanceFrequency + 4
50. 00260C9B:
51.     rdtsc
52.     add eax,dword ptr fs:[AC]
53.     adc edx,dword ptr fs:[B0]
54.     ret 4
55. ;---------------------------------------------------------------------------------------------------------
56. VOID
57. KeStallExecutionProcessor (
58.     IN ULONG MicroSeconds
59.     );
60.  
61. KeStallExecutionProcessor:
62.     mov edi,edi
63.     push ebp
64.     mov ebp,esp
65.     pop ebp
66.     jmp dword ptr ds:[pKeStallExecutionProcessor]   ;26D4C0->00260D44
67.  
68. extern pKeStallExecutionProcessor   ;Указатель на KepStallExecutionProcessor
69.  
70. KepStallExecutionProcessor:
71.     push ebx
72.     push edi
73.     xor eax,eax
74.     cpuid
75.     rdtsc
76.     mov ebx,eax
77.     mov edi,edx
78.     mov ecx,dword ptr ss:[esp+C]    ;MicroSeconds
79.     mov eax,dword ptr fs:[KPCR.StallScaleFactor]    ;4Ch
80.     mul ecx
81.     add ebx,eax
82.     adc edi,edx
83. 00260D60:
84.     rdtsc
85.     cmp edi,edx
86.     ja short 00260D60
87.     jb short 00260D6C
88.     cmp ebx,eax
89.     ja short 00260D60
90. 00260D6C:
91.     pop edi
92.     pop ebx
93.     ret 4
94. ;---------------------------------------------------------------------------------------------------------
95. VOID
96. HalCalibratePerformanceCounter (
97.     IN LONG volatile *Number,
98.     IN ULONGLONG NewCount
99.     );
100.  
101. HalCalibratePerformanceCounter:
102.     mov edi,edi
103.     push ebp
104.     mov ebp,esp
105.     push dword ptr ss:[ebp+10]
106.     push dword ptr ss:[ebp+C]
107.     push dword ptr ss:[ebp+8]
108.     call dword ptr ds:[pHalCalibratePerformanceCounter] ;26D4C4->002742E0
109.     pop ebp
110.     ret 0C
111.  
112. extern pHalCalibratePerformanceCounter  ;Указатель на HalpCalibratePerformanceCounter
113.  
114. HalpCalibratePerformanceCounter:
115.     push esi
116.     push edi
117.     push ebx
118.     mov esi,dword ptr ss:[esp+10]
119.     pushfd
120.     cli
121.     xor eax,eax
122.     lock dec dword ptr ds:[esi]
123. 002742EE:
124.     prefix rep:
125.     nop
126.     cmp dword ptr ds:[esi],0
127.     jnz short 002742EE
128.     cpuid
129.     mov ecx,MSR_TSC
130.     mov eax,dword ptr ss:[esp+18]
131.     mov edx,dword ptr ss:[esp+1C]
132.     mov dword ptr fs:[AC],eax
133.     mov dword ptr fs:[B0],edx
134.     xor eax,eax
135.     xor edx,edx
136.     wrmsr
137.     popfd
138.     pop ebx
139.     pop edi
140.     pop esi
141.     ret 0C
142. ;---------------------------------------------------------------------------------------------------------

 

leo

Ну так учесть можно. Для этого и нужно побольше цикл чтобы точнее было а то парозиты вылазят даже если 1000 циклов. Только следить чтобы небыло переключения процессов.

Ну так как раз мы сможем узнать чистое время с учетом возможности спаривания. А для точности я предлагал добавлять нопы. А то что в реальной обстановки будут другие инструкции так это должен учитывать, тот кто тестирует. А если твой код не покажет реальную обстановку то мы теряем пару тактов. Только потому что он не показывает возможности спаривания.

У Фога сказано, а в манах нет. Покажи строчку где это написано?

Не совпадают они тик в тик. Ты просто этого не видишь потому, что проводишь по 10 измерений. Проведи 100 и увидишь. Там вполне могут идти серии из 15 измерений для примера по 10 тиков и серии по 11 тиков.

В принципе я знал что ты так напишешь. Просто при больших участков кода возможны отрицательные значения как раз из-за переключения между процессорами.

 

А я против поголовного усреднения. Надо отбрасывать крайности. При сериализации (cpuid напр.) может быть заниженный результат? Т.е. крайность снизу? Думаю нет, то брать самый меньший результат как правильный. Простите вмешаюсь в дискуссию:

Проклятая защита от копирования цитат)

 

Pavia

Имеется в виду что команды осуществляющие цикл спариваются с кодом, код спаривается сам с собой и наконец жуткая вещь - реакция на выравнивание перехода в цикле. Логично интерпретировать эту кашу чтобы потом учесть весьма проблематично... Зато повторяемость у этой погрешности великолепная и сколько цикл ни крути от неё не избавишься.
ИМХО если ловить блох то нужно делать это непосредственно в том месте программы где эти блохи водятся а для оптимизации в общем виде сойдут и грубые измерения, позволяющие избавиться только от совсем уж тормозных несовершенств кода.