Registro de tempo em logs de debug

Guilherme Andrade Del Cantoni
1 parent 15823b63
Showing 2 changed files with 48 additions and 14 deletions Show diff stats
rn/ProcessarPendenciasRN.php
rn/ReceberProcedimentoRN.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);
@@ -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);
+    }
 }