Habilitar estadísticas de rendimiento en WildFly

Para solucionar problemas de rendimiento de la base de datos en WildFly, siga los pasos a continuación.

1. Ejecute el siguiente comando para enumerar las fuentes de datos disponibles.

   > cd ${WILDFLY_HOME}

   > ./bin/jboss-cli.sh --connect '/subsystem=datasources:read-resource()'

   {

       "outcome" => "success" ,

       "result" => {

           "data-source" => { "ejbcads" => undefined},

           "xa-data-source" => undefined

   }

   }

   Anote la fuente de datos utilizada por EJBCA, ya que esta información se utilizará en el siguiente paso. En el ejemplo anterior, el nombre de la fuente de datos es ejbcads , pero puede ser diferente en su sistema.
   

2. Ejecute los siguientes comandos para habilitar el rendimiento y el registro de SQL en Hibernate.
   

   Reemplace la fuente de datos ejbcads con el nombre de la fuente de datos que anotó en el paso anterior.

   ./bin/jboss-cli.sh --connect '/subsystem=datasources/data-source=ejbcads/statistics=pool:write-attribute(name=statistics-enabled,value=true)'

   ./bin/jboss-cli.sh --connect '/subsystem=datasources/data-source=ejbcads/statistics=jdbc:write-attribute(name=statistics-enabled,value=true)'

   ./bin/jboss-cli.sh --connect '/system-property=hibernate.generate_statistics:add(value=true)'

   ./bin/jboss-cli.sh --connect '/system-property=hibernate.show_sql:add(value=true)'

   ./bin/jboss-cli.sh --connect '/system-property=hibernate.format_sql:add(value=true)'

   ./bin/jboss-cli.sh --connect '/system-property=hibernate.use_sql_comments:add(value=true)'

   ./bin/jboss-cli.sh --connect '/subsystem=logging/logger=org.hibernate.stat:add()'

   ./bin/jboss-cli.sh --connect '/subsystem=logging/logger=org.hibernate.stat:write-attribute(name=level, value=DEBUG)'

3. Ejecute los siguientes comandos para habilitar la depuración de EJBCA y CeSeCore.

   ./bin/jboss-cli.sh --connect '/subsystem=logging/logger=org.ejbca:write-attribute(name=level, value=DEBUG)'

   ./bin/jboss-cli.sh --connect '/subsystem=logging/logger=org.cesecore:write-attribute(name=level, value=DEBUG)'

4. Reinicie WildFly.

   systemctl restart wildfly

5. Cargue EJBCA en el navegador y siga el archivo de registro.

   tail -f /opt/jboss/standalone/log/server.log

6. Puede ser útil conocer los tiempos de carga que indica el navegador como referencia. Suponiendo que se usa Chromium, se puede ver cuánto tiempo tarda en cargar los diferentes recursos presionando Ctrl+Mayús+I y abriendo la pestaña Red , como se muestra en la captura de pantalla a continuación.
   

   

