Add max transaction duration to logs
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:
- Initialise the store
[1] pry(main)> Gitlab::SafeRequestStore.begin!
=> true
[2] pry(main)> ::Gitlab::Metrics::Subscribers::ActiveRecord.db_counter_payload
- 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