Profiling

SHOW PROFILE

SHOW PROFILE is an SQL statement that shows a detailed execution profile of the previous SQL statement executed in the current SQL session. Also, profiling must be enabled in the current session before running the statement to be instrumented. That can be done with a SET profiling=1 statement. By default, profiling is disabled to avoid potential performance implications, and therefore the profile will be empty.

  • Status column briefly describes where exactly (in which state) was the time spent.
  • Duration column shows the wall clock time, in seconds.
  • Switches column displays the number of times query engine changed to the given state. Those are just logical engine state switches and not any OS level context switches nor function calls (even though some of the sections can actually map to function calls) and they do not have any direct effect on the performance. In a sense, number of switches is just a number of times when the respective instrumentation point was hit.
  • Percent column shows the percentage of time spent in this state.
  • SQL

SQL

  1. SET profiling=1;
  3. SELECT id FROM forum WHERE MATCH('the best') LIMIT 1;
  5. SHOW PROFILE;

Response

  1. Query OK, 0 rows affected (0.00 sec)
  3. +--------+
  4. | id     |
  5. +--------+
  6. | 241629 |
  7. +--------+
  8. 1 row in set (0.35 sec)
  10. +--------------+----------+----------+---------+
  11. | Status       | Duration | Switches | Percent |
  12. +--------------+----------+----------+---------+
  13. | unknown      | 0.000557 | 5        | 0.16    |
  14. | net_read     | 0.000016 | 1        | 0.00    |
  15. | local_search | 0.000076 | 1        | 0.02    |
  16. | sql_parse    | 0.000121 | 1        | 0.03    |
  17. | dict_setup   | 0.000003 | 1        | 0.00    |
  18. | parse        | 0.000072 | 1        | 0.02    |
  19. | transforms   | 0.000331 | 2        | 0.10    |
  20. | init         | 0.001945 | 3        | 0.56    |
  21. | read_docs    | 0.001257 | 76       | 0.36    |
  22. | read_hits    | 0.002598 | 186      | 0.75    |
  23. | get_docs     | 0.089328 | 2691     | 25.80   |
  24. | get_hits     | 0.189626 | 2799     | 54.78   |
  25. | filter       | 0.009369 | 2613     | 2.71    |
  26. | rank         | 0.029669 | 7760     | 8.57    |
  27. | sort         | 0.019070 | 2531     | 5.51    |
  28. | finalize     | 0.000001 | 1        | 0.00    |
  29. | clone_attrs  | 0.002009 | 1        | 0.58    |
  30. | aggregate    | 0.000054 | 2        | 0.02    |
  31. | net_write    | 0.000076 | 2        | 0.02    |
  32. | eval_post    | 0.000001 | 1        | 0.00    |
  33. | total        | 0.346179 | 18678    | 0       |
  34. +--------------+----------+----------+---------+
  35. 21 rows in set (0.00 sec)

States in the profile are returned in a prerecorded order that roughly maps (but is not identical) to the actual query order.

A list of states may (and will) vary over time, as we refine the states. Here’s a brief description of the currently profiled states.

  • unknown: generic catch-all state. Accounts for both not-yet-instrumented code, or just small miscellaneous tasks that do not really belong in any other state, but are too small to deserve their own state.
  • net_read: reading the query from the network (that is, the application).
  • io: generic file IO time.
  • dist_connect: connecting to remote agents in the distributed table case.
  • sql_parse: parsing the SQL syntax.
  • dict_setup: dictionary and tokenizer setup.
  • parse: parsing the full-text query syntax.
  • transforms: full-text query transformations (wildcard and other expansions, simplification, etc).
  • init: initializing the query evaluation.
  • open: opening the table files.
  • read_docs: IO time spent reading document lists.
  • read_hits: IO time spent reading keyword positions.
  • get_docs: computing the matching documents.
  • get_hits: computing the matching positions.
  • filter: filtering the full-text matches.
  • rank: computing the relevance rank.
  • sort: sorting the matches.
  • finalize: finalizing the per-table search result set (last stage expressions, etc).
  • dist_wait: waiting for the remote results from the agents in the distributed table case.
  • aggregate: aggregating multiple result sets.
  • net_write: writing the result set to the network.

Query profiling in HTTP JSON

You can view the final transformed query tree with all normalized keywords by adding a "profile":true property:

  1. {
  2.   "index":"test",
  3.   "profile":true,
  4.   "query":
  5.   {
  6.     "match_phrase": { "_all" : "had grown quite" }
  7.   }
  8. }

