[MDEV-6111] optimizer trace - Jira

Details

Type: Task
Status: Closed (View Workflow)
Priority: Critical
Resolution: Fixed
Fix Version/s: 10.4.3
Component/s: Optimizer
Labels:
- gsoc18
- optimizer

Description

In MySQL, Optimizer trace is a JSON object recording the execution path through the optimizer, decisions that were made and the reasons for them. See https://dev.mysql.com/doc/internals/en/optimizer-tracing.html

Users were asking for MariaDB to have a similar feature.

Attachments

- Sort By Name
- Sort By Date
- Ascending
- Descending
- Thumbnails
- List
- Download All

mdev6111-example-trace-from-mysql8.txt
10 kB
2018-11-14 07:36
screenshot-1.png
45 kB
2018-11-14 07:28

Issue Links

blocks

MDEV-7239 explain index choice

Closed

includes

MDEV-17929 Optimizer trace support for different parts of the server

Closed

MDEV-17930 Optimizer trace: what's on the execution path when trace=off?

Closed

MDEV-18117 Crash with Explain extended when using limit rows examined

Closed

MDEV-18172 Benchmarking 10.4 for optimizer trace

Closed

MDEV-18306 Optimizer_trace has invalid JSON near rows_estimation

Closed

MDEV-18489 Limit the memory used by the optimizer trace

Closed

relates to

MDEV-12980 Index hints for loose scan

Confirmed

MDEV-18670 Document optimizer trace

Closed

MDEV-20440 Optimizer trace: print more details about semi-join optimization

Closed

MDEV-18527 Optimizer trace for DELETE query shows table:null

Closed

MDEV-18528 Optimizer trace support for multi-table UPDATE and DELETE

Closed

MDEV-18741 Optimizer trace: multi-part key ranges are printed incorrectly.

Closed

MDEV-18822 investigate performance regressions in 10.4

Stalled

MDEV-19160 JSON_DETAILED output unnecessarily verbose (Part Time project)

Closed

MDEV-20444 More information regarding access of a table to be printed inside the optimizer_trace

Closed

(2 includes, 9 relates to)

Activity

Ascending order - Click to sort in descending order

Sergei Golubchik created issue - 2014-04-15 20:12

Sergei Golubchik made changes - 2014-04-15 20:13

Field	Original Value	New Value
Priority	Major [ 3 ]	Critical [ 2 ]

Sergei Golubchik made changes - 2014-04-17 19:50

Labels

optimizer

Sergei Golubchik made changes - 2014-04-22 16:28

Fix Version/s		10.2.0 [ 14601 ]
Fix Version/s	10.1.0 [ 12200 ]

Sergei Golubchik made changes - 2014-06-13 15:06

Workflow

defaullt [ 38927 ]

MariaDB v2 [ 42476 ]

roberto spadim made changes - 2014-12-02 03:38

Link

This issue blocks ~~MDEV-7239~~ [ ~~MDEV-7239~~ ]

Rasmus Johansson (Inactive) made changes - 2015-05-18 17:50

Workflow

MariaDB v2 [ 42476 ]

MariaDB v3 [ 61431 ]

Sergei Golubchik made changes - 2015-11-17 17:31

Fix Version/s

10.2 [ 14601 ]

Kirill Smelkov added a comment - 2016-09-21 21:25

Hello up there MariaDB team,

I'm currently debugging performance anomalies in MariaDB under NEO,
when same queries are usually executed fast, but sometimes badly slow. I've
discovered that some (not all) of such cases happen because wrong query
execution plan is somehow selected by optimizer. Why optimizer makes such
decision is a question.

For simple cases in a couple of times we can hopefully paper the problem over
with things like FORCE INDEX, but since this issue is starting to appear
regularly in many different places it is better to understand the root cause
and fix problem there.

That's where optimizer trace would be very handy - to get info from the system
about why such-and-such query execution decision has been made. With this
message I'd like to provide to MariaDB team feedback that optimizer trace is
needed in real-life since on production instances we cannot use debug builds
and get info from DBUG.

I provide examples of some anomalies in appendix for the reference.

Thanks beforehand,
Kirill

P.S. My familiarity with MariaDB is only several days, so please forgive me in
advance some possibly silly mistakes.

/cc ratzpo (@ratzpo)

Appendix

MariaDB 10.1.17. TokuDB is used as storage engine.

Example of bad query caught in slow log:

# Time: 160921 10:47:15

# User@Host: root[root] @ localhost []

# Thread_id: 6  Schema: neo1  QC_hit: No

# Query_time: 4.118192  Lock_time: 0.000024  Rows_sent: 0  Rows_examined: 8476058

# Rows_affected: 0

# explain: id   select_type     table   type    possible_keys       key             key_len ref             rows    r_rows          filtered        r_filtered      Extra

# explain: 1    SIMPLE          obj     ref     PRIMARY,partition   partition       10      const,const     1       8476058.00      100.00          0.00            Using where; Using index

