User Tools

Site Tools


replicator_agent_timing

Differences

This shows you the differences between two versions of the page.

Link to this comparison view

Both sides previous revision Previous revision
replicator_agent_timing [2019/01/18 10:47]
jackson.davenport create initial page for timing
replicator_agent_timing [2019/01/18 13:37] (current)
jackson.davenport Added finest logging section
Line 61: Line 61:
 ==== DB Timing ==== ==== 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. 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.
 <​code>​ <​code>​
 2019-01-18 10:​44:​29.183 INFO  - example_subscribe - SQLCommand - DB IO completed in 2ms - total: 232 avg: 4 2019-01-18 10:​44:​29.183 INFO  - example_subscribe - SQLCommand - DB IO completed in 2ms - total: 232 avg: 4
 </​code>​ </​code>​
 +
 +==== 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 
 +  - Decrypt & Deserialize it
 +  - Determine & Verify the table schema
 +  - Query the database to determine if it needs to insert or update
 +  - Build the statement to send to the database
 +  - 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:
 +<​code>​
 +...
 +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
 +...
 +</​code>​
 +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:
 +<​code>​
 +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
 +</​code>​
 +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