Статья Системные таймеры. Часть[6] - Основы профилирования кода

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


Аппаратные проблемы – конвейер CPU

Хотим мы того или нет, но профилируемый код рано-или-поздно попадёт в конвейер процессора. Это устройство уровня микроархитектуры позволяет процессору выполнять сразу несколько микроопераций (µOps) за такт. Кого интересуют детали его реализации, можете почитать статью на Хабре, а здесь я рассмотрю лишь связанные с ним проблемы.

В базовом варианте, исполнение процессором отдельных инструкций включает в себя 5-стадий. Поскольку в этих действиях просматривается строго определённая последовательность, её собрали в обобщённое понятие конвейер PipeLine:


1. Загрузка инструкции из кэша L1;
2. Разложение её на мелкие микрооперации – декодирование;
3. Загрузка привязанных к инструкции операндов (регистры/память);
4. Непосредственное исполнение микроопераций в блоках Execution ядра процессора;
5. Сброс результата обратно в регистры или память (отставка WriteBack).

Процессор принято разделять на два территориальных субъекта – исполнительное ядро BackEnd, и обеспечивающий работу ядра транспортный цех FrontEnd (см.рис.ниже). Эти два термина фломастером проводят черту так, что этапы 1,2,3 конвейера оказываются на территории фронта (на входе в процессор), а 4 и 5 лежат в исполнительном тылу BackEnd.

В ядре современного процессора могут находиться более 8-ми исполнительных блоков Execution-Unit: несколько целочисленных ALU, и отдельно для плавающей точки FPU. После декодирования инструкций на стадии[2], их микрокоды попадают в (жёлтый) блок-резервации, от куда в зависимости от типа инструкции подхватываются портами[0:2] исполнительных устройств:


Core.png


Cиним здесь выделены восемь мартеновских печей Execute, а зелёные блоки демонстрируют этап отставки WriteBack. Такому кол-ву блоков фронт должен поставлять непрерывный поток данных, иначе они будут по-просту голодать. Но построенные на базовых принципах конвейеры не справлялись с этой задачей, и пришлось к первой транспортной ленте добавить ещё 4 сдвинутых по фазе лент. Так конвейер стал скалярным и на продуктовую дотацию могут рассчитывать уже все исполнительные блоки ядра.

Позже выяснилось, что программисты редко используют сопроцессор FPU – в основном вся нагрузка ложится на целочисленные ALU. Это послужило толчком к технологии Hyper-Threading идея которой в том, чтобы создать ещё одну ксеро-копию фронта, не затрагивая при этом BackEnd. В результате ядро осталось прежним, зато транспортных жил получи две. Такая схема известна как "параллелизм на уровне потоков", хотя внутри ядра имеется ещё и параллелизм на уровне микро-инструкций (в данном случае 5 за такт). Основное требование к любого типа конвейерам – одинаковые его ширина и глубина, иначе в нём теряется смысл.

На рисунке ниже, стадии конвейера выделены цветом: [1]загрузка инструкции, [2]декодирование, [3]операнды, [4]исполнение, [5]запись результата. В сумме, процессор с уже прогретым 5-уровневым конвейером за один свой такт сможет выполнить 5 различных микроопераций в глубину
(не путать с инструкциями, которые стоят в иерархии выше и представлены здесь в виде одной строки):

Pipeline.png


Ещё у Pentium конвейер был 12-уровневым (я отобразил здесь только 4 в глубину), а на некоторых процессорах встречались даже 32-уровневые конвейеры. Создавая таких монстров инженеры преследовали всего одну цель – заставить процессор выполнить как-можно больше м/операций за единицу времени. Однако идея длинных конвейеров не прижилась из-за спекулятивного выполнения команд процессором. К примеру если переход был предсказан неверно, приходилось перезагружать его более длинной цепочкой. Поэтому в современном мире используются в среднем 14-уровневые конвейеры, а на процессорах с поддержкой HT (т.е. все Intel и некоторые AMD) он ещё и гипер-скалярный.

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


