министерство образования РФ
Санкт-Петербургский государственный электротехнический университет «ЛЭТИ»
Кафедра МОЭВМ
Лабораторная работа № 2
по дисциплине
«Метрология Программного обеспечения»
Преподаватель: Кирьянчиков В.А.
Выполнилa: Нго Макеме
Факультет: КТИ
Группа: 0305
Санкт-Петербург
2004
Цель работы:
Получение навыков измерения характеристик динамической сложности программ с помощью стандартного профилировщика TurboProfiler.
Задание:
-
Ознакомиться с документацией на TurboProfiler и выполнить для программы prost0.c следующее задание:
-
компиляция с использованием автономного отладчика;
-
профилирование по времени;
-
профилирование по частоте;
-
профилирование по средним временам на 1 вызов;
-
запись результатов профилирования в файл для печати.
-
Выполнить тестовые программы test_cy1.c, test_cyc.c, test_sub.c c анализом параметров повторения циклов и проверкой их влияния на точность и чувствительность профилирования.
-
Скомпилировать и выполнить под управлением TurboProfiler'а программы на Паскале и С, разработанные в 1-ой лабораторной работе. Снять все виды профилей, выявить "узкие места", ввести в программы усовершенствования и получить новые профили. Если времена выполнения рассматриваемых при профилировании фрагментов программы малы для учета TurboProfiler'ом, ввести вспомогательное зацикливание программы.
Выполнение:
-
Система Turbo Profiler фирмы Borland представляет собой профилировщик - программное средство, позволяющее получить ряд количественных данных о процессе выполнения Вашей программы и на основании этих данных выявить в ней "узкие места", отрицательно сказывающиеся на эффективности ее работы.
Работа с тестовой программой prost0.c
1) Профилирование по затрачиваемому времени и количеству выполнения каждой строки.
Time Counts
#include "stdio.h";
int primes[1000];
#define MAXPRIMES 1000
0.0000 1 main()
{
int j;
int lastprime, curprime;
0.0000 1 primes[0] = 2;
0.0000 1 primes[1] = 3;
0.0000 1 lastprime = 1;
0.0000 1 curprime = 3;
0.0001 1 printf("prime %d = %d\n", 0, primes[0]);
0.0001 1 printf("prime %d = %d\n", 1, primes[1]);
0.0004 500 while(curprime < MAXPRIMES)
{
0.0004 499 for(j = 0; j <= lastprime; j++)
0.5644 15122 if((curprime % primes[j]) == 0)
{
0.0002 333 curprime += 2;
0.0002 333 break;
}
0.0004 499 if(j <= lastprime)
0.0002 333 continue;
0.0001 166 lastprime++;
0.2100 166 printf("prime %d = %d\n", lastprime, curprime);
0.0001 166 primes[lastprime] = curprime;
0.0551 166 curprime += 2;
}
0.0000 1 }
2) Профилирование по времени и частоте.
Total time: 0.8330 sec
Sort: Name Pass count: +++ Time: ***
_main 1 <1% |
0.0000 sec <1% |
#PROST0_C#11 1 <1% |
0.0000 sec <1% |
#PROST0_C#12 1 <1% |
0.0000 sec <1% |
#PROST0_C#13 1 <1% |
0.0000 sec <1% |
#PROST0_C#14 1 <1% |
0.0000 sec <1% |
#PROST0_C#16 1 <1% |
0.0001 sec <1% |
#PROST0_C#17 1 <1% |
0.0001 sec <1% |
#PROST0_C#19 500 2% |+
0.0004 sec <1% |
#PROST0_C#21 499 2% |+
0.0004 sec <1% |
#PROST0_C#22 15122 82% |++++++++++++++++++++++++++++++++++++++++++++++
0.5644 sec 67% |*************************************
#PROST0_C#24 333 1% |+
0.0002 sec <1% |
#PROST0_C#26 333 1% |+
0.0002 sec <1% |
#PROST0_C#28 499 2% |+
0.0004 sec <1% |
#PROST0_C#29 333 1% |+
0.0002 sec <1% |
#PROST0_C#30 166 <1% |
0.0001 sec <1% |
#PROST0_C#31 166 <1% |
0.2100 sec 25% |**************
#PROST0_C#32 166 <1% |
0.0001 sec <1% |
#PROST0_C#33 166 <1% |
0.0551 sec 6% |***
#PROST0_C#35 1 <1% |
0.0000 sec <1% |
3) Профилирование по средним временам на один вызов.
_main 0.0000 sec/call |
#PROST0_C#11 0.0000 sec/call |
#PROST0_C#12 0.0000 sec/call |
#PROST0_C#13 0.0000 sec/call |
#PROST0_C#14 0.0000 sec/call |
#PROST0_C#16 0.0001 sec/call |******
#PROST0_C#17 0.0001 sec/call |****
#PROST0_C#19 0.0000 sec/call |
#PROST0_C#21 0.0000 sec/call |
#PROST0_C#22 0.0000 sec/call |*
#PROST0_C#24 0.0000 sec/call |
#PROST0_C#26 0.0000 sec/call |
#PROST0_C#28 0.0000 sec/call |
#PROST0_C#29 0.0000 sec/call |
#PROST0_C#30 0.0000 sec/call |
#PROST0_C#31 0.0012 sec/call |**********************************************
#PROST0_C#32 0.0000 sec/call |
#PROST0_C#33 0.0003 sec/call |************
#PROST0_C#35 0.0000 sec/call |
Выводы: результаты профилирования показывают, что 22 строка программы (вычисления) вызывается наиболее часто и занимает наибольшую часть времени от общего времени выполнения программы. Наибольшее время на один вызов занимает строка 31 (вывод на экран). Общее время на выполнение программы равно 0.8330 секунды.
-
Выполнение тестовых программ test_cyc.c, test_sub.c
-
test_cyc.c
1) Профилирование по затрачиваемому времени и количеству выполнения каждой строки.
Time Counts
#define Size 10000
int i, tmp, dim[Size];
0.0000 1 void main()
{
0.0000 1 for(i=0;i<Size/10;i++){ tmp=dim[0]; dim[0]=dim[i]; dim[i]=tmp;}
0.0001 1 for(i=0;i<Size/5;i++){ tmp=dim[0]; dim[0]=dim[i]; dim[i]=tmp;}
0.0002 1 for(i=0;i<Size/2;i++){ tmp=dim[0]; dim[0]=dim[i]; dim[i]=tmp;}
0.0005 1 for(i=0;i<Size;i++) { tmp=dim[0]; dim[0]=dim[i]; dim[i]=tmp;}
0.0000 1 for(i=0;i<Size/10;i++)
0.0558 1000 { tmp=dim[0]; dim[0]=dim[i]; dim[i]=tmp; };
0.0000 1 for(i=0;i<Size/5;i++)
0.0567 2000 { tmp=dim[0]; dim[0]=dim[i]; dim[i]=tmp; };
0.0000 1 for(i=0;i<Size/2;i++)
0.0594 5000 { tmp=dim[0]; dim[0]=dim[i]; dim[i]=tmp; };
0.0000 1 for(i=0;i<Size;i++)
0.2836 10000 { tmp=dim[0]; dim[0]=dim[i]; dim[i]=tmp; };
0.0000 1 for(i=0;i<Size/10;i++)
0.0557 1000 { tmp=dim[0];
0.0008 1000 dim[0]=dim[i];
0.0558 1000 dim[i]=tmp;
};
0.0000 1 for(i=0;i<Size/5;i++)
0.0016 2000 { tmp=dim[0];
0.0566 2000 dim[0]=dim[i];
0.1116 2000 dim[i]=tmp;
};
0.0000 1 for(i=0;i<Size/2;i++)
0.0593 5000 { tmp=dim[0];
0.0043 5000 dim[0]=dim[i];
0.1143 5000 dim[i]=tmp;
};
0.0000 1 for(i=0;i<Size;i++)
0.1188 10000 { tmp=dim[0];
0.2286 10000 dim[0]=dim[i];
0.1785 10000 dim[i]=tmp;
};
0.0000 1 }
Total time: 1.4457 sec
Show: Time and counts
Sort: Name Pass count: +++ Time: ***
_main 1 <1% |
0.0000 sec <1% |
#TEST_CYC#6 1 <1% |
0.0000 sec <1% |
#TEST_CYC#7 1 <1% |
0.0001 sec <1% |
#TEST_CYC#8 1 <1% |
0.0002 sec <1% |
#TEST_CYC#9 1 <1% |
0.0005 sec <1% |
#TEST_CYC#10 1 <1% |
0.0000 sec <1% |
#TEST_CYC#11 1000 1% |+++
0.0558 sec 3% |*********
#TEST_CYC#12 1 <1% |
0.0000 sec <1% |
#TEST_CYC#13 2000 2% |++++++
0.0567 sec 3% |*********
#TEST_CYC#14 1 <1% |
0.0000 sec <1% |
#TEST_CYC#15 5000 6% |+++++++++++++++
0.0594 sec 4% |*********
#TEST_CYC#16 1 <1% |
0.0000 sec <1% |
#TEST_CYC#17 10000 13% |+++++++++++++++++++++++++++++++
0.2836 sec 19% |**********************************************
#TEST_CYC#18 1 <1% |
0.0000 sec <1% |
#TEST_CYC#19 1000 1% |+++
0.0557 sec 3% |*********
#TEST_CYC#20 1000 1% |+++
0.0008 sec <1% |
#TEST_CYC#21 1000 1% |+++
0.0558 sec 3% |*********
#TEST_CYC#23 1 <1% |
0.0000 sec <1% |
#TEST_CYC#24 2000 2% |++++++
0.0016 sec <1% |
#TEST_CYC#25 2000 2% |++++++
0.0566 sec 3% |*********
#TEST_CYC#26 2000 2% |++++++
0.1116 sec 7% |******************
#TEST_CYC#28 1 <1% |
0.0000 sec <1% |
#TEST_CYC#29 5000 6% |+++++++++++++++
0.0593 sec 4% |*********
#TEST_CYC#30 5000 6% |+++++++++++++++
0.0043 sec <1% |
#TEST_CYC#31 5000 6% |+++++++++++++++
0.1143 sec 7% |******************
#TEST_CYC#33 1 <1% |
0.0000 sec <1% |
#TEST_CYC#34 10000 13% |+++++++++++++++++++++++++++++++
0.1188 sec 8% |*******************
#TEST_CYC#35 10000 13% |+++++++++++++++++++++++++++++++
0.2286 sec 15% |*************************************
#TEST_CYC#36 10000 13% |+++++++++++++++++++++++++++++++
0.1785 sec 12% |****************************
#TEST_CYC#38 1 <1% |
0.0000 sec <1% |
2) Профилирование по затрачиваемому времени на один вызов.
Total time: 1.4457 sec
Show: Time per call
Sort: Name
_main 0.0000 sec/call |
#TEST_CYC#6 0.0000 sec/call |****
#TEST_CYC#7 0.0001 sec/call |********
#TEST_CYC#8 0.0002 sec/call |***********************
#TEST_CYC#9 0.0005 sec/call |**********************************************
#TEST_CYC#10 0.0000 sec/call |
#TEST_CYC#11 0.0000 sec/call |****
#TEST_CYC#12 0.0000 sec/call |
#TEST_CYC#13 0.0000 sec/call |**
#TEST_CYC#14 0.0000 sec/call |
#TEST_CYC#15 0.0000 sec/call |
#TEST_CYC#16 0.0000 sec/call |
#TEST_CYC#17 0.0000 sec/call |**
#TEST_CYC#18 0.0000 sec/call |
#TEST_CYC#19 0.0000 sec/call |****
#TEST_CYC#20 0.0000 sec/call |
#TEST_CYC#21 0.0000 sec/call |****
#TEST_CYC#23 0.0000 sec/call |
#TEST_CYC#24 0.0000 sec/call |
#TEST_CYC#25 0.0000 sec/call |**
#TEST_CYC#26 0.0000 sec/call |****
#TEST_CYC#28 0.0000 sec/call |
#TEST_CYC#29 0.0000 sec/call |
#TEST_CYC#30 0.0000 sec/call |
#TEST_CYC#31 0.0000 sec/call |*
#TEST_CYC#33 0.0000 sec/call |
#TEST_CYC#34 0.0000 sec/call |
#TEST_CYC#35 0.0000 sec/call |*
#TEST_CYC#36 0.0000 sec/call |*
#TEST_CYC#38 0.0000 sec/call |
Вывод: результаты профилирования показывают, что время выполнения одних и тех же операций с массивами в разных частях программы одинаково, несмотря на различные варианты расположения операторов. Строка 9 занимает наибольшее время выполнения за один раз. Общее время выполнения программы равно 1.4457 секунд.
-
test_sub.c
1) Профилирование по затрачиваемому времени и количеству выполнения каждой строки.
Time Counts
const unsigned Size = 1000;
0.0000 4 void TestLoop(int nTimes)
{
static int TestDim[Size];
int tmp;
int iLoop;
0.1674 1804 while (nTimes > 0)
{
0.0016 1800 nTimes --;
0.0015 1800 iLoop = Size;
49.744 1801800 while (iLoop > 0)
{
44.133 1800000 iLoop -- ;
46.569 1800000 tmp = TestDim[0];
47.101 1800000 TestDim[0] = TestDim[nTimes];
45.608 1800000 TestDim[nTimes] = tmp;
}
}
0.0000 4 } /* TestLoop */
0.0000 1 void main()
{
0.0000 1 TestLoop(Size / 10); // 100 * 1000 повторений
0.0000 1 TestLoop(Size / 5); // 200 * 1000 повторений
0.0000 1 TestLoop(Size / 2); // 500 * 1000 повторений
0.0000 1 TestLoop(Size / 1); // 1000* 1000 повторений
0.0000 1 }
Total time: 233.32 sec
Show: Time and counts
Sort: Name Pass count: +++ Time: ***
TestLoop 4 <1% |
0.0000 sec <1% |
_main 1 <1% |
0.0000 sec <1% |
#TEST_SUB#10 1804 <1% |
0.1674 sec <1% |
#TEST_SUB#12 1800 <1% |
0.0016 sec <1% |
#TEST_SUB#14 1800 <1% |
0.0015 sec <1% |
#TEST_SUB#15 1801800 20% |++++++++++++++++++++++++++++++++++++++++++++++
49.744 sec 21% |**********************************************
#TEST_SUB#17 1800000 19% |+++++++++++++++++++++++++++++++++++++++++++++
44.133 sec 18% |**********************************************
#TEST_SUB#18 1800000 19% |+++++++++++++++++++++++++++++++++++++++++++++
46.569 sec 19% |**********************************************
#TEST_SUB#19 1800000 19% |+++++++++++++++++++++++++++++++++++++++++++++
47.101 sec 20% |**********************************************
#TEST_SUB#20 1800000 19% |+++++++++++++++++++++++++++++++++++++++++++++
45.608 sec 19% |**********************************************
#TEST_SUB#23 4 <1% |
0.0000 sec <1% |
#TEST_SUB#28 1 <1% |
0.0000 sec <1% |
#TEST_SUB#29 1 <1% |
0.0000 sec <1% |
#TEST_SUB#30 1 <1% |
0.0000 sec <1% |
#TEST_SUB#31 1 <1% |
0.0000 sec <1% |
#TEST_SUB#32 1 <1% |
0.0000 sec <1% |
2) Профилирование по затрачиваемому времени на один вызов.
Total time: 233.32 sec
Show: Time per call
Sort: Name
TestLoop 0.0000 sec/call |
_main 0.0000 sec/call |
#TEST_SUB#10 0.0000 sec/call |**********************************************
#TEST_SUB#12 0.0000 sec/call |
#TEST_SUB#14 0.0000 sec/call |
#TEST_SUB#15 0.0000 sec/call |*************
#TEST_SUB#17 0.0000 sec/call |************
#TEST_SUB#18 0.0000 sec/call |************
#TEST_SUB#19 0.0000 sec/call |************
#TEST_SUB#20 0.0000 sec/call |************
#TEST_SUB#23 0.0000 sec/call |
#TEST_SUB#28 0.0000 sec/call |
#TEST_SUB#29 0.0000 sec/call |
#TEST_SUB#30 0.0000 sec/call |
#TEST_SUB#31 0.0000 sec/call |
#TEST_SUB#32 0.0000 sec/call |
Вывод: Общее время выполнения программы равно 233.32 секунды. Весьма вероятно, что результаты профилирования данным профилировщиком не точны, хотя бы потому, что время вызова функций равно нулю, а это не может быть верно.