Como entender o tempo no dmesg

Question

Eu sei que o tempo em dmesg é o tempo desde a inicialização. Mas minha pergunta específica é que esse tempo é calculado no início ou no final do processo mencionado na linha?

Por que isso é importante?
Veja este exemplo:

[    4.352025] floppy0: no floppy controllers found
[    5.718270] random: nonblocking pool is initialized
[   94.134265] Adding 2094076k swap on /dev/sda5.  Priority:-1 extents:1 across:2094076k FS**
[   96.988453] init: bootchart main process (274) terminated with status 127

Se o tempo for calculado após o término do processo, o processo na terceira linha deve ser considerado responsável pela inicialização lenta.
Mas se o tempo é calculado a partir do início do processo, a segunda linha deve ser responsabilizada por isso.

Mas fica mais complicado quando verificamos dmesg long after boot.
Tome isso por exemplo:

[28047.749604] wlp3s0: associated
[28941.112855] [drm:intel_pipe_update_end [i915]] *ERROR* Atomic update failure on pipe A (start=757985 end=757986)
[31407.938694] cfg80211: World regulatory domain updated:
[31407.938699] cfg80211:  DFS Master region: unset

Esse intervalo de 2466s não deve ter nenhum significado útil.

Eu vejo muitas vezes que há confusão sobre qual linha em dmesg deve ser responsável por uma inicialização lenta.

Como podemos entender o tempo no dmesg?

    

Answer 1

dmesg não é um teste confiável de quanto tempo dura um processo de inicialização ou onde há gargalos de garrafas. De acordo com Wikipedia page :

  

Quando inicialmente inicializado, um sistema de computador carrega seu kernel na memória.   Neste estágio, os drivers de dispositivos presentes no kernel são configurados para   hardware relevante. Tais drivers, bem como outros elementos dentro do   kernel, pode produzir saída ("mensagens") relatando tanto a presença de   módulos e os valores de quaisquer parâmetros adotados

Em outras palavras, dmesg em si apenas coleta informações, são os drivers e outros processos do sistema que geram essas mensagens e podem gerá-las a qualquer momento. Entre essas mensagens pode haver ou não outros processos sendo gerados, por isso não é um indicador de quanto tempo o sistema inicializa.

dmesg também coleta mensagens continuamente do buffer de anel, então seu atraso de 2466s não indica algum processo de suspensão, meramente um evento ocorrido 2466s depois e qualquer que seja o processo ativo naquele momento apenas gera uma mensagem de kernel.

O que você quer, no entanto, é bootchart , que é usado especificamente para encontrar garrafas. pescoços no processo de inicialização. Eu só vi isso sendo referenciado em vários fóruns e neste site, mas nunca usei a mim mesmo, então não posso lhe dar mais informações do que isso

    

Answer 2

O comando dmesg lê o buffer printk do kernel usando o modo de acesso ao espaço do usuário via /dev/kmsg . Cada entrada tem um registro de data e hora monotônico em microssegundos , que é definido quando a entrada de registro é criada.

Portanto, a questão não pode ser, qual registro de data e hora o dmesg (ou o kernel) irá logar, mas deve ser quando o kernel criará a entrada de log para uma ação específica que ele faz.

Como eu acho, isso pode diferir de ação para ação. Quando um evento acontece ao kernel, por exemplo, conecte um dispositivo USB, o kernel registrará isso assim que tiver informações utilizáveis. Quando o kernel faz uma tarefa planejada, faz sentido registrar os resultados quando o trabalho é concluído. Se for um trabalho complexo, talvez ele produza algumas entradas de log enquanto é executado, mas como eu acho que geralmente depois que algo interessante aconteceu ou um pouco de tempo se foi.

Como você pode acessar o buffer printk do kernel é explicado aqui .

Portanto, se você quer saber especialmente se uma determinada entrada é registrada no início ou no final de uma ação, você precisa procurar no kernel-sorcecode ou módulo-quando o programa chamar a função de log.

    

Answer 3

Leia man dmesg , especialmente:

   -d, --show-delta
          Display the timestamp and time delta spent between messages.  If
          used together with --notime then only the time delta without the
          timestamp is printed.


   -T, --ctime
          Print  human  readable  timestamps.  The  timestamp   could   be
          inaccurate!

          The  time  source  used for the logs is not updated after system
          SUSPEND/RESUME.

O valor do registro de data e hora é "microssegundos desde a inicialização / 1000000" (parece com "segundos para 6 casas decimais). O registro de data e hora é definido como 0 na inicialização.

Como @cmks disse, o valor "microseconds since boot" é copiado para a entrada de log quando a entrada de log é inserida no buffer do kernel. dmesg interpreta esse valor de várias maneiras diferentes. dmesg -T -d | less mostrará os deltas. Eu li a pergunta, e a resposta de @cmks