Add Prometheus timers to the subsystems

[coriolinus]

This should assist in determining where the subsystems spend their time, which should help isolate performance issues.

Note: all these timers are cumulative timers: they include time spent in other parts of the stack. They observe automatically on drop.

Timers are implemented for:

• availability_distribution
• availability_store
• bitfield_distribution
• bitfield_signing
• candidate_backing
• candidate_selection
• candidate_validation
• chain_api
• collation_generation
• collator_protocol
• network_bridge Does not have any existing metrics; presumed to be uninteresting.
• pov_distribution
• provisioner
• runtime_api
• statement_distribution

TODO:

• Run a local net with a few nodes; collect up the statistics in local grafana; demo the output

[bkchr]

AFAIK prometheus is not really done for performance metrics?

https://github.com/tokio-rs/tracing probably is something that is better suited for this?

[coriolinus]

I see prometheus and tracing as answering different questions. Prometheus answers the question, "What is taking a while"; it lets us collect aggregated statistics about the performance characteristics of our async functions. Tracing answers the question, "What is the sequence of events that is happening"?

Both can be useful--in particular, tracing is a lot less worried about data cardinality, and so encourages us to tag events by i.e. the relay parent hash to which they're attached--but given that we already have prometheus set up and integrated, I'm going to to finish this up, then work on tracing as a separate task.

[coriolinus]

Note that all metrics currently use prometheus::DEFAULT_BUCKETS, which seems broadly applicable. Depending on the data we collect, it might be worth fine-tuning the buckets later.

[ordian]

Agree with Basti that for identifying bottlenecks tracing-timing fits better.

OTOH, having timing information on a live chain in combination with alerts might be helpful.
Curious to know what @mxinden thinks about this.

If we decide to keep the metrics, we should reduce the amount to the known slowest offenders (not all of them are equally useful) and maybe use a specific suffix for timing metrics.

[mxinden]

Agree with Basti that for identifying bottlenecks tracing-timing fits better.

OTOH, having timing information on a live chain in combination with alerts might be helpful.
Curious to know what @mxinden thinks about this.

If we decide to keep the metrics, we should reduce the amount to the known slowest offenders (not all of them are equally useful) and maybe use a specific suffix for timing metrics.

Is the motivation for this pull request a currently existing CPU bottleneck, or the general goal of catching such bottlenecks quickly in the future? As far as I can tell the observation timespan of some of these include await points, thus the observed time might be misleading as it could potentially include the time spent by unrelated logic on the CPU. If this is a pressing issue, I would suggest deploying a custom binary with these metrics to see if they are accurate and of any help. In case this should solve CPU issues in the future, I would suggest relying on CPU profiling like flamegraph as well as the already existing task related metrics such as the polkadot_tasks_polling_duration_* histogram (see the Substrate Service Tasks Grafana dashboards for more).

That said, I don't think these metrics are particularly costly. While histograms are more expensive than counters, this pull request does not use any HistogramVecs.

[ordian]

Thanks for your input @mxinden!

Is the motivation for this pull request a currently existing CPU bottleneck, or the general goal of catching such bottlenecks quickly in the future?

The latter, having metrics on a live chain will help us identify a problem more quickly.

As far as I can tell the observation timespan of some of these include await points, thus the observed time might be misleading as it could potentially include the time spent by unrelated logic on the CPU

That's a good point. But observation timespans will give us an understanding how long e.g. certain requests take time end-to-end. But I agree that sampling profilers like perf used by flamegraph answer how much CPU time is spent in an async task.

[drahnr]

Should we consider writing some rust harness code and verifying the prometheus events? I would prefer that over a complex bash script.

[coriolinus]

That's not a bad idea, but unless there's library support for submitting transactions to replace polkadot-js, it doesn't really get us much. Bash is an ugly language, but it's hard to beat it when your task is fundamentally to coordinate launching a bunch of stuff on the command line.

That said, if there's library support in Rust so it's possible to automate the registration, then that's a game-changer. I just don't know of it, if it exists.

[drahnr]

I think for now this is ok. Created a tracking issue #1991

[bkchr]

We support sending transactions from rust tests, there is no need to use polkadot-js for this. Do you even took a look at the integration test of the collator?

[coriolinus]

Yes, but my intent was to run them standalone for debugging purposes, not as part of the test suite. It's easier to reach for scripts/adder-collator.sh than cargo test -p whatever-module -- --nocapture --no-timeout, or whatever the proper incantation ends up being.

[drahnr]

I don't really agree with that, usually it should always be run with the the test suite, not only by some subset of devs that are aware of its existance.
The approach of adding shell scripts imho also doesn't scale well beyond 3.

[bkchr]

And we also have polkadot-launch by @shawntabrizi

[ordian]

Could you show us a screenshot of how histogram metrics look like and resolve merge conflicts please?

[coriolinus]

Could you show us a screenshot of how histogram metrics look like?

Prometheus doesn't render the histogram metrics, unfortunately; that's left to integration with Grafana. I verified that data is copied into Prometheus, but haven't bothered setting up Grafana for demo purposes: it felt like something which would take a fair amount of time (mostly because I'm unfamiliar with Grafana) without actually showing anything new; prometheus and grafana are well-known for working together.

What you can do right now is query the tabular data in prometheus by querying the polkadot_*_bucket fields. This brings up a table showing, for a range of time scales, what number of traces took less than that amount of time. Note that this data is cumulative: anything taking less than 0.05 seconds also took less than 0.1 seconds, etc. I'm sure you can do more with it than that, but I am not very fluent in prometheus queries.

[coriolinus]

bot merge

[ghost]

Missing process info; check that the PR belongs to a project column.

Merge can be attempted if:

• The PR has approval from two core-devs (or one if the PR is labelled insubstantial).
• The PR has approval from a member of substrateteamleads.
• The PR is attached to a project column and has approval from the project owner.

See https://github.com/paritytech/parity-processbot#faq

.