Using ucdbconntest to troubleshoot database slow response time
search cancel

Using ucdbconntest to troubleshoot database slow response time

book

Article ID: 423452

calendar_today

Updated On:

Products

CA Automic Workload Automation - Automation Engine CA Automic One Automation CA Automic Service Orchestration - Automation Engine CA Automic Operations Manager CA Automic Oracle

Issue/Introduction

The ucdbconntest utility (formerly known as SimDbOpen) is a diagnostic tool integrated into the Automation Engine codebase. It performs a standardized performance test by executing a loop of 1,000 database operations to measure latency and identify bottlenecks between the Automation Engine and the database.

Starting with version 24.3, the Automation Engine includes a new executable called ucdbconntest located in the bin directory. This tool replaces the SimDbOpen binary that was previously only available via support and is available on all supported AE core server operating systems.

The tool performs a loop of 1,000 executions of the following SQL operations:

  • INSERT

  • SELECT

  • ROLLBACK

  • SELECT (again)

By default, ucdbconntest utilizes the ucsrv.ini file for connection parameters, eliminating the need to provide an ODBC connect string on the command line.

Before it is run, it is important to have access to the database server. This tool can be compared to a wireshark trace but for the database.

Oracle Database

For Oracle, a trigger like this is set up.

grant alter session to <yourDBuser>;

create or replace trigger <yourDBuser>.trcaeopen
after logon
on <yourDBuser>.schema
begin
-- optionally add a tag to the trace file name to make the files easy to find:
execute immediate 'ALTER SESSION SET TRACEFILE_IDENTIFIER =''HolliDbOpenTest''';
-- enable sql_trace for this session:
execute immediate 'ALTER SESSION SET SQL_TRACE=TRUE';
execute immediate 'alter session set events ''10046 trace name context forever,level 12''';
execute immediate 'alter session set statistics_level=all';
execute immediate 'alter session set max_dump_file_size = unlimited';
end;

-- after capture remove trigger or disable
drop trigger <yourDBuser>.trcaeopen;
ALTER TRIGGER <yourDBuser>.trcaeopen DISABLE;

-- to find oracle TRACEFILE location
-- should be ../diag/rdbms/<instance>/<db>/trace/
-- f.ex. per01_ora_5760_HolliDbOpenTest.trc
select * from v$parameter;

MS SQL Database

For MS SQL, SQL Server Profiler can used to record the statement.

File > New Trace

Connect to the Database server where Automic is hosted

Hit run to start recording

Hit stop once ucdbconntest  is done running.

Hit File > Save As > Trace File.

PostgreSQL Database

The extension pg_stat_statements can be installed. Here is an example, you will need to restart the postgres service after running it. Refer to the PostgreSQL documentation for more information.

CREATE EXTENSION IF NOT EXISTS pg_stat_statements;

This will log all SQL statements coming in to your postgres database to a pg_stat_statements table that you can refer to.

We can test that it is installed properly via this query

SELECT * FROM pg_extension WHERE extname = 'pg_stat_statements';

But we will run this query to get the timestamps and queries to compare.

SELECT query, stats_since, total_exec_time FROM pg_stat_statements LIMIT 3000;

Environment

AE 24.3+

Resolution

The standard trace can be generated by this command from the Automation Engine bin directory.

ucdbconntest.exe -T2

If successful, it will first generate some information about the database, then it will generate 2 files in the Automation Engine temp directory.

The two files are named ucdbconntest.txt and ucdbconntest.trace

The ucdbconntest.trace is the most important part. It not only gives us information about the database but also about the time stamps of each query that we will need to compare with the database side. This is the application side for the DBA to refer to.