C-подобный:
;// Не правильный вход в профайлер
;// ------------------------------
     rdtsc            ;// EAX = счётчик TSC на входе
     push    eax      ;// запомнить его

;// ..... ;// сюда помещаем профилируемый код

     rdtsc            ;// EAX = счётчик на выходе
     pop     ebx      ;// EBX = счётчик на входе
     sub     eax,ebx  ;// вычислить разницу!
                      ;// EAX = время профилируемого кода в тактах процессора.

На первый взгляд вроде всё ОК.. но мы не учитываем здесь особенности работы ООО-ядра. Процессоры выполняют инструкции абсолютно не в том порядке, в котором они следуют в нашем коде, т.е. беспорядочно, спекулятивно. Собственно об этом говорит и архитектура их ядер "Out-Of-Order", ООО. Таким образом профилируемый код может попасть в ядро и выполниться там задолго до того, как отработает первый RDTSC на входе. Ясно, что в этом случае вместо ток-шоу мы получим порно.

Сбросить конвейер в дефолт позволяет т.н. сериализация потока команд, и ассемблер имеет специальные инструкции для этого. Выбрав одну из них, мы должны будем предварять ею каждое чтение счётчика TSC, чтобы профилируемый код не бежал впереди паровоза, а входил в девственный конвейер уже после чтения счётчика. Вот их перечень:


C-подобный:
;// Привилегированные инструкции сериализации,
;// которые нужно вызывать из RMode, или драйвера Win:
      MOV    CR,xxxx    ;// запись в контрольные регистры CR0..CR4
      MOV    DR,xxxx    ;// запись в регистры отладки DR0..DR7
      WRMSR             ;// запись в любые регистры MSR
      LGDT              ;// обновление таблицы дескрипторов GDT/LDT
      WBINVD            ;// инвалидация кэшей (их очистка)

;// Непривилегированные инструкции сериализации,
;// которые можно вызывать из любого уровня:
      CPUID             ;// идентификация процессора
      LFENCE            ;// Load Fence
      RDTSCP            ;// чтение усовершенствованного TSCР

Здесь видно, что у нас (как юзеров без привилегий) вариантов всего три..
lfence ставит барьер на последующее чтение кода по-типу шлагбаума и гарантирует, что на момент её вызова все имеющиеся в конвейере инструкции уже сойдут с него.. т.е. просто ждёт, поэтому и латентность (задержка) у неё большая – порядка 30-ти тактов. Но по сравнению с ней cpuid вообще тяжеловес, и тусуется в весовой категории от 100 до 500 тактов, в зависимости от модели процессора и аргумента в EAX. Инструкцию rdtscp поддерживают только 64-битные процессоры, поэтому оставлю её на ваше усмотрение.


C-подобный:
;// Правильный вход в профайлер
;// ----------------------------
     lfence            ;// подождать исполнения уже загруженного кода
     rdtsc             ;// счётчик TSC на входе в чистый конвейер
     push    eax edx   ;// запомнить его

;// ..... ;// сюда помещаем профилируемый код

     lfence            ;// подождать очистки конвейра
     rdtsc             ;// счётчик на выходе
     pop     ecx ebx   ;// счётчик на входе
     sub     eax,ebx   ;// вычислить разницу!
     sbb     edx,ecx   ;// EDX:EAX = время профилируемого кода в тактах процессора.

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


Проблемы ОС – планировщик потоков

Чтобы создать иллюзию одновременного выполнения нескольких задач, Win использует основанную на приоритетах "вытесняющую многозадачность". В этой схеме, в первую очередь обслуживаются процессы с высоким приоритетом в диапазоне 31..16. Пользовательским приложениям система назначает нижнюю половину с номерами от 15 до 1 – с барского стола им может перепасть только тогда, когда насытятся буржуи. И даже в этом случае, если во-время исполнения нашего процесса вдруг проснётся процесс в более высоким приоритетом, он сразу-же отберёт наше время, хоть мы и не отработали его до конца. Именно поэтому схему назвали вытесняющей..

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

BaseClass.png


