Exibe “tempo” do processo periodicamente

Question

Há uma semana, lancei as simulações da seguinte maneira:

make rebuild; time make run

Usando o comando time , gravei o tempo de CPU usado em cada caso.

Uma semana depois, as simulações terminaram, mas, para minha surpresa, as estatísticas de tempo não foram exibidas. A meta make run era basicamente apenas:

python SCRIPTNAME | tee SCRIPTNAME.log

e, de fato, vejo que a saída correspondente às 4 ou 5 últimas iterações (de 10000) não foi encontrada em lugar nenhum. Não foi exibido na tela nem anexado ao arquivo de log)

Minhas perguntas são:

1. Como isso pode ser?

2. É possível fazer com que time exiba as estatísticas de tempo periodicamente, para evitar a repetição de todas as simulações no caso que descrevi?

Answer 1

A saída time é exibida no stderr. Então, se você quiser capturar sua saída em um arquivo de log, você precisará redirecionar o stderr.

Mas observe que, em zsh , como em ksh , time é uma palavra-chave,

time cmd 2>&1 |  tee log

Na verdade, vezes cmd 2>&1 | tee log (e os dois cmd e tee ). Se você quiser sincronizar o cmd apenas e redirecionar o stdout e stderr de cmd e a time de saída para o canal para tee , será necessário:

{ time cmd; } 2>&1 | tee log

Quanto à recuperação periódica, não acho que seja possível. Isso é algo que é contabilizado pelo kernel e disponibilizado para o processo pai após a finalização após o pai ter wait () ed para seu filho (usando getrusage() ).

Observe também que o uso de netos que não são esperados por seus pais não é contabilizado mesmo se eles tiverem morrido no momento em que time relata o uso ( init realmente estará respondendo por eles). / p>

Um processo pode obter suas próprias informações de uso (veja, por exemplo, a saída de time sozinho em zsh ), mas novamente para a parte children , ele só seria incrementado quando seus filhos diretos morrem e relatam seu uso, por isso, mesmo se você iniciou make em segundo plano e executou time periodicamente, a parte children não seria incrementada para cada filho de make finalizar. make (o kernel em nome de make ) seria responsável pelo uso desses filhos, e esse uso cumulativo só seria disponibilizado para zsh quando make retornasse.

Se você estiver interessado apenas no tempo de CPU, e não nas outras informações rastreadas por getrusage() e informadas por time depois que você alterar $TIMEFMT , no Linux, você pode obter as informações de /proc/pid/stat e algum resumo de ps , mas novamente o uso de crianças para um determinado processo incluirá apenas o uso cumulativo dos filhos diretos encerrados. / p>

Algo como:

time cmd &
perl -MPOSIX -l -0777 -e '
  while (<STDIN>) {
    @f = /\(.*\)|\S+/gs;
    printf "%s %s cutime: %.2f cstime: %.2f\n",
      strftime("%T",localtime), $f[1],
      map {$_/POSIX::sysconf( &POSIX::_SC_CLK_TCK )}@f[15,16];
    sleep 1;
    seek STDIN,0,0;
  }' < /proc/$!/stat

Onde você verá o cutime (tempo de usuário cumulativo) e cstime (sistema) incrementando somente quando cada um dos filhos diretos do processo que executou cmd morre e cmd tiver esperado para eles.

Exemplo de saída com zsh -c 'repeat 5 {head -c200M /dev/zero | pixz > /dev/null}' como cmd :

15:19:32 (zsh) cutime: 0.00 cstime: 0.00
15:19:33 (zsh) cutime: 0.00 cstime: 0.00
15:19:34 (zsh) cutime: 0.05 cstime: 0.25
15:19:35 (zsh) cutime: 0.05 cstime: 0.25
15:19:36 (zsh) cutime: 19.21 cstime: 1.04
15:19:37 (zsh) cutime: 19.21 cstime: 1.04
15:19:38 (zsh) cutime: 19.21 cstime: 1.04
15:19:39 (zsh) cutime: 19.26 cstime: 1.31
15:19:40 (zsh) cutime: 37.94 cstime: 2.05
15:19:41 (zsh) cutime: 37.94 cstime: 2.05
15:19:42 (zsh) cutime: 37.97 cstime: 2.36
15:19:43 (zsh) cutime: 37.97 cstime: 2.36
15:19:44 (zsh) cutime: 57.17 cstime: 3.07
15:19:45 (zsh) cutime: 57.17 cstime: 3.07
15:19:46 (zsh) cutime: 57.22 cstime: 3.36
15:19:47 (zsh) cutime: 76.06 cstime: 4.10
15:19:48 (zsh) cutime: 76.06 cstime: 4.10
15:19:49 (zsh) cutime: 76.06 cstime: 4.10
15:19:50 (zsh) cutime: 76.08 cstime: 4.42

Onde você vê os horários sendo incrementados em massa (quando os processos head e pigz morrem).