Skip to content

Add max transaction duration to logs

Sylvester Chin requested to merge sc1-add-max-txn-duration into master

What does this MR do and why?

This MR adds db_xxx_txn_max_duration_s keys to the logs to further support our investigation for an appropriate txn duration threshold.

See gitlab-com/gl-infra/scalability#2860 (closed)

MR acceptance checklist

Please evaluate this MR against the MR acceptance checklist. It helps you analyze changes to reduce risks in quality, performance, reliability, security, and maintainability.

Screenshots or screen recordings

Screenshots are required for UI changes, and strongly recommended for all other merge requests.

Before After

How to set up and validate locally

On rails console:

  1. Initialise the store
[1] pry(main)> Gitlab::SafeRequestStore.begin!
=> true
[2] pry(main)> ::Gitlab::Metrics::Subscribers::ActiveRecord.db_counter_payload
  1. Verify that max transaction duration is recorded
[3] pry(main)> ::Gitlab::Metrics::Subscribers::ActiveRecord.db_counter_payload[:db_main_txn_max_duration_s]
=> 0.0
[4] pry(main)> ::Gitlab::Metrics::Subscribers::ActiveRecord.db_counter_payload[:db_main_txn_duration_s]
=> 0.0
[5] pry(main)> ApplicationRecord.transaction { User.first; sleep 2; User.first; User.first }
  TRANSACTION (0.1ms)  BEGIN /*application:console,db_config_name:main,console_hostname:SylvestersMBP2.localdomain,console_username:sylvesterchin,line:/lib/gitlab/database/schema_cache_with_renamed_table_legacy.rb:23:in `primary_keys'*/
  User Load (3.9ms)  SELECT "users".* FROM "users" ORDER BY "users"."id" ASC LIMIT 1 /*application:console,db_config_name:main,console_hostname:SylvestersMBP2.localdomain,console_username:sylvesterchin,line:(pry):5:in `block in __pry__'*/
  User Load (1.7ms)  SELECT "users".* FROM "users" ORDER BY "users"."id" ASC LIMIT 1 /*application:console,db_config_name:main,console_hostname:SylvestersMBP2.localdomain,console_username:sylvesterchin,line:(pry):5:in `block in __pry__'*/
  User Load (1.0ms)  SELECT "users".* FROM "users" ORDER BY "users"."id" ASC LIMIT 1 /*application:console,db_config_name:main,console_hostname:SylvestersMBP2.localdomain,console_username:sylvesterchin,line:(pry):5:in `block in __pry__'*/
  TRANSACTION (1.0ms)  COMMIT /*application:console,db_config_name:main,console_hostname:SylvestersMBP2.localdomain,console_username:sylvesterchin,line:/lib/gitlab/database.rb:392:in `commit'*/
=> #<User id:1 @root>
[6] pry(main)> ::Gitlab::Metrics::Subscribers::ActiveRecord.db_counter_payload[:db_main_txn_max_duration_s]
=> 2.115
[7] pry(main)> ::Gitlab::Metrics::Subscribers::ActiveRecord.db_counter_payload[:db_main_txn_duration_s]
=> 2.115
[8] pry(main)> ApplicationRecord.transaction { User.first; sleep 4; User.first; User.first }
  TRANSACTION (0.6ms)  BEGIN /*application:console,db_config_name:main,console_hostname:SylvestersMBP2.localdomain,console_username:sylvesterchin,line:(pry):8:in `block in __pry__'*/
  User Load (1.6ms)  SELECT "users".* FROM "users" ORDER BY "users"."id" ASC LIMIT 1 /*application:console,db_config_name:main,console_hostname:SylvestersMBP2.localdomain,console_username:sylvesterchin,line:(pry):8:in `block in __pry__'*/
  User Load (2.2ms)  SELECT "users".* FROM "users" ORDER BY "users"."id" ASC LIMIT 1 /*application:console,db_config_name:main,console_hostname:SylvestersMBP2.localdomain,console_username:sylvesterchin,line:(pry):8:in `block in __pry__'*/
  User Load (1.6ms)  SELECT "users".* FROM "users" ORDER BY "users"."id" ASC LIMIT 1 /*application:console,db_config_name:main,console_hostname:SylvestersMBP2.localdomain,console_username:sylvesterchin,line:(pry):8:in `block in __pry__'*/
  TRANSACTION (1.1ms)  COMMIT /*application:console,db_config_name:main,console_hostname:SylvestersMBP2.localdomain,console_username:sylvesterchin,line:/lib/gitlab/database.rb:392:in `commit'*/
=> #<User id:1 @root>
[9] pry(main)> ::Gitlab::Metrics::Subscribers::ActiveRecord.db_counter_payload[:db_main_txn_max_duration_s]
=> 4.027
[10] pry(main)> ::Gitlab::Metrics::Subscribers::ActiveRecord.db_counter_payload[:db_main_txn_duration_s]
=> 6.142
Edited by Sylvester Chin

Merge request reports