Generar estadísticas de rendimiento y carga de trabajo de SQL mediante el programa de utilidad Sumall

El programa de utilidad Sumall se utiliza para analizar los archivos db.log y generar un resumen de estadísticas de tiempos de ejecución de SQL de los que se realiza un seguimiento. Al investigar problemas de rendimiento se recomienda realizar un seguimiento de todas las sentencias SQL estableciendo el adicionador de base de datos en modalidad de depuración. Sólo si ve toda la carga de trabajo de SQL podrá evaluar el impacto relativo de sentencias SQL específicas. No sólo los SQL de larga ejecución pueden afectar al rendimiento, sino también demasiados SQL de ejecución rápida, que solo se ven al realizar un seguimiento del adicionador de base de datos en modalidad de depuración.

También se puede utilizar el mandato pimSupport.sh para realizar un seguimiento de todos los archivos de registro mientras se reproduce un caso de uso de rendimiento. Puede utilizar el mandato -t start|stop para realizar un seguimiento de todos los agregadores en modalidad de depuración.
El programa de utilidad se invoca ejecutando el mandato siguiente:

$JAVA_RT com.ibm.ccd.common.wpcsupport.util.Sumall <archivos db.log>

Si no está establecida la variable de entorno $JAVA_RT, puede que deba generar el contenido del archivo compat.sh:

. $TOP/bin/compat.sh

De forma predeterminada:
  • solo se evaluarán los SQL que no están marcados como retrasados (DELAYED)
  • los SQL iguales se agregan en una sola línea. Las consultas estáticas se diferencian por su nombre. Las consultas dinámicas se diferencian por los primeros n caracteres según define la opción leng (valor predeterminado = 70). De forma predeterminada, los valores de parámetros se sustituirán por el signo '?'. Por lo tanto, los SQL similares se pueden agregar.
  • Para cada SQL exclusivo se generarán valores estadísticos:
    • Tiempo total de ejecución en milisegundos: sum(ms)
    • número de ejecuciones: cnt
    • tiempo promedio de ejecución en milisegundos: avg(ms)
    • Coeficiente de variación para los SQL de los que se realiza un seguimiento: CV
    • Identificador SQL: QUERY
  • Las estadísticas de SQL se ordenarán según el tiempo de ejecución global en orden ascendente. Por lo tanto, los SQL con un total de tiempo de ejecución más elevado, se muestran directamente al final de la salida.
  • Al final de la salida visualizada se muestra una visión general de estadísticas agregadas, que muestra:
    • el rango de tiempo para el que se ha realizado un seguimiento de los SQL: Monitored timeperiod (MT)
    • Estadísticas totales agregadas para todos los SQL junto con el cálculo de %MT, que representa el total de SQL del que se ha realizado un seguimiento en relación con el periodo de tiempo supervisado.
Existen varias opciones para modificar este comportamiento:

Usage:
             $JAVA_RT com.ibm.ccd.common.wpcsupport.util.Sumall
                [leng=n characters] [delayed] [printsql] [cvon] [cleanoff]
                [fromtime="yyyy-MM-dd HH:mm:ss[,SSS]"] [totime="yyyy-MM-dd HH:mm:ss[,SSS]"]
                [threadname="<threadname>"] [threadlist] [version] [h|help] <db.log files>
Opciones
h|help:   mostrar información de uso

leng:     Valor predeterminado = 70. Define el número de caracteres desde el inicio de
             los SQL que se utilizan para la agregación de estadísticas

printsql: extrae los SQL y su tiempo de ejecución en orden secuencial, muestra una línea por SQL

delayed:     Solo se analizan los SQL marcados con retardo

cvon:        Se utiliza para activar el cálculo de coeficiente de variación (cv)
             Proporciona una métrica normalizada de la variación de tiempos de ejecución individuales
          respecto al tiempo de ejecución promedio.

cleanoff:    Cuando se establece, los valores de parámetros no se sustituyen en las series SQL dinámicas. En función del
             valor del parámetro leng, es posible que las consultas dinámicas del mismo tipo
             se notifiquen en líneas distintas, si los valores de parámetros individuales estén contenidos en los primeros
             caracteres n (leng). Esto puede ser adecuado si desea investigar consultas dinámicas con sus              valores de parámetros reales

fromtime:    Analizar solo los SQL con una indicación de hora > desde hora, con el formato de entrada necesario: aaaa-MM-dd HH:mm:ss

fromtime:    Analizar solo los SQL con una indicación de hora < hasta hora, con el formato de entrada necesario: aaaa-MM-dd HH:mm:ss

threadname:  Se analizarán los SQL solo para la hebra proporcionada. Utilice un threadname de acuerdo con la
             opción threadlist

threadlist:  Mostrar sqlstatistics por hebras ordenadas por el total de SQLruntime

version:     Mostrar versión actual

Salida de ejemplo

java -jar Sumall.jar db.log* threadname="jsp_57678: moveEntriesToNextStep.wpc"



      130     130       1,0   GEN_CTG_CSA_CAT_SYS_ATTR_GETBYCATEGORYID] SELECT * FROM tctg_csa_cat_s
      134     130       1,0   GEN_CTG_CHI_CATEGORY_HIERARCHY_GETBYCHILDID] SELECT * FROM tctg_chi_ca
      134     130       1,0   GEN_CTG_CFP_CAT_FULL_PATHS_GETBYCATEGORYID] SELECT * FROM tctg_cfp_cat
      158       1     158,0   GET_EVENT_ENTRY_MATCHING_SIGNATURE] SELECT wee_entry_id FROM twfl_wfe_
      219     235       0,9   GEN_SEC_SCU_USER_GETBYID] SELECT * FROM tsec_scu_user WHERE scu_user_i
      223     220       1,0   GEN_SEC_CMP_COMPANY_GETBYID] SELECT * FROM tsec_cmp_company WHERE cmp_
      267     278       1,0   GEN_CTG_ICM_ITEM_CATEGORY_MAP_GETBYITEMVERSION] SELECT * FROM tctg_icm
      276     250       1,1   GEN_CTG_ITD_ITEM_DETAIL_GETBYIDVERSION] SELECT * FROM tctg_itd_item_de
      431     428       1,0   GEN_CTG_ITM_ITEM_GETBYPRIMARYKEYVERSION] SELECT * FROM tctg_itm_item W
-----------------------------------------------
   sum(ms)    cnt   avg(ms)  QUERY

Monitored timeperiod (MT): 2015-07-24 10:37:54,467 - 2015-07-24 10:37:57,563 : 0,00 h | 0,00 m | 3,10 s

Statistical values for all queries
Total      Count      Average    Total        Total Runtime    % of MT
(ms)       (cnt)      (avg ms)   (minutes)    (hours)            (%)
     2862    2733         1         0,0         0,0             92,4

En la salida de ejemplo:

Se utiliza la opción thread name para extraer la carga de trabajo SQL activada solo por una hebra específica.

Las estadísticas SQL están basadas en los primeros 70 caracteres (valor predeterminado). Pueden variar utilizando la opción leng.

La salida se ordena de forma descendente en función de total run time. Los SQL con el impacto más elevado se muestran en la parte inferior.

Para cada sentencia SQL exclusiva, se muestran tres valores de estadísticas: total run time (milliseconds) (tiempo total de ejecución, minutos), number of executions (número de ejecuciones), average run time (milliseconds) (tiempo de ejecución promedio, milisegundos).

En Aggregated Statistics (Estadísticas agregadas), Monitored Time Period (MT) (Periodo de tiempo supervisado, MT), se muestra la duración de la hebra en función del primer y último SQL activados.

% of MT: Refleja la ocupación de SQL, en relación con Monitored time period (Periodo de tiempo supervisado). La regla empírica es:

  • > ; 80%: el rendimiento de la hebra está limitado por el rendimiento de SQL.
  • <= 80%: el proceso de datos utiliza mucha CPU (datos complejo, amplía lógica de código)

Casos de uso

En las siguientes secciones se muestran algunos casos de uso para describir cómo se utiliza e interpreta el programa de utilidad Sumall y su salida.

1.1 Rendimiento lento de la herramienta personalizada debido a SQL de larga ejecución (consultas con retardo)

Se ha notificado que algunas herramientas personalizadas han tardado más de 30 segundos en completarse. El análisis de los archivos db.log del servicio appsvr con el programa de utilidad sumall revela que es un único SQL, ejecutándose durante unos 27 segundos, lo que es razonable para la mayoría de los tiempos de ejecución:

