Практический сеанс профилировки с VTune в десяти шагах
Любой, даже самый совершенный, инструмент бесполезен, если мастер не умеет держать его в руках. Профилировщик VTune не относится к категории интуитивно-понятных программных продуктов, которые легко осваиваются методом "тыка". VTune – это профессиональный инструмент, и грамотная работа с ним немыслима без специального обучения. В противном случае, большой пласт его функциональных возможностей так и останется незамеченным, заставляя разработчика удивленно пожимать плечами "и что только в этом VTune остальные нашли?".
Настоящая глава ### статья, на учебник не претендует, но автор все же надеется, что она поможет сделать вам в освоении VTune первые шаги и познакомится с его основными функциональными возможностями и к тому же поможет вам решать: стоит ли использовать VTune или же лучше остановить свой выбор на более простом и легком в освоении профилировщике.
В качестве "подопытного кролика" для наших экспериментов с профилировкой и оптимизацией мы используем простой переборщик паролей. Во?первых, это наглядный и вполне реалистичный пример, а, во-вторых, в программах подобного рода требование к производительности превыше всего. Предвидя возможное негодование некоторых читателей, сразу же замечу, что ни о каком взломе настоящих шифров и паролей здесь речь не идет! Реализованный в программе криптоалгоритм не только нигде не используется в реальной жизни, но к тому же допускает эффективную атаку, раскалывающую зашифрованный текст практически мгновенно.
В первую нас очередь будет интересовать не сам взлом, а техника поиска горячих точек и возможные способы их ликвидации. Словом, ничуть не боясь оскорбить свою пуританскую мораль, набейте в редакторе исходный тест следующего содержания:
//----------------------------------------------------------------------------
// Это пример того, как не нужно писать программы! Здесь допущено множество
// ошибок, снижающих производительность. Профилировка позволяет найти их все
// --------------------------------------------------------------------------
// КОНФИГУРАЦИЯ
#define ITER 100000 // макс. итераций
#define MAX_CRYPT_LEN 200 // макс. длина шифротекста
// процедура расшифровки шифротекста найденным паролем
DeCrypt(char *pswd, char *crypteddata)
{
int a;
int p = 0; // указатель текущей позиции расшифровываемых данных
// * * * ОСНОВНОЙ ЦИКЛ РАСШИФРОВКИ * * *
do {
// расшифровываем текущий символ
crypteddata[p] ^= pswd[p % strlen(pswd)];
// переходим к расшифровке следующего символа
} while(++p < strlen(crypteddata));
}
// процедура вычисления контрольной суммы пароля
int CalculateCRC(char *pswd)
{
int a;
int x = -1; // ошибка вычисления CRC
// алгоритм вычисления CRC, конечно, кривой как бумеранг, но ногами чур
// не пинать, - это делалось исключительно для того, чтобы
// подемонстрировать missaling
for (a = 0; a <= strlen(pswd); a++) x += *(int *)((int)pswd + a);
return x;
}
// процедура проверки контрольной суммы пароля
int CheckCRC(char *pswd, int validCRC)
{
if (CalculateCRC(pswd) == validCRC)
return validCRC;
// else
return 0;
}
// процедура обработки текущего пароля
do_pswd(char *crypteddata, char *pswd, int validCRC, int progress)
{
char *buff;
// вывод текущего состояния на терминал
printf("Current pswd : %10s [%d%%]\r",&pswd[0],progress);
// проверка CRC пароля
if (CheckCRC(pswd, validCRC))
{ // <- CRC совпало
// копируем шифроданные во временный буфер
buff = (char *) malloc(strlen(crypteddata));
strcpy(buff, crypteddata);
// расшифровываем
DeCrypt(pswd, buff);
// выводим результат расшифровки на экран
printf("CRC %8X: try to decrypt: \"%s\"\n",
CheckCRC(pswd, validCRC),buff);
}
}
// процедура
перебора паролей
int gen_pswd(char *crypteddata, char *pswd, int max_iter, int validCRC)
{
int a;
int p = 0;
// генерировать
пароли
for(a = 0; a < max_iter; a++)
{
// обработать
текущий пароль
do_pswd(crypteddata, pswd, validCRC, 100*a/max_iter);
// * основной цикл генерации паролей *
// по алгоритму "защелка" или "счетчик"
while((++pswd[p])>'z')
{
pswd[p] = '!';
p++; if (!pswd[p])
{
pswd[p]=' ';
pswd[p+1]=0;
}
} // end while(pswd)
// возвращаем указатель на место
p = 0;
} // end for(a)
return 0;
}
// Функция выводит число, разделяя разряды точками
print_dot(float per)
{
// * * * КОНФИГУРАЦИЯ * * *
#define N 3 // отделять по три разряда
#define DOT_SIZE 1 // размер точки-разделителя
#define DOT "." // разделитель
int a;
char buff[666];
sprintf(buff,"%0.0f", per);
for(a = strlen(buff) - N; a > 0; a -= N)
{
memmove(buff + a + DOT_SIZE, buff + a, 66);
if(buff[a]==' ') break;
else
memcpy(buff + a, DOT, DOT_SIZE);
}
// выводиим на экран
printf("%s\n",buff);
}
main(int argc, char **argv)
{
// переменные
FILE *f; // для чтения исходного файла (если есть)
char *buff; // для чтения данных исходного файла
char *pswd; // текущий тестируемый
пароль (need by gen_pswd)
int validCRC; // для хранения оригинального CRC пароля
unsigned int t; // для замера времени исполнения перебора
int iter = ITER; // макс. кол-во перебираемых паролей
char *crypteddata; // для хранения шифрованных
// build-in default crypt
// кто прочтет, что здесь зашифровано, тот постигнет Великую Тайну
// Крис Касперски ;)
char _DATA_[] = "\x4B\x72\x69\x73\x20\x4B\x61\x73\x70\x65\x72\x73\x6B"\
"\x79\x20\x44\x65\x6D\x6F\x20\x43\x72\x79\x70\x74\x3A"\
"\xB9\x50\xE7\x73\x20\x39\x3D\x30\x4B\x42\x53\x3E\x22"\
"\x27\x32\x53\x56\x49\x3F\x3C\x3D\x2C\x73\x73\x0D\x0A";
// TITLE
printf( "= = = VTune profiling demo = = =\n"\
"==================================\n");
// HELP
if (argc==2)
{
printf("USAGE:\n\tpswd.exe [StartPassword MAX_ITER]\n");
return 0;
}
// выделение
памяти
printf("memory malloc\t\t");
buff = (char *) malloc(MAX_CRYPT_LEN);
if (buff) printf("+OK\n"); else {printf("-ERR\n"); return -1;}
// получение шифротекста для расшифровки
printf("get source from\t\t");
if (f=fopen("crypted.dat","r"))
{
printf("crypted.dat\n");
fgets(buff,MAX_CRYPT_LEN, f);
}
else
{
printf("build-in data\n");
buff=_DATA_;
}
// выделение CRC
validCRC=*(int *)((int) strstr(buff,":")+1);
printf("calculate CRC\t\t%X\n",validCRC);
if (!validCRC)
{
printf("-ERR: CRC is invalid\n");
return -1;
}
// выделение шифрованных данных
crypteddata=strstr(buff,":") + 5;
//printf("cryptodata\t\t%s\n",crypteddata);
// выделение памяти для парольного буфера
printf("memory malloc\t\t");
pswd = (char *) malloc(512*1024); pswd+=62;
/* демонстрация последствий ^^^^^^^^^^^ не выровненных данных */
/* размер блока объясняется тем, что при запросе таких блоков */
/* malloc всегда выравнивает адрес на 64 Кб, что нам и надо */
memset(pswd,0,666); // <-- инициализация
if (pswd) printf("+OK\n"); else {printf("-ERR\n"); return -1;}
// разбор аргументов командной строки
// получение стартового пароля и макс. кол-ва итераций
printf("get arg from\t\t");
if (argc>2)
{
printf("command line\n");
if(atol(argv[2])>0) iter=atol(argv[2]);
strcpy(pswd,argv[1]);
}
else
{
printf("build-in default\n");
strcpy(pswd,"!");
}
printf("start password\t\t%s\nmax iter\t\t%d\n",pswd,iter);
// начало
перебора паролей
printf("==================================\ntry search... wait!\n");
t=clock();
gen_pswd(crypteddata,pswd,iter,validCRC);
t=clock()-t;
// вывод кол-ва перебираемых паролей за сек
printf(" \rPassword per sec:\t");
print_dot(iter/(float)t*CLOCKS_PER_SEC);
return 0;
}
Листинг 11 [Profile/pdsw.c] Не оптимизированный вариант парольного переборщика
Откомпилировав этот пример с максимальной оптимизацией, запустим его на выполнение, чтобы убедиться насколько хорошо справился со своей работой машинный оптимизатор.
Прогон программы на P-III 733 даст скорость перебора… всего лишь порядка 30 тысяч паролей в секунду! Да это меньше, чем совсем ничего и такими темпами зашифрованный текст будет ломаться ну очень долго!!! Куда же уходят такты процессора?
Для поиска узких мест программы мы воспользуемся профилировщиком Intel VTune. Запустим его (не забывая, что под w2k/NT от требует для своей работы привилегий администратора) и, тем временем пока компьютер деловито шуршит винчестером, создадим таблицу символов (не путать с отладочной информацией!), без которой профилировщик ни за что не сможет определить какая часть исполняемого кода к какой функции относится. Для создания таблицы символов в командой строке компоновщика (линкера) достаточно указать ключ "/profile". Например, это может выглядеть так: "link /profile pswd.obj". Если все сделано правильно, образуется файл pswd.map приблизительно следующего содержания:
0001:00000000 _DeCrypt 00401000 f pswd.obj
0001:00000050 _CalculateCRC 00401050 f pswd.obj
0001:00000080 _CheckCRC 00401080 f pswd.obj
Ага, VTune уже готов к работе и терпеливо ждет наших дальнейших указаний, предлагая либо открыть существующий проект – "Open Existing Project" (но у нас нечего пока открывать), либо вызывать Мастера
для создания нового проекта – "New Project Wizard" (вот это, в принципе, нам подходит, но сумеем ли мы разобраться в настойках Мастера?), либо же выполнить быстрый анализ производительности приложения – "Quick Performance Analyses", – выбираем его! В появившемся диалогом окне указываем путь к файлу "pswd.exe" и нажимаем кнопочку "GO" (то есть "Иди").
VTune автоматически запускает профилируемое приложение и начинает собирать информацию о времени его выполнения в каждой точке программы, сопровождая этот процесс симпатичной змейкой - индикатором.
Если нам повезет и мы не зависнем, то через секунду-другую VTune распахнет себя на весь экран и вывалит множество окон с полезной и не очень информацией. Рассмотрим их поближе (см. рис. 0x001). В левой части экрана находится Навигатор Проекта, позволяющий быстро перемещаться между различными его части. Нам он пока не нужен и потому сосредоточим все свое внимание в центр экрана, где расположены окна диаграмм.
Верхнее окно показывает сколько времени выполнялась каждая точка кода, позволяя тем самым обнаружить "горячие" точки (Hot Spots), – т.е. те участки программы, на выполнение которых уходит наибольшее количество времени. В данном случае профилировщик обнаружил 187 горячих точке, о чем и уведомил нас в правой части окна. Обратите внимание на два пика, расположение чуть левее середины центра экрана. Это не просто горячие, а прямо-таки адски раскаленные точечки, съедающие львиную долю быстродействия программы, и именно с их оптимизации и надо начинать!
Подведем курсор к самому высокому пику – VTune тут же сообщит, что оно принадлежит функции out. Постой! Какой out?! Мы ничего такого не вызывали!! Кто же вызвал эту нехорошую функцию? (Несомненно, вы уже догадались, что это сделала функция printf, но давайте притворимся будто бы мы ничего не знаем, ведь в других случаях найти виновника не так просто).
Рисунок 6 0х001 Содержимое окон VTune сразу же после анализа приложения. В первую очередь нас интересует верхнее окно, "картографирующее" горячие точки, расположенные согласно их адресам. Нижнее окно содержит информацию о относительном времени выполнении всех модулей системы. Обратите внимание, модуль pswd.exe (на диаграмме он отмечен стрелкой) занял далеко не первое место и основную долю производительности "съел" кто-то другой. Создается обманчивое впечатление, что оптимизировать модуль pswd.exe бессмысленно, но это не так…
Чтобы не рыскать бес толку по всему коду, воспользуется другим инструментом профилировщика – "Call Graph", позволяющим в удобной для человека форме отобразить на экране иерархическую взаимосвязь различных функций (или классов – если вы пишите на Си ++).
В меню "Run" выбираем пункт "Win32* Call Graph Profiling Session" и вновь идем перекурить, пока VTune профилирует приложение. По завершению профилировки на экране появится еще два окна. Верхнее, содержащее электронную таблицу, мы рассматривать не будем (оно понятно и без слов), а вот к нижнему присмотримся повнимательнее. Пастельно-желтый фон украшают всего два ядовито-красных прямоугольника с надписями "Thread 400" и "mainCRTStartup". Щелкнем по последнему из них два раза, – VTune тут же выбросит целый веер дочерних функций, вызываемых стартовым кодом приложения. Находим среди них main (что будет очень просто, т.к. только main выделен красным цветом) и щелкаем по нему еще раз…. и будем действовать так до тех пор, пока не раскроем все дочерние функции процедуры main.
В результате выяснится, что функцию out действительно вызывает функция printf, а саму printf вызывает… do_pswd. Ну, да! Теперь мы "вспомнили", что использовали ее для вывода текущего тестируемого пароля на экран! Какая глупая идея! Вот оказывается куда ушла вся производительность!
Рисунок 7 0х002 Иерархия "горячих" функций, построенная Мастером Call Graph. Цвет символизирует "температуру" функции, а стоящее возле нее число сообщает сколько именно она вызвалась раз.
