March 15, 2017 at 14:21PG Metricus - collecting metrics from plpgsql code or how three lines of code simplified life
To begin with, all your ads live in the PostgreSQL database. Until now, the lion's share of business logic is hidden in stored procedures, and it is not always convenient to control their work.
For us, stored procedures are convenient, primarily because you do not need to transfer gigabytes of data between the database and the application. It’s convenient to do several actions with different tables in the database, and only report to the application that everything was successful. It is really convenient, but at the same time it brings a number of problems. The business logic is partially hidden in the database, the mechanisms that are used for debugging and monitoring in PHP / Go / Python / etc are not applicable on the DBMS side. Of course, there are some wonderful tools, for example, pg_stat_statements, but sometimes they can not fully answer the question, which piece of code in our large and complex storage doesn’t work like that. Our solution does not pretend to be a “silver bullet,” but it can help quickly determine the average execution time of pieces of code within a stored procedure, which runs thousands of times per second, and do it without creating an extra load. Interesting? Welcome!
At some point, we suddenly and suddenly needed to track the execution time of certain pieces of code in a large stored procedure. The procedure was complex, branchy and very often used. I wanted a quick and elegant solution without a long refactoring and unnecessary work. I wanted to see the result as clearly as possible, it would be ideal to get graphs of the frequency of calls over time, the amount of processed data, the average and percentile of the run time. And it's all in real time. In our company, it is customary to use the Brubeck / Graphite / Grafana stack to display such data, and we, first of all, began to think how to roll our metrics there.
The decision "on the forehead" - to write a stored procedure in plpython - disappeared right away, starting the python interpreter in order to "spit" the string over UDP is an obvious bust. The next option was to throw RAISE NOTICE, and then long and painfully rattle the logs. Besides the fact that it looks like some kind of perversion, the whole “real time” also disappears. There was also an option to just save the data to an unlogged table and dump the data with some kind of script in Brubeck. But adding records to a loaded system, especially if the request is only for fetching data, is also not a good option.
The decision came suddenly and unexpectedly. Accidentally remembered the LISTEN / NOTIFY mechanism and realized that this is it! For half an hour, we wrote a daemon in Python, which connects to PostgreSQL, listens to the channel and sends it to Brubeck, and inside the stored procedure we just write to this channel.
And now, actually, an example of use:
We save time before the request, save time after the request, subtract one from the other, translate it in milliseconds and send it to the channel. Our python daemon catches this message and sends it further to Brubeck.
This solution has several advantages:
Also, this solution has a number of features that are important to be aware of. All these features flow from the LISTEN / NOTIFY mechanism in PostgreSQL:
All these, of course, are trifles with which we personally get along well.
But that is not all!
A week before writing the article, a C extension for PostgreSQL, pg_metricus, was invented and written.
This extension does not use LISTEN / NOTIFY and sends metrics to the aggregator socket immediately at the time of the call. Due to which the data became independent of the state of the transaction. Even if the transaction was rolled back, all your data successfully reached the aggregator.
How to use it? Yes, everything is simple!
We specify the host and port of our aggregator in the settings of postgresql.conf:
Do
We collect source codes:
Install the extension:
And that’s all! You can send data!
In conclusion, I want to note that this approach allowed us to solve all the problems we voiced. We tested, rolled out into battle, and after 5 minutes we already had beautiful graphs in Grafana and the first idea of how, how often and for how long it takes to execute in our investigated logic. Clickable picture Thank you for your attention! We look forward to your questions and feedback. Projects are available at the links below: Github → https://github.com/avito-tech/pg_metricus_python → https://github.com/avito-tech/pg_metricus_c PGXN → https://pgxn.org/dist/pg_metricus
For us, stored procedures are convenient, primarily because you do not need to transfer gigabytes of data between the database and the application. It’s convenient to do several actions with different tables in the database, and only report to the application that everything was successful. It is really convenient, but at the same time it brings a number of problems. The business logic is partially hidden in the database, the mechanisms that are used for debugging and monitoring in PHP / Go / Python / etc are not applicable on the DBMS side. Of course, there are some wonderful tools, for example, pg_stat_statements, but sometimes they can not fully answer the question, which piece of code in our large and complex storage doesn’t work like that. Our solution does not pretend to be a “silver bullet,” but it can help quickly determine the average execution time of pieces of code within a stored procedure, which runs thousands of times per second, and do it without creating an extra load. Interesting? Welcome!
At some point, we suddenly and suddenly needed to track the execution time of certain pieces of code in a large stored procedure. The procedure was complex, branchy and very often used. I wanted a quick and elegant solution without a long refactoring and unnecessary work. I wanted to see the result as clearly as possible, it would be ideal to get graphs of the frequency of calls over time, the amount of processed data, the average and percentile of the run time. And it's all in real time. In our company, it is customary to use the Brubeck / Graphite / Grafana stack to display such data, and we, first of all, began to think how to roll our metrics there.
The decision "on the forehead" - to write a stored procedure in plpython - disappeared right away, starting the python interpreter in order to "spit" the string over UDP is an obvious bust. The next option was to throw RAISE NOTICE, and then long and painfully rattle the logs. Besides the fact that it looks like some kind of perversion, the whole “real time” also disappears. There was also an option to just save the data to an unlogged table and dump the data with some kind of script in Brubeck. But adding records to a loaded system, especially if the request is only for fetching data, is also not a good option.
The decision came suddenly and unexpectedly. Accidentally remembered the LISTEN / NOTIFY mechanism and realized that this is it! For half an hour, we wrote a daemon in Python, which connects to PostgreSQL, listens to the channel and sends it to Brubeck, and inside the stored procedure we just write to this channel.
And now, actually, an example of use:
x1 = clock_timestamp();
...your long running query...
x2 = clock_timestamp();
GET DIAGNOSTICS c = ROW_COUNT;
perform pg_notify('channel_test', format(E'%s.%s:%s|%s\n', 'db.sql.metric', 'long_query.duration', extract(millisecond from (x2 - x1))::bigint::text, 'ms'));
perform pg_notify('channel_test', format(E'%s.%s:%s|%s\n', 'db.sql.metric', 'long_query.count', c::text, 'c'));We save time before the request, save time after the request, subtract one from the other, translate it in milliseconds and send it to the channel. Our python daemon catches this message and sends it further to Brubeck.
This solution has several advantages:
- The solution was invented, implemented and deflated in 2 hours.
- There were no server restarts.
- Of the external dependencies, there is only one daemon in python.
- Minimum overhead, on our N thousand transactions per second, we did not see it.
Also, this solution has a number of features that are important to be aware of. All these features flow from the LISTEN / NOTIFY mechanism in PostgreSQL:
- The data you send to the channel is transaction dependent. If you sent something to the channel and the transaction was rolled back, nothing will come to the channel.
- LISTEN / NOTIFY does not work on standby.
- There are other features of NOTIFY in PostgreSQL, for example, that the same data will be delivered only once. All features are best found in the LISTEN / NOTIFY documentation.
All these, of course, are trifles with which we personally get along well.
But that is not all!
A week before writing the article, a C extension for PostgreSQL, pg_metricus, was invented and written.
This extension does not use LISTEN / NOTIFY and sends metrics to the aggregator socket immediately at the time of the call. Due to which the data became independent of the state of the transaction. Even if the transaction was rolled back, all your data successfully reached the aggregator.
How to use it? Yes, everything is simple!
We specify the host and port of our aggregator in the settings of postgresql.conf:
pg_metricus.host = '10.4.5.177'
pg_metricus.port = 8224Do
select pg_reload_conf()We collect source codes:
make installInstall the extension:
create schema metricus;
create extension pg_metricus schema metricus;And that’s all! You can send data!
x1 = clock_timestamp();
...your long running query...
x2 = clock_timestamp();
GET DIAGNOSTICS c = ROW_COUNT;
perform metricus.send_metric(format(E'%s.%s:%s|%s\n', 'db.sql.metric', 'long_query.duration', extract(millisecond from (x2 - x1))::bigint::text, 'ms'));
perform metricus.send_metric(format(E'%s.%s:%s|%s\n', 'db.sql.metric', 'long_query.count', c::text, 'c'));In conclusion, I want to note that this approach allowed us to solve all the problems we voiced. We tested, rolled out into battle, and after 5 minutes we already had beautiful graphs in Grafana and the first idea of how, how often and for how long it takes to execute in our investigated logic. Clickable picture Thank you for your attention! We look forward to your questions and feedback. Projects are available at the links below: Github → https://github.com/avito-tech/pg_metricus_python → https://github.com/avito-tech/pg_metricus_c PGXN → https://pgxn.org/dist/pg_metricus