This feature is somewhat similar to SHOW PLAN statement in SQL. The result appears as a profile property in the result set. For example:

  1. "profile":
  2. {
  3.   "query":
  4.   {
  5.     "type": "PHRASE",
  6.     "description": "PHRASE( AND(KEYWORD(had, querypos=1)),  AND(KEYWORD(grown, querypos=2)),  AND(KEYWORD(quite, querypos=3)))",
  7.     "children":
  8.     [
  9.       {
  10.         "type": "AND",
  11.         "description": "AND(KEYWORD(had, querypos=1))",
  12.         "max_field_pos": 0,
  13.         "children":
  14.         [
  15.           {
  16.             "type": "KEYWORD",
  17.             "word": "had",
  18.             "querypos": 1
  19.            }
  20.         ]
  21.       },
  22.       {
  23.         "type": "AND",
  24.         "description": "AND(KEYWORD(grown, querypos=2))",
  25.         "max_field_pos": 0,
  26.         "children":
  27.         [
  28.           {
  29.             "type": "KEYWORD",
  30.             "word": "grown",
  31.             "querypos": 2
  32.           }
  33.         ]
  34.       },
  35.       {
  36.         "type": "AND",
  37.         "description": "AND(KEYWORD(quite, querypos=3))",
  38.         "max_field_pos": 0,
  39.         "children":
  40.         [
  41.           {
  42.             "type": "KEYWORD",
  43.             "word": "quite",
  44.             "querypos": 3
  45.           }
  46.         ]
  47.       }
  48.     ]
  49.   }
  50. }

query property contains the transformed full-text query tree. Each node contains:

  • type: node type. Can be AND, OR, PHRASE, KEYWORD etc
  • description: query subtree for this node shown as a string (in SHOW PLAN format)
  • children: child nodes, if any
  • max_field_pos: maximum position within a field
  • word: transformed keyword. Keyword nodes only
  • querypos: position of this keyword in a query. Keyword nodes only
  • excluded: keyword excluded from query. Keyword nodes only
  • expanded: keyword added by prefix expansion. Keyword nodes only
  • field_start: keyword must occur at the very start of the field. Keyword nodes only
  • field_end: keyword must occur at the very end of the field. Keyword nodes only
  • boost: keyword IDF will be multiplied by this. Keyword nodes only

Query plan

SHOW PLAN is an SQL statement that displays the execution plan of the previous SELECT statement. The plan gets generated and stored during the actual execution, so profiling must be enabled in the current session before running that statement. That can be done with a SET profiling=1 statement.

To view query execution plan in JSON queries, add "profile":true to the query. The result appears as a profile property in the result set.

Note, there are 2 things returned in the SQL mode:

  • transformed_tree which shows the full-text query decomposition
  • enabled_indexes which shows information about effective secondary indexes
  • SQL
  • JSON

SQL JSON

  1. set profiling=1;
  3. select * from hn_small where match('dog|cat') limit 0;
  5. show plan;
  1. POST /search
  2. {
  3.   "index": "hn_small",
  4.   "query": {"query_string": "dog|cat"},
  5.   "_source": { "excludes":["*"] },
  6.   "limit": 0,
  7.   "profile":true
  8. }

Response

  1. *************************** 1. row ***************************
  2. Variable: transformed_tree
  3.    Value: OR(
  4.   AND(KEYWORD(dog, querypos=1)),
  5.   AND(KEYWORD(cat, querypos=2)))
  6. *************************** 2. row ***************************
  7. Variable: enabled_indexes
  8.    Value:
  9. 2 rows in set (0.00 sec)
  1. {
  2.   "took": 0,
  3.   "timed_out": false,
  4.   "hits": {
  5.     "total": 4453,
  6.     "total_relation": "eq",
  7.     "hits": []
  8.   },
  9.   "profile": {
  10.     "query": {
  11.       "type": "OR",
  12.       "description": "OR( AND(KEYWORD(dog, querypos=1)),  AND(KEYWORD(cat, querypos=2)))",
  13.       "children": [
  14.         {
  15.           "type": "AND",
  16.           "description": "AND(KEYWORD(dog, querypos=1))",
  17.           "children": [
  18.             {
  19.               "type": "KEYWORD",
  20.               "word": "dog",
  21.               "querypos": 1
  22.             }
  23.           ]
  24.         },
  25.         {
  26.           "type": "AND",
  27.           "description": "AND(KEYWORD(cat, querypos=2))",
  28.           "children": [
  29.             {
  30.               "type": "KEYWORD",
  31.               "word": "cat",
  32.               "querypos": 2
  33.             }
  34.           ]
  35.         }
  36.       ]
  37.     }
  38.   }
  39. }

