log_slow_rate_limit for slow logging

MySQL & MariaDB Other MySQL® Questions
1

Attempts to test this feature are meeting with limited success.

The goal is always log truly slow queries, which we consider 1 second or more, and to also log a representative sample of all other queries, which on this test system would be 1 in 100. On production it would be 1/1000 or more.

To start I take a pretty much default 5.6 instance of Percona Server and enable slow logging (long_query_time is set to 1) and add this.

mysql> set global log_slow_rate_type =“query”;
Query OK, 0 rows affected (0.00 sec)

mysql> set global log_slow_rate_limit = 100;
Query OK, 0 rows affected (0.00 sec)

mysql> set global slow_query_log_use_global_control =“all”;
Query OK, 0 rows affected (0.00 sec)

Here’s all the variables related to slow logging

show variables like ‘%slow%’;
±-----------------------------------±-----------------------------------------------------------------------+
| Variable_name | Value |
±-----------------------------------±-----------------------------------------------------------------------+
| log_slow_admin_statements | OFF |
| log_slow_filter | |
| log_slow_queries | ON |
| log_slow_rate_limit | 100 |
| log_slow_rate_type | query |
| log_slow_slave_statements | OFF |
| log_slow_sp_statements | ON |
| log_slow_verbosity | microtime,query_plan,innodb |
| slow_launch_time | 2 |
| slow_query_log | ON |
| slow_query_log_always_write_time | 1.000000 |
| slow_query_log_file | /datastore/mysql/devdb-slow.log |
| slow_query_log_timestamp_always | ON |
| slow_query_log_timestamp_precision | microsecond |
| slow_query_log_use_global_control | log_slow_filter,log_slow_rate_limit,log_slow_verbosity,long_query_time |
±-----------------------------------±-----------------------------------------------------------------------+
15 rows in set (0.00 sec)

This was enabled on a test database that runs tens to hundreds of queries per second, so I would have expected a query to be logged every 1-10 seconds. However in the first 24 hours this ran, only four queries showed up in the slow log.

There must be something simple that I am missing.

The log entries do have the expected comments about the rate type and limit, which shows that the system is aware of the config.

Log_slow_rate_type: query Log_slow_rate_limit: 100

2

Hi cmcgrail;

I think what’s getting you is the “log_slow_rate_limit” option. When you set it to 100, that actually means that only 1 out of 100 “slow” queries will actually get logged. So if 199 slow queries come through, only 1 will get logged. Once the 200th one comes through, then the second will get logged.

If you want to get a sample of all queries, then I would set long_query_time to 0, which will give you a large sampling of queries that are run. Or if you want every query, you could always use the general log (just for limited use while testing in dev).

Also keep in mind that the global variables only take effect for new connections, so if you have an application with persistent connections, global settings you change may not even be in use until the app connects again. This also applies to your own connection when testing.

-Scott

3

Ah. I think I get it now.

The way the documentation is written allows an interpretation where log_slow_rate_limit will force logging of queries to the slow log whether or not they were deemed slow by evaluation against the value of long_query_time.

The docs says stuff about log_slow_rate_limit like: “Specifies that only a fraction of session/query should be logged. Logging is enabled for every nth session/query.”

It would be more clear if it said “every nth slow query”.

I set long_query_time to 0 and set log_slow_rate_limit to 50 for a test where I was running queries in batches of 100, and the rate of logging seemed about what I wanted.

It would also be great if the docs gave a better idea of what would be logged in the case where log_slow_rate_type were set to session. Do you only get sessions if those sessions issued a slow query? Do you get the part of the session that preceded the slow query? I’m not planning on using that feature, but if I wanted to I would still have questions.

Thanks for your help again.