Handling slow log with suffixes (with max_slowlog_size and max_slowlog_files)

Percona Monitoring and Management (PMM) PMM 2.x
1

Hello,

There is an option in Percona server to automatically rotate slow logs, namely max_slowlog_size and max_slowlog_files.

As per the documentation, we only specify the prefix in the slow_query_log_file variable and then numbered suffixes are added :

For this feature to work variable slow_query_log_file needs to be set up manually and without the .log sufix. The slow query log files will be named using slow_query_log_file as a stem, to which a dot and a sequence number will be appended.

It seems that when using this functionnality PMM client seems to struggle to find the slowlog because it searches for the slowlog name without the suffix.

In my case :

PMM server v2.10.0

PMM client 2.9.1-6.stretch (debian package)

Server : 5.7.29-32-log Percona Server (GPL), Release 32, Revision 56bce88

mysql> show variables like '%slow%';
+-----------------------------------+-----------------------------------------------------------------------------------------------+
| Variable_name           | Value                                             |
+-----------------------------------+-----------------------------------------------------------------------------------------------+
| log_slow_admin_statements     | ON                                              |
| log_slow_filter          |                                                |
| log_slow_rate_limit        | 1                                               |
| log_slow_rate_type        | session                                            |
| log_slow_slave_statements     | ON                                              |
| log_slow_sp_statements      | ON                                              |
| log_slow_verbosity        | microtime,query_plan,innodb                                  |
| max_slowlog_files         | 6                                               |
| max_slowlog_size         | 268435456                                           |
| slow_launch_time         | 2                                               |
| slow_query_log          | ON                                              |
| slow_query_log_always_write_time | 1800.000000                                          |
| slow_query_log_file        | /var/lib/mysql/data/servername-slow                             |
| slow_query_log_use_global_control | log_slow_filter,log_slow_rate_limit,log_slow_verbosity,long_query_time,min_examined_row_limit |
+-----------------------------------+-----------------------------------------------------------------------------------------------+

PMM client status :

# pmm-admin list
Service type Service name     Address and port Service ID
MySQL     servername-mysql  /tmp/mysql.sock  /service_id/a357f4d6-d33b-43f8-b6ce-6a7963044650

Agent type         Status   Agent ID                    Service ID
pmm_agent          Connected /agent_id/6cd13230-e2f7-4aa2-923a-ddf9fa5a4afc
node_exporter        Running  /agent_id/2d47fef9-fdc2-46e8-859c-0704cb71b2cd
mysqld_exporter       Running  /agent_id/506c0710-4e1c-40ac-a4e4-9e8ab090c496 /service_id/a357f4d6-d33b-43f8-b6ce-6a7963044650
mysql_slowlog_agent     Waiting  /agent_id/ae6424bc-601a-46f3-ae51-d3e4fbd35722 /service_id/a357f4d6-d33b-43f8-b6ce-6a7963044650

If I check on the server I have the following slow log :

# ls -al /var/lib/mysql/data/servername-slow*
-rw-r----- 1 mysql mysql 249741292 Sep 29 17:16 /var/lib/mysql/data/servername-slow.000003

But in the log I find this error :

syslog:Sep 29 16:37:11 servername pmm-agent[31010]: #033[36mINFO#033[0m[2020-09-29T16:37:11.955+02:00] Processing file /var/lib/mysql/data/servername-slow. #033[36magentID#033[0m=/agent_id/ae6424bc-601a-46f3-ae51-d3e4fbd35722 #033[36mcomponent#033[0m=agent-builtin #033[36mtype#033[0m=qan_mysql_slowlog_agent
syslog:Sep 29 16:37:11 servername pmm-agent[31010]: #033[31mERRO#033[0m[2020-09-29T16:37:11.956+02:00] Failed to start reader for file /var/lib/mysql/data/servername-slow: open /var/lib/mysql/data/servername-slow: no such file or directory. #033[31magentID#033[0m=/agent_id/ae6424bc-601a-46f3-ae51-d3e4fbd35722 #033[31mcomponent#033[0m=agent-builtin #033[31mtype#033[0m=qan_mysql_slowlog_agent
syslog:Sep 29 16:37:11 servername pmm-agent[31010]: #033[36mINFO#033[0m[2020-09-29T16:37:11.956+02:00] Sending status: STARTING.           #033[36magentID#033[0m=/agent_id/ae6424bc-601a-46f3-ae51-d3e4fbd35722 #033[36mcomponent#033[0m=agent-builtin #033[36mtype#033[0m=qan_mysql_slowlog_agent
syslog:Sep 29 16:37:11 servername pmm-agent[31010]: #033[36mINFO#033[0m[2020-09-29T16:37:11.956+02:00] Sending status: WAITING.           #033[36magentID#033[0m=/agent_id/ae6424bc-601a-46f3-ae51-d3e4fbd35722 #033[36mcomponent#033[0m=agent-builtin #033[36mtype#033[0m=qan_mysql_slowlog_agent
syslog:Sep 29 16:37:14 servername pmm-agent[31010]: #033[31mERRO#033[0m[2020-09-29T16:37:14.545+02:00] Failed to stat file: stat /var/lib/mysql/data/servername-slow: no such file or directory #033[31magentID#033[0m=/agent_id/ae6424bc-601a-46f3-ae51-d3e4fbd35722 #033[31mcomponent#033[0m=agent-builtin #033[31mtype#033[0m=qan_mysql_slowlog_agent

