Acelerando o AdvPL – Parte 03

Introdução

Continuando os tópicos de performance e escalabilidade direcionados ao AdvPL, vamos hoje unir o útil ao agradável: Vamos abordar detalhes algumas boas práticas, inclusive algumas já mencionadas na documentação da TDN. Inclusive, enquanto este artigo era redigido, encontrei uma documentação muito interessante no link http://tdn.totvs.com/pages/viewpage.action?pageId=22480352, que abrange assuntos como as convenções da linguagem, padrões de design, práticas e técnicas, e inclusive desempenho.

Macroexecução em AdvPL

Como o foco deste tópico é justamente acelerar o AdvPL, vamos abordar um dos tópicos de desempenho (http://tdn.totvs.com/display/framework/Desempenho). Um dos testes realizados e publicados nesta seção da TDN foi uma comparação entre duas abordagens de exemplo de chamada de função, uma usando a macroexecução e outra usando a função Eval(), onde o teste realizado mostrou um melhor desempenho na macroexecução.

Fonte de testes

Baseado no fonte de testes da TDN, eu criei um fonte que simula quatro formas diferentes da chamada de uma função de processamento de exemplo, onde existe a passagem de dois parâmetros. Vamos ao código:

#INCLUDE "PROTHEUS.CH"
#DEFINE ITERATION_REPEAT 800000 // Repetições de testes
User Function EvalTest()
TesEcom1() // Teste 01 com "&" 
TesEcom2() // Teste 02 com "&"
TesEvalC() // Teste com Eval()
TesDiret() // Teste com chamada direta
Return
/* ---------------------------------------------------------------
Teste TesEcom1()
Usando macro-substituição, passando os parâmetros por fora da macro.
--------------------------------------------------------------- */
Static Function TesEcom1()
Local nX, nSeconds, nTimer
Local cRet := ""
Local cBloco := "FunTesExec"
nSeconds := Seconds()
For nX := 1 To ITERATION_REPEAT 
 cRet := &cBloco.(nX,10)
Next nX
nTimer := Seconds() - nSeconds
ConOut("("+procname(0)+") Tempo de execucao ....: " +str(nTimer,6,2)+' s.' )
Conout("("+procname(0)+") Operacoes por segundo.: "+str(ITERATION_REPEAT/nTimer,10))
Return
/* ---------------------------------------------------------------
Teste TesEcom2()
Usando macro-substituição, passando os parametros DENTRO da macro.
--------------------------------------------------------------- */
Static Function TesEcom2()
Local nX, nSeconds, nTimer
Local cRet := ""
Local cBloco
nSeconds := Seconds()
For nX := 1 To ITERATION_REPEAT 
 cBloco := "FunTesExec("+cValToChar(nX)+",10)"
 cRet := &(cBloco)
Next nX
nTimer := Seconds() - nSeconds
ConOut("("+procname(0)+") Tempo de execucao ....: " +str(nTimer,6,2)+' s.' )
Conout("("+procname(0)+") Operacoes por segundo.: "+str(ITERATION_REPEAT/nTimer,10))
Return
/* ---------------------------------------------------------------
Teste TesEvalC()
Usando Code-Block 
--------------------------------------------------------------- */
Static Function TesEvalC()
Local nX, nSeconds, nTimer
Local cRet := "" // Retorno do Bloco de Codigo
Local bBloco := {|p1,p2| FunTesExec(p1,p2)}
nSeconds := Seconds()
For nX := 1 To ITERATION_REPEAT
 cRet := Eval(bBloco,nx,10)
Next nX
nTimer := Seconds() - nSeconds
ConOut("("+procname(0)+") Tempo de execucao ....: " +str(nTimer,6,2)+' s.' )
Conout("("+procname(0)+") Operacoes por segundo.: "+str(ITERATION_REPEAT/nTimer,10))
Return
/* ---------------------------------------------------------------
Teste TesDiret()
Usando Chamada Direta
--------------------------------------------------------------- */
Static Function TesDiret()
Local nX := 0
Local nSeconds := 0
Local cRet := ""
nSeconds := Seconds()
For nX := 1 To ITERATION_REPEAT
 cRet := FunTesExec(nX,10)
Next nX
nTimer := Seconds() - nSeconds
ConOut("("+procname(0)+") Tempo de execucao ....: " +str(nTimer,6,2)+' s.' )
Conout("("+procname(0)+") Operacoes por segundo.: "+str(ITERATION_REPEAT/nTimer,10))
Return
/* ---------------------------------------------------------------
Funcao de Teste FunTesExec()
Apenas encapsula a função StrZero
--------------------------------------------------------------- */
STATIC Function FunTesExec(nExpr, nTam)
Local cNum
DEFAULT nExpr := 1
DEFAULT nTam := 1
cNum := StrZero(nExpr,nTam)
Return cNum

Resultados do teste

No meu notebook, os resultados obtidos no console do TOTVS AppServer foram estes :

(TESECOM1) Tempo de execucao ....: 3.16 s.
(TESECOM1) Operacoes por segundo.: 253325
(TESECOM2) Tempo de execucao ....: 21.12 s.
(TESECOM2) Operacoes por segundo.: 37879
(TESEVALC) Tempo de execucao ....: 3.16 s.
(TESEVALC) Operacoes por segundo.: 253084
(TESDIRET) Tempo de execucao ....: 2.34 s.
(TESDIRET) Operacoes por segundo.: 341297

Refletindo sobre estes tempos

Inicialmente, vamos ver o tempo mais rápido. Naturalmente, é uma chamada direta da função de processamento. Demorou 2,34 segundos para fazer 800 mil iterações. São aproximadamente 340 mil execuções por segundo. Depois vem os tempos de execução via macro (01) e Eval(), 3,16 segundos, aproximadamente 253 mil execuções por segundo. O tempo ficou 35 % maior para ambos os casos. Agora, o tempo mais lento, do segundo teste de macro-execução, demorou 21 segundos, apresentando um desempenho de 37 mil execuções por segundo, que ficou 9 vezes mais lento que o melhor resultado.

Agora, vamos olhar com uma lupa o “miolo” dos dois casos de teste com macro-execução, que é o foco principal deste post:

No primeiro teste, a chamada da função é realizada com uma forma de macro-substituição, onde apenas o nome da função a ser chamada está dentro da variável cBloco, e os parâmetros são passados explicitamente em cada chamada por fora da Macro.

cBloco := "FunTesExec"
For nX := 1 To ITERATION_REPEAT 
 cRet := &cBloco.(nX,10)
Next nX

No segundo teste, a macro é montada dentro de uma string, onde os parâmetros da função são montados dentro da string. Como a variável nX é local, ela não pode ser especificada diretamente, pois a visibilidade de resolução da macro não consegue pegar as variáveis locais.

For nX := 1 To ITERATION_REPEAT 
 cBloco := "FunTesExec("+cValToChar(nX)+",10)"
 cRet := &(cBloco)
Next nX

No primeiro teste, o texto da macro ( FunTesExec ) não muda durante as interações, o que permite ao AdvPL fazer um cache da resolução da macro, e acelerar o processo. Já no segundo teste, a macro é alterada com novos parâmetros a cada nova execução, o que exige que a macro seja recompilada na memória a cada iteração. Isto dá uma grande diferença de desempenho entre os dois ciclos de iterações.

Conclusão

Existem casos especiais onde a cópia dos parâmetros para uma macro precisam realmente ser feitas na chamada, mas agora não lembro de nenhum exemplo assim, “de cabeça”. Mas, para a maioria dos outros casos, onde você pode precisa fazer dinamicamente apenas a chamada de uma função dinâmica, cujo nome está em uma variável caractere, é mais rápido passar os parâmetros por fora.

Desejo a todos excelentes otimizações, um desempenho fantástico, e um ótimo final de semana 😀

Abraços, e até o próximo post 😉

Acelerando o AdvPL – Parte 02 (ERRATA)

Pessoal, boa tarde,

Hoje eu estava lendo novamente o código do post anterior, referente ao exemplo de um cache em array, com tamanho limitado de elementos, e uma optimização para subir no array cada item pesquisado, para que os itens mais pesquisados sejam encontrados sequencialmente em primeiro lugar, e encontrei um erro de lógica em um ponto da rotina … vamos ver apenas este pedaço do código:

Function GetJurosPad( cTipoCtr )
Local nJuros := -1
Local cChave := xFilial('ZZ1')+cTipoCtr
Local nPos := ascan(aJurosPad,{ |x| x[1] == cChave })
Local aTmp
If nPos > 0 
 // Achou no cache. 
 If nPos > 1 
 // nao esta na primeira posição, sobe uma 
   aTmp := aJurosPad[nPos]
   aJurosPad[nPos] := aJurosPad[nPos-1]
   aJurosPad[nPos-1] := aTmp
 Endif
 // Incrementa cache HITS -- achei no cache, economia de I/O
 nJurosHit++
 Return aJurosPad[nPos][2]
Endif

Reparem que a busca foi feita na declaração da variável nPos, usando Ascan(). Porém, caso o item encontrado não seja o primeiro elemento do array, o elemento encontrado sobe uma posição (usando a variável aTmp para fazer o SWAP). E, no final das contas, o valor retornado é a segunda coluna do elemento após a troca. Neste caso, a função somente vai retornar o valor correto caso o valor buscado seja encontrado no primeiro elemento do array.

Para  corrigir isto, precisamos armazenar o resultado encontrado antes de fazer a troca no array, e retornar este valor, veja a correção abaixo:

Function GetJurosPad( cTipoCtr )
Local nJuros := -1
Local cChave := xFilial('ZZ1')+cTipoCtr
Local nPos := ascan(aJurosPad,{ |x| x[1] == cChave })
Local aTmp
If nPos > 0 
 // Achou no cache. 
 nJuros := aJuros[nPos][2]
 If nPos > 1 
   // nao esta na primeira posição, sobe uma 
   aTmp := aJurosPad[nPos]
   aJurosPad[nPos] := aJurosPad[nPos-1]
   aJurosPad[nPos-1] := aTmp
 Endif
 // Incrementa cache HITS -- achei no cache, economia de I/O
 nJurosHit++
 Return nJuros
Endif

Lembrem-se da importância de revisar e testar o código. Ser um bom programador e ter experiência não vai te livrar de cometer erros, uma revisão de código e um bom teste nunca é uma questão de desconfiança, mas sim procedimento.

Até a próxima, pessoal 😀

Acelerando o AdvPL – Parte 02

Introdução

No tópico anterior deste assunto (https://siga0984.wordpress.com/2015/07/16/acelerando-o-advpl-parte-01/), foi abordado um caso de uso de uma função relativamente simples de identificação de linhas de um arquivo texto, onde pequenas alterações no código resultaram em ganhos significativos de desempenho. No post de hoje, vou abordar algumas premissas básicas e comuns em qualquer linguagem de programação, mas com foco no desenvolvimento em AdvPL.

Pontos Comuns de Desempenho

O primeiro e mais comentado paradigma de desempenho é “fazer mais com menos”. Logo, primeiro precisamos entender bem o que deve ser feito. Depois, qual é a forma mais simples de ser feito ( pode haver mais de uma ), e finalmente qual é a forma mais eficiente de ser feito. Acredito que os parágrafos abaixo sejam muito úteis nesta jornada.

1o. Aproveite as funções nativas da linguagem

Com uma linguagem de programação nas mãos, você pode criar quase tudo, inclusive recriar quase tudo. Muitas vezes uma determinada função da linguagem não atende a necessidade, então logo optamos por criar uma nova, escrita usando a própria linguagem. É claro que existem casos onde isto precisa ser feito, porém não se deve tomar por hábito fazer isso a cada desenvolvimento. Existe um overhead entre você chamar uma função da linguagem desenhada para realizar uma tarefa, e a linguagem executar vários statements e operadores para realizar a mesma tarefa.

Exemplo prático : A função AT()

Em AdvPL, temos uma função de busca por substring de texto, chamada AT(). Funções similares existem em diversas linguagens, no grupo de funções de manipulação de String. Basicamente, a função recebe duas strings como argumento, e realiza uma busca da primeira string dentro da segunda, e caso a primeira string seja encontrada inteira dentro da segunda string, a função retorna a posição do primeiro caractere encontrado na string-alvo da busca. Vamos recriar a função At() em Advpl, como sendo uma função estática, para fins de teste.

User Function TSTAT()
Local nI , nTimer
Local cString := "ABRACADABRAPEDECABRAEPAMININONDASEXEMPLOSTRINGLOUCO"
Local nPos1, nPos2
Local nCnt1 := 0
Local nCnt2 := 0 
 
nTimer := seconds()+1
While seconds() < nTimer
 nPos1 := at( "CO" , cString )
 nCnt1++
Enddo
conout("Buscas com AT() = "+cValToChar(nCnt1))
nTimer := seconds()+1
While seconds() < nTimer
 nPos2 := MYat( "CO" , cString )
 nCnt2++
Enddo
conout("Buscas com MYAT() = "+cValToChar(nCnt2))
conout("Confirmando o retorno das funcoes") 
conout("nPos1 = "+cValToChar(nPos1))
conout("nPos2 = "+cValToChar(nPos2))
Return
STATIC Function MyAT(cBusca,cString)
Local nI
Local nL := len(cBusca)
Local nT := len(cString) - nL + 1
For nI := 1 to nT
 If substr(cString,nI,nL) == cBusca
 return nI
 Endif
Next
Return 0

Propositalmente, a string a ser encontrada está no final da string a ser pesquisada, na posição 50. Compile e execute o programa e veja os resultados. Serão mostrados no log de console do TOTVS Application Server a quantidade de buscas realizadas em um segundo. No meu equipamento, os resultados foram:

Buscas com AT() = 1128241
Buscas com MYAT() = 92725
Confirmando o retorno das funcoes
nPos1 = 50
nPos2 = 50

Arredondando os números, a busca com AT() foi mais de 12x mais rápida do que com a MyAT(). Até aqui, tudo se parece muito com o primeiro exemplo mostrado no post anterior, certo? Sim, é isso mesmo. Mas neste post vamos entrar um pouco mais fundo na explicação do “por quê”.

Esta diferença de tempo é justificável ?

SIM. É justificável, e de forma razoavelmente simples. Para a linguagem AdvPL, a chamada da função At() representa uma chamada de uma função nativa do TOTVS Application Server, escrita em C++, que internamente foi desenhada para trabalhar da forma mais optimizada possível. Ao escrevermos uma função AdvPL para fazer o mesmo trabalho, devemos levar em conta que cada atribuição de variável, instrução de loop e incremento, instrução condicional, e demais funções e operadores básicos da linguagem têm um custo, são operações realizadas na camada do AdvPL, que possuem naturalmente o overhead implícito da camada de execução/runtime do AdvPL.

A função MyAT() acaba virando internamente uma sequência de operações, que vai executar a declaração de três variáveis em escopo local, inicializar uma com o retorno da função len() aplicada a um dos parâmetros, inicializar a outra com o resultado da operação matemática do retorno da função len() aplicada ao outro parâmetro, menos o tamanho do parâmetro de busca mais uma unidade, iniciar um laço de repetição (FOR), verificar se o resultado de uma função de extração de uma sequência de caracteres da string-alvo da busca a partir da posição atual é exatamente igual à string de pesquisa, que somente em caso afirmativo interrompe a execução da função, retornando a posição atual onde a string de busca foi encontrada, e retornando 0 quando todas as possibilidades de uma string existir dentro da outra forem verificadas.

Moral da estória: Não reinvente a roda, procure usar funções da linguagem que se aproximem do que você precisa. Noventa e duas mil requisições da função por segundo realmente não é um numero pequeno, porém basta inserir um looping dentro de outro, e um processamento de uma lista de elementos extensa precisar chamar a função mais de 10 milhões de vezes, o que demoraria aproximadamente 108 segundos usando a Myat(), enquanto que a At() demoraria apenas 9 segundos.

2o Em um ambiente distribuído, use a rede com sabedoria

Isto significa “minimizar” o uso da rede. Com o servidor de aplicação sendo executado em uma máquina, um banco de dados relacional em outra, e o servidor de arquivos em outra, cada iteração que usa a rede têm um custo do I/O, independente do tamanho do pacote. Porém, pacotes maiores, próximos ao tamanho do MTU (Maximum Transport Unit) — maior pacote trafegado pela rede sem fragmentação — da sua rede (normalmente de 1480 a 1500 bytes para redes Ethernet / PPPoE) aproveitam melhor a largura de banda da rede. Traduzindo para o português, é mais barato para a rede transportar uma unica requisição de 1024 Bytes do que trafegar 16 requisições de 64 bytes cada.

O mundo ideal é você reaproveitar o que já foi trafegado, por exemplo criando um cache local. Isto pode se aplicar a algumas partes do código, em momentos específicos, e pode ser um pouco mais complexo determinar o que você deve usar em um cache, e por quanto tempo essa informação pode ser mantida em cache antes de ser invalidada. Mas, usada de forma correta, ela pode acelerar incrivelmente a sua aplicação.

Exemplo prático: Consultas ao banco de dados

Em um determinado momento, durante um processamento de uma lista de itens, podem ser necessárias muitas consultas atômicas em tabelas de configuração ou em dados de baixa volatilidade. Quando a incidência de buscas destes dados são realizadas em mais de um momento distinto pela mesma rotina ou por rotinas comuns chamadas várias vezes durante o processo, nada mais elegante do que fazer um cache local dos resultados já obtidos anteriormente, primeiro verificando o dado em cache, e somente indo acessar o dado no SGDB ou no sistema de arquivos remoto se a informação ainda não está cacheada. Muitas aplicações WEB e de processamentos distribuídos utilizam-se destas técnicas, isso dá um fôlego bem maior para o Banco de Dados e para a rede.

Mas lembre-se, cache não é a solução mágica para tudo. Você somente vai ter ganho se houver incidência de buscas por informações já presentes no cache (cache hit). Se todas as suas buscas são diferentes, todos os resultados também serão, e guardar todos eles no cache, sendo que eles não serão pesquisados novamente, somente vai tornar o processamento e o consumo de memória mais acentuados.

E, a coisa se complica quando você decide fazer cache de informações de alta volatilidade, pois se é importante para a sua aplicação sempre pegar a ultima versão de uma informação, que é constantemente atualizada, seu cache precisa ser definido com um curto tempo de validade, pois a sincronização destes dados pela rede pode ter um custo muito alto, para por exemplo um programa notificar os demais para limparem os seus caches sob demanda a cada atualização — é bem mais barato definir um prazo de validade curto e o cache expirar e limpar-se após algum tempo.

Vamos tomar um exemplo, de uma função de processamento hipotética, que faz uma pesquisa em uma tabela para verificar qual é a taxa de juros padrão para cada tipo de contrato, em um momento de recálculo para emissão de boletos de cobrança atrasados com os valores atualizados. Imagine que a função seja a GetJurosPad(), que recebe como parâmetro um código do tipo de contrato, e retorne a taxa de juros padrão para o tipo informado. A consulta é realizada na tabela ZZ1, fazendo uma busca por código e retornando o valor encontrado. Caso o codigo não exista, a função retorna -1

Function GetJurosPad( cTipoCtr )
Local nJuros := -1
ZZ1->(DbSetOrder(1))
If ZZ1->(DbSeek( xFilial('ZZ1')+cTipoCtr ))
 nJuros := ZZ1->Z1_JUROS 
Endif
Return nJuros

Se esta função for chamada 10 mil vezes, cada chamadas desta função, independente do código informado como parâmetro, vão gerar uma requisição via rede ao banco de dados, para trazer o valor atualmente armazenado. Agora, se você tem apenas 10 tipos de contratos diferentes, podemos seguramente fazer um cache na memória, usando um array, para que apenas as requisições não existentes no cache durante o processamento realmente façam um I/O com o Banco de Dados pela rede, e todas as demais 9990 requisições peguem os resultados já armazenados na memória sem usar a rede. E, como as taxas de juros dos tipos de contratos é uma informação que somente é atualizada esporadicamente (baixa volatilidade) e normalmente antes ou depois do expediente, ela se torna um candidato ideal para um cache local.

Vamos fazer um exemplo usando array — pois sabemos que a tabela de taxas de juros é realmente pequena — e vamos usar uma variável STATIC do AdvPL para guardar os resultados, pois durante o processamento esta função pode ser chamada de vários pontos da aplicação.

STATIC aJurosPad := {}
// Funcao de limpeza do cache 
Function ClearJurosPad()
aSize(aJurosPad,0)
return
// Função usando o cache
Function GetJurosPad( cTipoCtr )
Local nJuros := -1
Local cChave := xFilial('ZZ1')+cTipoCtr
Local nPos := ascan(aJurosPad,{ |x| x[1] == cChave })
If nPos > 0 
 // Achou no cache, retorna direto
 Return aJurosPad[nPos][2]
Endif
// Nao achou, busca na tabela 
ZZ1->(DbSetOrder(1))
If ZZ1->(DbSeek( cChave ))
 nJuros := ZZ1->Z1_JUROS 
Endif
// Acrescenta o resultado no cache
aadd(aJurosPad,{cChave,nJuros})
Return nJuros

Para limpar o cache, no inicio e no final do processamento, usamos a função ClearJurosPad(). Durante o processamento, usamos a função GetJurosPad(). Para cada código informado, primeiro será verificado o cache da memória no array STATIC, e caso o código já tenha sido buscado, ele é retornado instantaneamente. Caso contrário, a busca é feita no banco, e sendo encontrado ou não, a resposta da busca é guardada no cache.

Pontos de atenção

O exemplo simplista visto acima é relativamente seguro e performático, dadas as características conhecidas da tabela: Poucos registros, e baixa volatilidade. Caso a tabela possa ter mais registros, este cache pode começar a perder desempenho fazendo busca sequencial no array, sendo mais indicado o uso de um Hash Map, E, a quantidade de elementos deve ser limitada, para não haver um consumo excessivo de memória. Quando o limite estabelecido for atingido, você joga fora uma informação pouco usada do cache, para armazenar uma nova informação.

Sabendo-se que, até 100 registros em cache são aceitáveis fazendo uma busca sequencial no array, podemos limitar o array a 100 elementos, criados sob demanda, e cada busca realizada onde o dado foi encontrado no cache, mas não está na primeira posição, faz o dado encontrado subir no array uma posição. Desse modo, o cache se auto-organiza para ir colocando no topo as buscas mais realizadas, e quando o array atingir 100 posições, uma nova entrada de dados é feita sobrescrevendo a última posição.

STATIC aJurosPad := {}
STATIC nJurosHit := 0
STATIC nJurosMis := 0
// Funcao de limpeza do cache 
Function ClearJurosPad()
aSize(aJurosPad,0)
nJurosHit := 0
nJurosMis := 0
return
// Função usando o cache
Function GetJurosPad( cTipoCtr )
Local nJuros := -1
Local cChave := xFilial('ZZ1')+cTipoCtr
Local nPos := ascan(aJurosPad,{ |x| x[1] == cChave })
Local aTmp
// Codigo revisado em 09/08/2015
// A versao do post original continha um erro de lógica.
// Para ver o que estava de errado e ver o que foi corrigido, acesse o post
// https://siga0984.wordpress.com/2015/08/09/acelerando-o-advpl-parte-02-errata/
If nPos > 0 
 // Achou no cache. 
 nJuros := aJurosPad[nPos][2]
 If nPos > 1 
   // nao esta na primeira posição, sobe uma 
   aTmp := aJurosPad[nPos]
   aJurosPad[nPos] := aJurosPad[nPos-1]
   aJurosPad[nPos-1] := aTmp
 Endif
 // Incrementa cache HITS -- achei no cache, economia de I/O
 nJurosHit++
 Return nJuros
Endif
// Nao achou, busca na tabela 
ZZ1->(DbSetOrder(1))
If ZZ1->(DbSeek( cChave ))
 nJuros := ZZ1->Z1_JUROS 
Endif
// Incrementa cache MISS -- teve que ir pro banco 
nJurosMis++
If len(aJurosPad) < 100
 // Acrescenta o resultado no cache
 aadd(aJurosPad,{cChave,nJuros})
Else
 // Cache cheio, coloca na ultima posição
 aJurosPad[100] := {cChave,nJuros}
Endif
Return nJuros

Com isso, você tem um cache limitado a 100 registros, onde os mais acessados vão sendo trazidos para o topo do array naturalmente, sem precisar fazer reordenação, e de quebra você ainda registra o numero de acertos (hits) e erros (miss) de cache, para poder consultar no final do processo o quanto o seu cache foi eficiente. A taxa de acertos deve ser maior que a de erros. Quanto maior, melhor a eficiência.

E lembre-se de chamar a função de limpeza deste cache antes de iniciar uma sequência de processamentos longa, e de limpar ao final do processamento — pois o seu programa pode permanecer carregado na memória por mais tempo após este processamento, e sem uma limpeza explícita, a memória usada pelo array de cache em uma variável static somente será realizada quando o seu programa for descarregado da memória (terminado).

O teste realizado com as funções acima, no cenário sem cache e com cache, apresentaram uma diferença gritante. A realização de 10 mil buscas aleatórias em registros encontrados na base de dados demoraram por volta de 6 segundos, enquanto a busca utilizando o cache demoraram 0,2 segundos, onde o cache foi alimentado com 200 registros da tabela. Outro ponto interessante do cache, é que a busca em disco faz o posicionamento em um registro e traz o valor de todos os campos, mas como desejamos apenas o valor de um campo do registro, o cache apenas guarda a chave de busca e o valor desejado, minimizando extraordinariamente o consumo de memória.

Conclusão

As boas práticas de desenvolvimento escalar e performático são praticamente as mesmas para qualquer linguagem, antes de mais nada precisamos entender o custo de um processamento, para propor alternativas que o tornem mais leve. Nos próximos tópicos sobre este assunto, vamos abordar alguns usos adicionais e interessantes de mecanismos de cache em processamentos.

Dúvidas, sugestões, reclamações e afins, comente este tópico. Achou este conhecimento útil e interessante ? Faça como eu : Compartilhe 😀

Até o próximo post, pessoal 😉

Identificando Problemas – Memória no AdvPL – Parte 01

Introdução

Normalmente identificar um problema em um ambiente de produção é uma mistura de talentos. Você deve ser um pouco garimpeiro, um pouco psiquiatra, um pouco detetive … Um dos primeiros posts a respeito de “problemas” está no link https://siga0984.wordpress.com/2014/12/14/pense-fora-da-caixa-e-resolva-problemas/ . No post de hoje, vamos arranhar a tampa da caixa de Pandora …

Problemas

“Um problema é uma dificuldade na obtenção de um determinado objectivo. Em certos contextos pode ter um significado especial” — Wikipédia

No contexto da tecnologia da informação, um problema é um nome bonito e simples para ilustrar que “algo não está funcionando como deveria funcionar”. A questão está em resolver esse “algo errado”, seguido das duas perguntas mais intrigantes da humanidade: “POR QUÊ ?” e “COMO FAZ PRA RESOLVER”.

O quê, onde, (desde) quando e como

São as quatro perguntas iniciais de qualquer problema. Primeiro, o que foi identificado ou nomeado como sendo um problema. A resposta desta pergunta também ajuda a identificar a criticidade do problema. Normalmente qualquer departamento de suporte está sujeito a receber uma ligação com um cliente ou analista de campo esbaforido, que logo diz o seguinte: “PelamordeDeus, o sistema caiu…”.

Um problema pode ser desde uma diferença de valores mostrados em dois relatórios, que em tese deveriam chegar a um mesmo número, uma impossibilidade de uso de uma determinada rotina devido a uma validação de dados que não está permitindo a continuidade do processo, uma finalização do programa ou rotina com uma mensagem de erro seguido do fechamento da aplicação de interface, uma etapa de processo que ao ser acionada “trava” a aplicação, ou um determinado processo (ou o sistema inteiro) demora muito para ser concluído ( lentidão isolada ou generalizada), enfim, tudo é “problema”.

Normalmente a criticidade de um problema não está ligado tecnicamente a dificuldade de resolver ou entender o problema, mas sim no que isso causa para o cliente. Não conseguir imprimir uma Fatura ou Nota de Saída de mercadorias, quando o cliente está com um caminhão de mercadorias fechando a saída da empresa esperando a nota sair, para o cliente isso é um problema de criticidade máxima.

Os demais detalhes (onde , quando e como) são muito importantes, pois vão dar uma idéia de localização do problema, (desde) quando ele passou a acontecer, e “como” ele acontece — ou melhor, o que precisa ser feito e de que forma para que o “problema” se manifeste. O “como” é a receita de bolo para fazer o problema acontecer. Você precisa saber de todos os ingredientes, a ordem que foram colocados na panela, se o fogo estava ligado antes dos ingredientes serem colocados lá, e por aí vai.

E, uma observação muito bem lembrada pelo meu amigo Alan Cândido… Normalmente o quando (desde quando), deve vir junto com a pergunta: Qual foi a última vez que funcionou, e o que aconteceu no ambiente entre a última vez que funcionou e foi percebido que a rotina / programa / sistema apresentou o problema? Houve alteração de customização atualização de ambiente, binário, RPO, update do Windows, deploy de serviço, alteração de parametrização ou configuração, etc…?  Todos os dados são relevantes, nem sempre eles parecem estar conectados, mas são relevantes.

O Contorno

Muitas vezes precisamos arrumar um contorno para o problema para depois resolvê-lo. A nota fiscal não está saindo na Impressora 01 ? Tente na impressora 02. A rotina não começa a imprimir pois acontece um erro de execução ? Começou a acontecer ontem, depois de uma atualização de sistema ? Verifique se dá pra voltar a versão anterior do ambiente (caso exista). Existem problemas que não tem contorno, ou que o contorno pode causar mais problemas. É necessário ser criterioso na avaliação e para propor uma alternativa viável.

Descobrindo a causa

Bem, para cada tipo de problema, existe um roteiro para descobrir a causa. Alguns problemas não tem causa aparente, então tudo em volta do problema deve ser verificado. Esta investigação e o registro dela vão ajudar os responsáveis por arrumar o problema a entender tudo o que já foi verificado e qual é o cenário onde o problema se manifesta.

Partindo para a solução

Uma vez que o problema e sua causa foi entendida, a solução do problema pode ser um procedimento, executado pelo cliente ou por um analista, ou DBA, ou uma atualização de um programa, ou de um executável ou DLL, da mesma forma que um problema é “algo”, a solução é “fazer alguma coisa” — o leque de opções é extremamente amplo. Um ponto importante ao fornecer uma solução é sinalizar ao cliente se isso realmente vai ( ou deveria resolver o problema ), ou se é uma ação sobre uma provável causa. Normalmente depois da terceira vez que você pede para o cliente fazer mais alguma coisa no ambiente dando a entender que aquilo é a solução, e a ação proposta não resolve, fica muito mais difícil dar suporte a um cliente que não acredita mais no suporte.

Entrando no AdvPL

Até agora, todos os parágrafos anteriores não traz nenhuma novidade, é o “Be-a-bá” do Analista de Suporte. Agora, vamos entrar em uma análise de ocorrência que costuma deixar todos de cabelo em pé … “Consumo de memória”, no contexto de uma aplicação AdvPL. Vamos “fatiar” esse assunto, para ser possível devorá-lo sem se engasgar.

Definição de Consumo de Memória

Quando usamos a expressão “consumo de memória”, entendemos que isto significa a quantidade total de memória RAM (também conhecida por memória volátil) alocada por uma aplicação em execução pelo sistema operacional em um equipamento, usada internamente para armazenar o próprio programa em execução, juntamente com os dados que são ou podem ser carregados para a memória para serem mostrados na interface, gravados ou lidos de uma unidade de disco ou de um banco de dados, e assim por diante.

Todo e qualquer programa apresenta um consumo de memória de acordo com “o que” o programa está carregando na memória. Um programa AdvPL pode criar um array e ler registros de uma Query do banco de dados, e isso vai consumir memória proporcionalmente em razão da quantidade de linhas e colunas populadas desse Array.

Memória total do equipamento

Em um computador, temos uma quantidade limitada de memória RAM. Um equipamento Desktop pode vir com 4 GB (gigabytes) de memória, ou mais. Equipamentos servidores, dependendo do porte do servidor, podem ter de 32 GB a 128 GB de memória. Este recurso será dividido entre todos os programas e serviços que estão sendo executados no equipamento, inclusive o próprio sistema operacional do equipamento.

Tendo essa perspectiva em vista, antes de mais nada é necessário saber quanto de memória a versão do sistema operacional do equipamento precisa para operar com “folga”. Caso a soma dos aplicativos carregados na memória mais o sistema operacional cheguem perto do limite físico de memória, o sistema operacional começa a transferir áreas da memória para o disco rígido (HD) do equipamento, e isso definitivamente têm um impacto muito grande no desempenho das aplicações em execução.

Memória por aplicativo

Cada aplicativo pode possuir uma característica diferenciada de consumo de memória. SGBDs normalmente consomem o tamanho necessário ou disponível (sob demanda ou pré-reservado) para manter os dados e índices mais acessados espelhados em memória, para proporcionar maior desempenho — é mais rápido buscar uma informação na memória do que no disco. Normalmente você configura um limite de memória que o SGBD pode usar, para que ele não “morda” toda a memória do servidor. Uma vez que este limite seja atingido, o SGBD “se vira” para tirar do cache as informações menos acessadas.

Quando vamos colocar mais aplicativos para serem executados no mesmo equipamento, precisamos tomar o cuidado de não deixar eles tomarem posse de mais memória do que a disponível para uso, senão já sabemos o que acontece …

AdvPL e Consumo sob demanda

Como acabamos de ver, um SGBD normalmente consome a memória montando caches de dados e índices conforme a base de dados é acessada mediante solicitações de uma aplicação. Porém, uma vez definido ou atingido um limite, o SGBD pode manter na memória os caches dos dados mais utilizados, e descartar os caches pouco acessados. Conforme a aplicação vai solicitando informações, o SGBD “se vira” para gerenciar os caches da melhor forma possível.

Quando temos uma aplicação que consome memória para um contexto de execução, normalmente tudo o que está sendo executado precisa estar na memória RAM, por questões de desempenho. O servidor de aplicação AdvPL – Totvs Application Server – consome memória sob demanda, para cada contexto de execução. Uma nova conexão vinda de um SmartClient ou um novo JOB iniciado no AdvPL (processo sem interface) vão consumir memória para carregar o(s) programa(s) do repositório de objetos (RPO), e memória para armazenar os conteúdos das variáveis do programa alimentadas durante a sua execução ( Instâncias de classes, strings, etc). Por ser uma aplicação multi-thread, isto é, com múltiplos processos internos, cada thread possui uma reserva mínima de memória feita pelo sistema operacional, mas toda a memória alocada por todos os processos são vistas como uma coisa só para o sistema operacional do equipamento. Tudo fica “em nome” do executável.

Quando uma aplicação qualquer, como por exemplo um SmartClient, realiza a carga de uma DLL para integração com um periférico ou serviço, caso os programas e funções da DLL precisem de memória, eles vão pedir para o sistema operacional, porém esta memória vai ser contabilizada para o executável do SmartClient, que fez a carga da DLL. A mesma coisa acontece para o DBAccess (Gateway de acesso a bancos de dados relacionais) e o TOTVS Application Server. Cada driver ( DLL/SO) de acesso a dados que consumir memória vai usar a área de endereçamento do executável.

Consumo de memória por Thread

O TOTVS Application Server possui um mecanismo de monitoramento de memória por thread, que pode ser habilitado utilizando a chave DebugThreadUsedMemory=1 na seção [GENERAL] do arquivo de configuração (appserver.ini). — Vide TDN no link http://tdn.totvs.com/display/tec/DebugThreadUsedMemory. Com este recurso habilitado, o TOTVS Application Server passa a registrar as alocações e liberações de memória de cada processo (thread) em execução, e mostra essa informação em uma coluna adicional na interface de monitoramento (TOTVS Monitor e/ou TDS Server Monitor).

Cada processo ou thread AdvPL em execução mantém na memória os fontes das funções chamadas durante a execução do programa, e como os programas podem alimentar variáveis de memória de tamanho dinâmico, alguns programas podem apresentar um consumo de memória maior ou menor em relação a outros. Inclusive, como o primeiro programa a ser executado provavelmente fará a carga das DLLS de acesso ao c-Tree e ao DBAccess, e mantém estas DLLs alocadas até o serviço do TOTVS Application Server ser finalizado, a primeira thread que entra no sistema para executar código AdvPL pode passar uma falsa sensação de consumo mais elevado que as demais.

Onde um programa aloca a memória ?

Além das variáveis de memória, criadas pelo programa e que podem ser alimentadas dinamicamente, contendo strings, objetos, arrays e afins, existem outros recursos que também consomem memória. Cada tabela aberta e em uso pelo sistema consome alguns KB de memória. Este consumo não é proporcional a quantidade de registros da tabela, mas é proporcional a quantidade de colunas, e a soma do tamanho de todas as colunas ( tamanho do registro). Cada aplicação de interface AdvPL, acessada pelo SmartClient, aloca e mantém na memória uma instância de cada classe de objeto de interface criado pelo programa em execução até que a janela ou container destes componentes seja fechado.

Logo, uma janela de diálogo de interface com mais componentes vai consumir mais memória do que um programa com menos componentes. Um processo com mais tabelas abertas tende a consumir mais do que um processo com menos tabelas e queries mantidas abertas.

Processo dedicado de monitoramento de memória

A partir do TOTVS Application Server, Build 7.00.100812P, foi introduzido no servidor de aplicação um processo interno dedicado ao monitoramento de memória. Vide TDN no link http://tdn.totvs.com/pages/viewpage.action?pageId=6065765. Com este processo “de olho” no consumo de memória do servidor AdvPL, caso a memória endereçada pelo serviço ultrapasse um limite seguro, automaticamente as novas conexões e nocas inicializações de Jobs são desabilitados. Em um ambiente de balanceamento de carga, o servidor “Master” ou “Balance” identifica este cenário, e não redireciona novas conexões para este serviço.

Para facilitar a identificação de onde a memória está sendo utilizada por cada programa, e inclusive para evitar que um programa consuma memória acima de um determinado limite, foram criadas configurações adicionais para monitoramento de memória, onde é possível definir por thread um limite de advertência e uum limite máximo de consumo. Neste caso, uma vez que o limite seja atingido, aquele processo é derrubado do sistema. Os detalhes desta implementação estão na TDN, no link http://tdn.totvs.com/pages/viewpage.action?pageId=6065765

Adicionalmente, caso seja definido um limite de advertência de consumo por processo, quando este limite for atingido, será gerado um error.log de advertência, onde são informados no stack de execução quais variáveis estão na memória e qual a estimativa de consumo para cada uma.

O que é “LEAK” de memória ?

O termo “memory leak”, ou ‘vazamento de memória’ é aplicado a um processo, que durante a sua execução realiza alocações de memória, mas não devolve ao sistema operacional toda a memória que foi utilizada. Normalmente isto gera no Totvs Application server o seguinte comportamento:

Após iniciar o serviço do Protheus, um ou mais usuários se conectam nele usando o SmartClient, e executam diversas aplicações durante um período de tempo. NO final do dia, depois que todos os usuários desconectarem do servidor, e não houver mais nenhum Job rodando, verificamos a memória ocupada pelo executável usando o Task Manager do Windows, e verificamos que, mesmo sem nenhuma conexão, o serviço do Application Server mantém de 200 a 300 MB de mempória alocada.

Até aqui, este é um comportamento normal, afinal as DLLs de acesso a dados não serão descarregadas até que o serviço seja finalizado, e internamente o servidor de aplicação utiliza um mecanismo de gerenciamento de memória que prioriza manter uma reserva de memória pré-alocada, que não é devolvida ao sistema operacional, o que agiliza as próximas execuções de aplicações.

Porém, após mais um dia de trabalho, depois que mais usuários executaram mais rotinas e programas, depois que o último usuário desconectou do servidor de aplicação, ele está ocupando 500 MB, e no outro dia 700 MB, e no outro dia 1 GB … Este crescimento da memória ao longo do tempo, medido depois que todos os usuários desconectaram do sistema, indica um comportamento de Leak de memória.

As causas do Leak

Em um programa AdvPL, você não tem acesso a nenhum mecanismo de alocação direta de memória explicitamente, as variáveis que você cria vão alocar memória dinamicamente para armazenar os conteúdos destas variáveis, e o servidor de aplicação têm mapas e listas de controle desses recursos. Porém, quando a execução de um processo termina, todos os recursos, variáveis, caches e etc usados por aquele processo são desalocados e a memória é (parcialmente) devolvida ao sistema operacional. Quando algum recurso interno da linguagem não fez a devolução de todas as áreas de memória, devido a uma ocorrência de processamento ou desvio lógico não previsto, uma ou mais áreas de memória formam “esquecidas” de serem devolvidas, e após o final do programa, permanecem alocadas da memória, sem referencia ao programa que as utilizava. Trata-se de uma área “perdida”, que o servidor de aplicação não vai conseguir reutilizar, e que ocupa espaço na memoria alocada.

Neste cenário, se um servidor de aplicação estiver deixando 200 Mg de Leak por dia na memória, após uma semana, a capacidade de atender conexões deste serviço vai ser prejudicada, pois ele já tem uma quantidade muito grande de memoria alocada e não utilizada, e se antes cabiam 20 usuários conectados neste serviço, com a memória ocupada, este servidor passa a aguentar apenas 15, 10 ou menos usuário, atingindo os limites de alocação de memória com menos usuários e podendo afetar a disponibilidade do ambiente ou deste serviço.

Na prática, não há nada em AdvPL que propositalmente deixe um leak na memória. Normalmente alguém esqueceu de devolver o conteúdo de um ponteiro, ou não foi prevista uma possibilidade de amarração de dados na memória, em uma condição específica, que não foi tratada adequadamente. Agora, uma coisa que é possível e relativamente comum de acontecer, é o consumo crescente de memória.

Definindo consumo crescente de memória

A determinação de um Leak é feita baseado no crescimento do saldo residual de memória alocada pelo executável de uma aplicação após os processos de execução terem sido finalizados. O Consumo crescente é caracterizado pela execução da mesma rotina, onde cada interação ou repetição do mesmo processo aloca mais memória durante o seu uso. Este consumo pode ser necessário ou intencional, ou pode ser uma falha de projeto ou lógica em um determinado componente.

Por exemplo, uma rotina de interface de consulta qualquer, que permite que o operador do sistema defina uma faixa de datas para pesquisa, e que disponibiliza estas informações na tela usando um Array AdvPL, ao invés de abrir um Browse sobre uma tabela de dados ou uma tabela temporária, fatalmente vai ocupar mais memória durante a sua execução, caso existam muitas informações a serem manipuladas.
Neste caso o desenvolvedor precisa tomar cuidado para criticar o tamanho do array, ou as informações que o usuário especifica para a pesquisa, pois o Array no AdvPL não têm limite definido de número de elementos. Ele pode se extender até ocupar toda a memória endereçável pelo servidor de aplicação AdvPL até derrubar o serviço — e todos os outros processos que nele estão sendo executados. Neste caso o consumo é intencional e necessário, mas deve ser dimensionado para não causar transtornos.

O outro cenário (falha de processo ou de lógica) pode ser caracterizado pelo seguinte cenário: Uma determinada função dentro de um fonte utiliza um array de escopo STATiC para realizar um cache de alguma coisa, e o programador esqueceu de fazer uma verificação para evitar que a mesma informação seja colocada no cache. Conforme a aplicação vai sendo executada, este array vai crescendo … após algumas horas trabalhando com a aplicação, aquele processo pode estar consumindo sozinho 400, 500 MB de memória. Porém, quando o programa é finalizado, toda a memoria ocupada (desnecessariamente) vai ser limpa.

Estes cenários são difíceis de serem identificados, requerem a habilitação dos mecanismos de monitoramento e acompanhamento dos logs gerados para levantar informações sobre quais rotinas e sob quais condições este consumo crescente é reproduzida.

Identificando o Leak

A forma mais elegante de confirmar se um consumo excessivo de memória é realmente um Leak, é utilizar as chaves DebugThreadUsedMemory=1 em conjunto da chave ServerMemoryInfo=1 ( ambas na seção [GENERAL] do appserver.ini). A primeira chave serve para ligar o consumo de memoria por processo, e a segunda faz com que o TOTVS Application Server grave no log de console ( console.log ) uma “foto” dos processos e da memória em uso em intervalos de 1 minuto, além de mostrar um status de alguns acumuladores de memória internos, depois que você finaliza o TOTVS Application Server, e todos os processos internos de execução foram finalizados.

Partindo para a prática

Insira as chaves mencionadas na seção [general] do appserver.ini, e suba o TOTVS Aplication Server em modo console. Você deve ver as seguintes informações:

Win NT/2000
[INFO ][SERVER] [Thread 7900] [SMARTHEAP] Registering Tasks...
[INFO ][SERVER] [Thread 7900] [SMARTHEAP] Version 8.0.0
*** TOTVS S.A. ***
*** www.totvs.com.br ***
TOTVS - Build 7.00.131227A - Jul 23 2015 - 06:50:20
'. TOTVS AppServer x32' console mode.
Press Ctrl+Break to terminate.
*** SERVER BUILD WITH EXTENDED PROFILER INFORMATION
*** SERVER BUILD WITH DUAL-STACK SOCKETS FOR IPV6 IMPLEMENTATION
*** DEFAULT SOCKET BIND IS IPV4
*** STARTING SERVER WITH DEBUG OF USED MEMORY PER THREAD
*** STARTING SERVER WITH PRECISION FLOATING POINT ARITHMETIC
---------------- OS System Info -----------------------------------------------
OS Version .........: Windows 8 [Version 6.2.9200]
OS Platform ........: Windows NT Based (x64)
OS Version Info ....:
-------------------------------------------------------------------------------
---------------- OS Memory Info -----------------------------------------------
Physical memory . 8084.27 MB. Used 3592.04 MB. Free 4492.23 MB.
Paging file ..... 10004.27 MB. Used 5486.12 MB. Free 4518.15 MB.
-------------------------------------------------------------------------------
[INFO ][SERVER] [Thread 7900] APP Virtual Address Allocation Limit .... 4095.88 MB.
[INFO ][SERVER] [Thread 7900] Memory Monitor Virtual Address LIMIT .... 4095.88 MB.
Http server is ready.
 Root path is c:\protheus11\http\
 Listening port 80 (default)
[INFO ][SERVER] Application PID ......... [8788]
[INFO ][SERVER] Application Main Thread .. [7900]
[INFO ][SERVER] [Thread 7900] Application Server started on port 6010
[31/07/2015 21:31:48] Server started.
----------- Total Thread Count ------------
 Total Threads ... 18
 Thread ... 3
 WThread ... 10
 SockServer ... 1
 HttpThread ... 3
 HttpServer ... 1
-------------- APO Map List ---------------
*** EMPTY ***
----------- Detailed Process List ----
[ 9156][ 0.00 MB][ Thread][ tMemoryMonitor][]
[ 4116][ 0.00 MB][ HttpServer][ tHttpServer][]
[ 8804][ 0.00 MB][ HttpThread][ tHttpWThread][]
[ 7532][ 0.00 MB][ HttpThread][ tHttpWThread][]
[ 10540][ 0.00 MB][ HttpThread][ tHttpWThread][]
[ 2072][ 0.00 MB][ Thread][ GenProcCleaner][]
[ 3252][ 0.01 MB][ SockServer][ tMainServer][]
[ 5988][ 0.00 MB][ WThread][ tWThreadBase][]
[ 3800][ 0.00 MB][ WThread][ tWThreadBase][]
[ 6472][ 0.00 MB][ WThread][ tWThreadBase][]
[ 7708][ 0.00 MB][ WThread][ tWThreadBase][]
[ 2444][ 0.00 MB][ WThread][ tWThreadBase][]
[ 10216][ 0.00 MB][ WThread][ tWThreadBase][]
[ 2892][ 0.00 MB][ WThread][ tWThreadBase][]
[ 10232][ 0.00 MB][ Thread][ tJobManager][]
[ 10864][ 0.00 MB][ WThread][ tWThreadBase][]
[ 8176][ 0.00 MB][ WThread][ tWThreadBase][]
[ 4264][ 0.00 MB][ WThread][ tWThreadBase][]
----------- Global List Info --------------
 IMAP Glb List ... 0.00 kB. Count 0
 Variable Glb List ... 0.00 kB. Count 0
 Session Glb List ... 0.00 kB. Count 0
 SymTab List ... 7.11 kB. Count 725 Hits 1035
----------- SmartHeap Pools Info ----------
 pooltString ... 67.97 kB. Count 18 Ok
 poolrContent ... 71.95 kB. Count 1 Ok
 pooltInstrVar ... 71.95 kB. Count 1 Ok
 pooltConst ... 3.98 kB. Count 0 Ok
 poolrContentTypeSimple ... 3.98 kB. Count 0 Ok
 poolrContentTypeDateTime ... 3.98 kB. Count 0 Ok
 poolrContentTypeInterval ... 3.98 kB. Count 0 Ok
 pooltDecimal ... 3.98 kB. Count 0 Ok
 poolt4GLInterFunctionCall ... 3.98 kB. Count 0 Ok
 pooltNamedVar ... 3.98 kB. Count 0 Ok
 pooltSum ... 3.98 kB. Count 0 Ok
 pooltCompare ... 3.98 kB. Count 0 Ok
 pooltLocalEnv ... 3.98 kB. Count 0 Ok
 pooltInterFunctionCall ... 3.98 kB. Count 0 Ok
 pooltDirectFunctionCall ... 3.98 kB. Count 0 Ok
 pooltApoReg ... 3.98 kB. Count 0 Ok
 pooltAssignBase ... 3.98 kB. Count 0 Ok
 pooltCodeBlock ... 7.97 kB. Count 0 Ok
 pooltCodeBlockEnv ... 3.98 kB. Count 0 Ok
 pooltCodeBlockRef ... 3.98 kB. Count 0 Ok
 pooltCodeBlockInstr ... 3.98 kB. Count 0 Ok
 pooltAPXmlDocInterface ... 3.98 kB. Count 0 Ok
 pooltClassData ... 71.95 kB. Count 380 Ok
 pooltAPXmlItem ... 3.98 kB. Count 0 Ok
 pooltPrgFunctXRefEle ... 3.98 kB. Count 0 Ok
 pooltIdentifier ... 3.98 kB. Count 0 Ok
 pooltNamedVarXVarRef ... 3.98 kB. Count 0 Ok
 pooltParmDefDet ... 3.98 kB. Count 0 Ok
 pooltVarList ... 3.98 kB. Count 0 Ok
 pooltStatList ... 7.97 kB. Count 0 Ok
 pooltParmList ... 3.98 kB. Count 0 Ok
 pooltArrayElement ... 3.98 kB. Count 0 Ok
 pooltBaseIf ... 3.98 kB. Count 0 Ok
 pooltMethod ... 71.95 kB. Count 758 Ok
 pooltFindObject ... 3.98 kB. Count 0 Ok
 pooltSelfVar ... 3.98 kB. Count 0 Ok
 pooltClassProp ... 3.98 kB. Count 0 Ok
 pooltClassInstance ... 3.98 kB. Count 0 Ok
 pooltMethodCall ... 3.98 kB. Count 0 Ok
 pooltReturn ... 3.98 kB. Count 0 Ok
 pooltStaticEnv ... 3.98 kB. Count 0 Ok
 pooltPrivateEnv ... 3.98 kB. Count 0 Ok
 Default Memory Pool ... 1663.33 kB. Count 3437 Ok
TOTAL POOLED MEMORY ... 2174.50 kB.
----------- OS Memory Summary -------------
Physical memory . 8084.27 MB. Used 3590.72 MB. Free 4493.55 MB.
Paging file ..... 10004.27 MB. Used 5503.69 MB. Free 4500.58 MB.
----------- APP Memory Summary ------------
 Server Memory Capacity ... 4095.88 MB.
 Service Used Memory ... 101.06 MB.
 Service Resident Memory ... 28.12 MB.
[INFO ][SERVER] [Thread 9156] [MEMORY] V-Load 0.02 - Peak 101.06 MB. - SL 4095.88 MB.
[INFO ][SERVER] [Thread 9156] [MEMORY] R-Load 1.00 - Peak 28.12 MB. - SL 28.12 MB.

Logo após iniciar o serviço, finalize ele usando Control+C e digitando SIM ou YES e pressionando ENTER.
Deve ser gravado um log parecido com o mostrado abaixo:

Digite SIM [Enter] (maiusculo) para sair
Type YES [Enter] (uppercase) to exit:
Wait...
[INFO ][SERVER] [Thread 9368] Application Server Console Stopped...
[INFO ][SERVER] [Thread 7900] Application Server (WIN32 version) in shutdown....
[INFO ][SERVER] [Thread 7900] [31/07/2015 21:33:07] Application SHUTDOWN in progress...
----------- Total Thread Count ------------
 Total Threads ... 18
 Thread ... 3
 WThread ... 10
 SockServer ... 1
 HttpThread ... 3
 HttpServer ... 1
-------------- APO Map List ---------------
*** EMPTY ***
----------- Detailed Process List ----
[ 9156][ 0.00 MB][ Thread][ tMemoryMonitor][]
[ 4116][ 0.00 MB][ HttpServer][ tHttpServer][]
[ 8804][ 0.00 MB][ HttpThread][ tHttpWThread][]
[ 7532][ 0.00 MB][ HttpThread][ tHttpWThread][]
[ 10540][ 0.00 MB][ HttpThread][ tHttpWThread][]
[ 2072][ 0.00 MB][ Thread][ GenProcCleaner][]
[ 3252][ 0.01 MB][ SockServer][ tMainServer][]
[ 5988][ 0.00 MB][ WThread][ tWThreadBase][]
[ 3800][ 0.00 MB][ WThread][ tWThreadBase][]
[ 6472][ 0.00 MB][ WThread][ tWThreadBase][]
[ 7708][ 0.00 MB][ WThread][ tWThreadBase][]
[ 2444][ 0.00 MB][ WThread][ tWThreadBase][]
[ 10216][ 0.00 MB][ WThread][ tWThreadBase][]
[ 2892][ 0.00 MB][ WThread][ tWThreadBase][]
[ 10232][ 0.00 MB][ Thread][ tJobManager][]
[ 10864][ 0.00 MB][ WThread][ tWThreadBase][]
[ 8176][ 0.00 MB][ WThread][ tWThreadBase][]
[ 4264][ 0.00 MB][ WThread][ tWThreadBase][]
----------- Global List Info --------------
 IMAP Glb List ... 0.00 kB. Count 0
 Variable Glb List ... 0.00 kB. Count 0
 Session Glb List ... 0.00 kB. Count 0
 SymTab List ... 7.11 kB. Count 725 Hits 1035
----------- SmartHeap Pools Info ----------
 pooltString ... 71.95 kB. Count 18 Ok
 poolrContent ... 71.95 kB. Count 1 Ok
 pooltInstrVar ... 71.95 kB. Count 1 Ok
 pooltConst ... 3.98 kB. Count 0 Ok
 poolrContentTypeSimple ... 3.98 kB. Count 0 Ok
 poolrContentTypeDateTime ... 3.98 kB. Count 0 Ok
 poolrContentTypeInterval ... 3.98 kB. Count 0 Ok
 pooltDecimal ... 3.98 kB. Count 0 Ok
 poolt4GLInterFunctionCall ... 3.98 kB. Count 0 Ok
 pooltNamedVar ... 3.98 kB. Count 0 Ok
 pooltSum ... 3.98 kB. Count 0 Ok
 pooltCompare ... 3.98 kB. Count 0 Ok
 pooltLocalEnv ... 3.98 kB. Count 0 Ok
 pooltInterFunctionCall ... 3.98 kB. Count 0 Ok
 pooltDirectFunctionCall ... 3.98 kB. Count 0 Ok
 pooltApoReg ... 3.98 kB. Count 0 Ok
 pooltAssignBase ... 3.98 kB. Count 0 Ok
 pooltCodeBlock ... 7.97 kB. Count 0 Ok
 pooltCodeBlockEnv ... 3.98 kB. Count 0 Ok
 pooltCodeBlockRef ... 3.98 kB. Count 0 Ok
 pooltCodeBlockInstr ... 3.98 kB. Count 0 Ok
 pooltAPXmlDocInterface ... 3.98 kB. Count 0 Ok
 pooltClassData ... 71.95 kB. Count 380 Ok
 pooltAPXmlItem ... 3.98 kB. Count 0 Ok
 pooltPrgFunctXRefEle ... 3.98 kB. Count 0 Ok
 pooltIdentifier ... 3.98 kB. Count 0 Ok
 pooltNamedVarXVarRef ... 3.98 kB. Count 0 Ok
 pooltParmDefDet ... 3.98 kB. Count 0 Ok
 pooltVarList ... 3.98 kB. Count 0 Ok
 pooltStatList ... 7.97 kB. Count 0 Ok
 pooltParmList ... 3.98 kB. Count 0 Ok
 pooltArrayElement ... 3.98 kB. Count 0 Ok
 pooltBaseIf ... 3.98 kB. Count 0 Ok
 pooltMethod ... 71.95 kB. Count 758 Ok
 pooltFindObject ... 3.98 kB. Count 0 Ok
 pooltSelfVar ... 3.98 kB. Count 0 Ok
 pooltClassProp ... 3.98 kB. Count 0 Ok
 pooltClassInstance ... 3.98 kB. Count 0 Ok
 pooltMethodCall ... 3.98 kB. Count 0 Ok
 pooltReturn ... 3.98 kB. Count 0 Ok
 pooltStaticEnv ... 3.98 kB. Count 0 Ok
 pooltPrivateEnv ... 3.98 kB. Count 0 Ok
 Default Memory Pool ... 1663.33 kB. Count 3439 Ok
TOTAL POOLED MEMORY ... 2178.48 kB.
----------- OS Memory Summary -------------
Physical memory . 8084.27 MB. Used 3592.28 MB. Free 4492.00 MB.
Paging file ..... 10004.27 MB. Used 5494.38 MB. Free 4509.89 MB.
----------- APP Memory Summary ------------
 Server Memory Capacity ... 4095.88 MB.
 Service Used Memory ... 100.67 MB.
 Service Resident Memory ... 28.04 MB.
**
[INFO ][SERVER] [Thread 9156] Memory Monitor END
...
/* =========================================================================
*** SMARTHEAP POOL STATUS AFTER FINISHED PROCESSES ***
pooltString ... 71.95 kB. Count 0 Ok
 poolrContent ... 71.95 kB. Count 0 Ok
 pooltInstrVar ... 71.95 kB. Count 0 Ok
 pooltConst ... 3.98 kB. Count 0 Ok
 poolrContentTypeSimple ... 3.98 kB. Count 0 Ok
 poolrContentTypeDateTime ... 3.98 kB. Count 0 Ok
 poolrContentTypeInterval ... 3.98 kB. Count 0 Ok
 pooltDecimal ... 3.98 kB. Count 0 Ok
 poolt4GLInterFunctionCall ... 3.98 kB. Count 0 Ok
 pooltNamedVar ... 3.98 kB. Count 0 Ok
 pooltSum ... 3.98 kB. Count 0 Ok
 pooltCompare ... 3.98 kB. Count 0 Ok
 pooltLocalEnv ... 3.98 kB. Count 0 Ok
 pooltInterFunctionCall ... 3.98 kB. Count 0 Ok
 pooltDirectFunctionCall ... 3.98 kB. Count 0 Ok
 pooltApoReg ... 3.98 kB. Count 0 Ok
 pooltAssignBase ... 3.98 kB. Count 0 Ok
 pooltCodeBlock ... 7.97 kB. Count 0 Ok
 pooltCodeBlockEnv ... 3.98 kB. Count 0 Ok
 pooltCodeBlockRef ... 3.98 kB. Count 0 Ok
 pooltCodeBlockInstr ... 3.98 kB. Count 0 Ok
 pooltAPXmlDocInterface ... 3.98 kB. Count 0 Ok
 pooltClassData ... 71.95 kB. Count 0 Ok
 pooltAPXmlItem ... 3.98 kB. Count 0 Ok
 pooltPrgFunctXRefEle ... 3.98 kB. Count 0 Ok
 pooltIdentifier ... 3.98 kB. Count 0 Ok
 pooltNamedVarXVarRef ... 3.98 kB. Count 0 Ok
 pooltParmDefDet ... 3.98 kB. Count 0 Ok
 pooltVarList ... 3.98 kB. Count 0 Ok
 pooltStatList ... 7.97 kB. Count 0 Ok
 pooltParmList ... 3.98 kB. Count 0 Ok
 pooltArrayElement ... 3.98 kB. Count 0 Ok
 pooltBaseIf ... 3.98 kB. Count 0 Ok
 pooltMethod ... 71.95 kB. Count 0 Ok
 pooltFindObject ... 3.98 kB. Count 0 Ok
 pooltSelfVar ... 3.98 kB. Count 0 Ok
 pooltClassProp ... 3.98 kB. Count 0 Ok
 pooltClassInstance ... 3.98 kB. Count 0 Ok
 pooltMethodCall ... 3.98 kB. Count 0 Ok
 pooltReturn ... 3.98 kB. Count 0 Ok
 pooltStaticEnv ... 3.98 kB. Count 0 Ok
 pooltPrivateEnv ... 3.98 kB. Count 0 Ok
 Default Memory Pool ... 1003.36 kB. Count 156 Ok
TOTAL POOLED MEMORY ... 1518.52 kB.
========================================================================= */

No momento que o Totvs Application Server inicia o “shutdown” do serviço, são mostrados os processos de execução AdvPL ( no nosso caso nenhum ), os processos internos ( Detailed Process List ), e os acumuladores de memória internos do Application Server em uso. Depois que todos os processos foram encerrados internamente, é mostrada uma nova foto dos acumuladores de memória, logo após a mensagem “*** SMARTHEAP POOL STATUS AFTER FINISHED PROCESSES ***”

Reparem que todos os acumuladores estão com o contador ZERO, exceto o Default Memory Pool, com 156 buffers. Este é o comportamento esperado de um servidor de aplicação sem Leak. O acumulador do Default Memory Pool pode variar um pouco, entre 180 e 220 elementos, as vezes mais ou menos … porém os demais acumuladores precisam estar com o contador ZERO após a mensagem “*** SMARTHEAP POOL STATUS AFTER FINISHED PROCESSES ***”. Caso exista um ou mais ( quando aparecem são sempre mais de um ) acumuladores com contador maior que zero, algum programa durante a sua execução deixou ponteiros de memória não referenciados sem desalocar a memória. Isso caracteriza a existência de Leak.

Achando o “culpado”

Agora vêm a parte difícil … Normalmente um servidor de aplicação AdvPL executa diversos códigos e rotinas de vários usuários, diariamente. Uma ou mais destas rotinas durante a sua execução não liberaram alguma porção da memória. Descobrir qual delas é o desafio. Normalmente a garimpagem desses dados é realizada com procedimentos de paradas mais frequentes dos serviços do TOTVS Application Server, e a geração do log de console desde o momento que o serviço foi iniciado.

A cada parada, verificamos se houve leak registrado no final, e verificamos pelos logs as rotinas executadas, e verificamos também se alguns erros críticos específicos foram registrados durante a execução do serviço.

Culpado No 1 : Access Violation e “Failure on Thread Delete”

Qualquer ocorrência de Access Violation ( ou violação de endereço de memória ) registrada pode interromper ou impedir a execução da finalização normal de um processo, o que pode deixar memória alocada após o final do processo, ou pior: Conexões com o DBAccess e com o License Server , arquivos abertos no disco, registros bloqueados no DBAccess, etc… PAra as aplicações endereçadas por estas conexões, a conexão ainda está ativa, pois o processo não foi totalmente finalizado. Neste caso, estes recursos somente serão liberados quando você finalizar o servidor de aplicação — parar o serviço do Tots Application Server.

Quando temos uma ocorrência de Access Violation, devemos verificar onde ela é reproduzida, se ela acontece em um ou mais programas, e tentar fazer uma receita de bolo para reproduzir a ocorrência, abrindo um chamado na Totvs. Caso não seja possível determinar uma receita de bolo para reproduzir o problema, o que caracteriza uma ocorrência esporádica, normalmente é disponibilizado ao cliente uma build “Debug” do TOTVs Application SErver. Esta build é capaz de gerar um arquivo chamado “core_nnnn.dmp”, contendo uma foto da memória inteira do TOTVS Application Server, no momento em que aconteceu um Access Violation. A análise deste log ajuda o departamento de tecnologia a identificar o que aconteceu.

Normalmente cada nova liberação dos executáveis e DLLS que compõe o TOTVS Application Server possuem correções, melhorias e proteções das situações encontradas entre os releases que podem ser a causa provável de uma ocorrência desta natureza. Por isso a TOTVS recomenda que o cliente esteja com a última build atualizada e liberada no Portal. Caso o Access Violation aconteça na última build, é gerada uma Build DEBUG do Application Server da última build para a avaliação da ocorrência.

Culpado No 2 : Impressões no servidor usando um Driver com interface

Caso você use a impressão do ERP para o Pool de impressão do Windows no servidor (e não no SmartClient), e você tenha no servidor um driver de geração de PDF (por exemplo), e o TOTVS Application Server sendo executado como serviço… caso você dispare uma impressão para este driver, ele vai tentar abrir uma caixa de diálogo na máquina onde está sendo executado o Totvs Application Server … mas como o APPServer está sendo executado como serviço, além disso não ser possível, isso literalmente TRAVA aquele processo, mantendo todos os recursos abertos, conexão com o DBAccess, processo preso no Protheus Monitor, conexão aberta no License Server, etc… Fatalmente, quando você tentar parar o serviço do Totvs Application Server, ele não vai sair … você vai precisar literalmente “chutar” o processo pelo TasK Manager do Windows. Cada processo que ficou travado vai permanecer como um “zumbi” no APPServer, e o acúmulo destes processos vai afetar a memória disponível para a execução dos programas.

Culpado No 3 : Falha de algum recurso do AdvPL

Durante a execução de um programa, alguma das funções ou classes chamadas não desalocou um ou mais ponteiros de memória, normalmente isso acontece quando uma situação particular nos destrutores não foi prevista. Neste caso, deve ser feita aquela garimpagem nos logs gerados durante a execução do Appllication Server, inclusive comparando logs onde houve a geração de leak e onde não houve a geração de leak, para tentar identificar quais programas são os possiveis candidatos, para fazer um teste pontual: Subir um TOTVs Application Server isolado, onde apenas um usuário conecta, e testa um programa. Após o usuário terminar o programa, o servidor é baixado, e o log deve ser verificado para ver se houve Leak.

Houve umm caso de Leak de memória que somente era reproduzido quando o usuário entrava no ERP pelo SIGAADV, e após o Menu do ERP ser mostrado, o usuário clicava e um “cadeado” na interface para trocar de módulo, e após realizar a troca de módulo pelo menos uma vez, a primeira janela da troca de módulo com todos os seus componentes e variáveis era “largada” na memória, ocupando um espaço significativo, obrigando os administradores do ambiente a reiniciar os serviços do Protheus antes do inicio do expediente.

A descoberta da causa desta ocorrência somente foi possível após analisar os logs de execução de vários serviços, e perguntando para os usuários qual foi o roteiro de trabalho deles durante o dia, comparando com o roteiro de trabalho de outros usuários que executaram as mesmas rotinas, mas não houve registro de leak no servidor usados por eles. Após fazer um teste usando uma rotina e trocando de módulo, foi percebido que somente neste caso o Leak era gerado.

Não é fácil encontrar um Leak nem um Access Violation. Uma vez que exista uma receita de bolo que sempre reproduza sempre o problema, o departamento de tecnologia consegue atuar, e muitas vezes propor um contorno. O difícil está em encontrar qual é a receita.

Uma vez que seja comprovada a existência de um Leak, é possível a geração de uma build de gaveta ( normalmente partindo da ultima versão liberada) com uma instrumentação específica para ajudar a encontrar ou a chegar perto do ponto que “sobrou” na memória, porém esta instrumentação deixa o processamento um pouco mais pesado.

Conclusão

Existem caminhos para chegar até a raiz do problema, alguns não são tão fáceis, tudo é diretamente proporcional a complexidade do problema. Espero que estas informações deem a todos alguma “luz” no fim do túnel e um ponto sólido de partida.

Abraços, e até o próximo post, pessoal 😀

Referências

PROBLEMA. In: WIKIPÉDIA, a enciclopédia livre. Flórida: Wikimedia Foundation, 2014. Disponível em: <https://pt.wikipedia.org/w/index.php?title=Problema&oldid=40832056>. Acesso em: 29 jul. 2015.