Início / unix / Perguntas / 517757
Accepted
sourcejedi
Asked: 2019-05-09 02:36:51 +0800 CST

Minha suposição básica sobre o sistema "iowait" não se sustenta

  • 772

Minha suposição básica é que, quando os únicos fatores limitantes de um processo são disco e CPU, o "iowait" total do sistema + uso da CPU deve ser igual a pelo menos 100% de uma CPU lógica. (Em outros casos, isso não acontecerá. Por exemplo, ao baixar um arquivo usando wget, a rede geralmente é o fator limitante).

Esta suposição é violada por um teste simples. Isso é esperado? Se for esperado, existe um conjunto de condições em que devo esperar que minha suposição seja verdadeira?

Há alguns antecedentes sobre "iowait" aqui: Como uma CPU sabe que há IO pendente? A resposta aqui cita a ideia contra-intuitiva de que a espera cumulativa "pode ​​diminuir em certas condições". Gostaria de saber se meu teste simples pode estar desencadeando uma condição tão não documentada?

ATUALIZAÇÃO : Por favor , pule para a resposta .

A resposta tem um teste mais simples do que o que usei originalmente. Eu preservei a pergunta original abaixo. A pergunta original pode mostrar alguns detalhes adicionais.

Pergunta original

Em um pequeno teste, costumo ddsolicitar ao kernel para gerar bytes aleatórios e gravá-los em um arquivo. Eu executo o ddcomando dentro perf statde , apenas para obter uma contagem do tempo de CPU gasto dentro do kernel. Eu também corro dentro perf trace -s, para relatar o tempo gasto dentro write(). Ao mesmo tempo, corro vmstat 5em outro terminal, para ver o sistema "iowait".

  1. Eu esperava ver pelo menos uma CPU inteira como "não ociosa", ou seja, 100% do tempo em execução ou interrompida, mas aguardando IO (estado "iowait"). Não era.
  2. (Além disso, eu esperava ver o tempo de "iowait" corresponder aproximadamente ao tempo gasto em write(). Mas não pareceu fazer isso.)

Os resultados detalhados e o ambiente de teste são mostrados abaixo. Também é mostrado um teste alternativo, onde minha suposição se manteve. Nota: era necessário correr para perf statdentro perf trace, e não o contrário. Isso é detalhado aqui: "perf stat" (e "time" !) mostra resultados incorretos ao executar "perf trace -s" ?

Informações básicas sobre "iowait"

A seguir está a definição retirada da página de sarmanual:

%iowait:

Porcentagem de tempo em que a CPU ou CPUs ficaram ociosas durante o qual o sistema teve uma solicitação de E/S de disco pendente.

Portanto, %iowait significa que, do ponto de vista da CPU, nenhuma tarefa foi executada, mas pelo menos uma E/S estava em andamento. iowait é simplesmente uma forma de tempo ocioso quando nada pode ser agendado. O valor pode ou não ser útil para indicar um problema de desempenho, mas informa ao usuário que o sistema está ocioso e poderia ter tido mais trabalho.

https://support.hpe.com/hpsc/doc/public/display?docId=c02783994

Há também um artigo mais longo: Entendendo a espera de E/S (ou por que 0% ocioso pode ser OK) . Isso explica como você pode ver a definição claramente a partir do código do kernel. O código mudou um pouco, mas a ideia ainda é clara:

/*
 * Account for idle time.
 * @cputime: the CPU time spent in idle wait
 */
void account_idle_time(u64 cputime)
{
    u64 *cpustat = kcpustat_this_cpu->cpustat;
    struct rq *rq = this_rq();

    if (atomic_read(&rq->nr_iowait) > 0)
        cpustat[CPUTIME_IOWAIT] += cputime;
    else
        cpustat[CPUTIME_IDLE] += cputime;
}