SET timestamp=1474447635;

SELECT tid FROM obj WHERE `partition`=5 AND oid=79613 AND tid>268544235197088772 ORDER BY tid LIMIT 1;

Similar query caught in process list with analyze:

MariaDB [neo1]> show processlist;

+----+------+-----------+------+---------+------+----------------------------+------------------------------------------------------------------------------------------------------+----------+

| Id | User | Host      | db   | Command | Time | State                      | Info                                                                                                 | Progress |

+----+------+-----------+------+---------+------+----------------------------+------------------------------------------------------------------------------------------------------+----------+

|  3 | root | localhost | neo0 | Sleep   |    8 |                            | NULL                                                                                                 |    0.000 |

|  4 | root | localhost | neo2 | Sleep   |   15 |                            | NULL                                                                                                 |    0.000 |

|  5 | root | localhost | neo3 | Sleep   |   11 |                            | NULL                                                                                                 |    0.000 |

|  6 | root | localhost | neo1 | Query   |    3 | Queried about 7710000 rows | SELECT tid FROM obj WHERE `partition`=5 AND oid=79613 AND tid>268544341634012678 ORDER BY tid LIMIT  |    0.000 |

| 10 | root | localhost | neo1 | Query   |    0 | init                       | show processlist                                                                                     |    0.000 |

+----+------+-----------+------+---------+------+----------------------------+------------------------------------------------------------------------------------------------------+----------+

5 rows in set (0.00 sec)

MariaDB [neo1]> show explain for 6;

+------+-------------+-------+------+-------------------+-----------+---------+-------------+------+------------------------------------------+

| id   | select_type | table | type | possible_keys     | key       | key_len | ref         | rows | Extra                                    |

+------+-------------+-------+------+-------------------+-----------+---------+-------------+------+------------------------------------------+

|    1 | SIMPLE      | obj   | ref  | PRIMARY,partition | partition | 10      | const,const |    1 | Using where; Using index; Using filesort |

+------+-------------+-------+------+-------------------+-----------+---------+-------------+------+------------------------------------------+

1 row in set, 1 warning (0.01 sec)

The same query in normal case:

MariaDB [neo1]> explain SELECT tid FROM obj WHERE `partition`=5 AND oid=79613 AND tid>268544341634012678 ORDER BY tid LIMIT 1;

+------+-------------+-------+-------+-------------------+-----------+---------+------+------+--------------------------+

| id   | select_type | table | type  | possible_keys     | key       | key_len | ref  | rows | Extra                    |

+------+-------------+-------+-------+-------------------+-----------+---------+------+------+--------------------------+

|    1 | SIMPLE      | obj   | range | PRIMARY,partition | partition | 18      | NULL | 1295 | Using where; Using index |

+------+-------------+-------+-------+-------------------+-----------+---------+------+------+--------------------------+

1 row in set (0.00 sec)

MariaDB [neo1]> analyze SELECT tid FROM obj WHERE `partition`=5 AND oid=79613 AND tid>268544341634012678 ORDER BY tid LIMIT 1;

+------+-------------+-------+-------+-------------------+-----------+---------+------+------+--------+----------+------------+--------------------------+

| id   | select_type | table | type  | possible_keys     | key       | key_len | ref  | rows | r_rows | filtered | r_filtered | Extra                    |

+------+-------------+-------+-------+-------------------+-----------+---------+------+------+--------+----------+------------+--------------------------+

|    1 | SIMPLE      | obj   | range | PRIMARY,partition | partition | 18      | NULL |  639 |   1.00 |   100.00 |     100.00 | Using where; Using index |

+------+-------------+-------+-------+-------------------+-----------+---------+------+------+--------+----------+------------+--------------------------+

1 row in set (0.00 sec)

MariaDB [neo1]> SELECT tid FROM obj WHERE `partition`=5 AND oid=79613 AND tid>268544341634012678 ORDER BY tid LIMIT 1;

+--------------------+

| tid                |

+--------------------+

| 268544342862377552 |

+--------------------+

1 row in set (0.00 sec)

NOTE the difference:

time: 4s vs < 0.01s
type: 'ref' vs 'range'
key_len: 10 vs 18 (partition, oid) vs (partition, oid, tid)
ref: const,const vs NULL
"Using filesort"

For the reference:

MariaDB [neo1]> describe obj;

+-----------+----------------------+------+-----+---------+-------+

| Field     | Type                 | Null | Key | Default | Extra |

+-----------+----------------------+------+-----+---------+-------+

| partition | smallint(5) unsigned | NO   | PRI | NULL    |       |

| oid       | bigint(20) unsigned  | NO   | PRI | NULL    |       |

| tid       | bigint(20) unsigned  | NO   | PRI | NULL    |       |

| data_id   | bigint(20) unsigned  | YES  | MUL | NULL    |       |

