Reduce object allocation when using LogLimitedArray
What does this MR do?
This MR estimates the input object size (as JSON) when iterating over the array within Gitlab::Utils::LogLimitedArray rather than calling to_json.
TLDR: Get the estimated size of the JSON object without actually serializing it.
['large', {}, 'object'].to_json.bytesize # 21
# vs
Gitlab::Utils::JsonSizeEstimator.estimate(['large', {}, 'object']) # 21Previous MR where this was originally implemented (split): !25808 (merged)
Performance
Script to compare execution times (within rails root): RAILS_ENV=production rails runner log_perf.rb
Before
normal_api_log_entry 18.199k i/s
large_api_log_entry 437.419 i/s
normal_log_entry 19.673k i/s
large_log_entry 534.500 i/sAllocations for simple log entry, total: 870
filename type count old_count total_age min_age max_age total_memsize
rails/railtie/configuration.rb:92 T_STRING 1 0 0 0 0 0
rails/railtie/configuration.rb:92 T_IMEMO 1 0 0 0 0 0
active_support/ordered_options.rb:42 T_STRING 1 0 0 0 0 0
gitlab/lograge/custom_options.rb:9 T_IMEMO 1 0 0 0 0 0
gitlab/lograge/custom_options.rb:12 T_IMEMO 1 0 0 0 0 0
gitlab/lograge/custom_options.rb:15 T_DATA 1 0 0 0 0 0
time.rb:722 T_STRING 1 0 0 0 0 0
active_support/core_ext/numeric/conversions.rb:108 T_STRING 1 0 0 0 0 0
gitlab/utils/log_limited_array.rb:16 T_IMEMO 1 0 0 0 0 0
active_support/core_ext/object/json.rb:158 T_IMEMO 1 0 0 0 0 0
active_support/json/encoding.rb:57 T_IMEMO 1 0 0 0 0 0
active_support/core_ext/object/json.rb:44 T_IMEMO 1 0 0 0 0 0
gitlab/utils/log_limited_array.rb:15 T_ARRAY 1 0 0 0 0 0
gitlab/lograge/custom_options.rb:14 T_HASH 1 0 0 0 0 0
gitlab/lograge/custom_options.rb:24 T_IMEMO 1 0 0 0 0 0
gitlab/gitaly_client.rb:341 T_ARRAY 1 0 0 0 0 0
labkit/correlation.rb:3 T_IMEMO 1 0 0 0 0 0
labkit/correlation.rb:10 T_MODULE 1 0 0 0 0 0
labkit/correlation.rb:10 T_STRING 1 0 0 0 0 0
labkit/correlation.rb:10 T_IMEMO 1 0 0 0 0 0
labkit/correlation/correlation_id.rb:3 T_IMEMO 1 0 0 0 0 0
labkit/correlation/correlation_id.rb:27 T_IMEMO 1 0 0 0 0 0
labkit/correlation/correlation_id.rb:26 T_MODULE 1 0 0 0 0 0
labkit/correlation/correlation_id.rb:26 T_STRING 1 0 0 0 0 0
labkit/correlation/correlation_id.rb:26 T_IMEMO 1 0 0 0 0 0
labkit/correlation/correlation_id.rb:8 T_FILE 1 0 0 0 0 0
labkit/context.rb:3 T_IMEMO 1 0 0 0 0 0
labkit/context.rb:133 T_STRING 1 0 0 0 0 0
labkit/context.rb:133 T_IMEMO 1 0 0 0 0 0
labkit/context.rb:23 T_ARRAY 1 0 0 0 0 0
labkit/context.rb:24 T_ARRAY 1 0 0 0 0 0
labkit/context.rb:26 T_CLASS 1 0 0 0 0 0
labkit/context.rb:26 T_IMEMO 1 0 0 0 0 0
labkit/context.rb:27 T_IMEMO 1 0 0 0 0 0
labkit/context.rb:37 T_IMEMO 1 0 0 0 0 0
labkit/context.rb:45 T_IMEMO 1 0 0 0 0 0
labkit/context.rb:49 T_IMEMO 1 0 0 0 0 0
labkit/context.rb:53 T_IMEMO 1 0 0 0 0 0
labkit/context.rb:57 T_IMEMO 1 0 0 0 0 0
labkit/context.rb:65 T_IMEMO 1 0 0 0 0 0
labkit/context.rb:74 T_IMEMO 1 0 0 0 0 0
labkit/context.rb:76 T_IMEMO 1 0 0 0 0 0
labkit/context.rb:82 T_IMEMO 1 0 0 0 0 0
labkit/context.rb:89 T_IMEMO 1 0 0 0 0 0
labkit/context.rb:93 T_IMEMO 1 0 0 0 0 0
labkit/context.rb:99 T_IMEMO 1 0 0 0 0 0
labkit/context.rb:117 T_ARRAY 1 0 0 0 0 0
active_support/core_ext/module/delegation.rb:187 T_ARRAY 1 0 0 0 0 0
active_support/core_ext/module/delegation.rb:190 T_STRING 1 0 0 0 0 0
active_support/core_ext/module/delegation.rb:191 T_STRING 1 0 0 0 0 0
active_support/core_ext/module/delegation.rb:193 T_ARRAY 1 0 0 0 0 0
labkit/context.rb:119 T_STRING 1 0 0 0 0 0
labkit/context.rb:119 T_IMEMO 1 0 0 0 0 0
labkit/context.rb:119 T_ARRAY 1 0 0 0 0 0
labkit/context.rb:121 T_IMEMO 1 0 0 0 0 0
labkit/context.rb:132 T_IMEMO 1 0 0 0 0 0
labkit/correlation/correlation_id.rb:25 T_CLASS 1 0 0 0 0 0
labkit/correlation/correlation_id.rb:25 T_IMEMO 1 0 0 0 0 0
labkit/correlation/correlation_id.rb:11 T_IMEMO 1 0 0 0 0 0
labkit/correlation/correlation_id.rb:17 T_IMEMO 1 0 0 0 0 0
labkit/correlation/correlation_id.rb:24 T_IMEMO 1 0 0 0 0 0
labkit/context.rb:72 T_ARRAY 1 0 0 0 0 0
gitlab/request_context.rb:14 T_OBJECT 1 0 0 0 0 0
log_perf.rb:72 T_ARRAY 2 0 0 0 0 0
time.rb:724 T_STRING 2 0 0 0 0 0
gitlab/rugged_instrumentation.rb:18 T_ARRAY 2 0 0 0 0 0
gitlab/lograge/custom_options.rb:28 T_FILE 2 0 0 0 0 0
labkit/correlation.rb:8 T_DATA 2 0 0 0 0 0
labkit/correlation/correlation_id.rb:8 T_HASH 2 0 0 0 0 0
labkit/context.rb:133 T_CLASS 2 0 0 0 0 0
active_support/core_ext/module/delegation.rb:187 T_DATA 2 0 0 0 0 0
active_support/core_ext/module/delegation.rb:219 T_STRING 2 0 0 0 0 0
active_support/core_ext/module/delegation.rb:223 T_STRING 2 0 0 0 0 0
active_support/core_ext/module/delegation.rb:217 T_ARRAY 2 0 0 0 0 0
active_support/core_ext/module/delegation.rb:217 T_STRING 2 0 0 0 0 0
active_support/core_ext/module/delegation.rb:231 T_DATA 2 0 0 0 0 0
active_support/core_ext/module/delegation.rb:231 T_HASH 2 0 0 0 0 0
labkit/context.rb:117 T_IMEMO 2 0 0 0 0 0
gitlab/request_context.rb:14 T_ARRAY 2 0 0 0 0 0
gitlab/lograge/custom_options.rb:12 T_HASH 3 0 0 0 0 0
active_support/json/encoding.rb:22 T_OBJECT 3 0 0 0 0 0
active_support/json/encoding.rb:30 T_HASH 3 0 0 0 0 0
active_support/json/encoding.rb:35 T_HASH 3 0 0 0 0 0
active_support/json/encoding.rb:107 T_HASH 3 0 0 0 0 0
json/common.rb:211 T_DATA 3 0 0 0 0 0
json/common.rb:223 T_STRING 3 0 0 0 0 0
labkit/correlation.rb:6 T_DATA 3 0 0 0 0 0
labkit/correlation/correlation_id.rb:8 T_DATA 3 0 0 0 0 0
active_support/core_ext/object/json.rb:172 T_IMEMO 4 0 0 0 0 0
active_support/json/encoding.rb:96 T_IMEMO 4 0 0 0 0 0
active_support/json/encoding.rb:96 T_HASH 4 0 0 0 0 0
gitlab/lograge/custom_options.rb:28 T_HASH 4 0 0 0 0 0
active_support/core_ext/module/delegation.rb:218 T_STRING 4 0 0 0 0 0
active_support/core_ext/module/delegation.rb:220 T_STRING 4 0 0 0 0 0
active_support/core_ext/module/delegation.rb:222 T_STRING 4 0 0 0 0 0
gitlab/lograge/custom_options.rb:12 T_ARRAY 6 0 0 0 0 0
active_support/core_ext/object/json.rb:172 T_STRING 6 0 0 0 0 0
gitlab/lograge/custom_options.rb:28 T_DATA 6 0 0 0 0 0
active_support/core_ext/module/delegation.rb:215 T_STRING 10 0 0 0 0 0
active_support/core_ext/module/delegation.rb:231 T_STRING 12 0 0 0 0 0
active_support/core_ext/object/json.rb:172 T_ARRAY 13 0 0 0 0 0
active_support/core_ext/object/json.rb:172 T_HASH 13 0 0 0 0 0
active_support/json/encoding.rb:96 T_ARRAY 13 0 0 0 0 0
active_support/json/encoding.rb:92 T_STRING 17 0 0 0 0 0
active_support/json/encoding.rb:58 T_IMEMO 17 0 0 0 0 0
active_support/core_ext/module/delegation.rb:231 T_IMEMO 18 0 0 0 0 0
active_support/core_ext/module/delegation.rb:231 T_ARRAY 18 0 0 0 0 0
json/common.rb:223 T_ARRAY 21 0 0 0 0 0
gitlab/lograge/custom_options.rb:28 T_ARRAY 31 0 0 0 0 0
active_support/core_ext/object/json.rb:39 T_STRING 34 0 0 0 0 0
gitlab/lograge/custom_options.rb:28 T_IMEMO 34 0 0 0 0 0
labkit/correlation/correlation_id.rb:8 T_ARRAY 60 0 0 0 0 0
labkit/correlation/correlation_id.rb:8 T_IMEMO 67 0 0 0 0 0
gitlab/lograge/custom_options.rb:28 T_STRING 123 0 0 0 0 0
labkit/correlation/correlation_id.rb:8 T_STRING 201 0 0 0 0 0
TOTAL 870 0 0 0 0 0
After
About 40% speedup.
normal_api_log_entry 33.117k i/s
large_api_log_entry 660.240 i/s
normal_log_entry 64.949k i/s
large_log_entry 1.142k i/sAllocations for simple log entry, total: 708
rails/railtie/configuration.rb:92 T_STRING 1 0 0 0 0 0
rails/railtie/configuration.rb:92 T_IMEMO 1 0 0 0 0 0
active_support/ordered_options.rb:42 T_STRING 1 0 0 0 0 0
gitlab/lograge/custom_options.rb:9 T_IMEMO 1 0 0 0 0 0
gitlab/lograge/custom_options.rb:12 T_IMEMO 1 0 0 0 0 0
gitlab/lograge/custom_options.rb:15 T_DATA 1 0 0 0 0 0
time.rb:722 T_STRING 1 0 0 0 0 0
active_support/core_ext/numeric/conversions.rb:108 T_STRING 1 0 0 0 0 0
gitlab/utils/log_limited_array.rb:15 T_ARRAY 1 0 0 0 0 0
gitlab/lograge/custom_options.rb:14 T_HASH 1 0 0 0 0 0
gitlab/lograge/custom_options.rb:24 T_IMEMO 1 0 0 0 0 0
gitlab/gitaly_client.rb:341 T_ARRAY 1 0 0 0 0 0
labkit/correlation.rb:3 T_IMEMO 1 0 0 0 0 0
labkit/correlation.rb:10 T_MODULE 1 0 0 0 0 0
labkit/correlation.rb:10 T_STRING 1 0 0 0 0 0
labkit/correlation.rb:10 T_IMEMO 1 0 0 0 0 0
labkit/correlation/correlation_id.rb:3 T_IMEMO 1 0 0 0 0 0
labkit/correlation/correlation_id.rb:27 T_IMEMO 1 0 0 0 0 0
labkit/correlation/correlation_id.rb:26 T_MODULE 1 0 0 0 0 0
labkit/correlation/correlation_id.rb:26 T_STRING 1 0 0 0 0 0
labkit/correlation/correlation_id.rb:26 T_IMEMO 1 0 0 0 0 0
labkit/correlation/correlation_id.rb:8 T_FILE 1 0 0 0 0 0
labkit/context.rb:3 T_IMEMO 1 0 0 0 0 0
labkit/context.rb:133 T_STRING 1 0 0 0 0 0
labkit/context.rb:133 T_IMEMO 1 0 0 0 0 0
labkit/context.rb:23 T_ARRAY 1 0 0 0 0 0
labkit/context.rb:24 T_ARRAY 1 0 0 0 0 0
labkit/context.rb:26 T_CLASS 1 0 0 0 0 0
labkit/context.rb:26 T_IMEMO 1 0 0 0 0 0
labkit/context.rb:27 T_IMEMO 1 0 0 0 0 0
labkit/context.rb:37 T_IMEMO 1 0 0 0 0 0
labkit/context.rb:45 T_IMEMO 1 0 0 0 0 0
labkit/context.rb:49 T_IMEMO 1 0 0 0 0 0
labkit/context.rb:53 T_IMEMO 1 0 0 0 0 0
labkit/context.rb:57 T_IMEMO 1 0 0 0 0 0
labkit/context.rb:65 T_IMEMO 1 0 0 0 0 0
labkit/context.rb:74 T_IMEMO 1 0 0 0 0 0
labkit/context.rb:76 T_IMEMO 1 0 0 0 0 0
labkit/context.rb:82 T_IMEMO 1 0 0 0 0 0
labkit/context.rb:89 T_IMEMO 1 0 0 0 0 0
labkit/context.rb:93 T_IMEMO 1 0 0 0 0 0
labkit/context.rb:99 T_IMEMO 1 0 0 0 0 0
labkit/context.rb:117 T_ARRAY 1 0 0 0 0 0
active_support/core_ext/module/delegation.rb:187 T_ARRAY 1 0 0 0 0 0
active_support/core_ext/module/delegation.rb:190 T_STRING 1 0 0 0 0 0
active_support/core_ext/module/delegation.rb:191 T_STRING 1 0 0 0 0 0
active_support/core_ext/module/delegation.rb:193 T_ARRAY 1 0 0 0 0 0
labkit/context.rb:119 T_STRING 1 0 0 0 0 0
labkit/context.rb:119 T_IMEMO 1 0 0 0 0 0
labkit/context.rb:119 T_ARRAY 1 0 0 0 0 0
labkit/context.rb:121 T_IMEMO 1 0 0 0 0 0
labkit/context.rb:132 T_IMEMO 1 0 0 0 0 0
labkit/correlation/correlation_id.rb:25 T_CLASS 1 0 0 0 0 0
labkit/correlation/correlation_id.rb:25 T_IMEMO 1 0 0 0 0 0
labkit/correlation/correlation_id.rb:11 T_IMEMO 1 0 0 0 0 0
labkit/correlation/correlation_id.rb:17 T_IMEMO 1 0 0 0 0 0
labkit/correlation/correlation_id.rb:24 T_IMEMO 1 0 0 0 0 0
labkit/context.rb:72 T_ARRAY 1 0 0 0 0 0
gitlab/request_context.rb:14 T_OBJECT 1 0 0 0 0 0
log_perf.rb:72 T_ARRAY 2 0 0 0 0 0
time.rb:724 T_STRING 2 0 0 0 0 0
gitlab/rugged_instrumentation.rb:18 T_ARRAY 2 0 0 0 0 0
gitlab/lograge/custom_options.rb:28 T_FILE 2 0 0 0 0 0
labkit/correlation.rb:8 T_DATA 2 0 0 0 0 0
labkit/correlation/correlation_id.rb:8 T_HASH 2 0 0 0 0 0
labkit/context.rb:133 T_CLASS 2 0 0 0 0 0
active_support/core_ext/module/delegation.rb:187 T_DATA 2 0 0 0 0 0
active_support/core_ext/module/delegation.rb:219 T_STRING 2 0 0 0 0 0
active_support/core_ext/module/delegation.rb:223 T_STRING 2 0 0 0 0 0
active_support/core_ext/module/delegation.rb:217 T_ARRAY 2 0 0 0 0 0
active_support/core_ext/module/delegation.rb:217 T_STRING 2 0 0 0 0 0
active_support/core_ext/module/delegation.rb:231 T_DATA 2 0 0 0 0 0
active_support/core_ext/module/delegation.rb:231 T_HASH 2 0 0 0 0 0
labkit/context.rb:117 T_IMEMO 2 0 0 0 0 0
gitlab/request_context.rb:14 T_ARRAY 2 0 0 0 0 0
gitlab/lograge/custom_options.rb:12 T_HASH 3 0 0 0 0 0
labkit/correlation.rb:6 T_DATA 3 0 0 0 0 0
labkit/correlation/correlation_id.rb:8 T_DATA 3 0 0 0 0 0
gitlab/lograge/custom_options.rb:28 T_HASH 4 0 0 0 0 0
active_support/core_ext/module/delegation.rb:218 T_STRING 4 0 0 0 0 0
active_support/core_ext/module/delegation.rb:220 T_STRING 4 0 0 0 0 0
active_support/core_ext/module/delegation.rb:222 T_STRING 4 0 0 0 0 0
gitlab/lograge/custom_options.rb:12 T_ARRAY 6 0 0 0 0 0
gitlab/utils/json_size_estimator.rb:53 T_STRING 6 0 0 0 0 0
gitlab/lograge/custom_options.rb:28 T_DATA 6 0 0 0 0 0
active_support/core_ext/module/delegation.rb:215 T_STRING 10 0 0 0 0 0
active_support/core_ext/module/delegation.rb:231 T_STRING 12 0 0 0 0 0
active_support/core_ext/module/delegation.rb:231 T_IMEMO 18 0 0 0 0 0
active_support/core_ext/module/delegation.rb:231 T_ARRAY 18 0 0 0 0 0
gitlab/lograge/custom_options.rb:28 T_ARRAY 31 0 0 0 0 0
gitlab/lograge/custom_options.rb:28 T_IMEMO 34 0 0 0 0 0
labkit/correlation/correlation_id.rb:8 T_ARRAY 60 0 0 0 0 0
labkit/correlation/correlation_id.rb:8 T_IMEMO 67 0 0 0 0 0
gitlab/lograge/custom_options.rb:28 T_STRING 123 0 0 0 0 0
labkit/correlation/correlation_id.rb:8 T_STRING 201 0 0 0 0 0
TOTAL 708 0 0 0 0 0Does this MR meet the acceptance criteria?
Conformity
-
Changelog entry -
Documentation (if required) -
Code review guidelines -
Merge request performance guidelines -
Style guides -
Database guides -
Separation of EE specific content
Availability and Testing
-
Review and add/update tests for this feature/bug. Consider all test levels. See the Test Planning Process. -
Tested in all supported browsers -
Informed Infrastructure department of a default or new setting change, if applicable per definition of done
Security
If this MR contains changes to processing or storing of credentials or tokens, authorization and authentication methods and other items described in the security review guidelines:
-
Label as security and @ mention @gitlab-com/gl-security/appsec -
The MR includes necessary changes to maintain consistency between UI, API, email, or other methods -
Security reports checked/validated by a reviewer from the AppSec team
Edited by Adam Hegyi