O artigo também mostra vários experimentos relacionados em um sistema de CPU única. Alguns dos experimentos até usam ddcom if=/dev/urandom ! No entanto, os experimentos não incluem meu teste dd if=/dev/urandom of=test.out . Ele só usa dd if=/dev/urandom of=/dev/null .

"IO wait" é um pouco mais complicado de pensar agora porque usamos sistemas multi-CPU, mas acho que ainda entendo, com base no código citado.

Meio Ambiente

Eu tenho quatro CPUs lógicas.

Eu uso o LVM e o sistema de arquivos ext4. Não estou usando nenhuma criptografia no meu disco ou sistema de arquivos. Eu não tenho nenhum sistema de arquivos de rede montado, então não estou lendo ou escrevendo um sistema de arquivos de rede.

Os resultados abaixo são do kernel 4.20.15-200.fc29.x86_64, usando o noopagendador de E/S. O cfqagendador de E/S também fornece resultados semelhantes.

(Eu também vi resultados semelhantes em uma compilação do kernel que foi baseada em uma configuração semelhante, mas estava mais próxima da versão 5.1 do kernel e usando mq-deadline. Então, isso estava usando o novo blk-mqcódigo).

Teste e resultados

$ sudo perf trace -s \
       perf stat \
       dd if=/dev/urandom of=test.out bs=1M oflag=direct count=3000

3000+0 records in
3000+0 records out
3145728000 bytes (3.1 GB, 2.9 GiB) copied, 31.397 s, 100 MB/s

 Performance counter stats for 'dd if=/dev/urandom of=test.out bs=1M oflag=direct count=3000':

         18,014.26 msec task-clock                #    0.574 CPUs utilized          
             3,199      context-switches          #    0.178 K/sec                  
                 4      cpu-migrations            #    0.000 K/sec                  
               328      page-faults               #    0.018 K/sec                  
    45,232,163,658      cycles                    #    2.511 GHz                    
    74,538,278,379      instructions              #    1.65  insn per cycle         
     4,372,725,344      branches                  #  242.737 M/sec                  
         4,650,429      branch-misses             #    0.11% of all branches        

      31.398466725 seconds time elapsed

       0.006966000 seconds user
      17.910332000 seconds sys

 Summary of events:
...
 dd (4620), 12156 events, 12.0%

   syscall            calls    total       min       avg       max      stddev
                               (msec)    (msec)    (msec)    (msec)        (%)
   --------------- -------- --------- --------- --------- ---------     ------
   read                3007 17624.985     0.002     5.861    12.345      0.21%
   write               3003 13722.837     0.004     4.570   179.928      2.63%
   openat                12     0.371     0.002     0.031     0.267     70.36%
...

Eu li a iowaitfigura da wacoluna de vmstat. Você pode saber quando o teste está sendo executado observando a iocoluna ( bo= 1K blocos de saída).

$ vmstat 5
procs -----------memory---------- ---swap-- -----io---- -system-- ------cpu-----
 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st
 0  0      0 5126892 176512 1486060   0   0  1788  4072  321  414  4  4 83  9  0
 1  0      0 5126632 176520 1485988   0   0     0     7  212  405  0  1 99  0  0
 0  0      0 5126884 176520 1485988   0   0     0     0  130  283  0  0 99  0  0
 0  0      0 5126948 176520 1485908   0   0     0     1  157  325  0  0 99  0  0
 0  0      0 5126412 176520 1486412   0   0   115     0  141  284  0  0 99  0  0
 0  2      0 5115724 176548 1487056   0   0     0  6019 18737 10733  3  6 89  2  0
 1  0      0 5115708 176580 1487104   0   0     3 91840 1276  990  0 13 77  9  0
 1  0      0 5115204 176600 1487128   0   0     2 91382 1382 1014  0 14 81  4  0
 1  0      0 5115268 176636 1487084   0   0     4 88281 1257  901  0 14 83  3  0
 0  1      0 5113504 177028 1487764   0   0    77 92596 1374 1111  0 15 83  2  0
 1  0      0 5114008 177036 1487768   0   0     0 113282 1460 1060  0 16 81  2  0
 1  0      0 5113472 177044 1487792   0   0     0 110821 1489 1118  0 16 74 10  0
 0  0      0 5123852 177068 1487896   0   0     0 20537  631  714  1  3 94  2  0
 0  0      0 5123852 177076 1487856   0   0     0    10  324  529  2  1 98  0  0
 2  0      0 5123852 177084 1487872   0   0     0    70  150  299  0  0 99  0  0