| value_tid | bigint(20) unsigned  | YES  |     | NULL    |       |

+-----------+----------------------+------+-----+---------+-------+

5 rows in set (0.00 sec)

MariaDB [neo1]> show index from obj;

+-------+------------+-----------+--------------+-------------+-----------+-------------+----------+--------+------+------------+---------+---------------+

| Table | Non_unique | Key_name  | Seq_in_index | Column_name | Collation | Cardinality | Sub_part | Packed | Null | Index_type | Comment | Index_comment |

+-------+------------+-----------+--------------+-------------+-----------+-------------+----------+--------+------+------------+---------+---------------+

| obj   |          0 | PRIMARY   |            1 | partition   | A         |    28253069 |     NULL | NULL   |      | BTREE      |         |               |

| obj   |          0 | PRIMARY   |            2 | tid         | A         |    28253069 |     NULL | NULL   |      | BTREE      |         |               |

| obj   |          0 | PRIMARY   |            3 | oid         | A         |    28253069 |     NULL | NULL   |      | BTREE      |         |               |

| obj   |          1 | partition |            1 | partition   | A         |    28253069 |     NULL | NULL   |      | BTREE      |         |               |

| obj   |          1 | partition |            2 | oid         | A         |    28253069 |     NULL | NULL   |      | BTREE      |         |               |

| obj   |          1 | partition |            3 | tid         | A         |    28253069 |     NULL | NULL   |      | BTREE      |         |               |

| obj   |          1 | data_id   |            1 | data_id     | A         |    28253069 |     NULL | NULL   | YES  | BTREE      |         |               |

+-------+------------+-----------+--------------+-------------+-----------+-------------+----------+--------+------+------------+---------+---------------+

7 rows in set (0.01 sec)

MariaDB [neo1]> show table status like 'obj'\G

*************************** 1. row ***************************

           Name: obj

         Engine: TokuDB

        Version: 10

     Row_format: Fixed

           Rows: 28253276

 Avg_row_length: 33

    Data_length: 957477808

Max_data_length: 9223372036854775807

   Index_length: 1779148337

      Data_free: 913293312

 Auto_increment: NULL

    Create_time: 2016-08-16 10:33:02

    Update_time: 2016-09-21 22:05:35

     Check_time: NULL

      Collation: utf8_unicode_ci

       Checksum: NULL

 Create_options:

        Comment:

1 row in set (0.00 sec)

Another example:

https://lab.nexedi.com/nexedi/neoppod/commit/13911ca3

