Sabemos que é lento na execução:
$ time ./junk.sh
Lines written: 14401
./junk.sh 2.27s user 3.31s system 21% cpu 25.798 total
(e essa é uma versão que imprime apenas 4 horas, não 2 anos).
Para entender melhor onde bash
está gastando seu tempo, podemos usar strace -c
.
$ strace -c ./junk.sh
Lines written: 14401
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
79.01 0.128906 4 28806 14403 waitpid
17.92 0.029241 2 14403 clone
2.45 0.003999 0 158448 rt_sigprocmask
0.33 0.000532 0 28815 rt_sigaction
0.29 0.000479 0 14403 sigreturn
Assim, podemos ver que as duas principais chamadas são waitpid
e clone
. Eles não ocupam muito tempo sozinhos (apenas 0.128906 segundos e 0.029241 segundos), mas nós podemos ver que eles estão sendo chamados muito, então estamos suspeitando que o problema é o fato de que estamos tendo que começar um date
separado comando para ecoar cada número.
Então eu fiz algumas pesquisas e descobri que você pode compilar bash
com gprof
support fazendo:
$ ./configure --enable-profiling --without-bash-malloc
$ make
Agora usando isso:
$ ./bash-gprof junk.sh
Lines written: 14401
$ gprof ./bash-gprof gmon.out
Each sample counts as 0.01 seconds.
% cumulative self self total
time seconds seconds calls s/call s/call name
8.05 0.28 0.28 14403 0.00 0.00 make_child
6.61 0.51 0.23 __gconv_transform_utf8_internal
5.75 0.71 0.20 fork
5.75 0.91 0.20 259446 0.00 0.00 hash_search
5.17 1.09 0.18 129646 0.00 0.00 dispose_words
Portanto, supondo que os nomes das funções sejam significativos, isso confirma que o problema é que estamos fazendo bash
fork e chamando um comando externo repetidamente.
Se movermos o >>
para o final do loop while
, ele dificilmente será afetado.
$ time ./junk2.sh
...
./junk2.sh 2.46s user 3.18s system 22% cpu 25.659 total
Mas a resposta de Gilles encontrou uma maneira de executar apenas date
uma vez e, não surpreendentemente, é muito mais rápido:
$ time ./bash-gprof junk3.sh
Lines written: 14401
./bash-gprof junk3.sh 0.10s user 0.16s system 96% cpu 0.264 total
$ strace -c ./bash-gprof junk3.sh
Lines written: 14401
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
97.63 0.039538 5648 7 3 waitpid
2.37 0.000961 37 26 writev
0.00 0.000000 0 9 read
...
0.00 0.000000 0 4 clone
$ gprof ./bash-gprof gmon.out
Flat profile:
Each sample counts as 0.01 seconds.
no time accumulated
% cumulative self self total
time seconds seconds calls Ts/call Ts/call name
0.00 0.00 0.00 1162 0.00 0.00 xmalloc
0.00 0.00 0.00 782 0.00 0.00 mbschr
0.00 0.00 0.00 373 0.00 0.00 shell_getc
7 waitpids
e 4 clones
em comparação com 28806 e 14403 no original!
Portanto, a moral é: se você tiver que chamar um comando externo dentro de um loop que é repetido muitas vezes, você precisará encontrar uma maneira de movê-lo para fora do loop ou alternar para uma linguagem de programação que não o faça. tem que chamar um comando externo para fazer o trabalho.
Conforme solicitado, um teste baseado no método de Iain (modificado para usar os mesmos nomes de variáveis e looping):
#!/bin/bash
datein=junk.$$.datein
file=junk.$$
((secY2=3600*4))
cnt=0
secBeg=$(date --date="2010-01-01 00:00:00" +%s)
secEnd=$((secBeg+secY2))
((sec=secBeg))
while ((sec<=secEnd)) ; do
echo @$sec >>"$datein"
((sec+=1))
((cnt+=1))
done
date --file="$datein" '+%Y-%m-%d %H:%M:%S' >>"$file"
ls -l "$file"
rm "$datein"
echo Lines written: $cnt
Resultados:
$ time ./bash-gprof ./junk4.sh
Lines written: 14401
./bash-gprof ./junk4.sh 0.92s user 0.20s system 94% cpu 1.182 total
$ strace -c ./junk4.sh
Lines written: 14401
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
91.71 0.116007 14501 8 4 waitpid
3.70 0.004684 0 14402 write
1.54 0.001944 0 28813 close
1.35 0.001707 0 72008 1 fcntl64
0.88 0.001109 0 43253 rt_sigprocmask
0.45 0.000566 0 28803 dup2
0.36 0.000452 0 14410 open
$ gprof ./bash-gprof gmon.out
Flat profile:
Each sample counts as 0.01 seconds.
% cumulative self self total
time seconds seconds calls ms/call ms/call name
22.06 0.15 0.15 __gconv_transform_utf8_internal
16.18 0.26 0.11 mbrtowc
7.35 0.31 0.05 _int_malloc
5.88 0.35 0.04 __profile_frequency
4.41 0.38 0.03 345659 0.00 0.00 readtok
4.41 0.41 0.03 _int_free
2.94 0.43 0.02 230661 0.00 0.00 hash_search
2.94 0.45 0.02 28809 0.00 0.00 stupidly_hack_special_variables
1.47 0.46 0.01 187241 0.00 0.00 cprintf
1.47 0.47 0.01 115232 0.00 0.00 do_redirections
Então close
e open
estão aparecendo.
Agora, a observação da Eelvex sobre >>
por linha versus >
em torno do loop while
começa a fazer a diferença.
Vamos fatorar isso ...
#!/bin/bash
datein=junk.$$.datein
file=junk.$$
((secY2=3600*4))
cnt=0
secBeg=$(date --date="2010-01-01 00:00:00" +%s)
secEnd=$((secBeg+secY2))
for ((sec=secBeg; sec<=secEnd; sec=sec+1)) ; do
echo @$sec
((cnt+=1))
done >"$datein"
date --file="$datein" '+%Y-%m-%d %H:%M:%S' >>"$file"
ls -l "$file"
rm "$datein"
echo Lines written: $cnt
$ time ./junk6.sh
Lines written: 14401
./junk6.sh 0.58s user 0.14s system 95% cpu 0.747 total
$ strace -c junk6.sh
Lines written: 14401
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
97.41 0.092263 11533 8 4 waitpid
2.06 0.001949 0 43252 rt_sigprocmask
0.53 0.000506 0 14402 write
0.00 0.000000 0 13 read
0.00 0.000000 0 10 open
0.00 0.000000 0 13 close
0.00 0.000000 0 1 execve
$ gprof ./bash-gprof gmon.out
Flat profile:
Each sample counts as 0.01 seconds.
% cumulative self self total
time seconds seconds calls ms/call ms/call name
10.00 0.05 0.05 72025 0.00 0.00 expand_word_internal
10.00 0.10 0.05 __gconv_transform_utf8_internal
8.00 0.14 0.04 __profile_frequency
8.00 0.18 0.04 _int_malloc
4.00 0.20 0.02 1355024 0.00 0.00 xmalloc
4.00 0.22 0.02 303217 0.00 0.00 mbschr
Que também é muito, muito mais rápido que o script original, mas um pouco mais lento que o de Gilles.