From 572912a30ee440a84b3fad2627e1348f5a07f59a Mon Sep 17 00:00:00 2001 From: Guilherme Andrade Del Cantoni Date: Mon, 27 May 2019 09:49:00 -0300 Subject: [PATCH] Registro de tempo em logs de debug --- rn/ProcessarPendenciasRN.php | 8 +++++++- rn/ReceberProcedimentoRN.php | 54 +++++++++++++++++++++++++++++++++++++++++------------- 2 files changed, 48 insertions(+), 14 deletions(-) diff --git a/rn/ProcessarPendenciasRN.php b/rn/ProcessarPendenciasRN.php index 55260a2..315fbb6 100644 --- a/rn/ProcessarPendenciasRN.php +++ b/rn/ProcessarPendenciasRN.php @@ -101,7 +101,9 @@ class ProcessarPendenciasRN extends InfraAgendamentoTarefa //Processamento de pendências de recebimento dos metadados do processo $this->objGearmanWorker->addFunction("receberProcedimento", function ($job) { try{ - $this->gravarLogDebug("Processando recebimento de processo [receberProcedimento] com IDT " . $job->workload(), 0, true); + $this->gravarLogDebug("Processando recebimento de protocolo [receberProcedimento] com IDT " . $job->workload(), 0, true); + $numTempoInicialRecebimento = microtime(true); + $numIdentificacaoTramite = intval($job->workload()); $objPenTramiteProcessadoRN = new PenTramiteProcessadoRN(PenTramiteProcessadoRN::STR_TIPO_PROCESSO); @@ -109,6 +111,10 @@ class ProcessarPendenciasRN extends InfraAgendamentoTarefa $objReceberProcedimentoRN = new ReceberProcedimentoRN(); $objReceberProcedimentoRN->receberProcedimento($numIdentificacaoTramite); } + + $numTempoTotalRecebimento = round(microtime(true) - $numTempoInicialRecebimento, 2); + $this->gravarLogDebug("Finalizado o recebimento de protocolo com IDT " . $job->workload() . "(Tempo total: {$numTempoTotalRecebimento}s)", 0, true); + } catch(Exception $e){ $this->gravarLogDebug(InfraException::inspecionar($e), 0, true); diff --git a/rn/ReceberProcedimentoRN.php b/rn/ReceberProcedimentoRN.php index a8d04ce..063942e 100644 --- a/rn/ReceberProcedimentoRN.php +++ b/rn/ReceberProcedimentoRN.php @@ -18,6 +18,8 @@ class ReceberProcedimentoRN extends InfraRN $this->objProcessoEletronicoRN = new ProcessoEletronicoRN(); $this->objProcedimentoAndamentoRN = new ProcedimentoAndamentoRN(); $this->objReceberComponenteDigitalRN = new ReceberComponenteDigitalRN(); + + $this->numTempoUltimoLog = null; } protected function inicializarObjInfraIBanco() @@ -110,21 +112,34 @@ class ReceberProcedimentoRN extends InfraRN $numOrdemComponente = $key + 1; if(!is_null($componentePendente)){ - //TODO: Necessário otimizar trecho abaixo para evitar download desnecessário de documentos - //TODO: Download do componente digital é realizado, mesmo já existindo na base de dados, devido a comportamento obrigatório do Barramento para mudança de status + //Download do componente digital é realizado, mesmo já existindo na base de dados, devido a comportamento obrigatório do Barramento para mudança de status //Ajuste deverá ser feito em versões futuas $arrayHash[] = $componentePendente; //Obter os dados do componente digital $this->gravarLogDebug("Baixando componente digital $numOrdemComponente", 6); + $numTempoInicialDownload = microtime(true); $objComponenteDigital = $this->objProcessoEletronicoRN->receberComponenteDigital($parNumIdentificacaoTramite, $componentePendente, $objTramite->protocolo); + $numTempoTotalDownload = round(microtime(true) - $numTempoInicialDownload, 2); + $numTamanhoArquivoKB = round(strlen($objComponenteDigital->conteudoDoComponenteDigital) / 1024, 2); + $numVelocidade = round($numTamanhoArquivoKB / $numTempoTotalDownload, 2); + $this->gravarLogDebug("Tempo total de download de $numTamanhoArquivoKB kb: {$numTempoTotalDownload}s ({$numVelocidade} kb/s)", 7); + + $numTempoInicialArmazenamento = microtime(true); $arrAnexosComponentes[$key][$componentePendente] = $this->objReceberComponenteDigitalRN->copiarComponenteDigitalPastaTemporaria($objComponenteDigital); $arrAnexosComponentes[$key]['recebido'] = false; + $numTempoTotalArmazenamento = round(microtime(true) - $numTempoInicialArmazenamento, 2); + $numVelocidade = round($numTamanhoArquivoKB / $numTempoTotalArmazenamento, 2); + $this->gravarLogDebug("Tempo total de armazenamento em disco: {$numTempoTotalArmazenamento}s ({$numVelocidade} kb/s)", 7); //Valida a integridade do hash - $this->gravarLogDebug("Validando integridade de componente digital $numOrdemComponente", 6); + $this->gravarLogDebug("Validando integridade de componente digital $numOrdemComponente", 7); + $numTempoInicialValidacao = microtime(true); $this->objReceberComponenteDigitalRN->validarIntegridadeDoComponenteDigital($arrAnexosComponentes[$key][$componentePendente], $componentePendente, $parNumIdentificacaoTramite, $numOrdemComponente); + $numTempoTotalValidacao = round(microtime(true) - $numTempoInicialValidacao, 2); + $numVelocidade = round($numTamanhoArquivoKB / $numTempoTotalValidacao, 2); + $this->gravarLogDebug("Tempo total de validação de integridade: {$numTempoTotalValidacao}s ({$numVelocidade} kb/s)", 7); } } @@ -212,7 +227,7 @@ class ReceberProcedimentoRN extends InfraRN { if(count($parArrHashComponentes) > 0){ //Obter dados dos componetes digitais - $this->gravarLogDebug("Iniciando o recebimento dos componentes digitais pendentes", 4); + $this->gravarLogDebug("Iniciando o armazenamento dos componentes digitais pendentes", 4); $objComponenteDigitalDTO = new ComponenteDigitalDTO(); $objComponenteDigitalDTO->setStrNumeroRegistro($parStrNumeroRegistro); $objComponenteDigitalDTO->setNumIdTramite($parNumIdentificacaoTramite); @@ -246,7 +261,7 @@ class ReceberProcedimentoRN extends InfraRN if($this->documentosPendenteRegistro($dblIdProcedimento, $dblIdDocumento, $strHash)){ $strNomeDocumento = array_key_exists($strHash, $arrStrNomeDocumento) ? $arrStrNomeDocumento[$strHash]['especieNome'] : '[Desconhecido]'; $this->objReceberComponenteDigitalRN->receberComponenteDigital($objComponenteDigitalDTOEnviado); - $strMensagemRecebimento = sprintf('Recebendo %s %s', $strNomeDocumento, $objComponenteDigitalDTOEnviado->getStrProtocoloDocumentoFormatado()); + $strMensagemRecebimento = sprintf('Armazenando componente do documento %s %s', $strNomeDocumento, $objComponenteDigitalDTOEnviado->getStrProtocoloDocumentoFormatado()); $this->objProcedimentoAndamentoRN->cadastrar(ProcedimentoAndamentoDTO::criarAndamento($strMensagemRecebimento, 'S')); $this->gravarLogDebug($strMensagemRecebimento, 6); } @@ -1846,14 +1861,6 @@ class ReceberProcedimentoRN extends InfraRN return $objProcedimentoAndamentoDTO; } - private function gravarLogDebug($strMensagem, $numIdentacao=0) - { - $strDataLog = date("d/m/Y H:i:s"); - $strLog = sprintf("[%s] [PROCESSAMENTO] %s %s", $strDataLog, str_repeat(" ", $numIdentacao * 4), $strMensagem); - InfraDebug::getInstance()->gravar($strLog); - } - - /** * Verifica se existe documentos com pendência de download de seus componentes digitais * @param [type] $parNumIdProcedimento Identificador do processo @@ -1928,4 +1935,25 @@ class ReceberProcedimentoRN extends InfraRN throw new InfraException($strMensagemPadrao . $strMensagemErro); } } + + private function gravarLogDebug($strMensagem, $numIdentacao=0, $bolLogTempoProcessamento=true) + { + $strDataLog = date("d/m/Y H:i:s"); + $strLog = sprintf("[%s] [PROCESSAMENTO] %s %s", $strDataLog, str_repeat(" ", $numIdentacao * 4), $strMensagem); + + //Registro de tempo de processamento desde último log + if($bolLogTempoProcessamento){ + $numTempoFinal = microtime(true); + if(is_null($this->numTempoUltimoLog)){ + //Inicializa contador de tempo de processamento + $this->numTempoUltimoLog = $numTempoFinal; + } else { + $numTempoProcessamento = round($numTempoFinal - $this->numTempoUltimoLog, 2); + $strLog .= " [tempo: +{$numTempoProcessamento}s]"; + $this->numTempoUltimoLog = $numTempoFinal; + } + } + + InfraDebug::getInstance()->gravar($strLog); + } } -- libgit2 0.21.2