Kirill Smelkov added a comment - 2016-09-21 21:25 Hello up there MariaDB team, I'm currently debugging performance anomalies in MariaDB under NEO , when same queries are usually executed fast, but sometimes badly slow. I've discovered that some (not all) of such cases happen because wrong query execution plan is somehow selected by optimizer. Why optimizer makes such decision is a question. For simple cases in a couple of times we can hopefully paper the problem over with things like FORCE INDEX , but since this issue is starting to appear regularly in many different places it is better to understand the root cause and fix problem there. That's where optimizer trace would be very handy - to get info from the system about why such-and-such query execution decision has been made. With this message I'd like to provide to MariaDB team feedback that optimizer trace is needed in real-life since on production instances we cannot use debug builds and get info from DBUG. I provide examples of some anomalies in appendix for the reference. Thanks beforehand, Kirill P.S. My familiarity with MariaDB is only several days, so please forgive me in advance some possibly silly mistakes. /cc ratzpo (@ratzpo) Appendix MariaDB 10.1.17. TokuDB is used as storage engine. Example of bad query caught in slow log: # Time: 160921 10:47:15 # User@Host: root[root] @ localhost [] # Thread_id: 6 Schema: neo1 QC_hit: No # Query_time: 4.118192 Lock_time: 0.000024 Rows_sent: 0 Rows_examined: 8476058 # Rows_affected: 0 # # explain: id select_type table type possible_keys key key_len ref rows r_rows filtered r_filtered Extra # explain: 1 SIMPLE obj ref PRIMARY,partition partition 10 const,const 1 8476058.00 100.00 0.00 Using where; Using index # SET timestamp=1474447635; SELECT tid FROM obj WHERE `partition`=5 AND oid=79613 AND tid>268544235197088772 ORDER BY tid LIMIT 1; Similar query caught in process list with analyze: MariaDB [neo1]> show processlist; +----+------+-----------+------+---------+------+----------------------------+------------------------------------------------------------------------------------------------------+----------+ | Id | User | Host | db | Command | Time | State | Info | Progress | +----+------+-----------+------+---------+------+----------------------------+------------------------------------------------------------------------------------------------------+----------+ | 3 | root | localhost | neo0 | Sleep | 8 | | NULL | 0.000 | | 4 | root | localhost | neo2 | Sleep | 15 | | NULL | 0.000 | | 5 | root | localhost | neo3 | Sleep | 11 | | NULL | 0.000 | | 6 | root | localhost | neo1 | Query | 3 | Queried about 7710000 rows | SELECT tid FROM obj WHERE `partition`=5 AND oid=79613 AND tid>268544341634012678 ORDER BY tid LIMIT | 0.000 | | 10 | root | localhost | neo1 | Query | 0 | init | show processlist | 0.000 | +----+------+-----------+------+---------+------+----------------------------+------------------------------------------------------------------------------------------------------+----------+ 5 rows in set (0.00 sec) MariaDB [neo1]> show explain for 6; +------+-------------+-------+------+-------------------+-----------+---------+-------------+------+------------------------------------------+ | id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra | +------+-------------+-------+------+-------------------+-----------+---------+-------------+------+------------------------------------------+ | 1 | SIMPLE | obj | ref | PRIMARY,partition | partition | 10 | const,const | 1 | Using where; Using index; Using filesort | +------+-------------+-------+------+-------------------+-----------+---------+-------------+------+------------------------------------------+ 1 row in set, 1 warning (0.01 sec) The same query in normal case: MariaDB [neo1]> explain SELECT tid FROM obj WHERE `partition`=5 AND oid=79613 AND tid>268544341634012678 ORDER BY tid LIMIT 1; +------+-------------+-------+-------+-------------------+-----------+---------+------+------+--------------------------+ | id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra | +------+-------------+-------+-------+-------------------+-----------+---------+------+------+--------------------------+ | 1 | SIMPLE | obj | range | PRIMARY,partition | partition | 18 | NULL | 1295 | Using where; Using index | +------+-------------+-------+-------+-------------------+-----------+---------+------+------+--------------------------+ 1 row in set (0.00 sec) MariaDB [neo1]> analyze SELECT tid FROM obj WHERE `partition`=5 AND oid=79613 AND tid>268544341634012678 ORDER BY tid LIMIT 1; +------+-------------+-------+-------+-------------------+-----------+---------+------+------+--------+----------+------------+--------------------------+ | id | select_type | table | type | possible_keys | key | key_len | ref | rows | r_rows | filtered | r_filtered | Extra | +------+-------------+-------+-------+-------------------+-----------+---------+------+------+--------+----------+------------+--------------------------+ | 1 | SIMPLE | obj | range | PRIMARY,partition | partition | 18 | NULL | 639 | 1.00 | 100.00 | 100.00 | Using where; Using index | +------+-------------+-------+-------+-------------------+-----------+---------+------+------+--------+----------+------------+--------------------------+ 1 row in set (0.00 sec) MariaDB [neo1]> SELECT tid FROM obj WHERE `partition`=5 AND oid=79613 AND tid>268544341634012678 ORDER BY tid LIMIT 1; +--------------------+ | tid | +--------------------+ | 268544342862377552 | +--------------------+ 1 row in set (0.00 sec) NOTE the difference: time: 4s vs < 0.01s type: 'ref' vs 'range' key_len: 10 vs 18 (partition, oid) vs (partition, oid, tid) ref: const,const vs NULL "Using filesort" For the reference: MariaDB [neo1]> describe obj; +-----------+----------------------+------+-----+---------+-------+ | Field | Type | Null | Key | Default | Extra | +-----------+----------------------+------+-----+---------+-------+ | partition | smallint(5) unsigned | NO | PRI | NULL | | | oid | bigint(20) unsigned | NO | PRI | NULL | | | tid | bigint(20) unsigned | NO | PRI | NULL | | | data_id | bigint(20) unsigned | YES | MUL | NULL | | | value_tid | bigint(20) unsigned | YES | | NULL | | +-----------+----------------------+------+-----+---------+-------+ 5 rows in set (0.00 sec) MariaDB [neo1]> show index from obj; +-------+------------+-----------+--------------+-------------+-----------+-------------+----------+--------+------+------------+---------+---------------+ | Table | Non_unique | Key_name | Seq_in_index | Column_name | Collation | Cardinality | Sub_part | Packed | Null | Index_type | Comment | Index_comment | +-------+------------+-----------+--------------+-------------+-----------+-------------+----------+--------+------+------------+---------+---------------+ | obj | 0 | PRIMARY | 1 | partition | A | 28253069 | NULL | NULL | | BTREE | | | | obj | 0 | PRIMARY | 2 | tid | A | 28253069 | NULL | NULL | | BTREE | | | | obj | 0 | PRIMARY | 3 | oid | A | 28253069 | NULL | NULL | | BTREE | | | | obj | 1 | partition | 1 | partition | A | 28253069 | NULL | NULL | | BTREE | | | | obj | 1 | partition | 2 | oid | A | 28253069 | NULL | NULL | | BTREE | | | | obj | 1 | partition | 3 | tid | A | 28253069 | NULL | NULL | | BTREE | | | | obj | 1 | data_id | 1 | data_id | A | 28253069 | NULL | NULL | YES | BTREE | | | +-------+------------+-----------+--------------+-------------+-----------+-------------+----------+--------+------+------------+---------+---------------+ 7 rows in set (0.01 sec) MariaDB [neo1]> show table status like 'obj'\G *************************** 1. row *************************** Name: obj Engine: TokuDB Version: 10 Row_format: Fixed Rows: 28253276 Avg_row_length: 33 Data_length: 957477808 Max_data_length: 9223372036854775807 Index_length: 1779148337 Data_free: 913293312 Auto_increment: NULL Create_time: 2016-08-16 10:33:02 Update_time: 2016-09-21 22:05:35 Check_time: NULL Collation: utf8_unicode_ci Checksum: NULL Create_options: Comment: 1 row in set (0.00 sec) Another example: https://lab.nexedi.com/nexedi/neoppod/commit/13911ca3