(And of course nothing shows up in the PMM interface)

Am I missing something here ? An option to specify that when registering the MySQL service ?

2

Hi @babine !

Thank you for the question!

As I see fromyour comment

max_slowlog_files = 6

But I see the only one slow log file “servername-slow.000003”. Can it be possible that others files were somehow removed by you or someone else?

3

Yes they were probably deleted at some point during tests or enabling/disabling slow logs (but they will stop to exist anyway at some point in the future when we arrive at 000008). I can create empty files to check if it changes anything but seeing as the error states “stat /var/lib/mysql/data/servername-slow: no such file or directory” it does not seem it is looking for files with numbered suffixes but rather using slow_query_log_file variable as is.

I’ll try creating empty files 000001 and 000002 and tell you if it changes something.

4

I created empty files just in case :

# ls -al /var/lib/mysql/data/*slow*
-rw-r--r-- 1 mysql mysql     0 Oct 5 16:01 /var/lib/mysql/data/servername-slow.000001
-rw-r--r-- 1 mysql mysql     0 Oct 5 16:01 /var/lib/mysql/data/servername-slow.000002
-rw-r----- 1 mysql mysql 291107123 Oct 2 09:17 /var/lib/mysql/data/servername-slow.000003
-rw-r----- 1 mysql mysql 226774898 Oct 5 16:01 /var/lib/mysql/data/servername-slow.000004

Still have the same error :

Oct 5 16:03:51 servername pmm-agent[31010]: #033[36mINFO#033[0m[2020-10-05T16:03:51.378+02:00] Processing file /var/lib/mysql/data/servername-slow. #033[36magentID#033[0m=/agent_id/ae6424bc-601a-46f3-ae51-d3e4fbd35722 #033[36mcomponent#033[0m=agent-builtin #033[36mtype#033[0m=qan_mysql_slowlog_agent
Oct 5 16:03:51 servername pmm-agent[31010]: #033[31mERRO#033[0m[2020-10-05T16:03:51.378+02:00] Failed to start reader for file /var/lib/mysql/data/servername-slow: open /var/lib/mysql/data/servername-slow: no such file or directory. #033[31magentID#033[0m=/agent_id/ae6424bc-601a-46f3-ae51-d3e4fbd35722 #033[31mcomponent#033[0m=agent-builtin #033[31mtype#033[0m=qan_mysql_slowlog_agent
Oct 5 16:03:51 servername pmm-agent[31010]: #033[36mINFO#033[0m[2020-10-05T16:03:51.378+02:00] Sending status: STARTING.           #033[36magentID#033[0m=/agent_id/ae6424bc-601a-46f3-ae51-d3e4fbd35722 #033[36mcomponent#033[0m=agent-builtin #033[36mtype#033[0m=qan_mysql_slowlog_agent
Oct 5 16:03:51 servername pmm-agent[31010]: #033[36mINFO#033[0m[2020-10-05T16:03:51.378+02:00] Sending status: WAITING.           #033[36magentID#033[0m=/agent_id/ae6424bc-601a-46f3-ae51-d3e4fbd35722 #033[36mcomponent#033[0m=agent-builtin #033[36mtype#033[0m=qan_mysql_slowlog_agent
Oct 5 16:03:54 servername pmm-agent[31010]: #033[31mERRO#033[0m[2020-10-05T16:03:54.531+02:00] Failed to stat file: stat /var/lib/mysql/data/servername-slow: no such file or directory #033[31magentID#033[0m=/agent_id/ae6424bc-601a-46f3-ae51-d3e4fbd35722 #033[31mcomponent#033[0m=agent-builtin #033[31mtype#033[0m=qan_mysql_slowlog_agent

PMM does not seem to support the fact that having these variables (max_slowlog_size and max_slowlog_files) set up causes the slow log filename(s) to differ from the slow_query_log_file variable.

5

Any news on that ? Should I open a bug report somewhere ?