domingo, 19 de abril de 2009

Qual o tempo de execução de meu aplicativo?

Há situações em que precisamos medir quanto tempo demorou a execução de um determinado procedimento, ou a execução de um programa. Neste caso no Linux podemos usar a função gettimeofday().

Para mais detalhes... na linha de comando digite: man gettimeofday

Algumas informações úteis:

- a função retorna um int
- o primeiro parâmetro é a struct timeval (arquivo time.h), e o segundo é um valor de timezone, mas esse parametro está deprecated, e como diz na documentação costuma-se usar um valor nullo (0, zero)
- para que isso funcione você precisa ter no seu computador a glibc.

Vamos ao código e posterior análise:
#include <stdio.h>
#include <stdlib.h>

double tempo()
{
struct timeval tv;
gettimeofday(&tv,0);
return tv.tv_sec + tv.tv_usec/1e6;
}

int main()
{
double t1,t2;
double i;
t1 = tempo();
printf("%lf\t",t1);

for(i=0;i<300000000;i++);

t2 = tempo();
printf("%lf\t",t2);

printf("%lf\n",t2-t1);
return 0;
}



1 - Criamos uma função que retorna um double, a função tempo()
double tempo()
{
struct timeval tv;
gettimeofday(&tv,0);

return tv.tv_sec + tv.tv_usec/1e6;
}

Essa função declara uma variável chamada tv, que é do tipo da struct timeval (lembre... essa struct está definida no arquivo time.h). Depois chamamos a função propriamente, passando um ponteiro para nossa variável tv e o segundo parâmetro como a documentação sugere com valor nulo.

Depois dividimos os microsegundos por 1000000 para convertê-los em segundos (deixe 1e6, não sei porque, mas se dividir por 1000000 não vai dar certo ... isso ainda é um mistério), somamos a esse resultado os os segundos de agora. A struct timeval tem dois atributos, tv_sec (os segundos de agora) e tv_usec (os microsegundos do segundo de agora). Como nossa variável se chama tv, então para acessar os microsegundos usamos tv.tv_usec.

Agora o main de nosso programa:

int main()
{
double t1,t2;
double i;
t1 = tempo();
printf("%lf\t",t1);

for(i=0;i<300000000;i++);

t2 = tempo();
printf("%lf\t",t2);

printf("%lf\n",t2-t1);
return 0;
}

Declaramos t1 e t2 do tipo double (a máscara para double é %lf lembra?) e também um i que vai ser nosso contador.

Queremos medir quanto tempo demorou um for de 0 até 300000000 (300 milhões), por isso guardamos o tempo de agora em t1 e depois do for em t2, mostramos isso na tela (já vai ver porque). Diminuimos t1 de t2 e temos em segundos quanto que demorou nosso bloco de códigos.

Compilando ...
gcc teste.c
mv a.out teste

Compilei (gerou o a.out) e renomeei isso para teste.

Executando:
./teste

Vai produzir um resultado como:
1240195429.991010 1240195432.975001 2.983991

Temos o tempo inicial, tempo final e a diferença. Atenção!! Se você tiver um computador lento é aconselhavel diminuir o tamanho do for ... a não ser que tenha paciência.

Estou rodando o programa num computador:
uname -a
Linux hrpc 2.6.27.14 # i686 Intel(R) Pentium(R) 4 CPU 3.00GHz GNU/Linux

Legal!! Descobrimos que demorou 2.98 segundos ... mas pense bem, foi a primeira vez que eu executei o programa na máquina ... será que nas vezes seguintes vai ser diferente o tempo? Talvez o programa já vai estar carregado na memória? E ... fora o programa eu tenho mais vários outros processos executando em meu computador... será que eles não interferem?

Só tem uma maneira de saber... rodando mais vezes o programa e vendo o tempo que resultou...