Julien Muchembled made changes - 2017-06-02 13:37

Link

This issue relates to MDEV-12980 [ MDEV-12980 ]

Alex/AT made changes - 2017-11-15 06:40

Comment

[ Alas, optimizer w/TokuDB seems to be tremendously broken after 10.1.23.
The only recommendation I've got is to create a ticket on Percona for that, still not done though.
Stay on 10.1.23 for now if you want it stable. ]

Julien Fritsch made changes - 2017-12-15 20:30

Link

This issue is part of MDEV-14666 [ MDEV-14666 ]

Julien Fritsch made changes - 2017-12-15 22:35

Link

This issue is part of PT-67 [ PT-67 ]

Vicențiu Ciorbaru made changes - 2018-03-01 19:52

Labels

optimizer

gsoc18 optimizer

Vicențiu Ciorbaru made changes - 2018-03-01 19:52

Assignee

Sergei Petrunia [ psergey ]

Sergei Golubchik made changes - 2018-03-01 19:55

Description

port optimizer trace from 5.6

Sergei Petrunia added a comment - 2018-05-04 13:46 - edited

Some ideas about features we should have: https://lists.launchpad.net/maria-developers/msg11266.html

Sergei Petrunia added a comment - 2018-05-04 13:46 - edited Some ideas about features we should have: https://lists.launchpad.net/maria-developers/msg11266.html

Sergei Petrunia added a comment - 2018-05-04 14:26 - edited

Ideas about features/milestones: https://lists.launchpad.net/maria-developers/msg11267.html

Sergei Petrunia added a comment - 2018-05-04 14:26 - edited Ideas about features/milestones: https://lists.launchpad.net/maria-developers/msg11267.html

Varun Gupta (Inactive) made changes - 2018-09-25 09:41

Assignee

Sergei Petrunia [ psergey ]

Varun Gupta [ varun ]

Varun Gupta (Inactive) added a comment - 2018-09-26 15:01 - edited

Takes from MYSQL's implementation

INFOMATMATION_SCHEMA.OPTIMIZER_TRACE

The table has the following fields

QUERY
Trace
MISSING_BYTES_BEYOND_MAX_MEM_SIZE
INSUFFICIENT_PRIVILEGES

Queries to trace

They are: SELECT; INSERT or REPLACE (with VALUES or SELECT); UPDATE/DELETE and their multi-table variants; all the previous ones prefixed by EXPLAIN; SET (unless it manipulates the optimizer_trace system variable); DO; DECLARE/CASE/IF/RETURN (stored routines language elements); CALL. If one of those statements is prepared and executed in separate steps, preparation and execution are separately traced.

Trace purging

By default, each new trace overwrites the previous trace. Thus, if a statement contains substatements (example: invokes stored procedures, stored functions, triggers), the top statement and substatements each generate one trace, but at the execution's end only the last substatement's trace is visible. A user who wants to see the trace of another substatement, can enable/disable tracing around the desired substatement, but this requires editing the routine's code, which may not be possible. Another solution is to tune trace purging.

SET optimizer_trace_offset=<OFFSET>, optimizer_trace_limit=<LIMIT>

The optimizer_trace System Variable

enabled: allows to enable/disable tracing
During disabling, we need to make sure that we remove DBUG_PRINT and use the optimizer trace to write to the trace file. Avoid duplication of code.
one_line: if on, the trace will have no whitespace; it's unreadable for humans but readable for JSON parsers (they ignore whitespace); the only advantage is a saving on space.

Selecting Optimizer Features to Trace

Those features can be excluded from tracing using the optimizer_trace_features system variable, which has these on/off switches

Security

INFORMATION_SCHEMA.OPTIMIZER_TRACE.INSUFFICIENT_PRIVILEGES
Who can view optimizer_trace?

INFORMATION_SCHEMA.OPTIMIZER_TRACE.INSUFFICIENT_PRIVILEGE
If a traced query uses views or stored routines that have SQL SECURITY with a value of DEFINER, it may be that a user other than the definer is denied from seeing the trace of the query. In that case, the trace is shown as empty and INSUFFICIENT_PRIVILEGES has a value of 1. Otherwise, the value is 0.

Varun Gupta (Inactive) added a comment - 2018-09-26 15:01 - edited Takes from MYSQL's implementation INFOMATMATION_SCHEMA.OPTIMIZER_TRACE The table has the following fields QUERY Trace MISSING_BYTES_BEYOND_MAX_MEM_SIZE INSUFFICIENT_PRIVILEGES Queries to trace They are: SELECT; INSERT or REPLACE (with VALUES or SELECT); UPDATE/DELETE and their multi-table variants; all the previous ones prefixed by EXPLAIN; SET (unless it manipulates the optimizer_trace system variable); DO; DECLARE/CASE/IF/RETURN (stored routines language elements); CALL. If one of those statements is prepared and executed in separate steps, preparation and execution are separately traced. Trace purging By default, each new trace overwrites the previous trace. Thus, if a statement contains substatements (example: invokes stored procedures, stored functions, triggers), the top statement and substatements each generate one trace, but at the execution's end only the last substatement's trace is visible. A user who wants to see the trace of another substatement, can enable/disable tracing around the desired substatement, but this requires editing the routine's code, which may not be possible. Another solution is to tune trace purging. SET optimizer_trace_offset=<OFFSET>, optimizer_trace_limit=<LIMIT> The optimizer_trace System Variable enabled: allows to enable/disable tracing During disabling, we need to make sure that we remove DBUG_PRINT and use the optimizer trace to write to the trace file. Avoid duplication of code. one_line: if on, the trace will have no whitespace; it's unreadable for humans but readable for JSON parsers (they ignore whitespace); the only advantage is a saving on space. Selecting Optimizer Features to Trace Those features can be excluded from tracing using the optimizer_trace_features system variable, which has these on/off switches Security INFORMATION_SCHEMA.OPTIMIZER_TRACE.INSUFFICIENT_PRIVILEGES Who can view optimizer_trace? INFORMATION_SCHEMA.OPTIMIZER_TRACE.INSUFFICIENT_PRIVILEGE If a traced query uses views or stored routines that have SQL SECURITY with a value of DEFINER, it may be that a user other than the definer is denied from seeing the trace of the query. In that case, the trace is shown as empty and INSUFFICIENT_PRIVILEGES has a value of 1. Otherwise, the value is 0.

Varun Gupta (Inactive) made changes - 2018-10-08 20:31

Status

Open [ 1 ]

In Progress [ 3 ]

Varun Gupta (Inactive) added a comment - 2018-10-30 07:54

The branch is 10.4-mdev6111

Varun Gupta (Inactive) added a comment - 2018-10-30 07:54 The branch is 10.4-mdev6111

Sergei Petrunia added a comment - 2018-11-02 13:12

https://jira.mariadb.org/browse/MDEV-13744 is an example where opt trace would be useful- to check whether loose scan was considered (and see that it was, but was discarded because it wasn't worth it)

Sergei Petrunia added a comment - 2018-11-02 13:12 https://jira.mariadb.org/browse/MDEV-13744 is an example where opt trace would be useful- to check whether loose scan was considered (and see that it was, but was discarded because it wasn't worth it)

Sergei Petrunia added a comment - 2018-11-14 07:23

Takeaways from yesterday discussion:

It would be nice to select parts of the trace somehow.
MySQL allows to control whether certain parts of the optimizer emit the trace: it has @@optimizer_trace_features where one can tune these flags: greedy_search,range_optimizer,dynamic_range,repeated_subselect.
Can one use JSON functions to select parts of the trace?

Sergei Petrunia added a comment - 2018-11-14 07:23 Takeaways from yesterday discussion: It would be nice to select parts of the trace somehow. MySQL allows to control whether certain parts of the optimizer emit the trace: it has @@optimizer_trace_features where one can tune these flags: greedy_search,range_optimizer,dynamic_range,repeated_subselect. Can one use JSON functions to select parts of the trace?

Sergei Petrunia made changes - 2018-11-14 07:28

Attachment

screenshot-1.png [ 46685 ]

Sergei Petrunia added a comment - 2018-11-14 07:29

