Confirmed that it is broken.
Few instances:
1. If log_slow_filter="full_scan" the query is logged even if it is not a full_scan
This is due to a bug:
a)sys_vars.cc:
const char *log_slow_filter_name[]= { "qc_miss", "full_scan", "full_join", "tmp_table", "tmp_table_on_disk", "filesort", "filesort_on_disk", 0};
b)sql_class.h:
#define QPLAN_NONE 0 #define QPLAN_QC 1 << 0 #define QPLAN_QC_NO 1 << 1 #define QPLAN_FULL_SCAN 1 << 2 #define QPLAN_FULL_JOIN 1 << 3 #define QPLAN_TMP_TABLE 1 << 4 #define QPLAN_TMP_DISK 1 << 5 #define QPLAN_FILESORT 1 << 6 #define QPLAN_FILESORT_DISK 1 << 7
c) /* Follow the slow log filter configuration. */ if (thd->variables.log_slow_filter != 0 && (!(thd->variables.log_slow_filter & thd->query_plan_flags) || ((thd->variables.log_slow_filter & SLOG_F_QC_NO) && (thd->query_plan_flags & QPLAN_QC)))) DBUG_VOID_RETURN;
So, as you can see the #defines and the set variables are not aligned.
For instance, for a non-table scan simple query with query cache miss thd->query_flags=2 (QPLAN_QC_NO)
But in the set, full_scan = 2 and qc_miss=1, so
thd->variables.log_slow_filter & thd->query_plan_flags = 2 & 2 => !(2 & 2) is false and the query is NOT filtered out.
The fix is simple:
=========================================================== --- sql/sql_class.h 2012-07-17 22:27:15.000000000 +0530 +++ /tmp/sql_class.h 2012-08-06 04:16:58.041077338 +0530 @@ -80,14 +80,14 @@ SLOG_RT_SESSION, SLOG_RT_QUERY }; #define QPLAN_NONE 0 -#define QPLAN_QC 1 << 0 -#define QPLAN_QC_NO 1 << 1 -#define QPLAN_FULL_SCAN 1 << 2 -#define QPLAN_FULL_JOIN 1 << 3 -#define QPLAN_TMP_TABLE 1 << 4 -#define QPLAN_TMP_DISK 1 << 5 -#define QPLAN_FILESORT 1 << 6 -#define QPLAN_FILESORT_DISK 1 << 7 +#define QPLAN_QC_NO 1 << 0 +#define QPLAN_FULL_SCAN 1 << 1 +#define QPLAN_FULL_JOIN 1 << 2 +#define QPLAN_TMP_TABLE 1 << 3 +#define QPLAN_TMP_DISK 1 << 4 +#define QPLAN_FILESORT 1 << 5 +#define QPLAN_FILESORT_DISK 1 << 6 +#define QPLAN_QC 1 << 7 enum enum_log_slow_filter { SLOG_F_QC_NO, SLOG_F_FULL_SCAN, SLOG_F_FULL_JOIN, SLOG_F_TMP_TABLE, SLOG_F_TMP_DISK, SLOG_F_FILESORT,
--- sql/sql_parse.cc 2012-07-17 22:27:15.000000000 +0530 +++ /tmp/sql_parse.cc 2012-08-06 04:26:48.177788229 +0530 @@ -1534,7 +1534,7 @@ /* Follow the slow log filter configuration. */ if (thd->variables.log_slow_filter != 0 && (!(thd->variables.log_slow_filter & thd->query_plan_flags) || - ((thd->variables.log_slow_filter & SLOG_F_QC_NO) && + ((thd->variables.log_slow_filter & QPLAN_QC_NO) && (thd->query_plan_flags & QPLAN_QC)))) DBUG_VOID_RETURN;
=================================================================
(The enum enum_log_slow_filter is also not required and can be removed)
2. If log_filter is anything that is not full_scan, the query is not logged (even if it doesn't belong in any categories above) for same reason as above.
Confirmed that it is broken.
Few instances:
1. If log_slow_ filter= "full_scan" the query is logged even if it is not a full_scan
This is due to a bug:
a)sys_vars.cc:
const char *log_slow_ filter_ name[]= { "qc_miss", "full_scan", "full_join",
"tmp_ table", "tmp_table_ on_disk" , "filesort", "filesort_on_disk", 0};
b)sql_class.h:
#define QPLAN_NONE 0
#define QPLAN_QC 1 << 0
#define QPLAN_QC_NO 1 << 1
#define QPLAN_FULL_SCAN 1 << 2
#define QPLAN_FULL_JOIN 1 << 3
#define QPLAN_TMP_TABLE 1 << 4
#define QPLAN_TMP_DISK 1 << 5
#define QPLAN_FILESORT 1 << 6
#define QPLAN_FILESORT_DISK 1 << 7
c) .log_slow_ filter != 0 && !(thd-> variables. log_slow_ filter & thd->query_ plan_flags) ||
((thd-> variables. log_slow_ filter & SLOG_F_QC_NO) &&
(thd-> query_plan_ flags & QPLAN_QC)))) VOID_RETURN;
/* Follow the slow log filter configuration. */
if (thd->variables
(
DBUG_
So, as you can see the #defines and the set variables are not aligned.
For instance, for a non-table scan simple query with query cache miss thd->query_flags=2 (QPLAN_QC_NO)
But in the set, full_scan = 2 and qc_miss=1,
so
thd->variables. log_slow_ filter & thd->query_ plan_flags = 2 & 2 => !(2 & 2) is false and the query is NOT filtered out.
The fix is simple:
======= ======= ======= ======= ======= ======= ======= ======= === slow_filter { F_TMP_TABLE, SLOG_F_TMP_DISK, SLOG_F_FILESORT,
--- sql/sql_class.h 2012-07-17 22:27:15.000000000 +0530
+++ /tmp/sql_class.h 2012-08-06 04:16:58.041077338 +0530
@@ -80,14 +80,14 @@
SLOG_RT_SESSION, SLOG_RT_QUERY
};
#define QPLAN_NONE 0
-#define QPLAN_QC 1 << 0
-#define QPLAN_QC_NO 1 << 1
-#define QPLAN_FULL_SCAN 1 << 2
-#define QPLAN_FULL_JOIN 1 << 3
-#define QPLAN_TMP_TABLE 1 << 4
-#define QPLAN_TMP_DISK 1 << 5
-#define QPLAN_FILESORT 1 << 6
-#define QPLAN_FILESORT_DISK 1 << 7
+#define QPLAN_QC_NO 1 << 0
+#define QPLAN_FULL_SCAN 1 << 1
+#define QPLAN_FULL_JOIN 1 << 2
+#define QPLAN_TMP_TABLE 1 << 3
+#define QPLAN_TMP_DISK 1 << 4
+#define QPLAN_FILESORT 1 << 5
+#define QPLAN_FILESORT_DISK 1 << 6
+#define QPLAN_QC 1 << 7
enum enum_log_
SLOG_F_QC_NO, SLOG_F_FULL_SCAN, SLOG_F_FULL_JOIN,
SLOG_
--- sql/sql_parse.cc 2012-07-17 22:27:15.000000000 +0530 .log_slow_ filter != 0 &&
(!(thd- >variables. log_slow_ filter & thd->query_ plan_flags) || variables. log_slow_ filter & SLOG_F_QC_NO) && variables. log_slow_ filter & QPLAN_QC_NO) &&
(thd- >query_ plan_flags & QPLAN_QC)))) VOID_RETURN;
+++ /tmp/sql_parse.cc 2012-08-06 04:26:48.177788229 +0530
@@ -1534,7 +1534,7 @@
/* Follow the slow log filter configuration. */
if (thd->variables
- ((thd->
+ ((thd->
DBUG_
======= ======= ======= ======= ======= ======= ======= ======= ======= ==
(The enum enum_log_ slow_filter is also not required and can be removed)
2. If log_filter is anything that is not full_scan, the query is not logged (even if it doesn't belong in any categories above) for same reason as above.