Uploaded image for project: 'MariaDB Server'
  1. MariaDB Server
  2. MDEV-6430

It is impossible to see if "filesort with small limit" optimization was used

    Details

    • Type: Bug
    • Status: Closed
    • Priority: Major
    • Resolution: Fixed
    • Affects Version/s: 10.0.12
    • Fix Version/s: 10.0.13
    • Component/s: None
    • Labels:
      None

      Description

      We've ported "filesort with small limit" optimization from mysql-5.6 into MariaDB 10.0.

      The problem is, it is impossible to see whether that optimization is used or not.

      In MySQL, one can check this as follows

      • set optimizer_trace=1
      • SELECT // need to run SELECT, not EXPLAIN
      • select * from optimizer_trace

      And then look for something like this:

            "join_execution": {
      ...
                  "filesort_priority_queue_optimization": {
                    "limit": 10,
                    "rows_estimate": 198717,
                    "row_size": 215,
                    "memory_available": 262144,
                    "chosen": true
                  },
      

      In MariaDB, there is no optimizer_trace, so one can't see it at all.

        Gliffy Diagrams

          Attachments

            Activity

            Hide
            psergey Sergei Petrunia added a comment - - edited

            It would be logical if the output was reflected in EXPLAIN. The problem is that both MySQL and MariaDB make the decision about whether to use PQ at a very late phase:

              #0  check_if_pq_applicable (param=0x7ffff7e9fb50, filesort_info=0x7ffff7e9fbd0, table=0x7fffe3cabe70, num_rows=216437, memory_available=2097152) at /home/psergey/dev2/10.0/sql/filesort.cc:1307
              #1  0x000000000084db80 in filesort (thd=0x7fffd4398070, table=0x7fffe3cabe70, sortorder=0x7fffe3c948a8, s_length=1, select=0x7fffe3c943b0, max_rows=10, sort_positions=false, examined_rows=0x7ffff7ea0100, found_rows=0x7ffff7ea0108) at /home/psergey/dev2/10.0/sql/filesort.cc:224
              #2  0x00000000006c46aa in create_sort_index (thd=0x7fffd4398070, join=0x7fffe3c78a98, order=0x7fffe3c78988, filesort_limit=10, select_limit=10, is_order_by=true) at /home/psergey/dev2/10.0/sql/sql_select.cc:20571
              #3  0x0000000000699c40 in JOIN::exec_inner (this=0x7fffe3c78a98) at /home/psergey/dev2/10.0/sql/sql_select.cc:3046
              #4  0x0000000000697142 in JOIN::exec (this=0x7fffe3c78a98) at /home/psergey/dev2/10.0/sql/sql_select.cc:2366
              #5  0x000000000069a715 in mysql_select (thd=0x7fffd4398070, rref_pointer_array=0x7fffd439c6d8, tables=0x7fffe3c78290, wild_num=1, fields=..., conds=0x0, og_num=1, order=0x7fffe3c78988, group=0x0, having=0x0, proc_param=0x0, select_options=2147748608, result=0x7fffe3c78a78, unit=0x7fffd439bd78, select_lex=0x7fffd439c460) at /home/psergey/dev2/10.0/sql/sql_select.cc:3303
            

            EXPLAIN execution does not go through filesort()/check_if_pq_applicable(). In order to check whether we're using PQ in EXPLAIN, one would need to do some code re-structuring.

            Show
            psergey Sergei Petrunia added a comment - - edited It would be logical if the output was reflected in EXPLAIN. The problem is that both MySQL and MariaDB make the decision about whether to use PQ at a very late phase: #0 check_if_pq_applicable (param=0x7ffff7e9fb50, filesort_info=0x7ffff7e9fbd0, table=0x7fffe3cabe70, num_rows=216437, memory_available=2097152) at /home/psergey/dev2/10.0/sql/filesort.cc:1307 #1 0x000000000084db80 in filesort (thd=0x7fffd4398070, table=0x7fffe3cabe70, sortorder=0x7fffe3c948a8, s_length=1, select=0x7fffe3c943b0, max_rows=10, sort_positions=false, examined_rows=0x7ffff7ea0100, found_rows=0x7ffff7ea0108) at /home/psergey/dev2/10.0/sql/filesort.cc:224 #2 0x00000000006c46aa in create_sort_index (thd=0x7fffd4398070, join=0x7fffe3c78a98, order=0x7fffe3c78988, filesort_limit=10, select_limit=10, is_order_by=true) at /home/psergey/dev2/10.0/sql/sql_select.cc:20571 #3 0x0000000000699c40 in JOIN::exec_inner (this=0x7fffe3c78a98) at /home/psergey/dev2/10.0/sql/sql_select.cc:3046 #4 0x0000000000697142 in JOIN::exec (this=0x7fffe3c78a98) at /home/psergey/dev2/10.0/sql/sql_select.cc:2366 #5 0x000000000069a715 in mysql_select (thd=0x7fffd4398070, rref_pointer_array=0x7fffd439c6d8, tables=0x7fffe3c78290, wild_num=1, fields=..., conds=0x0, og_num=1, order=0x7fffe3c78988, group=0x0, having=0x0, proc_param=0x0, select_options=2147748608, result=0x7fffe3c78a78, unit=0x7fffd439bd78, select_lex=0x7fffd439c460) at /home/psergey/dev2/10.0/sql/sql_select.cc:3303 EXPLAIN execution does not go through filesort()/check_if_pq_applicable(). In order to check whether we're using PQ in EXPLAIN, one would need to do some code re-structuring.
            Hide
            psergey Sergei Petrunia added a comment -

            Status variables do not have a counter for PQ-based sorting:

            MariaDB [j61]> show status like '%sort%';
            +-------------------+-------+
            | Variable_name     | Value |
            +-------------------+-------+
            | Sort_merge_passes | 0     |
            | Sort_range        | 0     |
            | Sort_rows         | 10000 |
            | Sort_scan         | 1     |
            +-------------------+-------+
            4 rows in set (0.00 sec)
            
            Show
            psergey Sergei Petrunia added a comment - Status variables do not have a counter for PQ-based sorting: MariaDB [j61]> show status like '%sort%'; +-------------------+-------+ | Variable_name | Value | +-------------------+-------+ | Sort_merge_passes | 0 | | Sort_range | 0 | | Sort_rows | 10000 | | Sort_scan | 1 | +-------------------+-------+ 4 rows in set (0.00 sec)
            Hide
            psergey Sergei Petrunia added a comment -

            Slow query log entry (with log_slow_verbosity=query_plan,explain):

            # Time: 140708 18:50:08
            # User@Host: root[root] @ localhost []
            # Thread_id: 3  Schema: j61  QC_hit: No
            # Query_time: 4.110269  Lock_time: 0.004791  Rows_sent: 10  Rows_examined: 100010
            # Full_scan: Yes  Full_join: No  Tmp_table: No  Tmp_table_on_disk: No
            # Filesort: Yes  Filesort_on_disk: No  Merge_passes: 0
            #
            # explain: id   select_type     table   type    possible_keys   key     key_len ref     rows    Extra
            # explain: 1    SIMPLE  t5      ALL     NULL    NULL    NULL    NULL    98496   Using filesort
            #
            use j61;
            SET timestamp=1404831008;
            select * from t5  order by a limit 10;
            

            " Filesort: Yes " comes from "log_slow_verbosity=explain", which originally comes from "extended statistics in the slow query log" from Percona Server. It may be natural to extend it to show whether PQ-based sorting was used.

            Show
            psergey Sergei Petrunia added a comment - Slow query log entry (with log_slow_verbosity=query_plan,explain): # Time: 140708 18:50:08 # User@Host: root[root] @ localhost [] # Thread_id: 3 Schema: j61 QC_hit: No # Query_time: 4.110269 Lock_time: 0.004791 Rows_sent: 10 Rows_examined: 100010 # Full_scan: Yes Full_join: No Tmp_table: No Tmp_table_on_disk: No # Filesort: Yes Filesort_on_disk: No Merge_passes: 0 # # explain: id select_type table type possible_keys key key_len ref rows Extra # explain: 1 SIMPLE t5 ALL NULL NULL NULL NULL 98496 Using filesort # use j61; SET timestamp=1404831008; select * from t5 order by a limit 10; " Filesort: Yes " comes from "log_slow_verbosity=explain", which originally comes from "extended statistics in the slow query log" from Percona Server. It may be natural to extend it to show whether PQ-based sorting was used.
            Hide
            psergey Sergei Petrunia added a comment - - edited

            Decisions after discussion: will both add a status counter and a slow query log entry.

            Slow query log entries will look like this:

            # Filesort: Yes  Filesort_on_disk: No  Merge_passes: 0  Priority_queue: Yes|No
            

            pt-query-digest is able to parse this.

            Status variable name will be:

            Sort_priority_queue_sorts
            
            Show
            psergey Sergei Petrunia added a comment - - edited Decisions after discussion: will both add a status counter and a slow query log entry. Slow query log entries will look like this: # Filesort: Yes Filesort_on_disk: No Merge_passes: 0 Priority_queue: Yes|No pt-query-digest is able to parse this. Status variable name will be: Sort_priority_queue_sorts

              People

              • Assignee:
                psergey Sergei Petrunia
                Reporter:
                psergey Sergei Petrunia
              • Votes:
                0 Vote for this issue
                Watchers:
                1 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved: