Existem muitas ferramentas para depurar programas do kernel e do espaço do usuário no Linux. A maioria deles tem impacto no desempenho e não pode ser executada facilmente em ambientes de produção. Alguns anos atrás, o eBPF
foi desenvolvido , o que fornece a capacidade de rastrear o kernel e o espaço do usuário com pouca sobrecarga, sem a necessidade de recompilar programas ou carregar módulos do kernel.
Agora existem muitas ferramentas que usam o eBPF e, neste artigo, explicaremos como escrever sua própria ferramenta de criação de perfil usando a
biblioteca PythonBCC . Este artigo é baseado em um problema real do ambiente de produção. Orientaremos você na solução do problema e mostraremos como as ferramentas Cco existentes podem ser usadas em alguns casos.
Ceph é lento
Uma nova plataforma foi adicionada a um cluster ceph. Depois de migrar alguns dados para a plataforma, a latência para solicitações de gravação foi maior que nos outros servidores.
Essa plataforma possui um novo dispositivo virtual de armazenamento em cache - bcache, que não usamos neste cluster antes - e um novo kernel - 4.15, que ainda não é usado em nenhum outro lugar nesse cluster. A raiz do problema pode estar em qualquer lugar, então vamos dar uma olhada mais profunda.
Investigando o Host
Vejamos o que está acontecendo dentro do processo ceph-osd. Usamos a ferramenta de rastreamento
perf e o
flamescope para criar gráficos de flama:
Como podemos ver no flamegraph,
fdatasync () passou muito tempo enviando biografia na função
generic_make_request () . Portanto, a raiz do nosso problema está em algum lugar fora do daemon ceph. Pode ser um problema de kernel, bcache ou disco. A saída do iostat mostrou alta latência para dispositivos bcache.
Outra descoberta suspeita é que o daemon systemd-udevd está consumindo CPU; cerca de 20% em várias CPUs. Esse é um comportamento estranho, por isso temos que descobrir o que está acontecendo. Como systemd-udevd trabalha com uevents, temos que usar o
udevadm monitor para descobrir se há algum evento no sistema. Após a verificação, vimos que muitos eventos de "alteração" estavam sendo gerados para cada dispositivo de bloco no sistema.
Isso é incomum, então vamos descobrir o que está causando o envio de todos esses eventos.
Usando o BCC Toolkit
Como já sabemos, o kernel (e ceph daemon) está gastando muito tempo executando funções
generic_make_requst () . Vamos medir sua latência usando a
funclatência do
kit de ferramentas BCC , apenas para garantir que estamos no caminho certo. Rastrearemos o PID do daemon ceph (argumento -p) em intervalos de 1 segundo (-i) e imprimiremos a latência em milissegundos (-m).
Essa função geralmente funciona muito rápido. Tudo o que faz é enviar a estrutura biológica para a fila do driver de dispositivo.
Bcache é um dispositivo complexo; de fato, consiste em 3 dispositivos: um dispositivo de suporte, que é um HDD lento no nosso caso; um dispositivo de armazenamento em cache, que é a partição da unidade NVMe; e um dispositivo virtual bcache, usado pelo aplicativo. Sabemos que o envio é lento, mas para qual dispositivo? Isso é algo que veremos um pouco mais tarde.
Por enquanto, sabemos que os eventos causam problemas nos ceph daemons e precisamos encontrar o software que os desencadeia. Não é fácil encontrar o que faz com que os eventos sejam gerados. Assumimos que é um software que roda apenas periodicamente. Para ver o que está sendo executado no sistema, usamos
execsnoop do kit de ferramentas BCC. Podemos executá-lo e redirecionar o
stdout para um arquivo.
Por exemplo:
/usr/share/bcc/tools/execsnoop | tee ./execdump
Não forneceremos a saída completa do execsnoop aqui, mas uma string interessante que encontramos lá foi:
sh 1764905 5802 0 sudo arcconf getconfig 1 AD | grep Temperature | awk -F '[:/]' '{print $2}' | sed 's/^ \([0-9]*\) C.*/\1/'
A terceira coluna é o PPID do processo. Verificamos o que era o 5802 e vimos que é um dos nossos threads do daemon de monitoramento. Olhando mais para a configuração do sistema de monitoramento, encontramos um parâmetro com defeito. A temperatura do HBA estava sendo recuperada a cada 30 segundos, o que é muito frequente. Depois de alterar o intervalo de verificação para um valor mais apropriado, vimos que nossa latência de ceph correspondia às outras plataformas.
Mas ainda não sabemos por que a latência do bcache foi alta. Montamos uma plataforma de teste com a mesma configuração e tentamos reproduzir o problema com o fio no dispositivo bcache enquanto acionamos simultaneamente o udev com o comando udevadm trigger.
Escrevendo ferramentas baseadas em Cco
O que vamos fazer aqui é escrever uma ferramenta simples que rastreie as chamadas mais lentas de generic_make_request () e imprima o nome do disco para o qual a função foi solicitada.
O plano é simples:
- Registre o kprobe em generic_make_request () :
- Salve o nome do disco disponível no argumento da função
- Salve o carimbo de data / hora atual
- Registre o kretprobe na instrução de retorno generic_make_request () :
- Recuperar o carimbo de data / hora atual
- Procure carimbos de data e hora salvos anteriormente e compare-os com os atuais
- Se o resultado for maior que o limite, procure nomes de discos salvos anteriormente e imprima-os no terminal com informações adicionais
Kprobes e
kretprobes usam pontos de interrupção para alterar o código de uma função em tempo de execução. Você pode encontrar
documentação e um bom
artigo sobre isso. Se você der uma olhada no código para diferentes
ferramentas de Cco , verá que todas elas têm uma estrutura idêntica. Ignoraremos a análise de argumentos e focaremos no próprio programa BPF.
O texto do nosso programa será definido em python da seguinte maneira:
bpf_text = “””
Os programas BPF usam
hashmaps para compartilhar dados entre diferentes funções. Usaremos o PID como uma chave e a estrutura auto-definida como um valor.
struct data_t { u64 pid; u64 ts; char comm[TASK_COMM_LEN]; u64 lat; char disk[DISK_NAME_LEN]; }; BPF_HASH(p, u64, struct data_t); BPF_PERF_OUTPUT(events);
Aqui, registramos um hashmap chamado
p com um tipo de chave
u64 e um tipo de valor
struct data_t . Este mapa pode ser acessado em nosso contexto de programa BPF. A macro
BPF_PERF_OUTPUT registra outro mapa chamado
events , que é usado para
enviar dados para o espaço do usuário.
Ao medir a latência entre a chamada de função e seu retorno ou entre uma chamada de função e outra, você deve ter certeza de que os dados que você salvou e acessou posteriormente se relacionam ao mesmo contexto. Em outras palavras, você deve estar ciente de quaisquer outras execuções paralelas da mesma função. É possível rastrear a latência entre a chamada de função de um processo e os retornos da mesma função de outro processo, mas isso não nos ajuda. Um bom exemplo é a
ferramenta de biolatência em que a
solicitação de ponteiro para
estrutura é usada como uma chave de hashmap.
Em seguida, precisamos escrever um código que será executado nas chamadas de função por meio de um mecanismo kprobe:
void start(struct pt_regs *ctx, struct bio *bio) { u64 pid = bpf_get_current_pid_tgid(); struct data_t data = {}; u64 ts = bpf_ktime_get_ns(); data.pid = pid; data.ts = ts; bpf_probe_read_str(&data.disk, sizeof(data.disk), (void*)bio->bi_disk->disk_name); p.update(&pid, &data); }
Aqui temos o primeiro
argumento generic_make_request () como o segundo argumento da nossa função. Em seguida, obtemos o PID e o registro de data e hora atuais em nanossegundos e os
gravamos nos dados struct data_t recentemente alocados. Nós obtemos o nome do disco da estrutura bio, que é passada para
generic_make_request () , e o salvamos em nossos
dados . A última etapa é adicionar uma entrada ao hashmap que descrevemos anteriormente.
Esta função será executada nos retornos
generic_make_request () :
void stop(struct pt_regs *ctx) { u64 pid = bpf_get_current_pid_tgid(); u64 ts = bpf_ktime_get_ns(); struct data_t* data = p.lookup(&pid); if (data != 0 && data->ts > 0) { bpf_get_current_comm(&data->comm, sizeof(data->comm)); data->lat = (ts - data->ts)/1000; if (data->lat > MIN_US) { FACTOR data->pid >>= 32; events.perf_submit(ctx, data, sizeof(struct data_t)); } p.delete(&pid); } }
Obtemos o PID e o carimbo de data e hora da saída anterior e procuramos no mapa de hash o valor where
key == PID atual . Se for encontrado, obtemos o nome do processo em execução e o adicionamos à estrutura de
dados . O que fazemos com
data-> pid aqui nos fornece o ID do grupo de threads. A função anteriormente chamada
bpf_get_current_pid_tgid () retorna o thread GID e PID do processo no mesmo valor de 64 bits.
Não estamos interessados no ID de cada segmento, mas queremos saber o PID do segmento principal. Após verificar se a latência está acima do limite, enviamos nossa estrutura de
dados para o espaço do usuário por meio do mapa de
eventos e excluímos a entrada de hashmap no final.
Em nosso script python, precisamos substituir
MIN_US e
FACTOR de acordo com o limite que queremos e a unidade de tempo que queremos ver em nosso resultado:
bpf_text = bpf_text.replace('MIN_US',str(min_usec)) if args.milliseconds: bpf_text = bpf_text.replace('FACTOR','data->lat /= 1000;') label = "msec" else: bpf_text = bpf_text.replace('FACTOR','') label = "usec"
Em seguida, precisamos preparar o programa BPF com uma
macro BPF () e registrar probes:
b = BPF(text=bpf_text) b.attach_kprobe(event="generic_make_request",fn_name="start") b.attach_kretprobe(event="generic_make_request",fn_name="stop")
Também precisamos definir a mesma estrutura que
struct data_t em nosso script para ler os dados do programa BPF:
TASK_COMM_LEN = 16
O último passo é imprimir os dados que queremos:
def print_event(cpu, data, size): global start event = ct.cast(data, ct.POINTER(Data)).contents if start == 0: start = event.ts time_s = (float(event.ts - start)) / 1000000000 print("%-18.9f %-16s %-6d %-1s %s %s" % (time_s, event.comm, event.pid, event.lat, label, event.disk)) b["events"].open_perf_buffer(print_event)
O script completo está disponível no
GitHub . Vamos executar o script e disparar eventos do udev enquanto o fio grava em um dispositivo bcache:
Sucesso! Agora vemos que o que parecia alta latência para o bcache é realmente a latência
generic_make_request () para seu dispositivo de backup.
Cavar no kernel
O que se arrasta ao enviar solicitações? Vimos que ocorreu um pico de latência antes mesmo que a contabilidade da solicitação fosse iniciada. Isso pode ser facilmente verificado executando o iostat durante o problema ou o
script BCC da
biolatência , que se baseia no início da solicitação de contabilidade, para que nenhuma ferramenta mostre o problema do disco.
Se dermos uma olhada em
generic_make_request () , veremos que há duas funções em execução antes do início da contabilidade. O primeiro é
generic_make_request_checks () , que é leve e verifica a biografia de acordo com as configurações do dispositivo, etc. O segundo é
blk_queue_enter () , que possui uma chamada
wait_event_interruptible () :
ret = wait_event_interruptible(q->mq_freeze_wq, (atomic_read(&q->mq_freeze_depth) == 0 && (preempt || !blk_queue_preempt_only(q))) || blk_queue_dying(q));
Aqui o kernel espera até que a fila seja descongelada. Vamos medir a latência de blk_queue_enter ():
~
Parece que estamos perto. As funções usadas para congelar / descongelar a fila são
blk_mq_freeze_queue e
blk_mq_unfreeze_queue . Eles são usados para alterar as configurações da fila, o que pode afetar as solicitações io atualmente em andamento. Quando
blk_mq_freeze_queue () é chamado,
q-> mq_freeze_depth é incrementado em
blk_freeze_queue_start () . Depois disso, o kernel espera que a fila fique vazia em
blk_mq_freeze_queue_wait () .
Esse tempo de espera é igual à latência do disco, porque o kernel precisa aguardar a conclusão de todas as operações io. Quando a fila está vazia, as alterações podem ser feitas. A etapa final é chamar
blk_mq_unfreeze_queue () , que diminui o contador
freeze_depth .
Agora sabemos o suficiente para corrigir o problema. O comando udevadm trigger altera as configurações dos dispositivos de bloco. Essas configurações são descritas nas regras do udev. Podemos descobrir quais configurações congelam a fila alterando-as via sysfs ou olhando o código-fonte do kernel. Como alternativa, podemos
chamar o trace do kit de ferramentas BCC para imprimir pilhas de kernel e usuário para cada chamada
blk_freeze_queue :
~
As regras do Udev não mudam frequentemente, portanto, mesmo atribuir valores já existentes a determinados parâmetros causa um aumento na latência de envio do aplicativo. É claro que gerar eventos do udev quando não há alterações na configuração de um dispositivo (nenhum dispositivo está conectado ou desconectado) não é uma boa prática. Ainda assim, podemos impedir que o kernel congele a fila se não houver motivo para fazer isso.
Três pequenas confirmações corrigem o problema.
Conclusão
O eBPF é um instrumento altamente flexível e poderoso. Neste artigo, analisamos apenas um caso e demonstramos um pouco do que ele é capaz. Se você estiver interessado em desenvolver ferramentas baseadas em Cco, dê uma olhada no
tutorial oficial , que descreve seus conceitos fundamentais.
Existem também outras ferramentas interessantes baseadas em eBPF disponíveis para criação de perfil e depuração. Um deles é o
bpftrace , que permite escrever oneliners poderosos e pequenos programas em uma linguagem do tipo awk. Outro é o
ebpf_exporter , que pode coletar métricas de alta resolução e baixo nível para o servidor prometheus, com suas excelentes habilidades de visualização e alerta.