o script bash não é executado corretamente no crontab, mas é executado manualmente

Question

Eu escrevi um pequeno script para determinar os IOPs médios por hora nos quais depois eu manualmente converto para um gráfico e planilha para gerenciamento para discutir uma possível atualização de SAN para um próximo projeto de expansão. O sistema em execução é atualmente uma máquina física que executa o RHEL 6.

Eu tenho o script agendado no crontab do root, como abaixo:

0 * * * * /bin/bash /IOPsLogs/IOPs.sh  >> /var/log/cronjobIOPs.log 2>&1

Meu script IOPs.sh se parece com:

#!/bin/bash
date >> /var/log/cronjobIOPs.log
date +"%Y-%m-%d--%H:00" >> /IOPsLogs/Daily$(date +%Y-%m-%d).log
timeout -sHUP 60m iostat -x 1 | grep sda -B 1 >> /IOPsLogs/IOPs_$(date +%Y-%m-%d--%H:00).log
grep "sda" /IOPsLogs/IOPs_$(date +%Y-%m-%d--%H:00 -d "1 hour ago").log | awk '{sum+=$4} END { print "Average IOPs read'/'sec= ",sum/NR}' >> /IOPsLogs/Daily$(date +%Y-%m-%d).log
grep "sda" /IOPsLogs/IOPs_$(date +%Y-%m-%d--%H:00 -d "1 hour ago").log | awk '{sum+=$5} END { print "Average IOPs write'/'sec= ",sum/NR}' >> /IOPsLogs/Daily$(date +%Y-%m-%d).log

o arquivo de log "/var/log/cronjobIOPs.log" se parece com: (O que é bom, já que não vejo erros.)

Mon Apr 27 00:00:01 MST 2015
Mon Apr 27 01:00:01 MST 2015
Mon Apr 27 02:00:01 MST 2015
Mon Apr 27 03:00:01 MST 2015
Mon Apr 27 04:00:01 MST 2015
Mon Apr 27 05:00:01 MST 2015
Mon Apr 27 06:00:01 MST 2015
Mon Apr 27 07:00:01 MST 2015
Mon Apr 27 08:00:01 MST 2015
Mon Apr 27 09:00:01 MST 2015
Mon Apr 27 10:00:01 MST 2015
Mon Apr 27 11:00:01 MST 2015
Mon Apr 27 12:00:01 MST 2015
Mon Apr 27 13:00:01 MST 2015
Mon Apr 27 14:00:01 MST 2015
Mon Apr 27 15:00:01 MST 2015
Mon Apr 27 16:00:01 MST 2015
Mon Apr 27 17:00:01 MST 2015
Mon Apr 27 18:00:01 MST 2015
Mon Apr 27 19:00:01 MST 2015
Mon Apr 27 20:00:01 MST 2015
Mon Apr 27 21:00:01 MST 2015
Mon Apr 27 22:00:01 MST 2015
Mon Apr 27 23:00:01 MST 2015
Tue Apr 28 00:00:01 MST 2015
Tue Apr 28 01:00:01 MST 2015
Tue Apr 28 02:00:01 MST 2015
Tue Apr 28 03:00:01 MST 2015
Tue Apr 28 04:00:01 MST 2015
Tue Apr 28 05:00:01 MST 2015
Tue Apr 28 06:00:01 MST 2015
Tue Apr 28 07:00:01 MST 2015
Tue Apr 28 08:00:01 MST 2015
Tue Apr 28 09:00:01 MST 2015

Agora, meu problema é que os logs diários são inconsistentes com o fato de fornecer uma média de leitura e gravação por hora. Às vezes, fornece mais de duas respostas a um carimbo de hora ou dois carimbos de hora. Algo parece estar errado com o timing de alguma forma? (Não é uma VM e não vejo nenhum desvio de tempo ao longo dos anos.) Se eu executar manualmente a cada hora, então funciona muito bem. Alguém tem alguma ideia ou abordagem diferente?

Average IOPs read/sec=  0.0442611
Average IOPs write/sec=  13.4663
2015-04-27--00:00
Average IOPs read/sec=  79.1727
Average IOPs write/sec=  22.7509
2015-04-27--01:00
2015-04-27--02:00
Average IOPs read/sec=  0.0370389
Average IOPs write/sec=  13.1389
Average IOPs read/sec=  36.6858
2015-04-27--03:00
Average IOPs write/sec=  250.514
Average IOPs read/sec=  32.6261
2015-04-27--04:00
Average IOPs write/sec=  391.811
Average IOPs read/sec=  1.64334
Average IOPs write/sec=  84.6204
2015-04-27--05:00
2015-04-27--06:00
Average IOPs read/sec=  0.0487056
Average IOPs write/sec=  12.8323
Average IOPs read/sec=  0.0617611
Average IOPs write/sec=  14.0306
2015-04-27--07:00
2015-04-27--08:00
Average IOPs read/sec=  0.11815
Average IOPs write/sec=  14.094
Average IOPs read/sec=  0.0817611
Average IOPs write/sec=  14.9651
2015-04-27--09:00
Average IOPs read/sec=  0.0434278
Average IOPs write/sec=  13.6037
2015-04-27--10:00
Average IOPs read/sec=  0.613706
Average IOPs write/sec=  14.9003
2015-04-27--11:00
Average IOPs read/sec=  0.0389833
Average IOPs write/sec=  13.9256
2015-04-27--12:00
2015-04-27--13:00
Average IOPs read/sec=  0.0642528
Average IOPs write/sec=  15.1321
Average IOPs read/sec=  0.144817
Average IOPs write/sec=  13.8244
2015-04-27--14:00
Average IOPs read/sec=  0.0384222
2015-04-27--15:00
Average IOPs write/sec=  13.0468
Average IOPs read/sec=  0.0312028
Average IOPs write/sec=  12.7255
2015-04-27--16:00
Average IOPs read/sec=  0.0781472
Average IOPs write/sec=  13.7179
2015-04-27--17:00
Average IOPs read/sec=  0.0798139
Average IOPs write/sec=  15.9144
2015-04-27--18:00
Average IOPs read/sec=  0.138147
Average IOPs write/sec=  13.7297
2015-04-27--19:00
Average IOPs read/sec=  0.0362028
Average IOPs write/sec=  13.2324
2015-04-27--20:00
Average IOPs read/sec=  0.254536
Average IOPs write/sec=  14.9013
2015-04-27--21:00
Average IOPs read/sec=  0.0314806
Average IOPs write/sec=  12.8527
2015-04-27--22:00
2015-04-27--23:00
Average IOPs read/sec=  21.6865
Average IOPs write/sec=  70.7389

    

Answer 1

É uma sobreposição entre uma execução do script e a outra feita uma hora depois. Às vezes, a nova execução escreve sua primeira linha antes que a primeira execução tenha escrito suas duas últimas linhas.

As duas primeiras linhas são da última execução realizada em 2015-04-26. Quando elas são escritas, a data é a de 2015-04-27, pois o arquivo de log usado é baseado na hora no momento da gravação, e não no início da execução.

Uma opção é armazenar data & tempo em variáveis e escreva todas as três linhas ao mesmo tempo no arquivo de data correto.