DB performance test (ucdbconntest)

[Michael A. Lowry]

When an AE work processes starts and connects to the database, it performs a simple performance test and prints the result of the test to the WP log in message U00003533.  This test has been part of the application for many years, and is described in KB 88675 - Performance problems and an explanation of U00003533. I also wrote about this in my 2023 discussion thread Description of DB performance check behind message U0003533.

With Automic Automation v21.0.9 and later, the DB test is performed automatically once per hour (at 5 minutes before the hour), and the results are logged to the database.

The documentation page Database Metric Visualization describes the DB performance test. The page Automic DB Metric Visualization also describes the DB performance test in detail, and includes a handy dashboard for visualizing historical DB performance metrics.

Both of these pages mention in passing a program called ucdbconntest. This program is included with the Automation Engine server starting with v24, and provides a quick way to measure current DB performance manually from the command line.

** Usage: ucdbconntest [-C<connection string>] [-I<INI file path>] [-T<trace flag>] [-V]
** Connection string examples:
** ORACLE:     'ODBCVAR=NNJNIORO,DSN=AEDB;UID=uc4;PWD=uc4;SP=NLS_LANGUAGE=AMERICAN,NLS_TERRITORY=AMERICA,CODESET=WE8MSWIN1252,NLS_LENGTH_SEMANTICS=CHAR'
** ORACLE:     'ODBCVAR=NNJNIORO,DSN=//DBHost:DBPort/DBserviceName;UID=uc4;PWD=uc4;SP=NLS_LANGUAGE=AMERICAN,NLS_TERRITORY=AMERICA,CODESET=WE8MSWIN1252,NLS_LENGTH_SEMANTICS=CHAR'
** SQLSERVER:  'ODBCVAR=NNNNNNRN,Driver={ODBC Driver 13 for SQL Server};Server=tcp:aesrv.uc4.com,1433;UID=uc4;PWD=uc4;database=AEDB;Mars_Connection=Yes;APP=UC4_AE'
** PostGreSQL: 'ODBCVAR=NNJNIORP,host=aesrv.uc4.com port=5432 dbname=AEDB user=uc4 password=uc4 connect_timeout=10 client_encoding=latin9'
** DB2 LUW:    'ODBCVAR=NNJNIORD,DSN=AEDB;UID=uc4;PWD=uc4'
** The encrypted password can be used as well.
** On Windows, use " instead of '.

To use ucdbconntest, one must provide either the path to a valid ucsrv.ini file (-I), or a valid ODBC connection string (-C).

bash-5.1$ ./ucdbconntest -C"${AUTOMIC_ODBC_SQLDRIVERCONNECT}"
U00003533 UCUDB: Check of data source finished: No errors. Performance CPU/DB: '198767791'/'61 (1000/16.381 s)'
BindCol :     0 ms
BindPar :     0 ms
Close   :     0 ms
Fetch   :     0 ms
Insert  :  3308 ms
Rollback:  3232 ms
Select  :  6556 ms
WARNING:  there is no transaction in progress
Database connection test finished successfully.

The output is written to the file ucdbconntest.log. (If tracing is enabled (-T), trace output is written to the file ucdbconntest.trace.)