$JAVA_RT com.ibm.ccd.common.wpcsupport.util.Sumall $TOP/appsvr*/db.log
...
       16       2       8,0     1,0   GET_DOC_STORE_REAL_FILES_WITH_ATTRIBUTE] SELECT DISTINCT dhi_doc_path,
       16       2       8,0     0,3   Dynamic:  [select * from ( SELECT ID FROM ( SELECT SEARCH_QUERY.ID AS
       18       2       9,0     0,8   GEN_SEC_UST_USER_SETTING_GETBYUSER] SELECT * FROM tsec_ust_user_settin
       48      41       1,2     0,8   OBJECT_ACCESS_FOR_USER_ROLE_ALL_GROUPS] SELECT orm_access, orm_access_
      420       2     210,0     1,0   GET_DOC_STORE_REAL_FILES] SELECT dhi_doc_path, dhi_doc_real_path FROM
      727       2     363,5     1,0   GEN_CTG_CAA_CATALOG_ATTRIBUTES_GETBYCATALOGVERSION] SELECT * FROM tctg
    27049       1   27049,0     0,0   Dynamic:  [select * from ( select distinct ita? .ita_value_string as c
-----------------------------------------------
   sum(ms)    cnt   avg(ms)     CV   QUERY

Monitored timeperiod (MT): 2013-11-08 11:50:11,128  -  2013-11-08 11:50:39,763 :  0,01 h | 0,00 m | 28,64 s

Statistical values for all queries
Total      count      Average    Total        Total Runtime    % of MT
(ms)       (cnt)      (avg ms)   (minutes)    (hours)            (%)
    28419     139       204         0,5         0,0             99,2

Para extraer la sentencia SQL completa, se pueden utilizar las opciones adicionales leng y cleanoff:

$JAVA_RT com.ibm.ccd.common.wpcsupport.util.Sumall $TOP/appsvr*/db.log db.log leng=5000 cleanoff
...
    27049       1   27049,0     0,0   Dynamic:  [select * from ( select distinct ita1.ita_value_string as c1, ita2.ita_value_string as c2, ita3.ita_value_string as c3, ita4.ita_value_string as c4, ita5.ita_value_string as c5, ita6.ita_value_string as c6, ita7.ita_value_string as c7, ita8.ita_value_string as c8,
...
ita18.ita_version_id <= 999999999 and ita18.ita_next_version_id >= 999999999 order by c18 asc, c7 asc ) where rownum <= 1000]
-----------------------------------------------
   sum(ms)    cnt   avg(ms)     CV   QUERY

Monitored timeperiod (MT): 2013-11-08 11:50:11,128  -  2013-11-08 11:50:39,763 :  0,01 h | 0,00 m | 28,64 s

Statistical values for all queries
Total      count      Average    Total        Total Runtime    % of MT
(ms)       (cnt)      (avg ms)   (minutes)    (hours)            (%)
   28419     139       204         0,5         0,0             99,2

En este caso de uso, el SQL de larga ejecución ha sido el resultado de una sentencia WQL compleja utilizada en la herramienta personalizada en combinación con el servidor de bases de datos configurado incorrectamente, lo que ha dado lugar a tiempos de cálculo de plan de consulta largos.
Cuando se identifican SQL de larga ejecución, definitivamente asegúrese de que las comprobaciones básicas (consulte Comprobaciones de salud básicas para garantizar un rendimiento óptimo) se han completado, para excluir problemas de mantenimiento y configuración generales.
Nota: Para ver qué sentencias SQL se han desencadenado al realizar la búsqueda avanzada en la interfaz de usuario o utilizar WQL en código personalizado, puede establecer el adicionador QUERY en $TOP/etc/default/log.xml en el valor de prioridad debug. El archivo de registro query.log mostrará tanto el WQL como la sentencia SQL resultante.

1.2 Rendimiento lento del trabajo de exportación debido a demasiado SQL, aunque se trata de sentencias SQL de rápida ejecución

No solo los SQL de larga ejecución pueden causar problemas de rendimiento, pero la optimización de código para evitar SQL duplicados puede ser clave para obtener también un rendimiento óptimo.
En este caso de uso, un trabajo de exportación existente no ha cumplido las expectativas de rendimiento. La agregación de estadísticas de las sentencias SQL de las que se ha hecho un seguimiento ha mostrado que el rendimiento de todos los SQL ha sido realmente bastante correcto con un tiempo de ejecución promedio de aproximadamente 1 milisegundo:

$JAVA_RT com.ibm.ccd.common.wpcsupport.util.Sumall $TOP/scheduler*/db.log

     2660    2632       1,0     0,3   GEN_CTG_ITM_ITEM_GETBYIDCTGVERSION] SELECT * FROM tctg_itm_item WHERE
     2666    2663       1,0     0,1   GEN_CTG_CHI_CATEGORY_HIERARCHY_GETBYPARENTID] SELECT * FROM tctg_chi_c
     2679    2663       1,0     0,1   GEN_CTG_CHI_CATEGORY_HIERARCHY_GETBYCHILDID] SELECT * FROM tctg_chi_ca
     2697    2663       1,0     0,2   GEN_CTG_CFP_CAT_FULL_PATHS_GETBYCATEGORYID] SELECT * FROM tctg_cfp_cat
     2785    2663       1,0     0,3   GEN_CTG_CAD_CATEGORY_DETAIL_GETBYIDVERSION] SELECT * FROM tctg_cad_cat
     3117    2663       1,2     0,4   GEN_CTG_CAT_CATEGORY_GETBYIDVERSION] SELECT * FROM tctg_cat_category W
    31379   31332       1,0     0,2   GEN_CTG_REC_RELATION_CONTAINER_GETBYCTGID] SELECT * FROM tctg_rec_rela
    35787      82     436,4     0,8   Dynamic:  [ select * from ( select distinct itm? .itm_id as c? from it
    62234  129382       0,5     1,1   Dynamic:  [ select distinct csm_spec_id from tctg_csm_category_spec_ma
   146526  160288       0,9     0,4   GEN_CTG_ITM_ITEM_GETBYPRIMARYKEYVERSION] SELECT * FROM tctg_itm_item W
   170744  160403       1,1     0,3   GEN_CTG_ITD_ITEM_DETAIL_GETBYIDVERSION] SELECT * FROM tctg_itd_item_de
   182688  191424       1,0     0,3   GEN_CTG_ICM_ITEM_CATEGORY_MAP_GETBYITEMVERSION] SELECT * FROM tctg_icm
