Общее время исполнения
Сведения о времени, которое приложение тратит на выполнение каждой точки программы, позволяют выявить его наиболее горячие участки. Правда, здесь необходимо сделать одно уточнение. Непосредственный замер покажет, что по крайней мере 99,99% всего времени выполнения профилируемая программа проводит внутри функции main, но ведь очевидно, что "горячей" является отнюдь не main, а вызываемые ею функции! Чтобы не вызывать у программистов недоумения, профилировщики обычно вычитают время, потраченное на выполнение дочерних функций, из общего времени выполнения каждой функции программы.
Рассмотрим, например, результат профилировки некоторого приложения профилировщиком profile.exe, входящего в комплект поставки компилятора Microsoft Visual C++.
Func Func+Child Hit
Time % Time % Count Function
---------------------------------------------------------
350,192 95,9 360,982 98,9 10000 _do_pswd (pswd_x.obj)
5,700 1,6 5,700 1,6 10000 _CalculateCRC (pswd_x.obj)
5,090 1,4 10,790 3,0 10000 _CheckCRC (pswd_x.obj)
2,841 0,8 363,824 99,6 1 _gen_pswd (pswd_x.obj)
1,226 0,3 365,148 100,0 1 _main (pswd_x.obj)
0,098 0,0 0,098 0,0 1 _print_dot (pswd_x.obj)
В средней колонке (Func + Child Time) приводится полное время исполнения каждой функции, львиная доля которого принадлежит функции main (ну этого следовало ожидать), за ней с минимальным отрывом следует gen_pswd со своими 99,5%, далее идет do_pswd – 98,9% и, сильно отставая от нее, где-то там на отшибе плетется CheckCRC, оттягивая на себя всего лишь 3,0%. А функцией Calculate CRC, робко откусывающей 1,6%, на первый взгляд можно и вовсе пренебречь! Итак, судя по всему, мы имеем три горячих точки: main, gen_pswd и do_pswd (см. рис. graph 0x002).
Рисунок 1 graph 0x002 Диаграмма, иллюстрирующая общее время выполнения каждой из функций.
Кажется мы имеем три горячих точки, но на самом деле это не так.
Впрочем, main можно откинуть сразу. Она – понятное дело – ни в чем не "виновата". Остаются gen_pswd и do_pswd. Если бы это были абсолютно независимые функции, то горячих точек было бы и впрямь две, но в нашем случае это не так. И, если из полного времени выполнения функции gen_pswd, вычесть время выполнения ее дочерней функции do_pswd у матери останется всего лишь… 0,8%. Да! Меньше процента времени выполнения!
Обратимся к крайней левой колонке таблицы профилировщика (funct time), чтобы подтвердить наши предположения. Действительно, в программе присутствует всего лишь одна горячая точка – do_pswd, и только ее оптимизация способна существенно увеличить быстродействие приложения.
Рисунок 2 graph 0x003 Диаграмма, иллюстрирующие чистое время работы каждой из функций (т.е. с вычетом времени дочерних функций). Как видно, в программе есть одна, но чрезвычайно горячая точка.
Хорошо, будем считать, что наиболее горячая функция определена и теперь мы горим желанием ее оптимизировать. А для этого недурно бы узнать картину распределения температуры внутри самой функции. К сожалению, профилировщик profile.exe (и другие подобные ему) не сможет ничем нам помочь, поскольку его разрешающая способность ограничивается именно функциями.
Но, на наше счастье существуют и более продвинутые профилировщики, уверенно различающие отдельные строки и даже машинные команды! К таким профилировщикам в частности относится VTune от Intel. Давайте запустим его и заглянем внутрь функции do_pswd (подробнее о технике работы с VTune см. "Практический сеанс профилировки с VTune").
Line Clock ticks Source temperature
105 729 while((++pswd[p])>'z'){ **************************>>>
106 14 pswd[p] = '!'; **************
107 1 y = y | y << 8; *
108 2 x -= k; **
109 k = k << 8; *
110 3 k += 0x59; ***
111 2 p++; **
112 1 } *
Листинг 1 Карта распределения "температуры" внутри функции do_pswd, полученная с помощью профилировщика VTune.
Вот теперь совсем другое дело – сразу видно, что целесообразно оптимизировать, а что и без того уже вылизано по самые помидоры. Горячие точки главным образом сосредоточены вокруг конструкции pswd[p], – она очень медленно выполняется. Почему? Исходный текст не дает непосредственного ответа на поставленный вопрос и потому совсем не ясно: что конкретно следует сделать для понижения температуры горячих точек.
Приходится спускаться на уровень "голых" машинных команд (благо VTune это позволяет). Вот, например, во что компилятор превратил безобидный на вид оператор присвоения pswd[p] = '!'
Line Instructions Cycles Count temperature
107 mov edx, DWORD PTR [ebp+0ch] 143 11 *****************************
107 ^ загрузить в регистр EDX указатель pswd
107 add edx, DWORD PTR [ebp-4] 22 11 *****
107 ^ сложить EDX с переменной p
107 mov BYTE PTR [edx], 021h 33 11 *******
107 ^ по полученному смещению записать значение 0х21 ('!')
Листинг 2 Исследование температуры машинных команд внутри конструкции pswd[p]='!'
Смотрите! В одной строке исходного текста происходит целых три обращения к памяти! Сначала указатель pswd загружается в регистр EDX, затем он суммируется с переменной p, которая так же расположена в памяти, и лишь затем по рассчитанному смещению в память благополучно записывается константа '!' (021h). Тем не менее, все равно остается не ясно почему загрузка указателя pswd занимает столько времени. Может быть, кто-то постоянно вытесняет pswd из кэша, заставляя процессор обращаться к медленной оперативной памяти? Так ведь нет! Программа работает с небольшим количеством переменных, заведомо умещающихся в кэше второго уровня.