По-умолчанию, пользовательским процессам система назначает класс Normal и соответственно потоки получают относительный приоритет [8]. Под этим флагом ходят почти все процессы в системе, и лишь некоторым из них она присваевает класс High. К примеру высокий приоритет имеет диспетчер-задач Taskmgr.exe, что позволяет ему вытеснять зависшие приложения. Если-бы у них был равный приоритет, это было-бы невозможно:


TaskMan.png


Система сажает на жёсткую диету все процессы с приоритетом Normal не оставляя им ни единого шанса получить квант до тех пор, пока работают процессы с более высоким приоритетом. Но тогда каким-же образом достигается компромисс, ведь наши потоки рискуют вообще никогда не попасть в поле зрения планировщика? Инженеры решили эту проблему просто.. Помимо приоритетов, с каждым потоком связывается понятие "состояние потока".

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

Потоки Thread могут находиться в одном из семи состояний, но только 4 из них заслуживают внимания. Обычной является ситуация, когда запущено два и более равноправных треда. К примеру сейчас у меня в фоне Total-Commander копирует файлы на флэшку, а в это время я печатаю текст. Тогда планировщик маятником выделяет квант мне, и по его истечению – квант тоталу, и так рекурсивно. Если-же в фоне имеется ещё один процесс но с более низким приоритетом (типа спуллер печати), он будет ждать, пока мы с тоталом не решим свои проблемы.


Sheduler.png


Процессорное время в виде квантов выделяется только тем потокам, которые находятся в состоянии "Running". В очередь-ожиданий поток может попасть или по нашему бездействию, или-же его могут вогнать туда функции типа Sleep() или WaitForХХObject(). В любом случае, пока не отработают все потоки из верхнего блока с приоритетом High, синему блоку с пулом Normal ничего не светит, но правда с небольшой поправкой. Не взирая на приоритеты, планировщик следит за всеми готовыми к исполнению потоками. Если в течении 4-сек готовый поток не получает управления, ему всё-же выделяется один квант, видимо из соображений жалости.

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

Оперировать приоритетами потоков позволяет функция SetThreadPriority(), а задавать базовые приоритеты процессам SetPriorityClass(). Причём делать это можно динамически, в произвольный момент времени, а не только при старте процесса/потока. Вот их прототипы (обе функции при ошибке возвращают нуль):


C-подобный:
BOOL SetPriorityClass(    ;//<---- задаёт базовый приоритет процессу!
    hProcess,             ;// дескриптор процесса (-1 для своего)
    dwPriorityClass       ;// запрашиваемый приоритет
   );
;//===== Класс приоритета ===============
REALTIME_PRIORITY_CLASS   ;// 0x100
    HIGH_PRIORITY_CLASS   ;// 0x80
  NORMAL_PRIORITY_CLASS   ;// 0x20
    IDLE_PRIORITY_CLASS   ;// 0x40


BOOL SetThreadPriority(   ;//<---- задаёт приоритет потоку процесса!
    hThread,              ;// дескриптор потока, можно получить через GetCurrentThread()
    dwPriority            ;// запрашиваемый уровень приоритета
   );
;//===== Уровни приоритетов =============
THREAD_PRIORITY_TIME_CRITICAL   ;//  15  критический!
THREAD_PRIORITY_HIGHEST         ;//  2   высокий
THREAD_PRIORITY_ABOVE_NORMAL    ;//  1
THREAD_PRIORITY_NORMAL          ;// 0    средний
THREAD_PRIORITY_BELOW_NORMAL    ;// -1
THREAD_PRIORITY_LOWEST          ;// -2   низкий
THREAD_PRIORITY_IDLE            ;// -15  фоновый

Текущий приоритет в регистр EAX возвращают родственные им функции GetPriorityClass() и GetThreadPriority().


Сбор информации о таймере Windows

Рассмотрим легитимные функции, которые предлагает нам система для измерения интервалов времени.

1. GetSystemTimeAdjustment() – возвращает интервал программного таймера ОС.
Как-правило это значение равно 15.625 милли-сек, и соответственно получаем частоту: 1 / 0.015625 = 64 Гц.
Таймер с таким разрешением – это слон в посудной лавке, но что примечательно, почти все системные функции наоборот прослушивают именно его:


GetTickCount() – возвращает счётчик милли-секунд, прошедших с момента последнего старта системы.
GetSystemTime() – возвращает текущее время Windows.
timeGetTime() – точная ксерокопия GetTickCount().
Sleep() – усыпляет поток на указанное количество милли-секунд.

API из этого списка абсолютно не пригодны для использования в профайлерах, т.к. ни одна из них не сможет вернуть значение меньше 15.625 ms. То-есть получаем мёртвую зону во времени с шагом: 15.625 --> 31.250 --> 46.875, и т.д.. Единственная функция, от которой можно поиметь выгоду это Sleep(). С её помощью, в течении 1-сек обычно калибруют какой-нибудь счётчик, чтобы узнать его частоту. Но и в этом случае мили-секунды принудительно округляются до величины, кратной тику системного таймера.

=== Важно! ===============
Выше упоминалось, что время, выделяемое потоку на исполнение исчисляется в квантах.
Во-всех клиентских версиях Win длительность одного кванта равна двум тикам системного таймера 15.625 *2 = 31.250 ms. Если система серверная, то квант растягивается на 12-тиков, или 187.5 ms. Как-только поток израсходует свой квант, планировщик сохраняет контекст его регистров, и даёт возможность поработать такое-же время сл.потоку в очереди, и так по кругу
.

Теперь перейдём к функциям тяжёлой артиллерии..

2. QueryPerformanceFrequency() – возвращает частоту высокоточного таймера HPET (High-Precision-Event-Timer). Его использует заслуживающий доверие системный монитор производительности (Win+R-->perfmon). В отличии от предыдущего таймера 60 Hz, частота НРЕТ уже 14 MHz. Если HPET аппаратно не доступен, монитор садится на ACPI-таймер 3.579 MHz. Здесь мы имеем дело уже не с программным таймером Win, а с аппаратными девайсами чипсета.

На этой частоте работает счётчик QueryPerformanceCounter(). Функция возвращает кол-во тиков высокоточного таймера (HPET или ACPI). Используя пару QPC+QPF, можно контролировать отрезки времени с интервалом: 1 / 3579545 = 279 нано-секунд. Хороший выстрел..

3. CPU frequency – тактовая частота процессора. Если даже взять мин.частоту CPU=1.0 GHz, то получим разрешение в 1 нано-сек. Профайлер с таким разрешением позволит замерять не только блоки программного кода, но и время выполнения отдельных инструкций ассемблера. В качестве счётчика этой частоты используется специально предназначенный для этих целей TSC (Time-Stamp-Counter). Вот это наш клиент!



Формула времени

В компьютерной системе счётчик тиков служит для измерения длительности какого-либо события. Чтобы из этого счётчика получить время в секундах, мы должны знать частоту, на которой работает данный счётчик. Тогда разделив кол-во тиков на частоту, получим время: Time = Ticks / Frequency. Частота в герцах вычисляется просто.. достаточно включить счётчик и подождать ровно 1-сек.

Понятия "счётчик и его частота" жёстко привязаны друг-к-другу и нужно соблюдать между ними симметрию. К примеру, заведомо ложное время даст попытка деления счётчика TSC на частоту таймера HPET, поскольку TSC увеличивается с каждым тактом процессора, а не с тиком НРЕТ. Если мы считаем при помощи QueryPerformanceCounter(), то её показания должны делить строго на QueryPerformanceFrequency() и ни на что другое.

Судя по списку выше, использовать в своём профайлере мы можем всего три устройства:


1. Системный таймер с нарушенным вестибулярным аппаратом и частотой всего 64 Гц – GetTickCount();
2. Резидент внешней разведки – таймер HPET/ACPI со-своим счётчиком QueryPerformanceCounter();
3. Несомненный лидер этого списка – счётчик процессора TSC.

Математический сопроцессор FPU

Поскольку центр тяжести смещается здесь в сторону TSC, то условимся в профайлере использовать именно его. Проблему больших частот и мелких отрезков времени придётся решать при помощи сопроцессора FPU и чисел с плавающей точкой (1 нано-сек, это 0.000000001 сек). Из инструкций сопра понадобятся всего три:

