Description of DB performance check behind message U0003533

[Michael A. Lowry]

When an Automation Engine server process starts up, it performs a test of the performance of the database. The AE prints the result of this test to the log in message U0003533. I recently spoke with @Markus Embacher at Broadcom. He kindly described the process in detail.

1. Insert a single row into the DIVDB table.
   

   INSERT INTO DIVDB (DIVDB_PK,DIVDB_Memo,DIVDB_String,DIVDB_Date) VALUES(1, ?, ?, ?)

   Bind parameters

   1. Raw data containing all of 256 code points of the character set including the null character 0x00.
   2. A string containing all of 255 characters of the character set (UTF-8, at least in the case of Oracle).
   3. The current date.
      
      
2. Select the same row from the DIVDB table.
   

   SELECT DIVDB_String, DIVDB_Date, DIVDB_Memo FROM DIVDB where DIVDB_PK = 1

3. Roll back the transaction.
   

   ROLLBACK

4. Perform the SELECT again

   SELECT DIVDB_String, DIVDB_Date, DIVDB_Memo FROM DIVDB where DIVDB_PK = 1

The AE server process performs these four operations 1000 times, and calculates the total amount of time required. The result is printed in message U0003533, like the message below.

U00003533 UCUDB: Check of data source finished: No errors. Performance CPU/DB: '475845032'/'173 (1000/5.753296 s)'

In this example, the AE server process reports that it took 5.753296 seconds to perform the above 4 steps 1000 times.

Note that the AE server process also performs these two additional checks:

• Do the data returned by the first SELECT statement match the data inserted by the INSERT statement? They should. (This is to catch any problems with code pages or NLS character sets.)
• Does the second SELECT statement return any data? It should not. (This is intended to catch any problems caused by DB performance tuning parameters that can prevent rollbacks from happening immediately.)

You can observe the performance test in action by enabling db=4 trace.

[Michael A. Lowry]

The strange formatting of the DB performance measurement reported in message U0003533 is a legacy of the way this performance test was performed in previous versions.

In another discussion thread, former Automic employee Harriet Kim explained the change:

The AE does an

 INSERT INTO DIVDB and SELECT from DIVDB.

 After 1 second, we check how often this was done.

With v12 sp1 this is changed and we do exactly 1000 INSERT and SELECT and provide the information how long this took.

Rather than change the message or introduce a new message, developers decided to simply include the new information inside parentheses at the end of the 2^nd message variable &02.

Prior to v12.0 SP1, the message would have looked something like this:

U00003533 UCUDB: Check of data source finished: No errors. Performance CPU/DB: '475845032'/'173'

Since v12.0 SP1, the message looks like this:

U00003533 UCUDB: Check of data source finished: No errors. Performance CPU/DB: '475845032'/'173 (1000/5.753296 s)'

In a nod to backward compatibility, the developers added a bit of code to estimate the previous performance measurement - namely, how many times the four statements (INSERT, SELECT, ROLLBACK, and SELECT) could have been performed in one second, extrapolated (or interpolated) from the collected timing measurement. So in the above message, the number 173 is just an estimate.

For some reason, message U0003544 was not updated to conform to the new way DB performance is measured.

U00003544 	UCUDB: Reference values tested with Linux x64 on XEON 3600 MHz: CPU 525716336, DB 3505

This message still shows number of times the four statements could be run in one second (3505), not the time it took to run them 1000 times.

[Markus Embacher]

Hi Michael,

the intention behind those figures is just to give users an indication about the performance of their system. If your value shows 173 then you know that in your environment the performance test executed about 20 times slower than the reference and there might be room for improvement.

The reference run took about 1000 / 3505 = 0,2853 seconds

Regards, Markus