Potential N+1 problem with ProcessBookkeepingService
Summary
During one of the recent incidents I believe I saw a namespace
N+1 and it took 92 seconds to process 1,000 items.
Steps to reproduce
No steps to reproduce yet, this will be a part of this issue.
What is the current bug behavior?
N+1 namespace queries
What is the expected correct behavior?
No N+1
Relevant logs and/or screenshots
Click to expand
D, [2023-09-21T06:50:41.658759 #2345327] DEBUG -- : Namespace Load (31.3ms) /*application:console,db_config_name:main_replica,console_hostname:console-01-sv-gprd,console_username:dgruzd-rails*/ SELECT "namespaces".* FROM "namespaces" WHERE "namespaces"."id" = 12104923 LIMIT 1
D, [2023-09-21T06:50:41.853604 #2345327] DEBUG -- : Namespace Load (31.4ms) /*application:console,db_config_name:main_replica,console_hostname:console-01-sv-gprd,console_username:dgruzd-rails*/ SELECT "namespaces".* FROM "namespaces" WHERE "namespaces"."id" = 11507242 LIMIT 1
D, [2023-09-21T06:50:42.205035 #2345327] DEBUG -- : Namespace Load (31.9ms) /*application:console,db_config_name:main_replica,console_hostname:console-01-sv-gprd,console_username:dgruzd-rails*/ SELECT "namespaces".* FROM "namespaces" WHERE "namespaces"."id" = 2628690 LIMIT 1
D, [2023-09-21T06:50:43.548729 #2345327] DEBUG -- : Namespace Load (31.4ms) /*application:console,db_config_name:main_replica,console_hostname:console-01-sv-gprd,console_username:dgruzd-rails*/ SELECT "namespaces".* FROM "namespaces" WHERE "namespaces"."id" = 5593806 LIMIT 1
D, [2023-09-21T06:50:43.733235 #2345327] DEBUG -- : Namespace Load (31.3ms) /*application:console,db_config_name:main_replica,console_hostname:console-01-sv-gprd,console_username:dgruzd-rails*/ SELECT "namespaces".* FROM "namespaces" WHERE "namespaces"."id" = 8378208 LIMIT 1
D, [2023-09-21T06:50:44.233472 #2345327] DEBUG -- : Namespace Load (31.4ms) /*application:console,db_config_name:main_replica,console_hostname:console-01-sv-gprd,console_username:dgruzd-rails*/ SELECT "namespaces".* FROM "namespaces" WHERE "namespaces"."id" = 51132717 LIMIT 1
D, [2023-09-21T06:50:45.211051 #2345327] DEBUG -- : Namespace Load (31.3ms) /*application:console,db_config_name:main_replica,console_hostname:console-01-sv-gprd,console_username:dgruzd-rails*/ SELECT "namespaces".* FROM "namespaces" WHERE "namespaces"."id" = 7661896 LIMIT 1
D, [2023-09-21T06:50:46.646714 #2345327] DEBUG -- : Namespace Load (30.8ms) /*application:console,db_config_name:main_replica,console_hostname:console-01-sv-gprd,console_username:dgruzd-rails*/ SELECT "namespaces".* FROM "namespaces" WHERE "namespaces"."id" = 59335707 LIMIT 1
D, [2023-09-21T06:50:46.896378 #2345327] DEBUG -- : Namespace Load (31.4ms) /*application:console,db_config_name:main_replica,console_hostname:console-01-sv-gprd,console_username:dgruzd-rails*/ SELECT "namespaces".* FROM "namespaces" WHERE "namespaces"."id" = 5665906 LIMIT 1
D, [2023-09-21T06:50:47.483144 #2345327] DEBUG -- : Namespace Load (31.5ms) /*application:console,db_config_name:main_replica,console_hostname:console-01-sv-gprd,console_username:dgruzd-rails*/ SELECT "namespaces".* FROM "namespaces" WHERE "namespaces"."id" = 13551551 LIMIT 1
D, [2023-09-21T06:50:48.247690 #2345327] DEBUG -- : Namespace Load (31.5ms) /*application:console,db_config_name:main_replica,console_hostname:console-01-sv-gprd,console_username:dgruzd-rails*/ SELECT "namespaces".* FROM "namespaces" WHERE "namespaces"."id" = 2938994 LIMIT 1
D, [2023-09-21T06:50:48.443566 #2345327] DEBUG -- : Namespace Load (31.1ms) /*application:console,db_config_name:main_replica,console_hostname:console-01-sv-gprd,console_username:dgruzd-rails*/ SELECT "namespaces".* FROM "namespaces" WHERE "namespaces"."id" = 818930 LIMIT 1
D, [2023-09-21T06:50:49.058088 #2345327] DEBUG -- : Namespace Load (31.2ms) /*application:console,db_config_name:main_replica,console_hostname:console-01-sv-gprd,console_username:dgruzd-rails*/ SELECT "namespaces".* FROM "namespaces" WHERE "namespaces"."id" = 6052424 LIMIT 1
D, [2023-09-21T06:50:49.522966 #2345327] DEBUG -- : Namespace Load (30.9ms) /*application:console,db_config_name:main_replica,console_hostname:console-01-sv-gprd,console_username:dgruzd-rails*/ SELECT "namespaces".* FROM "namespaces" WHERE "namespaces"."id" = 9694743 LIMIT 1
D, [2023-09-21T06:50:49.639623 #2345327] DEBUG -- : Namespace Load (31.2ms) /*application:console,db_config_name:main_replica,console_hostname:console-01-sv-gprd,console_username:dgruzd-rails*/ SELECT "namespaces".* FROM "namespaces" WHERE "namespaces"."id" = 5132456 LIMIT 1
D, [2023-09-21T06:50:49.819053 #2345327] DEBUG -- : Namespace Load (31.4ms) /*application:console,db_config_name:main_replica,console_hostname:console-01-sv-gprd,console_username:dgruzd-rails*/ SELECT "namespaces".* FROM "namespaces" WHERE "namespaces"."id" = 2116722 LIMIT 1
D, [2023-09-21T06:50:49.957073 #2345327] DEBUG -- : Namespace Load (31.5ms) /*application:console,db_config_name:main_replica,console_hostname:console-01-sv-gprd,console_username:dgruzd-rails*/ SELECT "namespaces".* FROM "namespaces" WHERE "namespaces"."id" = 5339817 LIMIT 1
D, [2023-09-21T06:50:50.649831 #2345327] DEBUG -- : Namespace Load (31.4ms) /*application:console,db_config_name:main_replica,console_hostname:console-01-sv-gprd,console_username:dgruzd-rails*/ SELECT "namespaces".* FROM "namespaces" WHERE "namespaces"."id" = 7939362 LIMIT 1
D, [2023-09-21T06:50:51.534617 #2345327] DEBUG -- : Namespace Load (30.8ms) /*application:console,db_config_name:main_replica,console_hostname:console-01-sv-gprd,console_username:dgruzd-rails*/ SELECT "namespaces".* FROM "namespaces" WHERE "namespaces"."id" = 13546012 LIMIT 1
D, [2023-09-21T06:50:51.816583 #2345327] DEBUG -- : Namespace Load (31.4ms) /*application:console,db_config_name:main_replica,console_hostname:console-01-sv-gprd,console_username:dgruzd-rails*/ SELECT "namespaces".* FROM "namespaces" WHERE "namespaces"."id" = 61377359 LIMIT 1
D, [2023-09-21T06:50:51.960637 #2345327] DEBUG -- : Namespace Load (31.4ms) /*application:console,db_config_name:main_replica,console_hostname:console-01-sv-gprd,console_username:dgruzd-rails*/ SELECT "namespaces".* FROM "namespaces" WHERE "namespaces"."id" = 12104923 LIMIT 1
D, [2023-09-21T06:50:54.307282 #2345327] DEBUG -- : Namespace Load (31.3ms) /*application:console,db_config_name:main_replica,console_hostname:console-01-sv-gprd,console_username:dgruzd-rails*/ SELECT "namespaces".* FROM "namespaces" WHERE "namespaces"."id" = 11990236 LIMIT 1
D, [2023-09-21T06:50:55.362536 #2345327] DEBUG -- : Namespace Load (31.2ms) /*application:console,db_config_name:main_replica,console_hostname:console-01-sv-gprd,console_username:dgruzd-rails*/ SELECT "namespaces".* FROM "namespaces" WHERE "namespaces"."id" = 51132717 LIMIT 1
D, [2023-09-21T06:50:57.743611 #2345327] DEBUG -- : Namespace Load (30.9ms) /*application:console,db_config_name:main_replica,console_hostname:console-01-sv-gprd,console_username:dgruzd-rails*/ SELECT "namespaces".* FROM "namespaces" WHERE "namespaces"."id" = 16128699 LIMIT 1
D, [2023-09-21T06:50:59.480611 #2345327] DEBUG -- : Namespace Load (31.5ms) /*application:console,db_config_name:main_replica,console_hostname:console-01-sv-gprd,console_username:dgruzd-rails*/ SELECT "namespaces".* FROM "namespaces" WHERE "namespaces"."id" = 5086770 LIMIT 1
Possible fixes
Apart from fixing the N+1, we might want to introduce some kind of logger/watcher to dynamically detect these issues on production.