User Tools

Site Tools


replicator_agent_timing

Replicator Agent Timing

Context

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 MBS (Queue Timing)
  2. How long it takes to both build the statement and send the statement to the database (DB Timing)

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

Implementation

For queue timing add in the tag <queue_timing/> to your task. For database timing add in the tag <db_timing/> to your task.

Example:

<?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_max_column_size>251</database_max_column_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.

replicator_agent_timing.txt · Last modified: 2019/01/18 13:37 by jackson.davenport