Example from the call: range optimization. A trace from mysql-8: [^mdev6111-example-trace-from-mysql8.json] .
There is a JSONPath language which allows to select all range_analysis nodes like so: $..range_analysis (you can check this online at http://jsonpath.com/). It is not clear which of the objects refers to which table, though.

Sergei Petrunia added a comment - 2018-11-14 07:29 Example from the call: range optimization. A trace from mysql-8: [^mdev6111-example-trace-from-mysql8.json] . There is a JSONPath language which allows to select all range_analysis nodes like so: $..range_analysis (you can check this online at http://jsonpath.com/ ). It is not clear which of the objects refers to which table, though.

Sergei Petrunia added a comment - 2018-11-14 07:35

JSON example I was using: [^mdev6111-example-trace-from-mysql8.json.txt]

Sergei Petrunia added a comment - 2018-11-14 07:35 JSON example I was using: [^mdev6111-example-trace-from-mysql8.json.txt]

Sergei Petrunia added a comment - 2018-11-14 07:36

Another attempt mdev6111-example-trace-from-mysql8.txt

Sergei Petrunia added a comment - 2018-11-14 07:36 Another attempt mdev6111-example-trace-from-mysql8.txt

Sergei Petrunia made changes - 2018-11-14 07:36

Attachment

mdev6111-example-trace-from-mysql8.txt [ 46686 ]

Sergei Petrunia added a comment - 2018-11-14 07:51

... However, MariaDB's JSON function do not allow to compute JSON paths? I tried JSON_EXTRACT and others, none could achieve what I wanted - extract all nodes in the document with the name range_analysis.

Sergei Petrunia added a comment - 2018-11-14 07:51 ... However, MariaDB's JSON function do not allow to compute JSON paths? I tried JSON_EXTRACT and others, none could achieve what I wanted - extract all nodes in the document with the name range_analysis .

Sergei Petrunia added a comment - 2018-11-14 07:53

As for pretty-printing, there is JSON_DETAILED function but its output is not as beautiful as the one that EXPLAIN FORMAT=JSON pretty-printer produces.

Example:

                                            "key_parts":

"a"

],

                                    "setup_range_conditions":

],

Sergei Petrunia added a comment - 2018-11-14 07:53 As for pretty-printing, there is JSON_DETAILED function but its output is not as beautiful as the one that EXPLAIN FORMAT=JSON pretty-printer produces. Example: "key_parts": [ "a" ] } ], "setup_range_conditions": [ ],

Sergei Petrunia added a comment - 2018-11-14 09:11

WIth holyfoot's and Serg's input:

mysql> select  JSON_DETAILED(JSON_EXTRACT(a, '$**.range_analysis')) from t20\G

*************************** 1. row ***************************

JSON_DETAILED(JSON_EXTRACT(a, '$**.range_analysis')): [

        "table_scan":

            "rows": 1000,

            "cost": 103.1

},

        "potential_range_indexes":

                "index": "a",

                "usable": true,

                "key_parts":

"a"

],

        "setup_range_conditions":

],

so, it is possible to extract parts of trace using JSON function. You'll need to re-format them, and formatter is not perfect, but still.