FILD - загрузить тики профилируемого кода в регистр FPU;
FIDIV – разделить тики на частоту процессора;
FSTP – сохранить полученное время в переменной размером qword (8-байт).

FPU имеет 8-регистров ST0..ST7, которые организованы в виде стека. Если регистр не указывается явно, то подразумевается ST0. Каждая загрузка значений инструкцией FILD приводит к тому, что весь стек смещается вниз, а на место первого ST0 встаёт загружаемое значение. Инструкция FST просто сохраняет ST0 в переменной (store), а FSTP сохраняет и снимает его со-стека (при этом весь стек смещается вверх). Вот пример операций из моего демо-профайлера (результат деления лежит в регистре ST0):

fpu.png


Для вывода на консоль полученного времени, воспользуемся всё тем-же printf() со-спецификатором %.3f, где 3 – это кол-во знаков после микро-секундной точки, т.е нано-сек. Ничто не мешает указать и 6, тогда получим пико-секунды (см.кол-во разрядов в регистре ST0 на рисунке выше). Но не будем доводить ситуацию до абсурда, т.к. при каждом последующем запуске профайлера пико (и даже нано-сек) всё-равно не будут стабильны – это погрешность, которую нужно воспринимать как неотъемлемую часть жёстких сил природы.


Практическая часть

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

Подглядывая за ходом работы процессора может возникнуть резонный вопрос – насколько правильные данные возвращает нам профайлер? ..т.е. не плохо-бы иметь под рукой эталонные значения. На эту роль претендует таблица растактовок Агнера Фога, которую можно
стянуть от сюда. Расход тактов на одну и туже инструкцию зависит от микро/архитектуры процессора и варьируется он в широких пределах. Агнер не поленился и собрал в одной доке информацию сразу обо всех актуальных процессорах. По этой причине, в демо-профайлере я предусмотрел вывод кодового имени CPU, прицепив к нему небольшую базу (пока только Intel, без AMD). Возвращает этот код CPUID с аргументом EAX=1:

C-подобный:
.data
table      dd   0x006d,dohan, 0x006e,yonah, 0x006f,conroe,0x00f2,netburst
           dd   0x1067,wolf,  0x106a,bloom, 0x106e,lynn,  0x206c,gulf
           dd   0x2065,arra,  0x206e,neh,   0x206f,west,  0x3067,silver
           dd   0x206a,sandy, 0x206d,sandy, 0x306a,ivy,   0x306e,ivy
           dd   0x306c,hass,  0x306f,hass,  0x4065,hass,  0x4066,hass
           dd   0x306d,broad, 0x4067,broad, 0x406f,broad, 0x5066,broad
           dd   0x406e,sky,   0x5065,sky,   0x506e,sky,   0x00f4,pres
           dd   0x506c,apollo,0x806e,kaby,  0x906e,coffe, 0x706a,gemini
           dd   0x406a,merri, 0x406c,charry,0x406d,avoton,0x5067,phi
           dd   0x506c,brox,  0x506a,moor,  0x506f,denver,0x606e,cougar
tableLen   =    ($ - table)/8

dohan      db   'Dothan',0
yonah      db   'Yonah',0
conroe     db   'Conroe',0
netburst   db   'Netburst',0
pres       db   'Prescott',0
wolf       db   'Wolfdale',0
bloom      db   'Bloomfield',0
lynn       db   'Lynnfield',0
gulf       db   'Gulftown',0
arra       db   'Arrandale',0
neh        db   'Nehalem',0
west       db   'Westmere',0
silver     db   'Silvermont',0
sandy      db   'Sandy-Bridge',0
ivy        db   'Ivy-Bridge',0
hass       db   'Haswell',0
broad      db   'Broadwell',0
sky        db   'Sky-Lake',0
apollo     db   'Apollo-Lake',0
kaby       db   'Kaby-Lake',0
coffe      db   'Coffee-Lake',0
gemini     db   'Gemini-Lake',0
merri      db   'Merrifield',0
charry     db   'Cherry View',0
avoton     db   'Avoton',0
phi        db   'Phi-Knights',0
brox       db   'Broxton',0
moor       db   'Moorefield',0
denver     db   'Denverton',0
cougar     db   'Cougar-Mountain',0
unk        db   'Unknown',0      
;//---------