In some cases the evaluated query tree can be rather different from the original one because of expansions and other transformations.

  • SQL
  • JSON

SQL JSON

  1. SET profiling=1;
  3. SELECT id FROM forum WHERE MATCH('@title way* @content hey') LIMIT 1;
  5. SHOW PLAN;
  1. POST /search
  2. {
  3.   "index": "forum",
  4.   "query": {"query_string": "@title way* @content hey"},
  5.   "_source": { "excludes":["*"] },
  6.   "limit": 1,
  7.   "profile": true
  8. }

Response

  1. Query OK, 0 rows affected (0.00 sec)
  3. +--------+
  4. | id     |
  5. +--------+
  6. | 711651 |
  7. +--------+
  8. 1 row in set (0.04 sec)
  10. +------------------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
  11. | Variable         | Value                                                                                                                                                                                                                                                                                                                                                                                                                   |
  12. +------------------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
  13. | transformed_tree | AND(
  14.   OR(
  15.     OR(
  16.       AND(fields=(title), KEYWORD(wayne, querypos=1, expanded)),
  17.       OR(
  18.         AND(fields=(title), KEYWORD(ways, querypos=1, expanded)),
  19.         AND(fields=(title), KEYWORD(wayyy, querypos=1, expanded)))),
  20.     AND(fields=(title), KEYWORD(way, querypos=1, expanded)),
  21.     OR(fields=(title), KEYWORD(way*, querypos=1, expanded))),
  22.   AND(fields=(content), KEYWORD(hey, querypos=2))) |
  23. +------------------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
  24. 1 row in set (0.00 sec)
  1. {
  2.   "took":33,
  3.   "timed_out":false,
  4.   "hits":
  5.   {
  6.     "total":105,
  7.     "hits":
  8.     [
  9.        {
  10.           "_id":"711651",
  11.           "_score":2539,
  12.           "_source":{}
  13.        }
  14.     ]
  15.   },
  16.   "profile":
  17.   {
  18.     "query":
  19.     {
  20.       "type":"AND",
  21.       "description":"AND( OR( OR( AND(fields=(title), KEYWORD(wayne, querypos=1, expanded)),  OR( AND(fields=(title), KEYWORD(ways, querypos=1, expanded)),  AND(fields=(title), KEYWORD(wayyy, querypos=1, expanded)))),  AND(fields=(title), KEYWORD(way, querypos=1, expanded)),  OR(fields=(title), KEYWORD(way*, querypos=1, expanded))),  AND(fields=(content), KEYWORD(hey, querypos=2)))",
  22.       "children":
  23.       [
  24.         {
  25.           "type":"OR",
  26.           "description":"OR( OR( AND(fields=(title), KEYWORD(wayne, querypos=1, expanded)),  OR( AND(fields=(title), KEYWORD(ways, querypos=1, expanded)),  AND(fields=(title), KEYWORD(wayyy, querypos=1, expanded)))),  AND(fields=(title), KEYWORD(way, querypos=1, expanded)),  OR(fields=(title), KEYWORD(way*, querypos=1, expanded)))",
  27.           "children":
  28.           [
  29.             {
  30.                "type":"OR",
  31.                "description":"OR( AND(fields=(title), KEYWORD(wayne, querypos=1, expanded)),  OR( AND(fields=(title), KEYWORD(ways, querypos=1, expanded)),  AND(fields=(title), KEYWORD(wayyy, querypos=1, expanded))))",
  32.                "children":
  33.                [
  34.                  {
  35.                    "type":"AND",
  36.                    "description":"AND(fields=(title), KEYWORD(wayne, querypos=1, expanded))",
  37.                    "fields":["title"],
  38.                    "max_field_pos":0,
  39.                    "children":
  40.                    [
  41.                      {
  42.                        "type":"KEYWORD",
  43.                        "word":"wayne",
  44.                        "querypos":1,
  45.                        "expanded":true
  46.                      }
  47.                    ]
  48.                  },
  49.                  {
  50.                    "type":"OR",
  51.                    "description":"OR( AND(fields=(title), KEYWORD(ways, querypos=1, expanded)),  AND(fields=(title), KEYWORD(wayyy, querypos=1, expanded)))",
  52.                    "children":
  53.                    [
  54.                      {
  55.                        "type":"AND",
  56.                        "description":"AND(fields=(title), KEYWORD(ways, querypos=1, expanded))",
  57.                        "fields":["title"],
  58.                        "max_field_pos":0,
  59.                        "children":
  60.                        [
  61.                          {
  62.                            "type":"KEYWORD",
  63.                            "word":"ways",
  64.                            "querypos":1,
  65.                            "expanded":true
  66.                          }
  67.                        ]
  68.                      },
  69.                      {
  70.                        "type":"AND",
  71.                        "description":"AND(fields=(title), KEYWORD(wayyy, querypos=1, expanded))",
  72.                        "fields":["title"],
  73.                        "max_field_pos":0,
  74.                        "children":
  75.                        [
  76.                          {
  77.                            "type":"KEYWORD",
  78.                            "word":"wayyy",
  79.                            "querypos":1,
  80.                            "expanded":true
  81.                          }
  82.                        ]
  83.                      }
  84.                    ]
  85.                  }
  86.                ]
  87.             },
  88.             {
  89.               "type":"AND",
  90.               "description":"AND(fields=(title), KEYWORD(way, querypos=1, expanded))",
  91.               "fields":["title"],
  92.               "max_field_pos":0,
  93.               "children":
  94.               [
  95.                  {
  96.                     "type":"KEYWORD",
  97.                     "word":"way",
  98.                     "querypos":1,
  99.                     "expanded":true
  100.                  }
  101.               ]
  102.             },
  103.             {
  104.               "type":"OR",
  105.               "description":"OR(fields=(title), KEYWORD(way*, querypos=1, expanded))",
  106.               "fields":["title"],
  107.               "max_field_pos":0,
  108.               "children":
  109.               [
  110.                 {
  111.                   "type":"KEYWORD",
  112.                   "word":"way*",
  113.                   "querypos":1,
  114.                   "expanded":true
  115.                 }
  116.               ]
  117.             }
  118.           ]
  119.         },
  120.         {
  121.           "type":"AND",
  122.           "description":"AND(fields=(content), KEYWORD(hey, querypos=2))",
  123.           "fields":["content"],
  124.           "max_field_pos":0,
  125.           "children":
  126.           [
  127.             {
  128.               "type":"KEYWORD",
  129.               "word":"hey",
  130.               "querypos":2
  131.             }
  132.           ]
  133.         }
  134.       ]
  135.     }
  136.   }
  137. }

