Notifications

385 views

Symptoms


Intermittently, incorrect value is being populated on metric_instance record.

For example, lets say we have a "metric_definition" defined for "Assignment Group" field on incident table.

As per this "metric_definition", when there is a change with the "Assignment Group" field on an incident record, system should create a new "metric_instance" record with the new value of "Assignment Group" field.

When the "Assignment Group" value is changed from "Group A" to "Group B", the newly created "metric_instance" record should have value as "Group B". However, intermittently, "metric_instance" record created with old value "Group A" instead of "Group B".

This article will brief on the possible reason for this incorrect behavior of the system.

Release


Any supported release.

Cause


Cause 1: "metric events" before insert/update business rule is not executing as the last one before committing DB update

The out of the box provided "metric events" before insert/update business rule is set to run just before the database insert/update is being made on task record. This is done via setting the order as "10,000".

However, if there are any other custom before insert/update business rule set up on task table with order as "10,000" or higher and if that takes longer time to execute ( for example longer than 3 seconds), the metric records would have been created before the actual insert/update are being fired on database level. 

Hence, the newly created metric instance record would have incorrect value. For example, "Group A" instead of "Group B".

Cause 2: Delay with the DB update due to DB performance issue

Ideally DB updates on task table would be completed in milli seconds and hence there will not be much time difference between the metric events business rule invoked (metric instance creation time) and actual DB update, it will be almost same time. Thus the metric instance record would be populated with the latest value which was committed to DB.

However, there are situations, where the DB update might take longer time to complete the update as shown below,

2018-09-10 11:12:28 (745) http-15 New transaction 70A77BC09860238018D4CB465AF2BA7F #12482810 /incident.do

2018-09-10 11:12:28 (752) Default-thread-113 70A77BC09860238018D4CB465AF2BA7F #12482810 /incident.do Parameters -------------------------

 ...

    activity_filter.cmdb_ci=

    sys_action=next_state_qualified

    sys_display.u_change_ticketing.u_template=

    activity_filter.u_third_party_caller=

   ..

2018-09-10 11:12:28 (752) Default-thread-113 70A77BC09860238018D4CB465AF2BA7F *** Start  #12482810 /incident.do, user: <user id>

2018-09-10 11:12:29 (694) http-42 New transaction 70A77BC09860238018D4CB465AF2BA7F #12482818 /xmlhttp.do

 

2018-09-10 11:12:43 (884) http-26 70A77BC09860238018D4CB465AF2BA7F /cancel_my_transaction.do -- transaction time: 0:00:00.000

 

2018-09-10 11:12:45 (773) http-44 70A77BC09860238018D4CB465AF2BA7F /cancel_my_transaction.do -- transaction time: 0:00:00.000

 

2018-09-10 11:12:47 (898) http-32 70A77BC09860238018D4CB465AF2BA7F /cancel_my_transaction.do -- transaction time: 0:00:00.000

 

2018-09-10 11:12:49 (987) http-30 70A77BC09860238018D4CB465AF2BA7F /cancel_my_transaction.do -- transaction time: 0:00:00.000

 

2018-09-10 11:12:52 (109) http-10 70A77BC09860238018D4CB465AF2BA7F /cancel_my_transaction.do -- transaction time: 0:00:00.000

 

2018-09-10 11:12:54 (207) http-2 70A77BC09860238018D4CB465AF2BA7F /cancel_my_transaction.do -- transaction time: 0:00:00.000

 

2018-09-10 11:12:54 (350) Default-thread-113 70A77BC09860238018D4CB465AF2BA7F Time: 0:00:25.425 id: sndb[glide.0] for: UPDATE task  SET `sys_updated_by` = '<user id>', `a_flt_3` = 0.5, `sys_mod_count` = 8, `a_flt_1` = 0.5, `sys_updated_on` = '2018-09-10 09:12:28', `state` = -9, `a_ref_6` = '<sys id of reference field>', `topic` = '0.50', `reject_handling` = '0.50', `a_ref_7` = '<sys id of reference field>' WHERE task.`sys_id` = '<sys id of task record>' 
 
You can see in the above logs that DB update took 25.425 seconds, during that time, possibly metrics instance records would be created, it will not wait for the update to complete. Hence, in such situations, metric instance record would be created with wrong value.

Resolution


Make sure the "Metrics event" business rule is the last before insert/update business rule to run just before firing insert/update on database level.

This can be achieved via setting highest order to "Metrics event" business rule than any other "before insert/update business rule" on task table.

If you are running into the issue, due to DB performance issue, please align with service now performance / DBA to identify the cause of performance issue and fix it.

Additional Information


Metrics

Metrics instance

Business rules

Execution order of scripts and engines

Article Information

Last Updated:2018-09-13 02:56:05
Published:2018-09-13