Большинство штатных API определяют версию платформы (Win-7/8/10) из реестра. Однако интересней вытащить её без посторонней помощи из структуры РЕВ процесса. Это актуально например для шелл-кодов, которые должны выживать в природе без обращения к сервисам ОС. Нужные поля начинаются со-смещения 0хА4 среди которых есть и номер сборки Build. Привязав к этому Build текстовую строку, можно выводить её на экран:

Peb_sys.png


C-подобный:
buildTbl   dd  2600,wXp,3790,wXp64,6001,wVst,7600,w7,7601,w7
           dd  9200,w8, 9600,w81, 17763,w10,18363,w10
buildLen   =   ($ - buildTbl)/8

wXp        db  '  Win-XP Service Pack ',0
wXp64      db  '  Win-XP 64 Service Pack ',0
wVst       db  '  Win-Vista Service Pack ',0
w7         db  '  Win-7 Service Pack ',0
w8         db  '  Win-8 Service Pack ',0
w81        db  '  Win-8.1 Service Pack ',0
w10        db  '  Win-10 Service Pack ',0
unk        db  '  Unknown ',0

В демонстрационном примере ниже я вывел вход и выход из профайлера в отдельные макросы Start/StopProfile. Макросы удобны тем, что упрощают чтение кода и избавляют от повторяющихся участков, но только в исходнике, а не в уже скомпилированном коде (см.отладчик). Внешним инклудом я сделал и вспомогательные процедуры, которые просто собирают информацию о системе и не имеют непосредственного отношения к процессу профилирования – это позволит сконцентрировать внимание только на полезной нагрузке Payload. Исходники main и инклуд-прицепа можно найти в скрепке.

C-подобный:
format   pe console
include 'win32ax.inc'
include 'profile.inc'
entry    start
;//---------
.data
title      db  ' [ Code Profile ] ver.0.1',0
sysInfo    db  10,' System info..'
           db  10,'    OS Build...........:  %d.%d.%d',0
cpuArch    db  10,'    Processor..........:  %d MHz  ----> %s',0
perFreq    db  10,'    Perf-Mon frequency.:  %d.%d MHz',0
tmrRes     db  10,'    System Timer.......:  %d.%d ms',0

info       db  10,'    %12.0f Ticks = %.3f Micro/sec',0

str01      db  10,10,' RDTSC'
           db  10,   ' -------------------',0
str02      db  10,10,' LFENCE'
           db  10,   ' -------------------',0
str03      db  10,10,' Sleep 500'
           db  10,   ' -------------------',0

profTick   dq  0   ;// qword под тики TSC
profTime   dq  0   ;// qword под время FPU
cpuFreq    dd  0   ;// частота процессора
counter    dd  0   ;// счётчик повторов
fix        dd  0   ;// погрешность LFENCE

tAdjust    dd  0   ;// переменные,
tResolut   dd  0   ;//  ..для функции,
tDisable   dd  0   ;//    ..GetSystemTimeAdjustment()

align      8
qpf        dd  0,0  ;// для fn.QueryPerformanceFrequency()
buff       db  0
;//*****************************************
;// оформляем макросы
macro     StartProfile
{         lfence
          rdtsc
          push    eax edx }   ;// запомнить счётчик TSC

