Timing for DataSync Agent

You can enable additional timing configurations within your agent.xml file which will give a more detailed view of how it is spending its time processing. The two configurations give details on

1. How long it takes to grab data from the Perspectium Integration Mesh (Queue Timing)

2. How long it takes to both build the statement and send the statement to the database (DB Timing). DB Timing records will include those to do a database action such as inserting, updating or delete as well as timings for querying for records to see if they exist as is done in the .bulk and .delete scenarios before the action action of insert/update/delete.  Querying for records is indicated with Query DB IO in the logs while other database actions are indicated with DB IO. 

From this and finer level logging we can get some further details on any bottlenecks which you may see.

Prerequisites

 First, you will need to set up one of the Perspectium DataSync Agents.

 You should stop running your DataSync Agent before making any Agent configuration changes.

Procedure

To change timing for the DataSync Agent, follow these steps:

Example Configuration for DataSync Agent

<?xml version="1.0" encoding="ISO-8859-1" standalone="no"?>
<config>
   <agent>
      <subscribe>
         <task>
            <task_name>example_subscribe</task_name>
            <message_connection password="YYYY" user="XXXX">https://example.perspectium.net</message_connection>
            <instance_connection password="YYYY" user="XXXX">https://example.service-now.com</instance_connection>
            <handler>com.perspectium.replicator.sql.SQLSubscriber</handler>
            <decryption_key>The cow jumped over the moon</decryption_key>
            <database_type>mysql</database_type>
            <database_server>localhost</database_server>
            <database_port>3306</database_port>
            <database_user>XXXX</database_user>
            <database_password>YYYY</database_password>
            <database_parms></database_parms>
            <database_column_max_size>251</database_column_max_size>
            <database>test_db</database>
 
            <queue_timing/>
            <db_timing/>
         </task>
      </subscribe>
      <max_reads_per_connect>4000</max_reads_per_connect>
      <polling_interval>5</polling_interval>
      <skip_message_set_processing/>
   </agent>
</config>

Logs

Queue Timing

You will likely see logs like the following for the queue_timing. This is showing when it did retrieve these 11 (4 KB) records it did so in 262 ms.

2019-01-18 10:42:13.872 INFO  - example_subscribe - SubscriberTask - Queue item retrieved in 0ms size: 4292
2019-01-18 10:42:13.896 INFO  - example_subscribe - SubscriberTask - Queue item retrieved in 0ms size: 4292
2019-01-18 10:42:13.950 INFO  - example_subscribe - SubscriberTask - Queue item retrieved in 0ms size: 4292
2019-01-18 10:42:14.004 INFO  - example_subscribe - SubscriberTask - Queue item retrieved in 1ms size: 4292
2019-01-18 10:42:14.129 INFO  - example_subscribe - SubscriberTask - Queue item retrieved in 102ms size: 0
2019-01-18 10:42:14.129 INFO  - example_subscribe - SubscriberTask - example_subscribe 11 items retrieved from queue: psp.out.replicator.example in 262ms avg: 23ms
2019-01-18 10:42:14.232 INFO  - example_subscribe - SubscriberTask - Queue item retrieved in 102ms size: 0
2019-01-18 10:42:14.232 INFO  - example_subscribe - SubscriberTask - example_subscribe 1 items retrieved from queue: psp.out.replicator.example in 102ms avg: 102ms

DB Timing

You will likely see logs like the following for the db_timing. This is showing for that given record the DB IO took 2 ms, with an average of 4 ms so far.
Note: This will only log the DB IO for every 50 records.

2019-01-18 10:44:29.183 INFO  - example_subscribe - SQLCommand - DB IO completed in 2ms - total: 232 avg: 4

Finest Logs

If you enable “FINEST” level of logging you can also drill down into the logs see the time it takes to execute our DB commands. When the Agent receives a message it will

1. Decrypt & Deserialize it

2. Determine & Verify the table schema

3. Query the database to determine if it needs to insert or update

4. Build the statement to send to the database

5. Send the statement to the database

For the most part the longest delays are steps 3 and 5, querying the database and updating the database.

Query

Here is an example of the Agent finishing verifying the Table Schema and querying for whether to do an insert or update:

...
2019-01-08 16:44:33.172 FINEST - example_subscribe - SQLRow - Processing column: "state"
2019-01-08 16:44:33.172 FINEST - example_subscribe - SQLCommand - executeQuery calling build...
2019-01-08 16:44:33.172 FINEST - example_subscribe - StatementBuilder - processing row size: 0
2019-01-08 16:44:33.203 FINE  - example_subscribe - SQLCommand - PreparedStatement results: false closed: false
2019-01-08 16:44:33.203 FINE  - example_subscribe - TableAction - Action: insert
2019-01-08 16:44:33.203 FINE  - example_subscribe - TableAction - Action: insert
2019-01-08 16:44:33.203 FINEST - example_subscribe - StatementBuilder - processing row size: 50
...

At 16:44.33 172 it finished verifying the schema and executed the query. At 16:44:33.203 we got the response from the database. So in this case the database took 31 milliseconds to return this value to us. From this we determined that we have to perform an insert.

Insert/Update

Here is an example of the Agent finishing building the statement to send to the database:

2019-01-08 16:44:33.204 FINE  - example_subscribe - StatementBuilder - Table: "incident" Column: "state" index: 50 type: 2 value: 1
2019-01-08 16:44:33.204 FINEST - example_subscribe - StatementBuilder - SourceColumnName: state ColumnName: "state" SQLType: 4 DBType: 2 column size: 40 table size: 38 value size: 1
2019-01-08 16:44:33.238 FINE  - example_subscribe - SQLCommand - PreparedStatement results: false updateCount: 1 closed: false
2019-01-08 16:44:33.238 FINEST - example_subscribe - MessageBus - recv issued using: Uri: https://example.perspectium.net queue: psp.out.replicator.example

At 16:44.33 204 it finished building the statement and executed the insert. At 16:44:33.238 we got the response from the database. So in this case the database took 34 milliseconds to commit the insert.