-----------------------------------------------
   sum(ms)    cnt   avg(ms)     CV   QUERY

Monitored timeperiod (MT): 2013-07-04 23:00:03,856  -  2013-07-04 23:11:37,963 :  0,19 h | 11,00 m | 694,11 s

Statistical values for all queries
Total      count      Average    Total        Total Runtime    % of MT
(ms)       (cnt)      (avg ms)   (minutes)    (hours)            (%)
   650683  694645         0        10,8         0,2             93,7

De todos modos, el número de sentencias SQL activadas era una alerta. Se ha planteado la sospecha de que se han recuperado los mismos objetos de la base de datos varias veces. Para investigarlo, se puede ejecutar el programa de utilidad sumall con un parámetro leng grande y una opción cleanoff:

$JAVA_RT com.ibm.ccd.common.wpcsupport.util.Sumall $TOP/scheduler*/db.log leng=5000 cleanoff > sumallstat.out

Posteriormente, las sentencias SQL seleccionadas se pueden extraer para comprobar si hay ejecuciones duplicadas. La siguiente salida de ejemplo se ha abreviado para que se visualice mejor.

grep GEN_CTG_ITM_ITEM_GETBYPRIMARYKEYVERSION sumallstat.out
...
2480    2006       1,2     0,4   GEN_CTG_ITM...] SELECT * FR... AND itm_container_id = 6019 AND itm_primary_key = '1' ...
3888    4382       0,9     0,4   GEN_CTG_ITM...] SELECT * FR... AND itm_container_id = 64402 AND itm_primary_key = 'ma...
5174    5746       0,9     0,4   GEN_CTG_ITM...] SELECT * FR... AND itm_container_id = 64402 AND itm_primary_key = 'ma...
5823    6436       0,9     0,4   GEN_CTG_ITM...] SELECT * FR... AND itm_container_id = 64402 AND itm_primary_key = 'ma...
7869    8428       0,9     0,4   GEN_CTG_ITM...] SELECT * FR... AND itm_container_id = 6582 AND itm_primary_key = 'CHL...

Las estadísticas han revelado que se han recuperado artículos de determinados catálogos un par de miles de veces durante una única ejecución de exportación. Al final, la lógica de exportación se ha mejorado implementando almacenamiento en caché de los objetos utilizados habitualmente.


Última actualización: 11 Mar 2019