;// ===== Макрос на выходе
;// вычитает разницу тиков и выводит на консоль тики/время
macro     StopProfile
{         lfence
          rdtsc
          pop     ecx ebx     ;// счётчик TSC на входе
          sub     eax,ebx     ;//
          sbb     edx,ecx     ;// EDX:EAX = разница в тиках
          sub     eax,[fix]   ;// применить погрешность
          push    edx eax     ;// положить в стек для FPU

          finit                ;// ======== сопроцессор ==========
          fild    qword[esp]   ;// взять тики со-стека в регистр ST0
          fst     [profTick]   ;// сохранить их в переменной для вывода
          fidiv   [cpuFreq]    ;// получить время = тики / частоту CPU
          fstp    [profTime]   ;// сохранить время в переменной!
          add     esp,8        ;// восстановить стек от пушей..

         cinvoke  printf,info,dword[profTick],dword[profTick+4],\
                              dword[profTime],dword[profTime+4]
}
;//***** С Е К Ц И Я  К О Д А *********************
.code
start:  invoke  SetConsoleTitle,title        ;// обзовём консоль
        invoke  SetProcessAffinityMask,-1,1  ;// оставить только одно ядро CPU
        invoke  SetPriorityClass,-1,HIGH_PRIORITY_CLASS  ;// повысить приоритет процесса!!!

        call    Initialize      ;// проводим инициализацию из инклуда..
                                ;// выводит версию системы, частоты и т.п.

;//==== Профилируем саму инструкцию RDTSC ==================
       cinvoke  printf,str01
        mov     [counter],5     ;// количество прогонов
@@:     StartProfile            ;// зовём макрос

        rdtsc                   ;// код, время которого хотим узнать

        StopProfile             ;// выводим данные на консоль
        dec     [counter]       ;//
        jnz     @b              ;// повторить 5-раз..

;//==== Время инструкции LFENCE ===========================
       cinvoke  printf,str02
        mov     [counter],5
@@:     StartProfile

        lfence

        StopProfile
        dec     [counter]
        jnz     @b

;//==== Профилируем функцию Sleep(), ======================
;//==== с задержкой 500 милли-секунд, или 0,5 сек
       cinvoke  printf,str03
        mov     [counter],5
@@:     StartProfile

        invoke  Sleep,500

        StopProfile
        dec     [counter]
        jnz     @b

@exit: cinvoke  gets,buff     ;// ждём клаву..
       cinvoke  exit,0        ;// на выход!

;//*************************************************************
;// секция для базы-данных: версия системы и м/архитектура CPU
section '.info' data readable writable
build      dd  0
buildTbl   dd  2600,wXp,3790,wXp64,6001,wVst,7600,w7,7601,w7
           dd  9200,w8, 9600,w81, 17763,w10,18363,w10
buildLen   =   ($ - buildTbl)/8

wXp        db  '  Win-XP Service Pack ',0
wXp64      db  '  Win-XP 64 Service Pack ',0
wVst       db  '  Win-Vista Service Pack ',0
w7         db  '  Win-7 Service Pack ',0
w8         db  '  Win-8 Service Pack ',0
w81        db  '  Win-8.1 Service Pack ',0
w10        db  '  Win-10 Service Pack ',0
unk        db  '  Unknown ',0
;//----------------
;// база микроархитектуры процессора
table      dd   0x006d,dohan, 0x006e,yonah, 0x006f,conroe,0x00f2,netburst
           dd   0x1067,wolf,  0x106a,bloom, 0x106e,lynn,  0x206c,gulf
           dd   0x2065,arra,  0x206e,neh,   0x206f,west,  0x3067,silver
           dd   0x206a,sandy, 0x206d,sandy, 0x306a,ivy,   0x306e,ivy
           dd   0x306c,hass,  0x306f,hass,  0x4065,hass,  0x4066,hass
           dd   0x306d,broad, 0x4067,broad, 0x406f,broad, 0x5066,broad
           dd   0x406e,sky,   0x5065,sky,   0x506e,sky,   0x00f4,pres
           dd   0x506c,apollo,0x806e,kaby,  0x906e,coffe, 0x706a,gemini
           dd   0x406a,merri, 0x406c,charry,0x406d,avoton,0x5067,phi
           dd   0x506c,brox,  0x506a,moor,  0x506f,denver,0x606e,cougar
tableLen   =    ($ - table)/8