Sergei Petrunia added a comment - 2018-11-14 09:11 WIth holyfoot 's and Serg's input: mysql> select JSON_DETAILED(JSON_EXTRACT(a, '$**.range_analysis')) from t20\G *************************** 1. row *************************** JSON_DETAILED(JSON_EXTRACT(a, '$**.range_analysis')): [ { "table_scan": { "rows": 1000, "cost": 103.1 }, "potential_range_indexes": [ { "index": "a", "usable": true, "key_parts": [ "a" ] } ], "setup_range_conditions": [ ], so, it is possible to extract parts of trace using JSON function. You'll need to re-format them, and formatter is not perfect, but still.

Ralf Gebhardt made changes - 2018-11-14 11:02

Epic Link

PT-76 [ 68557 ]

Ralf Gebhardt made changes - 2018-11-14 11:12

Team

Server DEV

Sergei Petrunia made changes - 2018-12-07 14:01

Link

This issue includes ~~MDEV-17929~~ [ ~~MDEV-17929~~ ]

Sergei Petrunia made changes - 2018-12-07 14:50

Link

This issue includes ~~MDEV-17930~~ [ ~~MDEV-17930~~ ]

Varun Gupta (Inactive) made changes - 2018-12-26 19:58

Fix Version/s

10.4 [ 22408 ]

Varun Gupta (Inactive) made changes - 2019-01-02 12:48

Link

This issue includes ~~MDEV-18117~~ [ ~~MDEV-18117~~ ]

Varun Gupta (Inactive) made changes - 2019-01-02 22:12

Assignee	Varun Gupta [ varun ]	Sergei Petrunia [ psergey ]
Status	In Progress [ 3 ]	In Review [ 10002 ]

Sergei Petrunia made changes - 2019-01-18 19:04

Link

This issue includes ~~MDEV-18306~~ [ ~~MDEV-18306~~ ]

Sergei Petrunia made changes - 2019-01-18 22:09

Link

This issue includes ~~MDEV-18172~~ [ ~~MDEV-18172~~ ]

Varun Gupta (Inactive) made changes - 2019-02-06 06:44

Link

This issue includes ~~MDEV-18489~~ [ ~~MDEV-18489~~ ]

Sergei Petrunia made changes - 2019-02-09 16:28

Link

This issue relates to ~~MDEV-18527~~ [ ~~MDEV-18527~~ ]

Sergei Petrunia made changes - 2019-02-09 16:38

Link

This issue relates to ~~MDEV-18528~~ [ ~~MDEV-18528~~ ]

Sergei Petrunia made changes - 2019-02-14 17:04

Assignee	Sergei Petrunia [ psergey ]	Varun Gupta [ varun ]
Status	In Review [ 10002 ]	Stalled [ 10000 ]

Varun Gupta (Inactive) made changes - 2019-02-18 11:52

Component/s		Optimizer [ 10200 ]
Fix Version/s		10.4.3 [ 23230 ]
Fix Version/s	10.4 [ 22408 ]
Resolution		Fixed [ 1 ]
Status	Stalled [ 10000 ]	Closed [ 6 ]

Ian Gilfillan made changes - 2019-02-20 23:08

Link

This issue relates to ~~MDEV-18670~~ [ ~~MDEV-18670~~ ]

Sergei Petrunia made changes - 2019-02-26 22:07

Link

This issue relates to ~~MDEV-18741~~ [ ~~MDEV-18741~~ ]

Sergei Petrunia made changes - 2019-04-03 13:44

Link

This issue relates to ~~MDEV-19160~~ [ ~~MDEV-19160~~ ]

Sergei Petrunia made changes - 2019-04-10 07:56

Link

This issue relates to MDEV-18822 [ MDEV-18822 ]

Sergei Petrunia added a comment - 2019-08-13 13:11

Pushed this:

https://github.com/MariaDB/server/commit/2dbe472ed011a951b28434ae8e67945e964d2030

Optimizer trace: print cost and #rows of the join prefix

The names rows_for_plan and cost_for_plan follow MySQL

Also added post-join-operation selectivity cost

Sergei Petrunia added a comment - 2019-08-13 13:11 Pushed this: https://github.com/MariaDB/server/commit/2dbe472ed011a951b28434ae8e67945e964d2030 Optimizer trace: print cost and #rows of the join prefix The names rows_for_plan and cost_for_plan follow MySQL Also added post-join-operation selectivity cost

Sergei Petrunia added a comment - 2019-08-25 08:08 - edited

Pushed this:

http://lists.askmonty.org/pipermail/commits/2019-August/013945.html

http://lists.askmonty.org/pipermail/commits/2019-August/013945.html

commit 4a490d1a993959222deb8bae822f40575586a148 (HEAD -> 10.4, origin/HEAD, origin/10.4, tmp10)

Author: Sergei Petrunia <psergey@askmonty.org>

Date:   Sun Aug 25 11:03:19 2019 +0300

    MDEV-6111: Optimizer Trace: add tracing for semi-join optimizations

    Added:

    - "semijoin_strategy_choice" element (actions in advance_sj_state(), name

      matches the name in MySQL)

    - semijoin_table_pullout element.

UPDATE: filed a MDEV to track the above patch: ~~MDEV-20440~~.

Sergei Petrunia added a comment - 2019-08-25 08:08 - edited Pushed this: http://lists.askmonty.org/pipermail/commits/2019-August/013945.html http://lists.askmonty.org/pipermail/commits/2019-August/013945.html commit 4a490d1a993959222deb8bae822f40575586a148 (HEAD -> 10.4, origin/HEAD, origin/10.4, tmp10) Author: Sergei Petrunia <psergey@askmonty.org> Date: Sun Aug 25 11:03:19 2019 +0300 MDEV-6111: Optimizer Trace: add tracing for semi-join optimizations Added: - "semijoin_strategy_choice" element (actions in advance_sj_state(), name matches the name in MySQL) - semijoin_table_pullout element. UPDATE : filed a MDEV to track the above patch: MDEV-20440 .

Sergei Petrunia made changes - 2019-08-28 09:46

Link

This issue relates to ~~MDEV-20440~~ [ ~~MDEV-20440~~ ]

Varun Gupta (Inactive) made changes - 2019-08-29 06:20

Link

This issue relates to ~~MDEV-20444~~ [ ~~MDEV-20444~~ ]

Marko Mäkelä made changes - 2019-10-25 10:46

Link

This issue relates to MENT-455 [ MENT-455 ]

Sergei Golubchik made changes - 2021-12-06 21:22

Workflow

MariaDB v3 [ 61431 ]

MariaDB v4 [ 132320 ]

People

Assignee:: Varun Gupta (Inactive)

Reporter:: Sergei Golubchik

Votes:: 10 Vote for this issue

Watchers:: 17 Start watching this issue

Dates

Created:: 2014-04-15 20:12

Updated:: 2023-05-16 14:01

Resolved:: 2019-02-18 11:52

Git Integration

Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.

MariaDB Server

Details

Description

Attachments

Attachments

Issue Links

Activity

Appendix

INFOMATMATION_SCHEMA.OPTIMIZER_TRACE

Queries to trace

Trace purging

The optimizer_trace System Variable

Selecting Optimizer Features to Trace

Security

People

Dates

Git Integration