Comment 2 for bug 1030783

Revision history for this message
Raghavendra D Prabhu (raghavendra-prabhu) wrote :

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.