20251223/093329.196 - LoadLibrary UCUPGS
20251223/093329.196 - U00003545 UCUDB: Opening database ...
20251223/093329.196 - U00029112 UCUDB - Length of the DB-History area: 100
20251223/093329.341 - U00029110 UCUDB - Session parameters:
20251223/093329.342 - U00029179 PGSQRY: 'PGSQuery::ExecuteX(BEGIN)'
20251223/093329.343 - U00003535 DB INFO: 'SID                   = 8704'
20251223/093329.343 - U00029179 PGSQRY: 'PGSQuery::CommitX(END)'
20251223/093329.343 - U00029115 UCUDB - OPEN          Database handles  DB-HENV: e12a7840  DB-HDBC: 0
20251223/093329.343 - U00003535 DB INFO: 'DATABASE-NAME         = 'automic'
20251223/093329.357 - U00003535 DB INFO: 'DBMS-NAME             = PostgreSQL'
20251223/093329.357 - U00003535 DB INFO: 'DBMS-VER              = PostgreSQL 17.6 on x86_64-windows, compiled by msvc-19.44.35213, 64-bit'
20251223/093329.357 - U00003535 DB INFO: 'ODBC-VER              = ODBC not used'
20251223/093329.357 - U00003535 DB INFO: 'DRIVER-NAME           = PostgreSQL Access Library'
20251223/093329.357 - U00003535 DB INFO: 'DRIVER-ODBC-VER       ='
20251223/093329.357 - U00003535 DB INFO: 'DRIVER-VER            = 160000'
20251223/093329.357 - U00003535 DB INFO: 'DATABASE-COLLATION    = 160000'
20251223/093329.357 - U00003535 DB INFO: 'ODBC-API-CONFORMANCE  ='
20251223/093329.357 - U00003535 DB INFO: 'TXN-CAPABLE           ='
20251223/093329.357 - U00003535 DB INFO: 'DEFAULT-TXN-ISOLATION ='
20251223/093329.357 - U00003535 DB INFO: 'TXN-ISOLATION-OPTION  ='
20251223/093329.357 - U00003535 DB INFO: 'POS-OPERATIONS        ='
20251223/093329.357 - U00003535 DB INFO: 'POSITIONED-STATEMENTS ='
20251223/093329.358 - U00003535 DB INFO: 'SCROLL-CONCURRENCY    ='
20251223/093329.358 - U00003535 DB INFO: 'SCROLL-OPTIONS        ='
20251223/093329.358 - U00003535 DB INFO: 'STATIC-SENSITIVITY    ='
20251223/093329.358 - U00003535 DB INFO: 'LOCK-TYPES            ='
20251223/093329.358 - show client_encoding
20251223/093329.358 - U00029179 PGSQRY: 'PGSQuery::ExecuteX(BEGIN)'
20251223/093329.359 - UCUDB32 SLCT RET 0000 HSTMT: 0000012DE1586380 VALUE: 0000012DE1586380 ALL:  0.00049 DB:  0.00049 ODBC:  0.00000 UDB:  0.00000
20251223/093329.359 - UCUDB32 READ RET 0000 HSTMT: 0000012DE1586380 VALUE: 0000012DE1586380 ALL:  0.00000 DB:  0.00000 ODBC:  0.00000 UDB:  0.00000
20251223/093329.359 - UCUDB32 CLST RET 0000 HSTMT: 0000012DE1586380 VALUE: 0000012DE1586380 ALL:  0.00000 DB:  0.00000 ODBC:  0.00000 UDB:  0.00000
20251223/093329.359 - SELECT pg_encoding_to_char(encoding) FROM pg_database WHERE datname = 'automic'
20251223/093329.360 - UCUDB32 SLCT RET 0000 HSTMT: 0000012DE1586380 VALUE: 0000012DE1586380 ALL:  0.00146 DB:  0.00146 ODBC:  0.00000 UDB:  0.00000
20251223/093329.360 - UCUDB32 READ RET 0000 HSTMT: 0000012DE1586380 VALUE: 0000012DE1586380 ALL:  0.00000 DB:  0.00000 ODBC:  0.00000 UDB:  0.00000
20251223/093329.360 - UCUDB32 CLST RET 0000 HSTMT: 0000012DE1586380 VALUE: 0000012DE1586380 ALL:  0.00000 DB:  0.00000 ODBC:  0.00000 UDB:  0.00000
20251223/093329.360 - U00037180 Collation in Database: 'UTF8'.
20251223/093329.360 - U00003535 DB INFO: 'ODBC_TRACE            = 301'
20251223/093329.364 - U00029179 PGSQRY: 'PGSQuery::CommitX(END)'
20251223/093329.365 - U00029179 PGSQRY: 'PGSQuery::ExecuteX(BEGIN)'
20251223/093329.366 - DELETE FROM DIVDB WHERE DIVDB_PK= 1
20251223/093329.366 - UCUDB32 DLTE RET 0000 HSTMT: 0000012DE1586380 VALUE: 0000012DE1586380 ALL:  0.00150 DB:  0.00150 ODBC:  0.00000 UDB:  0.00000
20251223/093329.366 - UCUDB32 CLST RET 0000 HSTMT: 0000012DE1586380 VALUE: 0000012DE1586380 ALL:  0.00000 DB:  0.00000 ODBC:  0.00000 UDB:  0.00000
20251223/093329.367 - U00029179 PGSQRY: 'PGSQuery::CommitX(END)'
20251223/093329.367 - UCUDB32 CMIT RET 0000 HSTMT: 0000012DE1586380 VALUE: 0000012DE1586380 ALL:  0.00035 DB:  0.00035 ODBC:  0.00000 UDB:  0.00000
20251223/093329.367 - INSERT INTO DIVDB (DIVDB_PK,DIVDB_Memo,DIVDB_String,DIVDB_Date) VALUES(1, ?, ?, ?)
20251223/093329.367 - U00029179 PGSQRY: 'PGSQuery::ExecuteX(BEGIN)'
20251223/093329.368 - UCUDB32 INSR RET 0000 HSTMT: 0000012DE1586380 VALUE: 0000012DE1586380 ALL:  0.00114 DB:  0.00114 ODBC:  0.00000 UDB:  0.00000
20251223/093329.368 - UCUDB32 CLST RET 0000 HSTMT: 0000012DE1586380 VALUE: 0000012DE1586380 ALL:  0.00000 DB:  0.00000 ODBC:  0.00000 UDB:  0.00000
20251223/093329.368 - SELECT DIVDB_String, DIVDB_Date, DIVDB_Memo FROM DIVDB where DIVDB_PK = 1
20251223/093329.369 - UCUDB32 SLCT RET 0000 HSTMT: 0000012DE1586380 VALUE: 0000012DE1586380 ALL:  0.00050 DB:  0.00050 ODBC:  0.00000 UDB:  0.00000
20251223/093329.369 - UCUDB32 READ RET 0000 HSTMT: 0000012DE1586380 VALUE: 0000012DE1586380 ALL:  0.00000 DB:  0.00000 ODBC:  0.00000 UDB:  0.00000
20251223/093329.369 - UCUDB32 CLST RET 0000 HSTMT: 0000012DE1586380 VALUE: 0000012DE1586380 ALL:  0.00000 DB:  0.00000 ODBC:  0.00000 UDB:  0.00000
20251223/093329.369 - U00029179 PGSQRY: 'PGSQuery::RollbackX(ROLLBACK)'

The log provides a time stamp of the query and what query it is running. The DBA must compare the time stamps of ucdbconntest.trace with the output of the log set up from the DBMS end (Trigger log for Oracle, MS SQL Profiler for MS SQL, and output from pg_stat_statements for postgres).

Note: A delay may not always be caused by the DBMS. By comparing the time ucdbconntest sent the query and the receival time from the database end, we can find how much time it took to get there. If the majority of the delay is the transient time, the network team needs to investigate further and improve the time between the two servers.

Powered by Wolken Software