See also EXPLAIN QUERY. It displays the execution tree of a full-text query without actually executing the query.

JSON result set notes

query property contains the transformed fulltext query tree. Each node contains:

  • type: node type. Can be AND, OR, PHRASE, KEYWORD etc.
  • description: query subtree for this node shown as a string (in SHOW PLAN format)
  • children: child nodes, if any
  • max_field_pos: maximum position within a field
  • word: transformed keyword. Keyword nodes only.
  • querypos: position of this keyword in a query. Keyword nodes only.
  • excluded: keyword excluded from query. Keyword nodes only.
  • expanded: keyword added by prefix expansion. Keyword nodes only.
  • field_start: keyword must occur at the very start of the field. Keyword nodes only.
  • field_end: keyword must occur at the very end of the field. Keyword nodes only.
  • boost: keyword IDF will be multiplied by this. Keyword nodes only.

Dot format for SHOW PLAN

SHOW PLAN format=dot allows to return the full-text query execution tree in hierarchical format suitable for visualization by existing tools, for example https://dreampuf.github.io/GraphvizOnline :

  1. MySQL [(none)]> show plan option format=dot\G
  2. *************************** 1. row ***************************
  3. Variable: transformed_tree
  4.    Value: digraph "transformed_tree"
  5. {
  7. 0 [shape=record,style=filled,bgcolor="lightgrey" label="AND"]
  8. 0 -> 1
  9. 1 [shape=record,style=filled,bgcolor="lightgrey" label="AND"]
  10. 1 -> 2
  11. 2 [shape=record label="i | { querypos=1 }"]
  12. 0 -> 3
  13. 3 [shape=record,style=filled,bgcolor="lightgrey" label="AND"]
  14. 3 -> 4
  15. 4 [shape=record label="me | { querypos=2 }"]
  16. }

SHOW PLAN graphviz example