7. Realice alguna operación que se sepa que es lenta y capture la salida del registro. Por ejemplo, al cargar la página del registro de auditoría, se obtendría una salida similar a la siguiente:

   2019-11-11 14:15:13,553 INFO [stdout] (EJB default - 2) Hibernate: select peerdata0_.id as id1_25_, peerdata0_.connectorState as connecto2_25_, peerdata0_.data as data3_25_, peerdata0_.name as name4_25_, peerdata0_.rowProtection as rowProte5_25_, peerdata0_.rowVersion as rowVersi6_25_, peerdata0_.url as url7_25_ from PeerData peerdata0_

   2019-11-11 14:15:13,554 DEBUG [org.hibernate.stat.internal.ConcurrentStatisticsImpl] (EJB default - 2) HHH000117: HQL: SELECT a FROM PeerData a, time: 1ms, rows: 2

   2019-11-11 14:15:13,556 INFO [org.hibernate.engine.internal.StatisticalLoggingSessionEventListener] (EJB default - 2) Session Metrics {

   304609 nanoseconds spent acquiring 1 JDBC connections;

   41073 nanoseconds spent releasing 1 JDBC connections;

   343180 nanoseconds spent preparing 1 JDBC statements;

   290351 nanoseconds spent executing 1 JDBC statements;

   0 nanoseconds spent executing 0 JDBC batches;

   0 nanoseconds spent performing 0 L2C puts;

   0 nanoseconds spent performing 0 L2C hits;

   0 nanoseconds spent performing 0 L2C misses;

   0 nanoseconds spent executing 0 flushes (flushing a total of 0 entities and 0 collections);

   0 nanoseconds spent executing 0 partial-flushes (flushing a total of 0 entities and 0 collections)

   }

   2019-11-11 14:15:14,400 INFO [stdout] (EJB default - 10) Hibernate: select accesstree0_.pK as pK1_11_0_, accesstree0_.authorizationTreeUpdateNumber as authoriz2_11_0_, accesstree0_.rowProtection as rowProte3_11_0_, accesstree0_.rowVersion as rowVersi4_11_0_ from AuthorizationTreeUpdateData accesstree0_ where accesstree0_.pK=?

   2019-11-11 14:15:14,402 INFO [org.hibernate.engine.internal.StatisticalLoggingSessionEventListener] (EJB default - 10) Session Metrics {

   454643 nanoseconds spent acquiring 1 JDBC connections;

   81895 nanoseconds spent releasing 1 JDBC connections;

   519914 nanoseconds spent preparing 1 JDBC statements;

   433415 nanoseconds spent executing 1 JDBC statements;

   0 nanoseconds spent executing 0 JDBC batches;

   0 nanoseconds spent performing 0 L2C puts;

   0 nanoseconds spent performing 0 L2C hits;

   0 nanoseconds spent performing 0 L2C misses;

   0 nanoseconds spent executing 0 flushes (flushing a total of 0 entities and 0 collections);

   0 nanoseconds spent executing 0 partial-flushes (flushing a total of 0 entities and 0 collections)

   }

   2019-11-11 14:15:16,861 INFO [org.cesecore.audit.impl.log4j.Log4jDevice] (default task-17) 2019-11-11 14:15:16+01:00;ACCESS_CONTROL;SUCCESS;ACCESSCONTROL;CORE;CN=SuperAdmin,O=PrimeKey Solutions AB,C=SE;;;;resource0=/administrator;resource1=/secureaudit/auditor/select

   2019-11-11 14:15:16,862 DEBUG [org.cesecore.audit.log.InternalSecurityEventsLoggerSessionBean] (default task-17) LogDevice: Log4jDevice Proc: 1

   2019-11-11 14:15:16,865 INFO [stdout] (default task-17) Hibernate: insert into AuditRecordData (additionalDetails, authToken, customId, eventStatus, eventType, module, nodeId, rowProtection, rowVersion, searchDetail1, searchDetail2, sequenceNumber, service, timeStamp, pk) values (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)

   2019-11-11 14:15:16,894 INFO [org.hibernate.engine.internal.StatisticalLoggingSessionEventListener] (default task-17) Session Metrics {

   711999 nanoseconds spent acquiring 1 JDBC connections;

   34333 nanoseconds spent releasing 1 JDBC connections;

   749310 nanoseconds spent preparing 1 JDBC statements;

   321017 nanoseconds spent executing 1 JDBC statements;

   0 nanoseconds spent executing 0 JDBC batches;

   0 nanoseconds spent performing 0 L2C puts;

   0 nanoseconds spent performing 0 L2C hits;

   0 nanoseconds spent performing 0 L2C misses;

   1637963 nanoseconds spent executing 1 flushes (flushing a total of 1 entities and 0 collections);

   0 nanoseconds spent executing 0 partial-flushes (flushing a total of 0 entities and 0 collections)

   }

8. También puede utilizar la utilidad ping en Linux para medir el RTT entre la máquina EJBCA y la máquina DBMS.

   > ping <HOST> -c 10

   PING <HOST> (<IP>) 56 ( 84 ) bytes of data.

   64 bytes from <HOST> (<IP>): icmp_seq= 1 ttl= 64 time= 0.028 ms

   [...]

   --- <HOST> ping statistics ---

   10 packets transmitted, 10 received, 0 % packet loss, time 9193ms

   rtt min/avg/max/mdev = 0.052 / 0.077 / 0.086 / 0.013 ms

   Esto es útil si su base de datos reside en otra máquina y desea determinar si la red entre la máquina EJBCA y la máquina DBMS es un cuello de botella.

La investigación anterior muestra valores bastante normales. La carga de la página del registro de auditoría en Chromium tardó unos 350 ms. De estos 350 ms, unos 6 ms se dedicaron a realizar tres consultas a la base de datos. De estos 6 ms, aproximadamente 0,1 ms se debieron a retrasos en la red.

Consultas de bases de datos de registros mediante MariaDB

Si está utilizando MariaDB, puede habilitar el registro de consultas lentas, así como consultas que no utilizan un índice, ejecutando los siguientes comandos:

A continuación se muestra un ejemplo de cómo puede verse el archivo de registro /tmp/mariadb-slow.log si se detectan consultas lentas:

Para obtener más información, consulte el artículo de la base de conocimientos de MariaDB Descripción general del registro de consultas lentas .