Resultados do teste onde ele se mantém (dentro de uma VM)

Eu tentei o mesmo teste dentro de uma VM com 1 CPU, que estava executando o kernel 5.0.9-301.fc30.x86_64e usando mq-deadline(e, portanto, blk-mq). Neste teste, funcionou como eu esperava.

$ sudo perf trace -s \
       perf stat \
       dd if=/dev/urandom of=test.out bs=1M oflag=direct count=3000
[sudo] password for alan-sysop:
3000+0 records in
3000+0 records out
3145728000 bytes (3.1 GB, 2.9 GiB) copied, 46.8071 s, 67.2 MB/s

 Performance counter stats for 'dd if=/dev/urandom of=test.out bs=1M oflag=direct count=3000':

         18,734.89 msec task-clock                #    0.400 CPUs utilized
            16,690      context-switches          #    0.891 K/sec
                 0      cpu-migrations            #    0.000 K/sec
               328      page-faults               #    0.018 K/sec
   <not supported>      cycles
   <not supported>      instructions
   <not supported>      branches
   <not supported>      branch-misses

      46.820355993 seconds time elapsed

       0.011840000 seconds user
      18.531449000 seconds sys


 Summary of events:
...
 dd (1492), 12156 events, 38.4%

   syscall            calls    total       min       avg       max      stddev
                               (msec)    (msec)    (msec)    (msec)        (%)
   --------------- -------- --------- --------- --------- ---------     ------
   write               3003 28269.070     0.019     9.414  5764.657     22.39%
   read                3007 18371.469     0.013     6.110    14.848      0.53%
   execve                 6    10.399     0.012     1.733    10.328     99.18%
...

Saída de vmstat 5:

$ vmstat 5
procs -----------memory---------- ---swap-- -----io---- -system-- ------cpu-----                                                                     
 r  b  swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st                                                                     
 0  0     0 726176  52128 498508    0    0  2040   231  236  731  7  5 77 11  0                                                                     
 0  0     0 726176  52136 498508    0    0     0    10   25   46  0  0 99  1  0                                                                     
 0  0     0 726208  52136 498508    0    0     0     0   29   56  0  0 100  0  0                                                                    
 0  1     0 702280  55944 511780    0    0  2260 13109 4399 9049  3 17 55 25  0                                                                     
 0  1     0 701776  56040 511960    0    0    18 129582 1406 1458 0 73  0 27  0                                                                    
 0  2     0 701524  56156 512168    0    0    22 87060  960  991  0 50  0 50  0                                                                     
 3  1     0 701524  56228 512328    0    0    14 118170 1301 1322 0 68  0 32  0                                                                    
 1  1     0 701272  56260 512392    0    0     6 86426  994  982  0 53  0 46  0                                                                     
 0  2     0 701020  56292 512456    0    0     6 56115  683  660  0 37  0 63  0                                                                     
 3  2     0 700540  56316 512504    0    0     5 33450  446  457  0 26  0 74  0                                                                     
 0  2     0 700860  56332 512536    0    0     3 16998  311  240  0 19  0 81  0                                                                     
 1  2     0 700668  56368 512616    0    0     7 32563  443  428  0 24  0 76  0                                                                     
 1  0     0 700668  56392 512648    0    0     3 20338  245  272  0 12  0 88  0                                                                   
 0  1     0 707096  56408 512920    0    0    54 20913  312  530  0 12 79  8  0                                                                     
 0  0     0 707064  56432 512920    0    0     0    49   39   64  0  0 45 55  0                                                                     
 0  0     0 707064  56432 512920    0    0     0     0   24   46  0  0 100  0  0                                                                    
 0  0     0 707064  56432 512920    0    0     0    80   28   47  0  0 100  0  0

Eu tentei adicionar uma CPU à VM e testar novamente. Os resultados foram variáveis: às vezes ele mostrava cerca de 0% na coluna ociosa e às vezes mostrava cerca de 50% ocioso (ou seja, uma em cada duas CPUs). No caso de 0% "idle", "iowait" foi muito alto, ou seja, vale mais de uma CPU. Ou seja, meu ponto de expectativa 2 não estava correto. Posso aceitar de má vontade esta aparente limitação de "iowait" em sistemas multi-CPU. (Embora eu não entenda muito bem. Se alguém quiser explicar exatamente, seria ótimo). No entanto, "idle" não estava acima de 50% em nenhum dos casos, portanto, esses testes ainda eram consistentes com minha primeira suposição sobre "iowait".

Eu tentei desligar a VM e iniciá-la com 4 CPUs. Da mesma forma, muitas vezes eu tinha exatamente 75% ocioso, e às vezes eu tinha tão baixo quanto 50% ocioso, mas não vi mais de 75% ocioso (ou seja, mais de três de quatro CPUs).

Já no sistema físico com 4 CPUs, ainda consigo reproduzir o resultado de mais de 80% de ociosidade conforme mostrado acima.

linux

1 respostas

  1. Best Answer

    Aviso de conteúdo : este post inclui links para várias discussões e códigos do Linux. Alguns conteúdos vinculados não atendem ao Código de Conduta atual para StackExchange ou Linux . Principalmente eles "insultam o código [mas não a pessoa]". No entanto, alguma linguagem é usada, que simplesmente não deve ser repetida. Peço que evitem imitar, repetir ou debater tal linguagem.

    Re: iowait vs contabilidade ociosa é "inconsistente" - iowait é muito baixo

    Em 07/05/2019 12:38, Peter Zijlstra escreveu:

    Em sex, 05 de julho de 2019 às 12:25:46 +0100, Alan Jenkins escreveu:

    Meu tempo de CPU "iowait" parece ser informado incorretamente. Você sabe por que isso pode acontecer?

    Porque iowait é um número aleatório mágico que não tem significado sensato. Pessoalmente, prefiro excluir tudo, exceto ABI :/

    Veja também o comentário próximo a nr_iowait()

    Obrigado. Eu considero [os problemas mencionados na documentação atual] como problemas diferentes, mas você quer dizer que não há muita demanda (ou ponto) para "consertar" meu problema.

    Encontrei meu problema. Já foi notado há cinco anos, e não seria trivial consertar.

    O tempo "iowait" é atualizado pela função account_idle_time():

    /*
 * Account for idle time.
 * @cputime: the CPU time spent in idle wait
 */
void account_idle_time(u64 cputime)
{
    u64 *cpustat = kcpustat_this_cpu->cpustat;
    struct rq *rq = this_rq();

    if (atomic_read(&rq->nr_iowait) > 0)
        cpustat[CPUTIME_IOWAIT] += cputime;
    else
        cpustat[CPUTIME_IDLE] += cputime;
}

    Isso funciona como eu esperava, se você estiver aproximando o tempo de CPU por "amostragem" com a interrupção tradicional do temporizador ("tick"). No entanto, pode não funcionar se o tick estiver desligado durante o tempo ocioso para economizar energia - NO_HZ_IDLE. Também pode falhar se você permitir que o tick seja desativado por motivos de desempenho NO_HZ_FULL- porque isso requer a inicialização VIRT_CPU_ACCOUNTING. A maioria dos kernels Linux usa o recurso de economia de energia. Alguns sistemas embarcados não usam nenhum dos recursos. Segue minha explicação:

    Quando o IO é concluído, o dispositivo envia uma interrupção . O manipulador de interrupção do kernel ativa o processo usando try_to_wake_up(). Ele subtrai um do nr_iowaitcontador:

    if (p->in_iowait) {
    delayacct_blkio_end(p);
    atomic_dec(&task_rq(p)->nr_iowait);
}

    Se o processo for acordado em uma CPU ociosa, essa CPU chama account_idle_time(). Dependendo de qual configuração se aplica, isso é chamado de tick_nohz_account_idle_ticks()from __tick_nohz_idle_restart_tick()ou vtime_task_switch()from finish_task_switch().

    Por esta altura, ->nr_iowaitjá foi decrementado. Se for reduzido a zero, nenhum tempo de espera será registrado.

    Este efeito pode variar: depende de qual CPU o processo é ativado. Se o processo for acordado na mesma CPU que recebeu a interrupção de conclusão de IO, o tempo ocioso poderá ser contabilizado antes, antes de ->nr_iowaitser decrementado. No meu caso, descobri que a CPU 0 lida com a interrupção ahci , olhando para watch cat /proc/interrupts.

    Eu testei isso com uma leitura sequencial simples:

    dd if=largefile iflag=direct bs=1M of=/dev/null

    Se eu fixar o comando na CPU 0 usando taskset -c 0 ..., vejo valores "corretos" para iowait. Se eu fixá-lo em uma CPU diferente, vejo valores muito mais baixos. Se eu executar o comando normalmente, ele varia dependendo do comportamento do agendador, que mudou entre as versões do kernel. Em kernels recentes (4.17, 5.1, 5.2-rc5-ish), o comando parece gastar cerca de 1/4 do tempo na CPU 0, porque o tempo "iowait" é reduzido a essa fração.

    (Não explicado: por que executar este teste em minha máquina virtual agora parece reproduzir iowait "correto", para cada (ou qualquer) CPU. Suspeito que isso possa envolver IRQ_TIME_ACCOUNTING, embora esse recurso também esteja sendo usado em meus testes fora da VM.

    Também não confirmei exatamente por que a supressão NO_HZ_IDLEfornece iowait "correto" para cada CPU em 4.17+, mas não em 4.16 ou 4.15.

    Executar este teste na minha máquina virtual parece reproduzir iowait "correto", para cada (ou qualquer) CPU. Isso se deve a IRQ_TIME_ACCOUNTING. Também é usado nos testes fora da VM, mas recebo mais interrupções ao testar dentro da VM. Especificamente, há mais de 1.000 "interrupções de chamada de função" por segundo na CPU virtual em que "dd" é executado.

    Então você não deve confiar muito nos detalhes da minha explicação :-)

    Há alguns antecedentes sobre "iowait" aqui: Como uma CPU sabe que há IO pendente? A resposta aqui cita a ideia contra-intuitiva de que a espera cumulativa "pode ​​diminuir em certas condições". Gostaria de saber se meu teste simples pode estar desencadeando uma condição tão não documentada?

    Sim.

    Quando pesquisei pela primeira vez, encontrei conversas sobre "soluços". Além disso, o problema foi ilustrado mostrando que o tempo cumulativo de "iowait" não era monotônico. Ou seja, às vezes saltou para trás (diminuiu). Não foi tão simples quanto o teste acima.

    No entanto, quando investigaram, encontraram o mesmo problema fundamental. Uma solução foi proposta e prototipada, por Peter Zijlstra e Hidetoshi Seto, respectivamente. O problema é explicado na mensagem de capa:

    [RFC PATCH 0/8] retrabalho na contabilidade de espera (2014-07-07)

    Não encontrei nenhuma evidência de progresso além disso. Havia uma pergunta aberta sobre um dos detalhes. Além disso, a série completa tocou em código específico para as arquiteturas de CPU PowerPC, S390 e IA64. Então eu digo que isso não é trivial para corrigir.

    • 7

relate perguntas