This reduces the overhead of the method instrumentation code primarily
by reducing the number of method calls. There are also some other small
optimisations such as not casting timing values to Floats (there's no
particular need for this), using Symbols for method call metric names,
and reducing the number of Hash lookups for instrumented methods.
The exact impact depends on the code being executed. For example, for a
method that's only called once the difference won't be very noticeable.
However, for methods that are called many times the difference can be
more significant.
For example, the loading time of a large commit
(nrclark/dummy_project@81ebdea5df)
was reduced from around 19 seconds to around 15 seconds using these
changes.
Process.clock_gettime allows getting the real time in nanoseconds as
well as allowing one to get a monotonic timestamp. This offers greater
accuracy without the overhead of having to allocate a Time instance. In
general using Time.now/Time.new is about 2x slower than using
Process.clock_gettime(). For example:
require 'benchmark/ips'
Benchmark.ips do |bench|
bench.report 'Time.now' do
Time.now.to_f
end
bench.report 'clock_gettime' do
Process.clock_gettime(Process::CLOCK_MONOTONIC, :millisecond)
end
bench.compare!
end
Running this benchmark gives:
Calculating -------------------------------------
Time.now 108.052k i/100ms
clock_gettime 125.984k i/100ms
-------------------------------------------------
Time.now 2.343M (± 7.1%) i/s - 11.670M
clock_gettime 4.979M (± 0.8%) i/s - 24.945M
Comparison:
clock_gettime: 4979393.8 i/s
Time.now: 2342986.8 i/s - 2.13x slower
Another benefit of using Process.clock_gettime() is that we can simplify
the code a bit since it can give timestamps in nanoseconds out of the
box.
This makes it easier to query, simplifies the code, and makes it
possible to figure out what transaction the data belongs to (simply
because it's now stored _in_ the transaction).
This new setup keeps track of both the real/wall time _and_ CPU time
spent in a block, both measured using milliseconds (to keep all units
the same).
This adds the ability to write application metrics (e.g. SQL timings) to
InfluxDB. These metrics can in turn be visualized using Grafana, or
really anything else that can read from InfluxDB. These metrics can be
used to track application performance over time, between different Ruby
versions, different GitLab versions, etc.
== Transaction Metrics
Currently the following is tracked on a per transaction basis (a
transaction is a Rails request or a single Sidekiq job):
* Timings per query along with the raw (obfuscated) SQL and information
about what file the query originated from.
* Timings per view along with the path of the view and information about
what file triggered the rendering process.
* The duration of a request itself along with the controller/worker
class and method name.
* The duration of any instrumented method calls (more below).
== Sampled Metrics
Certain metrics can't be directly associated with a transaction. For
example, a process' total memory usage is unrelated to any running
transactions. While a transaction can result in the memory usage going
up there's no accurate way to determine what transaction is to blame,
this becomes especially problematic in multi-threaded environments.
To solve this problem there's a separate thread that takes samples at a
fixed interval. This thread (using the class Gitlab::Metrics::Sampler)
currently tracks the following:
* The process' total memory usage.
* The number of file descriptors opened by the process.
* The amount of Ruby objects (using ObjectSpace.count_objects).
* GC statistics such as timings, heap slots, etc.
The default/current interval is 15 seconds, any smaller interval might
put too much pressure on InfluxDB (especially when running dozens of
processes).
== Method Instrumentation
While currently not yet used methods can be instrumented to track how
long they take to run. Unlike the likes of New Relic this doesn't
require modifying the source code (e.g. including modules), it all
happens from the outside. For example, to track `User.by_login` we'd add
the following code somewhere in an initializer:
Gitlab::Metrics::Instrumentation.
instrument_method(User, :by_login)
to instead instrument an instance method:
Gitlab::Metrics::Instrumentation.
instrument_instance_method(User, :save)
Instrumentation for either all public model methods or a few crucial
ones will be added in the near future, I simply haven't gotten to doing
so just yet.
== Configuration
By default metrics are disabled. This means users don't have to bother
setting anything up if they don't want to. Metrics can be enabled by
editing one's gitlab.yml configuration file (see
config/gitlab.yml.example for example settings).
== Writing Data To InfluxDB
Because InfluxDB is still a fairly young product I expect the worse.
Data loss, unexpected reboots, the database not responding, you name it.
Because of this data is _not_ written to InfluxDB directly, instead it's
queued and processed by Sidekiq. This ensures that users won't notice
anything when InfluxDB is giving trouble.
The metrics worker can be started in a standalone manner as following:
bundle exec sidekiq -q metrics
The corresponding class is called MetricsWorker.