Segue abaixo um shell script que faz o programa executar 50 vezes e guarda (acumulando) o valor dos printf em um arquivo. Atenção para o caminho dos arquivos aí na sua máquina.
#!/bin/sh
i=1
while [ $i -le 50 ]
do
/home/helton2/teste >> /home/helton2/resultados.txt
i=`expr $i + 1`
done

exit 0

Este código aí acima é do arquivo runteste.sh, criamos esse arquivo e damos permissão de execução a ele (chmod +x runteste.sh), aí ele é um executável igual nosso programa em C.

Para rodá-lo então:
./runteste.sh

Isso vai criar em "/home/helton2/" o arquivo "resultados.txt" com valores semelhantes (depende de em que dia você está executando e quão rápida é sua máquina) aos listado abaixo:

1240195429.991010 1240195432.975001 2.983991
1240195432.980598 1240195436.225005 3.244407
1240195436.230919 1240195439.232810 3.001891
1240195439.238001 1240195442.226818 2.988817
1240195442.231239 1240195445.222347 2.991108
1240195445.228246 1240195448.210298 2.982052
1240195448.216515 1240195451.466147 3.249632
1240195451.472111 1240195454.732387 3.260276
1240195454.738784 1240195457.728088 2.989304
1240195457.734230 1240195460.976687 3.242457
1240195460.981184 1240195464.242882 3.261698
1240195464.247674 1240195467.239435 2.991761
1240195467.245351 1240195470.236075 2.990724
1240195470.241656 1240195473.518475 3.276819
1240195473.522821 1240195476.506720 2.983899
1240195476.511950 1240195479.494113 2.982163
1240195479.499256 1240195482.492852 2.993596
1240195482.497447 1240195485.473576 2.976129
1240195485.478231 1240195488.463446 2.985215
1240195488.471239 1240195491.746600 3.275361
1240195491.752356 1240195494.763777 3.011421
1240195494.768697 1240195498.037331 3.268634
1240195498.041838 1240195501.072781 3.030943
1240195501.077732 1240195504.334191 3.256459
1240195504.340106 1240195507.636492 3.296386
1240195507.641648 1240195510.639141 2.997493
1240195510.644422 1240195513.607822 2.963400
1240195513.613151 1240195516.608085 2.994934
1240195516.613102 1240195519.872248 3.259146
1240195519.877602 1240195523.154833 3.277231
1240195523.162235 1240195526.428517 3.266282
1240195526.433406 1240195529.866800 3.433394
1240195529.879949 1240195533.494374 3.614425
1240195533.499518 1240195536.512687 3.013169
1240195536.517868 1240195539.777852 3.259984
1240195539.784743 1240195543.055148 3.270405
1240195543.060538 1240195546.337556 3.277018
1240195546.343325 1240195549.587118 3.243793
1240195549.591585 1240195552.838038 3.246453
1240195552.844843 1240195556.124090 3.279247
1240195556.129737 1240195559.367544 3.237807
1240195559.375004 1240195562.423662 3.048658
1240195562.428425 1240195565.675685 3.247260
1240195565.680207 1240195568.961254 3.281047
1240195568.966475 1240195572.196674 3.230199
1240195572.202217 1240195575.433472 3.231255
1240195575.454523 1240195578.449320 2.994797
1240195578.454862 1240195581.466028 3.011166
1240195581.471327 1240195584.739090 3.267763
1240195584.744280 1240195587.976532 3.232252

Agora sim temos dados um pouco melhores!!! Copie-os na sua planilha de cálculos preferida e jogue com os dados!!!!

Aqui achei algumas coisas:

melhor tempo: 2,9634000
pior tempo: 3,6144250
tempo médio: 3,1538744
Maior diferença de tempo : 0,6510250

Sem contar que daria para fazer um belo gráfico de dispersão com esses dados!

Valeu pessoal!!

Planejo fazer meu próximo post sobre structs.

Agradescimentos a Claudio Schepke pela dica da função gettimeofday

2 comentários: