Author: Sungjin Kim
It’s critical to improve performance while operating a database system. Unlike other DBMS, CUBRID is composed of a three-tier structure of JDBC driver-broker-database server.
Among the three layers, the broker is a CUBRID-only middleware that relays communications between the server and external applications, providing connection pooling, monitoring, log tracking and analysis functions. CUBRID can perform SQL performance analysis through the SQL LOG file generated by the CUBRID BROKER process. (Other DBMS performance monitoring can be confirmed by querying the system DMV.)
In this article, we will introduce useful utilities for analysing and improving performance problems using SQL LOG files created by CUBRID BROKER, and the first utility we will introduce is breaker_log_top.
When executed, the broker_log_top utility analyses the SQL LOG files generated during a specific period and lists them in order of longest execution time. This utility leaves 2 result files, log_top.res and log_top.q.
- The log_top.res file stores the maximum execution time, minimum execution time, average execution time, and execution count (error occurrence count) for SQLs executed during a specific period.
- The log_top.q file stores the SQL statements corresponding to the query numbers listed in log_top.res.
Here’s how to run the utility:
$ broker_log_top [options] sql_log_file_list
The sql_log_file_list above refers to the SQL LOG file generated by the CUBRID BROKER process.
The SQL log file records the SQL requested by the application client and saves it with the name <broker_name>_<app_server_num>.sql.log. SQL logs are generated only when the SQL_LOG parameter value is ON (default). If the default setting is set, you can check the files in the $CUBRID/log/broker/sql_log directory.
You can check the status of the BROKER by inquiring the following procedure:
$ cubrid broker info 브로커명 | grep LOG_DIR | grep -vE "ACCESS|ERROR|SLOW"
Now let's run the utility:
$ broker_log_top query_editor_*.sql.log query_editor_1.sql.log query_editor_2.sql.log query_editor_3.sql.log print results... $ ls log_top.q log_top.res query_editor_1.sql.log query_editor_2.sql.log query_editor_3.sql.log
As shown in the results screen above, log_top.q file and log_top.res file have been created. However, *.sql.log is not recognized on Windows, so all target files must be listed with a space separator as shown below:
C:\CUBRID\log\broker\sql_log> broker_log_top query_editor_1.sql.log query_editor_2.sql.log query_editor_.sql.log query_editor_1.sql.log query_editor_2.sql.log query_editor_3.sql.log print results...
Now, let’s look at the resulting log_top.res file.
$ head log_top.res max min avg cnt(err) ----------------------------------------------------- [Q1] 0.013 0.010 0.011 3 (0) [Q2] 0.013 0.013 0.013 1 (0) [Q3] 0.010 0.009 0.009 2 (0) [Q4] 0.003 0.003 0.003 3 (0) [Q5] 0.002 0.002 0.002 3 (0) [Q6] 0.002 0.002 0.002 2 (0) [Q7] 0.001 0.000 0.000 48 (0) [Q8] 0.001 0.000 0.000 3 (0)
You can see that the query number [Q1] was executed 3 times, there was no execution failure due to the same SQL error, and the execution time took up to 0.013 seconds, and at least 0.010 seconds, and on average 0.011 seconds.
As an example, it is the result of log_top.res of the SQL statement of the specific system in operation above.
[Q1] is expressed as the slowest, but since it takes 0.172 seconds on average, we can assume that an instantaneous locking phenomenon occurred. However, the average execution time of [Q2] and [Q3] are 2.116sec and 4.342sec respectively and the number of executions was high, which indicate that can be the target SQL that requires tuning.
Therefore, the SQL syntax with a high number of executions and a slow average rate are subject to tuning, and the phenomena of the average speed is fast, but the SQL slowed down at a specific point in time is due to a temporary lock phenomenon, transaction contention should be investigated.
Now let's look at the contents of the log_top.q file.
$ head -20 log_top.q [Q1]-------------------------------------------query_editor_1.sql.log:56 17-12-27 19:01:19.641 (2) execute srv_h_id 1 SELECT a.attr_name, a.attr_type, a.from_class_name, a.data_type, a.prec, a.scale, a.is_nullable, a.domain_class_name, a.default_value, a.def_order, c.is_system_class, c.class_type, c.partitioned, c.owner_name, c.class_name, a.from_attr_name, c.is_reuse_oid_class FROM db_attribute a, db_class c WHERE c.class_name=a.class_name ORDER BY a.class_name, a.def_order 17-12-27 19:01:19.655 (2) execute 0 tuple 342 time 0.013 [Q2]-------------------------------------------query_editor_1.sql.log:1218 17-12-27 19:10:50.189 (90) execute srv_h_id 1 commit; 17-12-27 19:10:50.203 (90) execute 0 tuple 0 time 0.013 [Q3]-------------------------------------------query_editor_1.sql.log:599 17-12-27 19:01:33.509 (44) execute srv_h_id 1 SELECT c.class_name, COUNT(*) AS count_column, CAST(SUM( CASE WHEN "data_type" = 'BIGINT' THEN 8.0 WHEN "data_type" = 'INTEGER' THEN 4.0 WHEN "data_type" = 'SMALLINT' THEN 2.0 WHEN "data_type" = 'FLOAT' THEN 4.0 WHEN "data_type" = 'DOUBLE' THEN 8.0 WHEN "data_type" = 'MONETARY' THEN 12.0 WHEN "data_type" = 'STRING' THEN a.prec WHEN "data_type" = 'VARCHAR' THEN a.prec WHEN "data_type" = 'NVARCHAR' THEN a.prec WHEN "data_type" = 'CHAR' THEN a.prec WHEN "data_type" = 'NCHAR' THEN a.prec WHEN "data_type" = 'TIMESTAMP' THEN 8.0 WHEN "data_type" = 'DATE' THEN 4.0 WHEN "data_type" = 'TIME' THEN 4.0 WHEN "data_type" = 'DATETIME' THEN 4.0 WHEN "data_type" = 'BIT' THEN FLOOR(prec / 8.0) WHEN "data_type" = 'BIT VARYING' THEN FLOOR(prec / 8.0) ELSE 0 END ) AS BIGINT) AS size_column, SUM( CASE WHEN "data_type" = 'STRING' THEN 1 WHEN "data_type" = 'VARCHAR' THEN 1 WHEN "data_type" = 'NVARCHAR' THEN 1 WHEN "data_type" = 'NCHAR' THEN 1 WHEN "data_type" = 'BIT VARYING' THEN 1 ELSE 0 END ) AS size_over_column, MAX(c.class_type) AS class_type, MAX(c.partitioned) AS partitioned FROM db_class c, db_attribute a WHERE c.class_name = a.class_name AND c.is_system_class = 'NO' AND c.class_type = 'CLASS' AND a.from_class_name IS NULL GROUP BY c.class_name 17-12-27 19:01:33.518 (44) execute 0 tuple 11 time 0.010 [Q4]-------------------------------------------query_editor_1.sql.log:1392 17-12-27 20:33:38.058 (109) execute_all srv_h_id 1 SELECT a.class_name, a.attr_name, a.attr_type, a.data_type, a.prec, a.scale FROM db_attr_setdomain_elm a WHERE a.class_name = ? ORDER BY a.class_name, a.attr_name 17-12-27 20:33:38.058 (109) bind 1 : VARCHAR (5)code 17-12-27 20:33:38.059 (109) execute_all 0 tuple 0 time 0.010
If the SQL statement for each query number is extracted, and the slowest query is extracted from the same SQL, and variable binding is used, even mapping values according to the order of binding variables can be known. The SQL statement in query number [Q4] shows that the SQL statement in line 1,392 of the query_editor_1.sql.log file was extracted and the 109th SQL performed in that session.
Now, we will extract the SQL LOG file for each transaction using the -t option. The reason for extracting transaction-specific SQL Log files is to consider possible exceptions (temporarily slowed by a lock) because the information generated in the log_top.res, log_top.q file is time measured only for individual SQL phrases.
$ broker_log_top -t query_editor_*.sql.log query_editor_1.sql.log query_editor_2.sql.log query_editor_3.sql.log $ ls log_top.q log_top.res log_top.t query_editor_1.sql.log query_editor_2.sql.log query_editor_3.sql.log
You can see the log_top.t file is created as above, you can check the file with vi, etc.
First, if you look at the transaction information, the transaction remains unclosed after the initial update, and the health check SQL statement is executed several times in WAS, and the update statement is executed again at the end, and the TCL statement is executed to complete the transaction.
The implication in this example is that if the code table does not have an index on the f_name column, certain DML statements from other transactions that access the code table for about 32 seconds will wait until the table is unlocked, indicating that the code table's concurrency is deteriorated.
Secondly, you can see that COMMIT did not come in for about 20 seconds after the SQL syntax was performed.
The broker_log_top utility also enables additional options that allow you to extract multiple SQL LOG files in a specific time zone when you analyze them.
Corresponding options and detailed descriptions are in CUBRID Mannual: CUBRID Management à Controlling CUBRID Process at https://www.cubrid.org/manual/en/10.1/admin/control.html#broker-log.
In the next article, I will introduce the cubrid_replay utility that can reproduce the past situation using the SQL LOG file.