2020-10-30 14:08:56 -04:00
---
stage: none
group: unassigned
2020-11-26 01:09:20 -05:00
info: To determine the technical writer assigned to the Stage/Group associated with this page, see https://about.gitlab.com/handbook/engineering/ux/technical-writing/#assignments
2020-10-30 14:08:56 -04:00
---
2016-04-28 15:44:21 -04:00
# Performance Guidelines
This document describes various guidelines to follow to ensure good and
consistent performance of GitLab.
## Workflow
The process of solving performance problems is roughly as follows:
2020-02-19 22:08:57 -05:00
1. Make sure there's an issue open somewhere (for example, on the GitLab CE issue
2020-05-21 02:08:25 -04:00
tracker), and create one if there is not. See [#15607 ](https://gitlab.com/gitlab-org/gitlab-foss/-/issues/15607 ) for an example.
2018-11-12 19:39:21 -05:00
1. Measure the performance of the code in a production environment such as
2016-04-28 15:44:21 -04:00
GitLab.com (see the [Tooling ](#tooling ) section below). Performance should be
measured over a period of _at least_ 24 hours.
2018-11-12 19:39:21 -05:00
1. Add your findings based on the measurement period (screenshots of graphs,
2016-04-28 15:44:21 -04:00
timings, etc) to the issue mentioned in step 1.
2018-11-12 19:39:21 -05:00
1. Solve the problem.
2020-02-19 22:08:57 -05:00
1. Create a merge request, assign the "Performance" label and follow the [performance review process ](merge_request_performance_guidelines.md ).
2018-11-12 19:39:21 -05:00
1. Once a change has been deployed make sure to _again_ measure for at least 24
2016-04-28 15:44:21 -04:00
hours to see if your changes have any impact on the production environment.
2018-11-12 19:39:21 -05:00
1. Repeat until you're done.
2016-04-28 15:44:21 -04:00
When providing timings make sure to provide:
2018-11-13 01:07:16 -05:00
- The 95th percentile
- The 99th percentile
- The mean
2016-04-28 15:44:21 -04:00
2016-05-03 13:46:14 -04:00
When providing screenshots of graphs, make sure that both the X and Y axes and
2016-04-28 15:44:21 -04:00
the legend are clearly visible. If you happen to have access to GitLab.com's own
monitoring tools you should also provide a link to any relevant
graphs/dashboards.
## Tooling
2018-11-06 08:21:04 -05:00
GitLab provides built-in tools to help improve performance and availability:
2016-04-28 15:44:21 -04:00
2018-11-13 01:07:16 -05:00
- [Profiling ](profiling.md ).
2019-02-27 19:21:37 -05:00
- [Distributed Tracing ](distributed_tracing.md )
2018-11-13 01:07:16 -05:00
- [GitLab Performance Monitoring ](../administration/monitoring/performance/index.md ).
- [Request Profiling ](../administration/monitoring/performance/request_profiling.md ).
- [QueryRecoder ](query_recorder.md ) for preventing `N+1` regressions.
- [Chaos endpoints ](chaos_endpoints.md ) for testing failure scenarios. Intended mainly for testing availability.
2020-06-02 17:08:00 -04:00
- [Service measurement ](service_measurement.md ) for measuring and logging service execution.
2016-04-28 15:44:21 -04:00
2020-02-19 22:08:57 -05:00
GitLab team members can use [GitLab.com's performance monitoring systems ](https://about.gitlab.com/handbook/engineering/monitoring/ ) located at
2021-02-03 16:09:17 -05:00
[`dashboards.gitlab.net` ](https://dashboards.gitlab.net ), this requires you to log in using your
2020-02-19 22:08:57 -05:00
`@gitlab.com` email address. Non-GitLab team-members are advised to set up their
2020-05-13 17:08:55 -04:00
own Prometheus and Grafana stack.
2016-04-28 15:44:21 -04:00
## Benchmarks
Benchmarks are almost always useless. Benchmarks usually only test small bits of
code in isolation and often only measure the best case scenario. On top of that,
2020-02-19 22:08:57 -05:00
benchmarks for libraries (such as a Gem) tend to be biased in favour of the
2016-04-28 15:44:21 -04:00
library. After all there's little benefit to an author publishing a benchmark
that shows they perform worse than their competitors.
Benchmarks are only really useful when you need a rough (emphasis on "rough")
understanding of the impact of your changes. For example, if a certain method is
slow a benchmark can be used to see if the changes you're making have any impact
on the method's performance. However, even when a benchmark shows your changes
improve performance there's no guarantee the performance also improves in a
production environment.
When writing benchmarks you should almost always use
[benchmark-ips ](https://github.com/evanphx/benchmark-ips ). Ruby's `Benchmark`
module that comes with the standard library is rarely useful as it runs either a
single iteration (when using `Benchmark.bm` ) or two iterations (when using
2020-02-19 22:08:57 -05:00
`Benchmark.bmbm` ). Running this few iterations means external factors, such as a
video streaming in the background, can very easily skew the benchmark
2016-04-28 15:44:21 -04:00
statistics.
Another problem with the `Benchmark` module is that it displays timings, not
iterations. This means that if a piece of code completes in a very short period
of time it can be very difficult to compare the timings before and after a
certain change. This in turn leads to patterns such as the following:
```ruby
Benchmark.bmbm(10) do |bench|
bench.report 'do something' do
100.times do
... work here ...
end
end
end
```
This however leads to the question: how many iterations should we run to get
meaningful statistics?
The benchmark-ips Gem basically takes care of all this and much more, and as a
result of this should be used instead of the `Benchmark` module.
In short:
2018-11-12 19:39:21 -05:00
- Don't trust benchmarks you find on the internet.
- Never make claims based on just benchmarks, always measure in production to
2016-04-28 15:44:21 -04:00
confirm your findings.
2018-11-12 19:39:21 -05:00
- X being N times faster than Y is meaningless if you don't know what impact it
2020-12-10 16:10:15 -05:00
has on your production environment.
2018-11-12 19:39:21 -05:00
- A production environment is the _only_ benchmark that always tells the truth
2016-04-28 15:44:21 -04:00
(unless your performance monitoring systems are not set up correctly).
2018-11-12 19:39:21 -05:00
- If you must write a benchmark use the benchmark-ips Gem instead of Ruby's
2016-04-28 15:44:21 -04:00
`Benchmark` module.
2016-11-04 07:43:02 -04:00
## Profiling
By collecting snapshots of process state at regular intervals, profiling allows
2020-07-14 02:09:17 -04:00
you to see where time is spent in a process. The
[Stackprof ](https://github.com/tmm1/stackprof ) gem is included in GitLab,
allowing you to profile which code is running on CPU in detail.
2016-11-04 07:43:02 -04:00
2020-07-14 02:09:17 -04:00
It's important to note that profiling an application *alters its performance* .
Different profiling strategies have different overheads. Stackprof is a sampling
2020-12-10 16:10:15 -05:00
profiler. It samples stack traces from running threads at a configurable
2021-07-19 14:08:23 -04:00
frequency (for example, 100hz, that is 100 stacks per second). This type of profiling
2020-07-14 02:09:17 -04:00
has quite a low (albeit non-zero) overhead and is generally considered to be
safe for production.
### Development
A profiler can be a very useful tool during development, even if it does run *in
an unrepresentative environment*. In particular, a method is not necessarily
troublesome just because it's executed many times, or takes a long time to
execute. Profiles are tools you can use to better understand what is happening
in an application - using that information wisely is up to you!
2016-11-04 07:43:02 -04:00
Keeping that in mind, to create a profile, identify (or create) a spec that
exercises the troublesome code path, then run it using the `bin/rspec-stackprof`
2020-02-19 22:08:57 -05:00
helper, for example:
2016-11-04 07:43:02 -04:00
2020-01-30 10:09:15 -05:00
```shell
2016-11-04 07:43:02 -04:00
$ LIMIT=10 bin/rspec-stackprof spec/policies/project_policy_spec.rb
2020-02-19 22:08:57 -05:00
2016-11-04 07:43:02 -04:00
8/8 |====== 100 ======>| Time: 00:00:18
Finished in 18.19 seconds (files took 4.8 seconds to load)
8 examples, 0 failures
==================================
Mode: wall(1000)
Samples: 17033 (5.59% miss rate)
GC: 1901 (11.16%)
==================================
TOTAL (pct) SAMPLES (pct) FRAME
6000 (35.2%) 2566 (15.1%) Sprockets::Cache::FileStore#get
2018 (11.8%) 888 (5.2%) ActiveRecord::ConnectionAdapters::PostgreSQLAdapter#exec_no_cache
1338 (7.9%) 640 (3.8%) ActiveRecord::ConnectionAdapters::PostgreSQL::DatabaseStatements#execute
3125 (18.3%) 394 (2.3%) Sprockets::Cache::FileStore#safe_open
913 (5.4%) 301 (1.8%) ActiveRecord::ConnectionAdapters::PostgreSQLAdapter#exec_cache
288 (1.7%) 288 (1.7%) ActiveRecord::Attribute#initialize
246 (1.4%) 246 (1.4%) Sprockets::Cache::FileStore#safe_stat
295 (1.7%) 193 (1.1%) block (2 levels) in class_attribute
187 (1.1%) 187 (1.1%) block (4 levels) in class_attribute
```
You can limit the specs that are run by passing any arguments `rspec` would
normally take.
The output is sorted by the `Samples` column by default. This is the number of
samples taken where the method is the one currently being executed. The `Total`
column shows the number of samples taken where the method, or any of the methods
it calls, were being executed.
To create a graphical view of the call stack:
2020-01-30 10:09:15 -05:00
```shell
2019-09-10 06:15:43 -04:00
stackprof tmp/project_policy_spec.rb.dump --graphviz > project_policy_spec.dot
dot -Tsvg project_policy_spec.dot > project_policy_spec.svg
2016-11-04 07:43:02 -04:00
```
2021-02-03 16:09:17 -05:00
To load the profile in [KCachegrind ](https://kcachegrind.github.io/ ):
2016-11-04 07:43:02 -04:00
2020-01-30 10:09:15 -05:00
```shell
2020-07-15 08:09:26 -04:00
stackprof tmp/project_policy_spec.rb.dump --callgrind > project_policy_spec.callgrind
2019-09-10 06:15:43 -04:00
kcachegrind project_policy_spec.callgrind # Linux
qcachegrind project_policy_spec.callgrind # Mac
2016-11-04 07:43:02 -04:00
```
2021-02-03 16:09:17 -05:00
For flame graphs, enable raw collection first. Note that raw
2020-07-15 08:09:26 -04:00
collection can generate a very large file, so increase the `INTERVAL` , or
run on a smaller number of specs for smaller file size:
```shell
RAW=true bin/rspec-stackprof spec/policies/group_member_policy_spec.rb
```
2021-02-03 16:09:17 -05:00
You can then generate, and view the resultant flame graph. It might take a
2020-07-15 08:09:26 -04:00
while to generate based on the output file size:
```shell
# Generate
stackprof --flamegraph tmp/group_member_policy_spec.rb.dump > group_member_policy_spec.flame
# View
stackprof --flamegraph-viewer=group_member_policy_spec.flame
```
2020-02-19 22:08:57 -05:00
It may be useful to zoom in on a specific method, for example:
2016-11-04 07:43:02 -04:00
2020-01-30 10:09:15 -05:00
```shell
2016-11-04 07:43:02 -04:00
$ stackprof tmp/project_policy_spec.rb.dump --method warm_asset_cache
2020-02-19 22:08:57 -05:00
2016-11-04 07:43:02 -04:00
TestEnv#warm_asset_cache (/Users/lupine/dev/gitlab.com/gitlab-org/gitlab-development-kit/gitlab/spec/support/test_env.rb:164)
samples: 0 self (0.0%) / 6288 total (36.9%)
callers:
6288 ( 100.0%) block (2 levels) in < top ( required ) >
callees (6288 total):
6288 ( 100.0%) Capybara::RackTest::Driver#visit
code:
| 164 | def warm_asset_cache
| 165 | return if warm_asset_cache?
| 166 | return unless defined?(Capybara)
| 167 |
6288 (36.9%) | 168 | Capybara.current_session.driver.visit '/'
| 169 | end
$ stackprof tmp/project_policy_spec.rb.dump --method BasePolicy#abilities
BasePolicy#abilities (/Users/lupine/dev/gitlab.com/gitlab-org/gitlab-development-kit/gitlab/app/policies/base_policy.rb:79)
samples: 0 self (0.0%) / 50 total (0.3%)
callers:
25 ( 50.0%) BasePolicy.abilities
25 ( 50.0%) BasePolicy#collect_rules
callees (50 total):
25 ( 50.0%) ProjectPolicy#rules
25 ( 50.0%) BasePolicy#collect_rules
code:
| 79 | def abilities
| 80 | return RuleSet.empty if @user && @user .blocked?
| 81 | return anonymous_abilities if @user .nil?
50 (0.3%) | 82 | collect_rules { rules }
| 83 | end
```
Since the profile includes the work done by the test suite as well as the
application code, these profiles can be used to investigate slow tests as well.
However, for smaller runs (like this example), this means that the cost of
2020-12-10 16:10:15 -05:00
setting up the test suite tends to dominate.
2016-11-04 07:43:02 -04:00
2020-07-14 02:09:17 -04:00
### Production
Stackprof can also be used to profile production workloads.
In order to enable production profiling for Ruby processes, you can set the `STACKPROF_ENABLED` environment variable to `true` .
The following configuration options can be configured:
2021-02-03 16:09:17 -05:00
- `STACKPROF_ENABLED` : Enables Stackprof signal handler on SIGUSR2 signal.
2020-07-14 02:09:17 -04:00
Defaults to `false` .
2020-10-19 11:08:58 -04:00
- `STACKPROF_MODE` : See [sampling modes ](https://github.com/tmm1/stackprof#sampling ).
Defaults to `cpu` .
- `STACKPROF_INTERVAL` : Sampling interval. Unit semantics depend on `STACKPROF_MODE` .
2021-02-18 19:11:06 -05:00
For `object` mode this is a per-event interval (every `nth` event is sampled)
2021-04-20 14:09:37 -04:00
and defaults to `100` .
For other modes such as `cpu` this is a frequency interval and defaults to `10100` μs (99hz).
2020-07-14 02:09:17 -04:00
- `STACKPROF_FILE_PREFIX` : File path prefix where profiles are stored. Defaults
to `$TMPDIR` (often corresponds to `/tmp` ).
- `STACKPROF_TIMEOUT_S` : Profiling timeout in seconds. Profiling will
automatically stop after this time has elapsed. Defaults to `30` .
- `STACKPROF_RAW` : Whether to collect raw samples or only aggregates. Raw
2021-02-03 16:09:17 -05:00
samples are needed to generate flame graphs, but they do have a higher memory
2020-07-14 02:09:17 -04:00
and disk overhead. Defaults to `true` .
Once enabled, profiling can be triggered by sending a `SIGUSR2` signal to the
2020-12-10 16:10:15 -05:00
Ruby process. The process begins sampling stacks. Profiling can be stopped
by sending another `SIGUSR2` . Alternatively, it stops automatically after
2020-07-14 02:09:17 -04:00
the timeout.
Once profiling stops, the profile is written out to disk at
`$STACKPROF_FILE_PREFIX/stackprof.$PID.$RAND.profile` . It can then be inspected
further via the `stackprof` command line tool, as described in the previous
section.
Currently supported profiling targets are:
- Puma worker
- Sidekiq
2020-12-04 16:09:29 -05:00
NOTE:
2021-06-03 08:10:18 -04:00
The Puma master process is not supported.
Sending SIGUSR2 to it triggers restarts. In the case of Puma,
2020-07-14 02:09:17 -04:00
take care to only send the signal to Puma workers.
2021-02-03 16:09:17 -05:00
This can be done via `pkill -USR2 puma:` . The `:` distinguishes between `puma
2020-07-14 02:09:17 -04:00
4.3.3.gitlab.2 ...` (the master process) from `puma: cluster worker 0: ...` (the
worker processes), selecting the latter.
2020-07-30 11:09:40 -04:00
For Sidekiq, the signal can be sent to the `sidekiq-cluster` process via `pkill
2020-12-10 16:10:15 -05:00
-USR2 bin/sidekiq-cluster`, which forwards the signal to all Sidekiq
2021-02-18 19:11:06 -05:00
children. Alternatively, you can also select a specific PID of interest.
2020-07-30 11:09:40 -04:00
2020-07-14 02:09:17 -04:00
Production profiles can be especially noisy. It can be helpful to visualize them
2021-02-03 16:09:17 -05:00
as a [flame graph ](https://github.com/brendangregg/FlameGraph ). This can be done
2020-07-14 02:09:17 -04:00
via:
```shell
bundle exec stackprof --stackcollapse /tmp/stackprof.55769.c6c3906452.profile | flamegraph.pl > flamegraph.svg
```
2016-11-04 07:43:02 -04:00
2017-01-26 16:31:43 -05:00
## RSpec profiling
2020-12-16 19:09:53 -05:00
The GitLab development environment also includes the
2021-02-18 19:11:06 -05:00
[`rspec_profiling` ](https://github.com/foraker/rspec_profiling ) gem, which is used
2017-01-26 16:31:43 -05:00
to collect data on spec execution times. This is useful for analyzing the
performance of the test suite itself, or seeing how the performance of a spec
may have changed over time.
To activate profiling in your local environment, run the following:
2020-01-30 10:09:15 -05:00
```shell
2019-09-10 06:15:43 -04:00
export RSPEC_PROFILING=yes
rake rspec_profiling:install
2017-01-26 16:31:43 -05:00
```
This creates an SQLite3 database in `tmp/rspec_profiling` , into which statistics
are saved every time you run specs with the `RSPEC_PROFILING` environment
variable set.
Ad-hoc investigation of the collected results can be performed in an interactive
shell:
2020-01-30 10:09:15 -05:00
```shell
2017-01-26 16:31:43 -05:00
$ rake rspec_profiling:console
2020-02-19 22:08:57 -05:00
2017-01-26 16:31:43 -05:00
irb(main):001:0> results.count
=> 231
irb(main):002:0> results.last.attributes.keys
=> ["id", "commit", "date", "file", "line_number", "description", "time", "status", "exception", "query_count", "query_time", "request_count", "request_time", "created_at", "updated_at"]
irb(main):003:0> results.where(status: "passed").average(:time).to_s
=> "0.211340155844156"
```
2019-07-12 04:09:23 -04:00
2017-01-26 16:31:43 -05:00
These results can also be placed into a PostgreSQL database by setting the
`RSPEC_PROFILING_POSTGRES_URL` variable. This is used to profile the test suite
when running in the CI environment.
2020-11-02 13:09:03 -05:00
We store these results also when running nightly scheduled CI jobs on the
default branch on `gitlab.com` . Statistics of these profiling data are
[available online ](https://gitlab-org.gitlab.io/rspec_profiling_stats/ ). For
example, you can find which tests take longest to run or which execute the most
2020-07-06 17:08:51 -04:00
queries. This can be handy for optimizing our tests or identifying performance
issues in our code.
2021-03-10 13:09:32 -05:00
## Memory optimization
2019-09-24 11:06:34 -04:00
2021-03-10 13:09:32 -05:00
We can use a set of different techniques, often in combination, to track down memory issues:
2020-11-16 13:09:15 -05:00
- Leaving the code intact and wrapping a profiler around it.
2021-03-10 13:09:32 -05:00
- Use memory allocation counters for requests and services.
2020-11-16 13:09:15 -05:00
- Monitor memory usage of the process while disabling/enabling different parts of the code we suspect could be problematic.
2021-03-10 13:09:32 -05:00
### Memory allocations
Ruby shipped with GitLab includes a special patch to allow [tracing memory allocations ](https://gitlab.com/gitlab-org/gitlab/-/issues/296530 ).
This patch is available by default for
[Omnibus ](https://gitlab.com/gitlab-org/omnibus-gitlab/-/merge_requests/4948 ),
[CNG ](https://gitlab.com/gitlab-org/build/CNG/-/merge_requests/591 ),
[GitLab CI ](https://gitlab.com/gitlab-org/gitlab-build-images/-/merge_requests/355 ),
[GCK ](https://gitlab.com/gitlab-org/gitlab-compose-kit/-/merge_requests/149 )
2021-04-26 17:10:25 -04:00
and can additionally be enabled for [GDK ](https://gitlab.com/gitlab-org/gitlab-development-kit/-/blob/main/doc/advanced.md#apply-custom-patches-for-ruby ).
2021-03-10 13:09:32 -05:00
2021-05-19 02:10:37 -04:00
This patch provides the following metrics that make it easier to understand efficiency of memory use for a given codepath:
2021-03-10 13:09:32 -05:00
2021-05-19 02:10:37 -04:00
- `mem_total_bytes` : the number of bytes consumed both due to new objects being allocated into existing object slots
plus additional memory allocated for large objects (that is, `mem_bytes + slot_size * mem_objects` ).
- `mem_bytes` : the number of bytes allocated by `malloc` for objects that did not fit into an existing object slot.
2021-03-10 13:09:32 -05:00
- `mem_objects` : the number of objects allocated.
2021-05-19 02:10:37 -04:00
- `mem_mallocs` : the number of `malloc` calls.
2021-03-10 13:09:32 -05:00
The number of objects and bytes allocated impact how often GC cycles happen.
2021-05-19 02:10:37 -04:00
Fewer object allocations result in a significantly more responsive application.
2021-03-10 13:09:32 -05:00
It is advised that web server requests do not allocate more than `100k mem_objects`
and `100M mem_bytes` . You can view the current usage on [GitLab.com ](https://log.gprd.gitlab.net/goto/3a9678bb595e3f89a0c7b5c61bcc47b9 ).
#### Checking memory pressure of own code
There are two ways of measuring your own code:
1. Review `api_json.log` , `development_json.log` , `sidekiq.log` that includes memory allocation counters.
1. Use `Gitlab::Memory::Instrumentation.with_memory_allocations` for a given codeblock and log it.
1. Use [Measuring module ](service_measurement.md )
```json
{"time":"2021-02-15T11:20:40.821Z","severity":"INFO","duration_s":0.27412,"db_duration_s":0.05755,"view_duration_s":0.21657,"status":201,"method":"POST","path":"/api/v4/projects/user/1","mem_objects":86705,"mem_bytes":4277179,"mem_mallocs":22693,"correlation_id":"...}
```
#### Different types of allocations
The `mem_*` values represent different aspects of how objects and memory are allocated in Ruby:
- The following example will create around of `1000` of `mem_objects` since strings
can be frozen, and while the underlying string object remains the same, we still need to allocate 1000 references to this string:
```ruby
Gitlab::Memory::Instrumentation.with_memory_allocations do
1_000.times { '0123456789' }
end
=> {:mem_objects=>1001, :mem_bytes=>0, :mem_mallocs=>0}
```
- The following example will create around of `1000` of `mem_objects` , as strings are created dynamically.
Each of them will not allocate additional memory, as they fit into Ruby slot of 40 bytes:
```ruby
Gitlab::Memory::Instrumentation.with_memory_allocations do
s = '0'
1_000.times { s * 23 }
end
=> {:mem_objects=>1002, :mem_bytes=>0, :mem_mallocs=>0}
```
- The following example will create around of `1000` of `mem_objects` , as strings are created dynamically.
Each of them will allocate additional memory as strings are larger than Ruby slot of 40 bytes:
```ruby
Gitlab::Memory::Instrumentation.with_memory_allocations do
s = '0'
1_000.times { s * 24 }
end
=> {:mem_objects=>1002, :mem_bytes=>32000, :mem_mallocs=>1000}
```
- The following example will allocate over 40kB of data, and perform only a single memory allocation.
The existing object will be reallocated/resized on subsequent iterations:
```ruby
Gitlab::Memory::Instrumentation.with_memory_allocations do
str = ''
append = '0123456789012345678901234567890123456789' # 40 bytes
1_000.times { str.concat(append) }
end
=> {:mem_objects=>3, :mem_bytes=>49152, :mem_mallocs=>1}
```
- The following example will create over 1k of objects, perform over 1k of allocations, each time mutating the object.
This does result in copying a lot of data and perform a lot of memory allocations
(as represented by `mem_bytes` counter) indicating very inefficient method of appending string:
```ruby
Gitlab::Memory::Instrumentation.with_memory_allocations do
str = ''
append = '0123456789012345678901234567890123456789' # 40 bytes
1_000.times { str += append }
end
=> {:mem_objects=>1003, :mem_bytes=>21968752, :mem_mallocs=>1000}
```
2020-11-16 13:09:15 -05:00
### Using Memory Profiler
We can use `memory_profiler` for profiling.
2020-12-16 19:09:53 -05:00
The [`memory_profiler` ](https://github.com/SamSaffron/memory_profiler ) gem is already present in the GitLab `Gemfile` ,
2020-11-16 13:09:15 -05:00
you just need to require it:
```ruby
require 'sidekiq/testing'
report = MemoryProfiler.report do
# Code you want to profile
end
output = File.open('/tmp/profile.txt','w')
report.pretty_print(output)
```
The report breaks down 2 key concepts:
- Retained: long lived memory use and object count retained due to the execution of the code block.
- Allocated: all object allocation and memory allocation during code block.
2020-12-10 16:10:15 -05:00
As a general rule, **retained** is always smaller than or equal to **allocated** .
2020-11-16 13:09:15 -05:00
2020-12-10 16:10:15 -05:00
The actual RSS cost is always slightly higher as MRI heaps are not squashed to size and memory fragments.
2020-11-16 13:09:15 -05:00
### Rbtrace
2019-09-24 11:06:34 -04:00
One of the reasons of the increased memory footprint could be Ruby memory fragmentation.
To diagnose it, you can visualize Ruby heap as described in [this post by Aaron Patterson ](https://tenderlovemaking.com/2017/09/27/visualizing-your-ruby-heap.html ).
2020-03-02 04:07:59 -05:00
To start, you want to dump the heap of the process you're investigating to a JSON file.
2019-09-24 11:06:34 -04:00
2020-03-02 04:07:59 -05:00
You need to run the command inside the process you're exploring, you may do that with `rbtrace` .
`rbtrace` is already present in GitLab `Gemfile` , you just need to require it.
2019-09-24 11:06:34 -04:00
It could be achieved running webserver or Sidekiq with the environment variable set to `ENABLE_RBTRACE=1` .
To get the heap dump:
```ruby
bundle exec rbtrace -p < PID > -e 'File.open("heap.json", "wb") { |t| ObjectSpace.dump_all(output: t) }'
```
Having the JSON, you finally could render a picture using the script [provided by Aaron ](https://gist.github.com/tenderlove/f28373d56fdd03d8b514af7191611b88 ) or similar:
2020-01-30 10:09:15 -05:00
```shell
2019-09-24 11:06:34 -04:00
ruby heapviz.rb heap.json
```
2020-02-19 22:08:57 -05:00
2019-09-24 11:06:34 -04:00
Fragmented Ruby heap snapshot could look like this:
![Ruby heap fragmentation ](img/memory_ruby_heap_fragmentation.png )
2021-02-18 19:11:06 -05:00
Memory fragmentation could be reduced by tuning GC parameters [as described in this post ](https://www.speedshop.co/2017/12/04/malloc-doubles-ruby-memory.html ). This should be considered as a tradeoff, as it may affect overall performance of memory allocation and GC cycles.
2019-09-24 11:06:34 -04:00
2016-04-28 15:44:21 -04:00
## Importance of Changes
2016-05-03 13:46:14 -04:00
When working on performance improvements, it's important to always ask yourself
2016-04-28 15:44:21 -04:00
the question "How important is it to improve the performance of this piece of
code?". Not every piece of code is equally important and it would be a waste to
spend a week trying to improve something that only impacts a tiny fraction of
our users. For example, spending a week trying to squeeze 10 milliseconds out of
a method is a waste of time when you could have spent a week squeezing out 10
seconds elsewhere.
There is no clear set of steps that you can follow to determine if a certain
piece of code is worth optimizing. The only two things you can do are:
1. Think about what the code does, how it's used, how many times it's called and
2020-02-19 22:08:57 -05:00
how much time is spent in it relative to the total execution time (for example, the
2016-04-28 15:44:21 -04:00
total time spent in a web request).
2019-07-18 22:20:32 -04:00
1. Ask others (preferably in the form of an issue).
2016-04-28 15:44:21 -04:00
2020-02-19 22:08:57 -05:00
Some examples of changes that are not really important/worth the effort:
2016-04-28 15:44:21 -04:00
2018-11-13 01:07:16 -05:00
- Replacing double quotes with single quotes.
- Replacing usage of Array with Set when the list of values is very small.
- Replacing library A with library B when both only take up 0.1% of the total
2016-04-28 15:44:21 -04:00
execution time.
2018-11-13 01:07:16 -05:00
- Calling `freeze` on every string (see [String Freezing ](#string-freezing )).
2016-04-28 15:44:21 -04:00
## Slow Operations & Sidekiq
2020-02-19 22:08:57 -05:00
Slow operations, like merging branches, or operations that are prone to errors
2016-04-28 15:44:21 -04:00
(using external APIs) should be performed in a Sidekiq worker instead of
directly in a web request as much as possible. This has numerous benefits such
as:
2020-12-10 16:10:15 -05:00
1. An error doesn't prevent the request from completing.
1. The process being slow doesn't affect the loading time of a page.
1. In case of a failure you can retry the process (Sidekiq takes care of
2016-04-28 15:44:21 -04:00
this automatically).
2020-12-10 16:10:15 -05:00
1. By isolating the code from a web request it should be easier to test
2016-04-28 15:44:21 -04:00
and maintain.
It's especially important to use Sidekiq as much as possible when dealing with
Git operations as these operations can take quite some time to complete
depending on the performance of the underlying storage system.
## Git Operations
Care should be taken to not run unnecessary Git operations. For example,
retrieving the list of branch names using `Repository#branch_names` can be done
without an explicit check if a repository exists or not. In other words, instead
of this:
```ruby
if repository.exists?
repository.branch_names.each do |name|
...
end
end
```
2016-05-03 13:46:14 -04:00
You can just write:
2016-04-28 15:44:21 -04:00
```ruby
repository.branch_names.each do |name|
...
end
```
## Caching
2020-12-10 16:10:15 -05:00
Operations that often return the same result should be cached using Redis,
2016-05-03 13:46:14 -04:00
in particular Git operations. When caching data in Redis, make sure the cache is
2016-04-28 15:44:21 -04:00
flushed whenever needed. For example, a cache for the list of tags should be
flushed whenever a new tag is pushed or a tag is removed.
2016-05-03 13:46:14 -04:00
When adding cache expiration code for repositories, this code should be placed
in one of the before/after hooks residing in the Repository class. For example,
if a cache should be flushed after importing a repository this code should be
added to `Repository#after_import` . This ensures the cache logic stays within
the Repository class instead of leaking into other classes.
2016-04-28 15:44:21 -04:00
2016-05-03 13:46:14 -04:00
When caching data, make sure to also memoize the result in an instance variable.
While retrieving data from Redis is much faster than raw Git operations, it still
has overhead. By caching the result in an instance variable, repeated calls to
2020-12-10 16:10:15 -05:00
the same method don't retrieve data from Redis upon every call. When
2016-05-03 13:46:14 -04:00
memoizing cached data in an instance variable, make sure to also reset the
2016-04-28 15:44:21 -04:00
instance variable when flushing the cache. An example:
```ruby
def first_branch
@first_branch ||= cache.fetch(:first_branch) { branches.first }
end
def expire_first_branch_cache
cache.expire(:first_branch)
@first_branch = nil
end
```
2018-08-01 15:56:53 -04:00
## String Freezing
2016-04-28 15:44:21 -04:00
In recent Ruby versions calling `freeze` on a String leads to it being allocated
2020-12-10 16:10:15 -05:00
only once and re-used. For example, on Ruby 2.3 or later this only allocates the
2016-04-28 15:44:21 -04:00
"foo" String once:
```ruby
10.times do
'foo'.freeze
end
```
2018-08-01 15:56:53 -04:00
Depending on the size of the String and how frequently it would be allocated
(before the `.freeze` call was added), this _may_ make things faster, but
2020-12-10 16:10:15 -05:00
this isn't guaranteed.
2018-08-01 15:56:53 -04:00
2020-12-10 16:10:15 -05:00
Strings are frozen by default in Ruby 3.0. To prepare our codebase for
this eventuality, we are adding the following header to all Ruby files:
2018-08-01 15:56:53 -04:00
```ruby
# frozen_string_literal: true
```
This may cause test failures in the code that expects to be able to manipulate
strings. Instead of using `dup` , use the unary plus to get an unfrozen string:
```ruby
test = +"hello"
test += " world"
```
2018-09-29 18:25:28 -04:00
When adding new Ruby files, please check that you can add the above header,
as omitting it may lead to style check failures.
2021-01-26 10:08:58 -05:00
## Banzai pipelines and filters
When writing or updating [Banzai filters and pipelines ](https://gitlab.com/gitlab-org/gitlab/-/tree/master/lib/banzai ),
it can be difficult to understand what the performance of the filter is, and what effect it might
have on the overall pipeline performance.
To perform benchmarks run:
```shell
bin/rake benchmark:banzai
```
This command generates output like this:
```plaintext
--> Benchmarking Full, Wiki, and Plain pipelines
Calculating -------------------------------------
Full pipeline 1.000 i/100ms
Wiki pipeline 1.000 i/100ms
Plain pipeline 1.000 i/100ms
-------------------------------------------------
Full pipeline 3.357 (±29.8%) i/s - 31.000
Wiki pipeline 2.893 (±34.6%) i/s - 25.000 in 10.677014s
Plain pipeline 15.447 (±32.4%) i/s - 119.000
Comparison:
Plain pipeline: 15.4 i/s
Full pipeline: 3.4 i/s - 4.60x slower
Wiki pipeline: 2.9 i/s - 5.34x slower
.
--> Benchmarking FullPipeline filters
Calculating -------------------------------------
Markdown 24.000 i/100ms
Plantuml 8.000 i/100ms
SpacedLink 22.000 i/100ms
...
TaskList 49.000 i/100ms
InlineDiff 9.000 i/100ms
SetDirection 369.000 i/100ms
-------------------------------------------------
Markdown 237.796 (±16.4%) i/s - 2.304k
Plantuml 80.415 (±36.1%) i/s - 520.000
SpacedLink 168.188 (±10.1%) i/s - 1.672k
...
TaskList 101.145 (± 6.9%) i/s - 1.029k
InlineDiff 52.925 (±15.1%) i/s - 522.000
SetDirection 3.728k (±17.2%) i/s - 34.317k in 10.617882s
Comparison:
Suggestion: 739616.9 i/s
Kroki: 306449.0 i/s - 2.41x slower
InlineGrafanaMetrics: 156535.6 i/s - 4.72x slower
SetDirection: 3728.3 i/s - 198.38x slower
...
UserReference: 2.1 i/s - 360365.80x slower
ExternalLink: 1.6 i/s - 470400.67x slower
ProjectReference: 0.7 i/s - 1128756.09x slower
.
--> Benchmarking PlainMarkdownPipeline filters
Calculating -------------------------------------
Markdown 19.000 i/100ms
-------------------------------------------------
Markdown 241.476 (±15.3%) i/s - 2.356k
```
This can give you an idea how various filters perform, and which ones might be performing the slowest.
The test data has a lot to do with how well a filter performs. If there is nothing in the test data
that specifically triggers the filter, it might look like it's running incredibly fast.
Make sure that you have relevant test data for your filter in the
[`spec/fixtures/markdown.md.erb` ](https://gitlab.com/gitlab-org/gitlab/-/blob/master/spec/fixtures/markdown.md.erb )
file.
2020-03-25 17:08:06 -04:00
## Reading from files and other data sources
Ruby offers several convenience functions that deal with file contents specifically
or I/O streams in general. Functions such as `IO.read` and `IO.readlines` make
it easy to read data into memory, but they can be inefficient when the
data grows large. Because these functions read the entire contents of a data
2020-12-10 16:10:15 -05:00
source into memory, memory use grows by _at least_ the size of the data source.
In the case of `readlines` , it grows even further, due to extra bookkeeping
2020-03-25 17:08:06 -04:00
the Ruby VM has to perform to represent each line.
Consider the following program, which reads a text file that is 750MB on disk:
```ruby
File.readlines('large_file.txt').each do |line|
puts line
end
```
Here is a process memory reading from while the program was running, showing
how we indeed kept the entire file in memory (RSS reported in kilobytes):
```shell
$ ps -o rss -p < pid >
RSS
783436
```
And here is an excerpt of what the garbage collector was doing:
```ruby
pp GC.stat
{
:heap_live_slots=>2346848,
:malloc_increase_bytes=>30895288,
...
}
```
We can see that `heap_live_slots` (the number of reachable objects) jumped to ~2.3M,
which is roughly two orders of magnitude more compared to reading the file line by
line instead. It was not just the raw memory usage that increased, but also how the garbage collector (GC)
responded to this change in anticipation of future memory use. We can see that `malloc_increase_bytes` jumped
to ~30MB, which compares to just ~4kB for a "fresh" Ruby program. This figure specifies how
2020-12-10 16:10:15 -05:00
much additional heap space the Ruby GC claims from the operating system next time it runs out of memory.
2020-03-25 17:08:06 -04:00
Not only did we occupy more memory, we also changed the behavior of the application
to increase memory use at a faster rate.
2020-12-10 16:10:15 -05:00
The `IO.read` function exhibits similar behavior, with the difference that no extra memory is
allocated for each line object.
2020-03-25 17:08:06 -04:00
### Recommendations
Instead of reading data sources into memory in full, it is better to read them line by line
instead. This is not always an option, for instance when you need to convert a YAML file
into a Ruby `Hash` , but whenever you have data where each row represents some entity that
can be processed and then discarded, you can use the following approaches.
First, replace calls to `readlines.each` with either `each` or `each_line` .
The `each_line` and `each` functions read the data source line by line without keeping
already visited lines in memory:
```ruby
File.new('file').each { |line| puts line }
```
Alternatively, you can read individual lines explicitly using `IO.readline` or `IO.gets` functions:
```ruby
while line = file.readline
# process line
end
```
This might be preferable if there is a condition that allows exiting the loop early, saving not
just memory but also unnecessary time spent in CPU and I/O for processing lines you're not interested in.
2018-08-01 15:56:53 -04:00
## Anti-Patterns
2016-04-28 15:44:21 -04:00
2020-04-15 11:09:17 -04:00
This is a collection of [anti-patterns ](https://en.wikipedia.org/wiki/Anti-pattern ) that should be avoided
2020-02-19 22:08:57 -05:00
unless these changes have a measurable, significant, and positive impact on
2018-08-01 15:56:53 -04:00
production environments.
2016-04-28 15:44:21 -04:00
2018-08-01 15:56:53 -04:00
### Moving Allocations to Constants
Storing an object as a constant so you only allocate it once _may_ improve
2020-12-10 16:10:15 -05:00
performance, but this is not guaranteed. Looking up constants has an
2018-08-01 15:56:53 -04:00
impact on runtime performance, and as such, using a constant instead of
referencing an object directly may even slow code down. For example:
2016-04-28 15:44:21 -04:00
```ruby
SOME_CONSTANT = 'foo'.freeze
9000.times do
SOME_CONSTANT
end
```
The only reason you should be doing this is to prevent somebody from mutating
the global String. However, since you can just re-assign constants in Ruby
there's nothing stopping somebody from doing this elsewhere in the code:
```ruby
SOME_CONSTANT = 'bar'
```
2019-02-20 15:08:03 -05:00
## How to seed a database with millions of rows
You might want millions of project rows in your local database, for example,
in order to compare relative query performance, or to reproduce a bug. You could
2020-03-13 14:09:39 -04:00
do this by hand with SQL commands or using [Mass Inserting Rails
Models](mass_insert.md) functionality.
2019-02-20 15:08:03 -05:00
2020-03-13 14:09:39 -04:00
Assuming you are working with ActiveRecord models, you might also find these links helpful:
- [Insert records in batches ](insert_into_tables_in_batches.md )
2019-02-20 15:08:03 -05:00
- [BulkInsert gem ](https://github.com/jamis/bulk_insert )
- [ActiveRecord::PgGenerateSeries gem ](https://github.com/ryu39/active_record-pg_generate_series )
### Examples
2021-02-03 16:09:17 -05:00
You may find some useful examples in [this snippet ](https://gitlab.com/gitlab-org/gitlab-foss/snippets/33946 ).