Generating Usage Statistics timing out on queries to ci_builds
Summary
Users are getting timeout errors when trying to generate JSON UsageData
to populate the Usage Statistics page.
When triggering the ping refresh via the Rails console, we can see that several COUNT
queries are made to the ci_builds
table, taking anywhere from a couple of seconds to several minutes:
(56457.5ms) SELECT COUNT(DISTINCT "ci_builds"."user_id") FROM "ci_builds" WHERE "ci_builds"."type" = 'Ci::Build' AND "ci_builds"."user_id" >= 1 AND "ci_builds"."user_id" < 3659
The actual row count doesn't seem too impressive to justify the problem:
gitlabhq_production=# SELECT COUNT(DISTINCT "ci_builds"."user_id") FROM "ci_builds" WHERE "ci_builds"."type" = 'Ci::Build';
count
-------
1471
(1 row)
Steps to reproduce
Unsure yet what the necessary elements are to trigger the issue.
Example Project
TBD
What is the current bug behavior?
The URL https://gitlab.xxxxx/admin/application_settings/usage_data.json fails, throwing a 502
error.
- The UI Request: Admin / Settings / Metrics and profiling / Usage statistics / "Preview payload" returns "Error fetching payload data. "
Running the command via Rails console eventually works, but can take several hours.
What is the expected correct behavior?
These queues should be optimized to run faster -- usage ping generation should not time out.
Relevant logs and/or screenshots
Rack::Timeout::RequestTimeoutException stacktrace
Rack::Timeout::RequestTimeoutException (Request ran for longer than 60000ms): lib/gitlab/database/batch_count.rb:95:in `count' lib/gitlab/database/batch_count.rb:29:in `batch_count' lib/gitlab/utils/usage_data.rb:48:in `count' lib/gitlab/usage_data.rb:95:in `system_usage_data' ee/lib/ee/gitlab/usage_data.rb:190:in `system_usage_data' lib/gitlab/usage_data.rb:50:in `block in uncached_data' lib/gitlab/utils/usage_data.rb:123:in `with_finished_at' lib/gitlab/usage_data.rb:46:in `uncached_data' ee/lib/ee/gitlab/usage_data.rb:64:in `block in uncached_data' lib/gitlab/utils/usage_data.rb:123:in `with_finished_at' ee/lib/ee/gitlab/usage_data.rb:63:in `uncached_data' lib/gitlab/usage_data.rb:39:in `block in data' lib/gitlab/usage_data.rb:38:in `data' app/controllers/admin/application_settings_controller.rb:66:in `block (2 levels) in usage_data' app/controllers/admin/application_settings_controller.rb:64:in `usage_data' ee/lib/gitlab/ip_address_state.rb:10:in `with' ee/app/controllers/ee/application_controller.rb:44:in `set_current_ip_address' app/controllers/application_controller.rb:482:in `set_current_admin' lib/gitlab/session.rb:11:in `with_session' app/controllers/application_controller.rb:473:in `set_session_storage' lib/gitlab/i18n.rb:73:in `with_locale' lib/gitlab/i18n.rb:79:in `with_user_locale' app/controllers/application_controller.rb:467:in `set_locale' lib/gitlab/error_tracking.rb:52:in `with_context' app/controllers/application_controller.rb:532:in `sentry_context' app/controllers/application_controller.rb:460:in `block in set_current_context' lib/gitlab/application_context.rb:56:in `block in use' lib/gitlab/application_context.rb:56:in `use' lib/gitlab/application_context.rb:22:in `with_context' app/controllers/application_controller.rb:451:in `set_current_context' lib/gitlab/metrics/elasticsearch_rack_middleware.rb:16:in `call' lib/gitlab/middleware/rails_queue_duration.rb:33:in `call' lib/gitlab/metrics/rack_middleware.rb:16:in `block in call' lib/gitlab/metrics/transaction.rb:56:in `run' lib/gitlab/metrics/rack_middleware.rb:16:in `call' lib/gitlab/request_profiler/middleware.rb:17:in `call' lib/gitlab/jira/middleware.rb:19:in `call' lib/gitlab/middleware/go.rb:20:in `call' lib/gitlab/etag_caching/middleware.rb:21:in `call' lib/gitlab/middleware/multipart.rb:172:in `call' lib/gitlab/middleware/read_only/controller.rb:50:in `call' lib/gitlab/middleware/read_only.rb:18:in `call' lib/gitlab/middleware/same_site_cookies.rb:27:in `call' lib/gitlab/middleware/handle_malformed_strings.rb:21:in `call' lib/gitlab/middleware/basic_health_check.rb:25:in `call' lib/gitlab/middleware/handle_ip_spoof_attack_error.rb:25:in `call' lib/gitlab/middleware/request_context.rb:21:in `call' config/initializers/fix_local_cache_middleware.rb:11:in `call' lib/gitlab/metrics/requests_rack_middleware.rb:76:in `call' lib/gitlab/middleware/release_env.rb:12:in `call' ack::Timeout::RequestTimeoutException (Request ran for longer than 60000ms): lib/gitlab/database/batch_count.rb:95:in `count' lib/gitlab/database/batch_count.rb:29:in `batch_count' lib/gitlab/utils/usage_data.rb:48:in `count' lib/gitlab/usage_data.rb:95:in `system_usage_data' ee/lib/ee/gitlab/usage_data.rb:190:in `system_usage_data' lib/gitlab/usage_data.rb:50:in `block in uncached_data' lib/gitlab/utils/usage_data.rb:123:in `with_finished_at' lib/gitlab/usage_data.rb:46:in `uncached_data' ee/lib/ee/gitlab/usage_data.rb:64:in `block in uncached_data' lib/gitlab/utils/usage_data.rb:123:in `with_finished_at' ee/lib/ee/gitlab/usage_data.rb:63:in `uncached_data' lib/gitlab/usage_data.rb:39:in `block in data' lib/gitlab/usage_data.rb:38:in `data' app/controllers/admin/application_settings_controller.rb:66:in `block (2 levels) in usage_data' app/controllers/admin/application_settings_controller.rb:64:in `usage_data' ee/lib/gitlab/ip_address_state.rb:10:in `with' ee/app/controllers/ee/application_controller.rb:44:in `set_current_ip_address' app/controllers/application_controller.rb:482:in `set_current_admin' lib/gitlab/session.rb:11:in `with_session' app/controllers/application_controller.rb:473:in `set_session_storage' lib/gitlab/i18n.rb:73:in `with_locale' lib/gitlab/i18n.rb:79:in `with_user_locale' app/controllers/application_controller.rb:467:in `set_locale' lib/gitlab/error_tracking.rb:52:in `with_context' app/controllers/application_controller.rb:532:in `sentry_context' app/controllers/application_controller.rb:460:in `block in set_current_context' lib/gitlab/application_context.rb:56:in `block in use' lib/gitlab/application_context.rb:56:in `use' lib/gitlab/application_context.rb:22:in `with_context'
Results of GitLab environment info
Reported on GitLab Versions 13.9 and 13.11.
Possible fixes
Running the equivalent request via Rails circumvents the timeout issue and allows the ping to be generated, if the command is allowed to run for sufficient time:
# Start a rails console session
sudo gitlab-rails console
# Enable debug logging
Rails.logger.level = Logger::DEBUG
# Generate the cached usage ping
Gitlab::UsageData.to_json
# Generate a fresh new usage ping
Gitlab::UsageData.to_json(force_refresh: true)
One possibility is that the query mentioned above is not using an index to execute.