Details
-
Bug
-
Status: Closed (View Workflow)
-
Critical
-
Resolution: Fixed
-
10.3(EOL), 10.4(EOL), 10.5, 10.6, 10.8(EOL), 10.9(EOL), 10.10(EOL), 10.11, 11.0(EOL)
Description
There is an issue for logging query on slow log table.
Since we set log_output=FILE and the data type for 'rows_examined' column on CVS table slow_log is INT, when this value exceeds the maximum allowed value for INT , an error is logged into error log.
([ERROR] Unable to write to mysql.slow_log)
|
Because the INSERT into the slow_log table fails due to the maximum value being exceeded. This is the output when we change the log_output to file:
# Thread_id: 380229 Schema: andre_k QC_hit: No# Query_time: 0.028396 Lock_time: 0.001841 Rows_sent: 2 Rows_examined: 10958383778436017378# Rows_affected: 0 Bytes_sent: 124# Tmp_tables: 2 Tmp_disk_tables: 0 Tmp_table_sizes: 380968# Full_scan: Yes Full_join: No Tmp_table: Yes Tmp_table_on_disk: No# Filesort: Yes Filesort_on_disk: No Merge_passes: 0 Priority_queue: Yes |
# SET timestamp=1677147120; |
# SELECT get_id(CAST(aes_decrypt(tab1.NAME_F,'V41iNM0n4') AS char),'KM_ID_PL') as get_string, (CASE WHEN (SELECT ID FROM tab2 where tab2.TAB1_ID = tab1.ID LIMIT 1) IS NULL THEN 0 ELSE 1 END) AS IS_ATTFROM tab1ORDER BY 2 DESCLIMIT 2; |
use case huge_value_rows_examined.txt is attached.
Attachments
Issue Links
- is duplicated by
-
MDEV-22860 Change EXAMINED_ROWS in I_S.PROCESSLIST from INT to BIGINT UNSIGNED
-
- Closed
-
- relates to
-
-
- Closed
-
-
-
- Closed
-
-
-
- Closed
-
Activity
Short recap:
For sub statements we reset the counters and calculate only what happens in the sub statement. This is fine.
Sub statements only shows up in the slow query log if LOG_SLOW_DISABLE_SP is not set.
For the top statement, we collect counters for the top statement + all included sub statements.
One could argue that for the top statement we should not print the sub statement status (except if LOG_SLOW_DISABLE_SP is set).
Historically we have printed everything for the top statement and I think this is fine for now.
It may cause confusion if the number of statistics changes just because a user changes the value of
LOG_SLOW_DISABLE_SP (by default it is set).
This means that your current patch is fine as it only extends the counters.
What should probably be done in the documentation is to clearly state that slow query log statistics for a statement always includes all statistics for all called stored procedures or stored functions.
sanja It looks like the existing patch has been approved, do you think this can be included in the next release?
sanja I wouldn't just yet, looking at the figure:
--- /home/dan/repos/mariadb-server-10.4/mysql-test/main/log_slow_debug.result 2023-09-21 19:35:56.918844459 +1000
|
+++ /home/dan/repos/mariadb-server-10.4/mysql-test/main/log_slow_debug.reject 2023-09-21 19:43:41.965315498 +1000
|
@@ -246,6 +246,12 @@
|
1 0
|
2 0
|
SET GLOBAL debug_dbug=@old_dbug;
|
+SELECT sql_text,rows_examined FROM mysql.slow_log;
|
+sql_text rows_examined
|
+SET SESSION long_query_time= 0 0
|
+SET GLOBAL debug_dbug="+d,debug_huge_number_of_examined_rows" 0
|
+SELECT * FROM tab_MDEV_30820 ORDER BY 1 4
|
+SET GLOBAL debug_dbug=@old_dbug 0
|
SET @@long_query_time= @old_long_query_time;
|
SET @@global.log_output= @old_log_output;
|
SET @@global.slow_query_log= @old_slow_query_log;
|
It doesn't appear that the very large number ended up in the logs. I foolishly started https://github.com/MariaDB/server/pull/2767 before seeing this commit thinking all the datatypes needed to be ulonglong. I get the same mtr result however.
the large numbers was result of counting bug. but theoretically they possible
The author want reseting counters instead removing restoring it (so above should be redone)