dohan      db   'Dothan',0
yonah      db   'Yonah',0
conroe     db   'Conroe',0
netburst   db   'Netburst',0
pres       db   'Prescott',0
wolf       db   'Wolfdale',0
bloom      db   'Bloomfield',0
lynn       db   'Lynnfield',0
gulf       db   'Gulftown',0
arra       db   'Arrandale',0
neh        db   'Nehalem',0
west       db   'Westmere',0
silver     db   'Silvermont',0
sandy      db   'Sandy-Bridge',0
ivy        db   'Ivy-Bridge',0
hass       db   'Haswell',0
broad      db   'Broadwell',0
sky        db   'Sky-Lake',0
apollo     db   'Apollo-Lake',0
kaby       db   'Kaby-Lake',0
coffe      db   'Coffee-Lake',0
gemini     db   'Gemini-Lake',0
merri      db   'Merrifield',0
charry     db   'Cherry View',0
avoton     db   'Avoton',0
phi        db   'Phi-Knights',0
brox       db   'Broxton',0
moor       db   'Moorefield',0
denver     db   'Denverton',0
cougar     db   'Cougar-Mountain',0

;//*******************************************************
section '.idata' import data readable
library  msvcrt,'msvcrt.dll',kernel32,'kernel32.dll'
import   msvcrt, printf,'printf',exit,'exit',gets,'gets'
include 'api\kernel32.inc'

Result.png


Обратите внимание, что время исполнения инструкций напрямую зависит от тактовой частоты процессора. На правом скрине частота ~1 GHz и потому время почти совпадает с тиками счётчика TSC, т.к. соотношение 1:1. Зато на левом.. с частотой процессора 2.5 GHz, потраченные на RDTSC такты почти такие-же, а вот расходное время уже в 2-раза меньше. Кроме того здесь видно, что микро/архитектура "Wolfdale" в тактах выполняет инструкцию LFENCE в 4-раза быстрее, чем это делает "Gemini-Lake", поэтому поправки на очистку конвейера в виде константы тут не преемлемы, и нужно вычислять её динамически, что собственно и предусмотрено в коде.

Посмотрите, сколько времени исполнялась функция Sleep() с 500 милли-сек задержкой, и сколько на неё тратят тактов CPU с различной тактовой частотой. Время в обоих случаях правильное и равно ~500'000 микро-сек (это говорит о том, что профайлер работает корректно). Но вот по тактам, за это время процессору с 2-раза большей частотой приходится и простучать в 2-раза больше – 1 млрд, против 500 млн.

Заслуживает внимания и частота, которую возвращает нам функция QueryPerformanceFrequency(). Мой бук с десяткой юзает НРЕТ, а десктопный чипсет G41 с семёркой вообще что-то среднее между ACPI-таймером (частота 3.5 MHz) и древним таймером PIT. В отличии от перфмона, системный таймер ОС никуда не спешит и в обоих случаях период его активности ограничивается одним разом в 15.6 милли-сек. Кстати именно поэтому, если вскормить профайлеру Sleep() с аргументом в диапазоне 1..14, он будет возвращать 15.6 ms. Это потому, что более мелкие интервалы вызывают помешательство функции, т.к. она физически не может отследить меньшее время, а только кратное 15. (правда при помощи timeBeginPeriod(1) можно уменьшить его до 1 ms, но это уже другая история).



Заключение

В наше время, заниматься профилированием кода ради оптимизации программ не имеет смысла – это было актуально на заре компьютерной индустрии. Процессоры (в том числе и компиляторы, особенно С++) сейчас намного умнее некоторых программистов, и на автомате отсеивают бесполезный код. Тестирование производительности скорее носит спортивный интерес, позволяя продвигаться всё глубже в дебри аппаратных механизмов. Есть поговорка: -"глухой считает, что те-кто танцуют – сумасшедшие". Так и здесь.. Некоторым это занятие может показаться бесполезным, но только не тем, кто увлечён низкоуровневым программированием. Раз-уж ассемблер сам предлагает нам такие возможности, так почему-же ими не воспользоваться?
 

Вложения

  • PROFILE.ZIP
    5,3 КБ · Просмотры: 401
Последнее редактирование:

Katran

One Level
13.06.2020
3
1
Мне было очень интересно. Спасибо за статьи.
 
Мы в соцсетях: