Introdução do problema

Recentemente eu realizei um trabalho de refactoring em um dos sistemas da Gigatron para melhorar o tempo de startup do software. Nesse caso em particular, o software é construído em Delphi e é um dos maiores projetos (em quantidade de código) que temos internamente.

Nesse artigo eu vou relatar a técnica que utilizei para identificar os pontos chave para otimização do programa e algumas das melhorias implementadas.

Pré-requisitos

Antes de começar o trabalho de identificação dos gargalos, é importante preparar:

• O código: Crie um novo branch no SCV para todo o trabalho de testes. Isso vai permitir testar a diferença de desempenho entre o início e o fim do trabalho de otimização e descartar alterações rapidamente caso não sejam necessárias;

• O mindset: Durante a análise e correção, repita o mantra: /“A medida vem primeiro”/. Se você vai fazer um trabalho de otimização de execução de código, é comum já começá-lo com alguma ideia de quais são os pontos de contenção. Mas é essencial que você valide se esses são realmente os pontos mais importantes.

A técnica que utilizei foi bem simples e é aplicável em vários outros escopos: criar um relatório dos tempos de execução entre diversos pontos chave da inicialização do sistema e depois otimizar esses pontos.

Classe TPerformanceCounter

Para medir o tempo de execução das funções, precisamos de uma função que calcule a diferença de tempo entre pontos de código. Para Windows, as duas funções usadas para medição de diferença de tempo são GetTickCount e QueryPerformanceCounter.

A segunda função tem maior precisão, portanto utilizei ela na elaboração de uma classe (TPerformanceCounter) para medição da passagem do tempo conforme a inicialização do sistema progride:

Uma instancia dessa classe pode ser usada para medir o progresso da inicialização através de uma chamada a função start() e subsequentes chamadas a função currentMs() que irá retornar a diferença em millisegundos entre o start e o currentMs.

Primeiro teste

Para esse experimento em particular, utilizei um método simples para coleta dos dados de tempo: habilitei a geração do console na aplicação (Project -> Options -> Aba Linker -> Opção Generate Console Application) e criei uma função currentToConsole() para emitir o tempo em millisegundos entre as principais etapas da inicialização do sistema.

Note que na unit unPerfCounter.pas é inicializada uma variável global chamada masterPerf que é iniciada automaticamente. Isso é útil para testar um processo que acontece através de várias units e vai permitir medir seções de inicialização de units.

A primeira medição deve ser feita no programa original, sem otimizações, para servir de base nas comparações com as melhorias.

O programa instrumentado para medição deve ser algo assim:

Quando esse programa for executado, o console deve mostrar o tempo entre o carregamento da unit UnPerfCounter (por isso ela deve ser a primeira da lista no dpr) e cada emissão individual do currentToConsole().

Se o programa sob teste for grande o suficiente e tiver procedimentos o suficiente na sua inicialização, só esse teste já é capaz de apontar as principais áreas problemáticas. Caso necessário, você pode inserir mais pontos de medição individuais quando a diferença entre os locais for muito grande.

O ideal é encontrar procedimentos ou módulos que individualmente demorem mais do que 500ms para inicialização e que possam ser refatorados.

Tempo e Ordem de inicialização das units

Se o sistema sendo testado tiver uma quantidade grande de units, pode ser que até mesmo o tempo entre o início da execução do sistema (o momento em que o usuário efetua um duplo clique no atalho do programa) e o momento em que a primeira mensagem de debug aparece (no início do begin do DPR) seja muito grande (ordem de segundos).

Nesse caso, pode ser que alguma das units tenha uma seção initialization onde algum processo muito lento está sendo feito.

Para descobrir qual unit isso acontece, faça o seguinte. Em primeiro lugar, descubra a ordem efetiva de inicialização de todas as units (inclusive das bibliotecas usadas no programa). Essa ordem não é a ordem de declaração no DPR, é uma ordem que o compilador define que as units devem ser inicializadas de acordo com as suas respectivas cláusulas uses.

Felizmente, essa resposta no StackOverflow me colocou no caminho certo e me permitiu preparar uma segunda unit de depuração que emite a ordem completa de carregamento do sistema:

Adicione a unDebugUnitInitOrder no fim da lista de uses do programa e modifique o sistema.dpr para chamar a função extractUnitOrder() logo após o begin. Isso cria um arquivo unit-order.txt no diretório do executável com a ordem das units.

Com a lista concreta da ordem de inicialização, você pode medir quais grupos de units demoram mais tempo adicionando uma seção de initialization em algumas delas, chamando o masterPerf.currentToConsole() e comparando os tempos de execução entre cada chamada.

Uma outra alternativa é usar um pequeno utilitário para modificar a inicialização de todas units do sistema para emitir o aviso de teste. Fiz esse utilitário e disponibilizei nesse repo no github.

No meu caso, isso me permitiu identificar uma unit em particular que dominava o tempo de inicialização: a unit ssl_openssl_lib.pas, parte integrante do ProjetoACBR.

O problema principal dessa unit é a chamada a função randScreen() que está deprecada e é extremamante lenta. A discussão completa pode ser vista nesse post no fórum do projeto ACBR.

Threaded Splash

Após o refactoring do código onde possível para diminuir o tempo de carregamento, pode ser (e isso é verdade no meu caso) que ele ainda seja grande demais para parecer instantâneo ao usuário final.

Nesse caso, é necessário adicionar uma splash screen na inicialização do sistema para que o usuário tenha ciência de o processo de carregamento está em andamento.

Mas é muito importante que essa splash não atrase o carregamento do executável, caso contrário adicioná-la piora o problema. A técnica padrão de criar um form de splash no início do begin do dpr e exibi-lo tem dois problemas:

• O form só é exibido após o carregamento das units, que nós já vimos pode ser um tempo significativo em um sistema grande;

• O form consome recursos da main thread (thread onde todos os procedimentos da VCL são executados), o que atrasa ainda mais o sistema.

A melhor forma de adicionar uma tela de splash é com uma janela que implemente sua própria thread de processamento de mensagens. Felizmente existe uma demo disso no Embarcadero Developer Network que pode ser usada como base.

O ideal é que esse form seja criado na seção de inicialização de uma unit no topo da seção uses do DPR, para que ele seja a primeira coisa exibida no programa.

Conclusão

Otimização prematura é a raiz de todos os problemas (diz Knuth). Mas em um sistema grande e com tempo de vida medido em décadas, em algum momento ela é necessária. E o tempo de inicialização do sistema é um ótimo ponto para gastar alguns pontos de otimização.

O processo descrito nesse artigo pode ser usado não só nesse contexto, mas para qualquer processo longo composto de etapas discretas. Já para processos repetitivos (cálculos em um laço ou temporizadores com intervalo regular) ele precisa de algumas adaptações (dê uma olhada nas funções de acumulação da classe TPerformanceCounter).