20250417/091802.981 - U00003545 UCUDB: Opening database ...
20250417/091802.981 - U00029112 UCUDB - Length of the DB-History area: 100
20250417/091803.230 - U00029110 UCUDB - Session parameters:
20250417/091803.291 - U00003535 DB INFO: 'SID                   = 612687'
20250417/091803.315 - U00029115 UCUDB - OPEN          Database handles  DB-HENV: 3a7068c0  DB-HDBC: 0
20250417/091803.349 - U00003535 DB INFO: 'DATABASE-NAME         = ddp0007482'
20250417/091803.349 - U00003535 DB INFO: 'DBMS-NAME             = PostgreSQL'
20250417/091803.378 - U00003535 DB INFO: 'DBMS-VER              = PostgreSQL 14.17 on x86_64-pc-linux-gnu, compiled by gcc (GCC) 11.2.0, 64-bit'
20250417/091803.378 - U00003535 DB INFO: 'ODBC-VER              = ODBC not used'
20250417/091803.378 - U00003535 DB INFO: 'DRIVER-NAME           = PostgreSQL Access Library'
20250417/091803.378 - U00003535 DB INFO: 'DRIVER-ODBC-VER       ='
20250417/091803.378 - U00003535 DB INFO: 'DRIVER-VER            = 170004'
20250417/091803.378 - U00003535 DB INFO: 'DATABASE-COLLATION    = 170004'
20250417/091803.378 - U00003535 DB INFO: 'ODBC-API-CONFORMANCE  ='
20250417/091803.378 - U00003535 DB INFO: 'TXN-CAPABLE           ='
20250417/091803.378 - U00003535 DB INFO: 'DEFAULT-TXN-ISOLATION ='
20250417/091803.378 - U00003535 DB INFO: 'TXN-ISOLATION-OPTION  ='
20250417/091803.378 - U00003535 DB INFO: 'POS-OPERATIONS        ='
20250417/091803.378 - U00003535 DB INFO: 'POSITIONED-STATEMENTS ='
20250417/091803.378 - U00003535 DB INFO: 'SCROLL-CONCURRENCY    ='
20250417/091803.378 - U00003535 DB INFO: 'SCROLL-OPTIONS        ='
20250417/091803.378 - U00003535 DB INFO: 'STATIC-SENSITIVITY    ='
20250417/091803.378 - U00003535 DB INFO: 'LOCK-TYPES            ='
20250417/091803.467 - U00037180 Collation in Database: 'UTF8'.
20250417/091803.467 - U00003535 DB INFO: 'ODBC_TRACE            = 32648'
20250417/092007.359 - U00003533 UCUDB: Check of data source finished: No errors. Performance CPU/DB: '556775829'/'8 (1000/122.357784 s)'
20250417/092007.359 - U00003544 UCUDB: Reference values tested with Linux x64 on XEON 3600 MHz: CPU 525716336, DB 3505
20250417/092007.477 - U00003524 UCUDB: ===> Time critical DB call!       OPC: 'OPEN' time: '124:518.555.000'
20250417/092007.528 - U00003523 UCUDB: Maximum time required for a DB call: '124:518.555.000'.
20250417/092007.528 - U00003522 UCUDB: Database closed. Total time for DB calls: '124:569.734.000' seconds.
20250417/092007.528 - U00003549 UCUDB: '            2021' 'OTHERS    ' calls took '124:569.734.000' sec.
20250417/092007.528 - U00003549 UCUDB: '               0' 'SELECT    ' calls took '0:000.000.000' sec.
20250417/092007.528 - U00003549 UCUDB: '               0' 'EXECUTE   ' calls took '0:000.000.000' sec.
20250417/092007.528 - U00003549 UCUDB: '               0' 'UPDATE    ' calls took '0:000.000.000' sec.
20250417/092007.528 - U00003549 UCUDB: '               0' 'DELETE    ' calls took '0:000.000.000' sec.
20250417/092007.528 - U00003549 UCUDB: '               0' 'INSERT    ' calls took '0:000.000.000' sec.
20250417/092007.528 - U00003549 UCUDB: '               0' 'READ      ' calls took '0:000.000.000' sec.
20250417/092007.528 - U00003549 UCUDB: '            3013' 'CLOSESTMT ' calls took '0:000.000.000' sec.
20250417/092007.528 - U00003549 UCUDB: '            1005' 'TRANSACT  ' calls took '0:000.000.000' sec.

The DB metrics visualization dashboard relies on several SQL queries that fetch historical performance statistics from the PMMA and PMMAV tables. Here’s an example (PostgreSQL), based on AE.VARA.SQLI.GET.DB.PERFORMANCE.VALUES.LOG.

SELECT pmma_timestamp timestamp, pmmav_value db_perf_value, (1000 / pmmav_value) as seconds
	FROM pmma INNER JOIN pmmav ON PMMAV_PMMA_IDNR = PMMA_IDNR
		WHERE PMMA_PMMD_IDNR = 8
		    and pmmav_key = 'db-perf'
			and PMMA_TIMESTAMP >= now() - interval '30 days'
ORDER BY PMMA_TIMESTAMP desc

You can find a similar query in this 2023 post by @Marcin Uracz.

See also: 

• System Performance
• PERFORMANCE Parameters

[Michael A. Lowry]

Here are some more observations about how performance tests are run, and the statistics logged.

• The performance test runs automatically when a WP starts up.
• Additionally, one normal (non-Java) WP is chosen by the PWP to perform periodic performance tests as long as the system is running.
• This WP runs the performance test once per hour at 5 minutes before the hour (:55).
• The performance test measures the time required to run a sequence of 4 SQL operations (INSERT, SELECT, ROLLBACK, and SELECT) a total of 1000 times.
• When the performance test is complete, the WP writes message U00003533 to its log.
• The WP also stores the DB performance test result to a new db-perf row in the pmmav_value table. However, the WP does not directly store the number of seconds required to complete the test. Instead, the WP stores an estimate of how many times the test sequence could have been completed in 1 second. (This is essentially just 1000 divided by number of seconds required to run the test.)
• The milliseconds are truncated to 000 in pmma_timestamp. Otherwise, the timestamp stored in the DB is the same as the one printed to the log.