PROFILE
On this page
Provides detailed resources usage metrics about a query.
The output of this command can be visualized using Visual Explain.
Syntax
PROFILE <statement>;
Note
See the Remarks below for information about supported statements.
SHOW PROFILE [<JSON>] [PLAN <plan_id>] [PROCESS <process_id>] [INTO OUTFILE <file_name>] [EXTENDED] [UI] [ON NODE <node_id>];
Remarks
-
Prior to the 8.
1 release, PROFILE
could only be utilized on a manual basis.The command was appended to the beginning of the query to be profiled as shown above. Once the query finished executing, the SHOW PROFILE
command was run to obtain the profile results.This profiling method is called an explicit profile since the PROFILE
command is explicitly written with the query. -
Now SingleStore offers two automatic profiling (called "auto profiling" hereafter) methods:
FULL
andLITE
.Auto profiling and explicit profiling share the same query plans, but the difference between them is the level of statistic collecting. Currently, auto profiling is not the default setting. See Query Performance Tools for more details about auto profiling. -
For
ON NODE
the node specified must be an aggregator node.ON NODE
must be used withPROCESS
orPLAN
.---SupportedSHOW PROFILE PROCESS 4 ON NODE 17;SHOW PROFILE JSON PROCESS 4 ON NODE 17;SHOW PROFILE UI PROCESS 4 ON NODE 17;SHOW PROFILE EXTENDED PROCESS 4 ON NODE 17;SHOW PROFILE JSON EXTENDED PROCESS 4 ON NODE 17;SHOW PROFILE STATS PROCESS 4 ON NODE 17;SHOW PROFILE PLAN 4 ON NODE 17;SHOW PROFILE JSON PLAN 4 ON NODE 17;SHOW PROFILE UI PLAN 4 ON NODE 17;SHOW PROFILE EXTENDED PLAN 4 ON NODE 17;SHOW PROFILE JSON EXTENDED PLAN 4 ON NODE 17; -
When you run a
PROFILE
statement, it executes the associated statement and collects resource usage metrics about the statement.The PROFILE
command works withSELECT
,UPDATE
,INSERT .
, and. . SELECT DELETE
statements, but notINSERT
statements. -
After the query has executed, run the
SHOW PROFILE
statement to display the collected metrics.Like the EXPLAIN statement, SHOW PROFILE
displays query execution operations as a tree, where the operator at the top is the last executed before returning the result to the client, and operators below are executed before their parents; however,SHOW PROFILE
additionally displays resource usage metrics for the operators in the execution tree. -
To get more accurate resource usage metrics of a query, run the
PROFILE
statement twice followed by theSHOW PROFILE
statement.
Note
You must connected to the master aggregator when running this command on reference tables.
-
The
SHOW PROFILE JSON
command returns the profile information of a query in JSON (machine readable format).To get this information, run the PROFILE
command followed by theSHOW PROFILE JSON
command.This information includes detailed statistics about some operators and statistics on compilation time (displayed under compile_
).time_ stats See Example1 for details. -
If the variable
profile_
is set tofor_ debug ON
,SHOW PROFILE JSON
will output additional data that is useful for troubleshooting query optimizer issues.See more about this variable in the Non-Sync Variables List. See all possible additional data output in PROFILE JSON Metrics link. See an example of this below as well. -
Run the
SHOW PROFILE PLAN
command with a specificplan_
to display profile information (optionally in JSON format) for any plan in the cache that was run inid PROFILE
mode.For information related to plan_
, refer to the SHOW PLAN topic.id ---To display profile information for a specific planSHOW PROFILE PLAN 4;---To display the profile information for a specific plan in JSON formatSHOW PROFILE JSON PLAN 4;
-
To write the result of a profile query to a file, use the
INTO OUTFILE file_
clause.name It creates a new file at the specified location and writes the query profile details to the file. Enter the absolute path to the file as the file_
parameter.name The output file can be a JSON or a text file.
Note
If the file already exists, then SingleStore will throw an error.
-
To write the profile information of a query in JSON format to a file:
SHOW PROFILE JSON INTO OUTFILE '/tmp/testprof.json';
-
To write the profile information of a query to a text file:
SHOW PROFILE INTO OUTFILE '/tmp/testprof.txt';
-
To write the profile statistics of a specific plan ID to a file:
SHOW PROFILE PLAN 7 INTO OUTFILE '/tmp/profile_plan7.txt';
-
To write the profile statistics of a specific plan ID in JSON format to a file:
SHOW PROFILE JSON PLAN 7 INTO OUTFILE '/tmp/profjson_plan7.json';
-
The
SHOW PLAN [JSON] plan_
command displays theid EXPLAIN
plan of a query.Refer to SHOW PLAN for details. -
The
SHOW PROFILE EXTENDED
output includes the leaf query text.
Profiling a Hung Query
To get information on progress of a query and to debug queries with long execution times, run the PROFILE
statement in one connection and SHOW PROFILE PROCESS
in another connection.
PROFILE select_statement;
SHOW PROFILE;
Simultaneously, open another connection on the same aggregator (you can specify the aggregator node via the ON NODE
clause) and run the SHOW PROFILE PROCESS
statement while the PROFILE
statement is in progress:
SHOW PROFILE PROCESS process_id;
You can get the process ID from the SHOW PROCESSLIST command or the CONNECTION_
SHOW PROCESSLIST;
SELECT CONNECTION_ID();
If there is a skew between different partitions, then SHOW PROFILE
displays additional details of the skewed metric.SHOW PROFILE
query in the following format: [memory_
where,
-
The total across all partitions is
v
. -
The partition with the largest amount is partition
x
with memory usew
. -
The average memory usage per partition is
y
. -
The standard deviation is
z
.
If all data is on one partition, then the actual_
has the same count across all partitions as max on a single partition.SHOW PROFILE JSON
always displays these additional details, even when there is no skew.
PROFILE
Metrics
The following table provides a brief explanation of the metrics that are gathered when executing a statement using PROFILE
.
Metric |
Description |
---|---|
exec_ |
Time spent in running each operator. |
network_ |
Wait time spent while flushing data to the network |
memory_ |
Memory used by the operator in KB |
network_ |
Data sent over the network in KB |
actual_ |
Number of rows processed by the operator. |
est_ |
Estimated number of rows in a table. |
est_ |
Estimated number of rows of a table after applying all single-table filters |
start_ |
Time difference between the query start and operator execution as start_ |
end_ |
Time when the operator finishes execution |
Not all of the above metrics will be gathered for queries where execution performance may be hindered by gathering such metrics.
PROFILE
Metrics for Columnstore Queries that Use Filters
The following table provides a brief explanation of the columnstore metrics that are gathered when running PROFILE
with a columnstore query that uses filters.SHOW PROFILE JSON
, following PROFILE
.
Metric |
Description |
---|---|
columnstore_ |
The type of filter used (full row scan, hash index, or bloom). |
columnstore_ |
The number of rows that the filter predicate was evaluated on. |
columnstore_ |
The number of rows that passed the filter predicate. |
columnstore_ |
The number of rows that the filter predicate was evaluated on, using operations on encoded data. |
columnstore_ |
The number of rows that passed the filter predicate, using operations on encoded data. |
columnstore_ |
The number of average filtering operations performed on each row. |
columnstore_ |
This is the same as |
columnstore_ |
This is the same as |
Whether or not a filter predicate was evaluated using operations on encoded data depends on the filter predicate itself as well as the encodings of the involved columns.columnstore_
is lower than columnstore_
, either the filter predicate does not support operations on encoded data or there were some segments with encodings that do not support operations on encoded data.
Some filter predicates are children of other filter predicates.columnstore_
metric can be inspected to find which method of evaluation is used in what proportion.
Important
Up-to-date PROFILE
metrics for columnstore filters are available after the columnstore background flusher has run.OPTIMIZE TABLE .
.
See an example that provides resource usage metrics for a columnstore query that uses filters.
PROFILE
Blob Cache Metrics
For columnstore tables stored in unlimited storage, there are additional metrics to provide information about the blob cache.
Metric |
Description |
---|---|
blobcache_ |
The number of blobs downloaded from unlimited storage due to local blob cache misses. The metric has the following sub-categories:
|
blobcache_ |
The number of blob bytes downloaded from unlimited storage due to local blob cache misses. The metric has the following sub-categories:
|
blobcache_ |
The number of blobs accessed by the query. "Accessed” means the query has read some data from the blob. The metric has the following sub-categories:
|
blobcache_ |
The number of blob bytes accessed by the query. The metric has the following sub-categories:
|
blobcache_ |
The time that was spent on waiting for blob cache data. |
PROFILE JSON
Fields
When unlimited is enabled, PROFILE JSON
provides information about the segments and blobs retrieved from unlimited storage to the blob cache (on local disk) under the ColumnStoreScan executor.
Field |
Description |
---|---|
segments_ |
The number of segments that were scanned. |
segments_ |
The number of segments that were not scanned due to segment elimination. |
segments_ |
The number of segments that were not scanned, because they are fully contained. |
segments_ |
Represents the number of segments in the blob cache, which did not need retrieval from unlimited storage. |
column_ |
The number of rows scanned using the row index (COLUMN GROUP). |
column_ |
The number of rows scanned when scanning the individual column segments. |
blob_ |
The total time spent waiting for blobs to be retrieved over the network. |
total_ |
The total size of blobs retrieved from unlimited storage and stored in the blob cache. |
blobs_ |
Provides detail about various blob sizes and types retrieved.
|
PROFILE JSON
Metrics with profile_ for_ debug
= ON
The following list shows all additional data included in the output of SHOW PROFILE JSON
when it is run with the variable set_
set to ON
.
-
DDL for all database objects relevant to the query
-
Global variable settings
-
Session variable settings
-
Table statistics metadata
-
Sampling cache for filter selectivities
-
Sampling cache for row counts
-
Autostats results cache
The following commands can be used without needing to set the profile_
PROFILE REPRO <query>;SHOW REPRODUCTION;
SingleStore will continue to support the profile_PROFILE
and SHOW PROFILE JSON
commands for backward compatibility.
Note that the profile_
session variable can only be used on fully or partially executed queries.
PROFILE JSON
Metrics with enable_ spilling
= ON
Sometimes, a GROUP BY
query will use a hash table internally to execute the query, which is known as a HashGroupBy operation.
Note: SingleStore recommends to use an SSD for the spilling directory, since it can result in a tenfold increase in performance.
The output of SHOW PROFILE JSON
also includes the following metrics, when the sync variable enable_
is set to ON
(starting with version 7.ON
is the default value for this sync variable):
-
spill_
: The number of rows spilled to diskoutputted_ rows -
spill_
: The number of bytes spilled to diskdisk_ usage
The sync variables spilling_
, spilling_
, and spilling_
(starting with version 7.
Visual Profile via SHOW PROFILE UI
Using SHOW PROFILE UI
will generate a URL that loads a visual representation of the query profile.
Examples
Example 1
The SHOW PROFILE JSON
statement displays the compilation and optimizer statistics.profile_
is set to OFF
.
For example, run the following PROFILE
query:
PROFILE SELECT * from Emp;
+-----------+---------+
| Name | City |
+-----------+---------+
| Sam | Chicago |
| Jack | Norway |
| Tom | Chicago |
| Neil | Chicago |
+-----------+---------+
4 rows in set (0.29 sec)
Now run the SHOW PROFILE JSON
command.
SHOW PROFILE JSON;
+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
"query_info":{
"query_text":"profile select * from Emp",
"total_runtime_ms":"291",
"text_profile":"Gather partitions:all alias:remote_0 actual_rows: 9 exec_time: 0ms start_time: 00:00:00.001 end_time: 00:00:00.143\nProject [Emp.Name, Emp.City] actual_rows: 9 exec_time: 0ms start_time: 00:00:00.139 network_traffic: 0.100000 KB network_time: 1ms\nTableScan trades.Emp actual_rows: 9 exec_time: 0ms start_time: 00:00:00.139\nCompile Total Time: 147ms\n",
"compile_time_stats":{
"mbc_emission":"0",
"create_mbc_context":"4",
"expanding_views":"0",
"optimizer_query_rewrites":"1",
"optimizer_stats_analyze":"0",
"optimizer_stats_other":"0",
"optimizer_stats_sampling":"0",
"optimizer_setting_up_subselect":"0",
"optimizer_distributed_optimizations":"0",
"optimizer_enumerate_temporary_tables":"0",
"optimizer_singlebox_optimizations_agg":"0",
"optimizer_rewrite_estimate_cost":"0",
"optimizer_stats_autostats":"0",
"ppc_check":"0",
"generating_query_mpl":"1",
"generating_user_function_mpl":"0",
"module_cleaning":"0",
"dump_clean_bitcode":"0",
"llvm_optimization":"0",
"dump_optimized_bitcode":"0",
"machine_code_generation":"0",
"llvm_printing":"0",
"asm_printing":"0",
"symbol_resolution":"0",
"unknown":"138",
"total":"147"
}
}
} |
+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+-
1 row in set (0.00 sec)
If you had run PROFILE
again prior to running SHOW PROFILE JSON
, the results would have been more accurate.
Note: The PROFILE
command can be used for long running queries to analyze the query plan and search for unexpectedly expensive operators.SHOW PROFILE JSON
command to analyze the query plan visually in the Visual Explain UI.
Example 2
This example shows how to run SHOW PROFILE JSON
with the variable profile_
set to ON
in order to get additional data output beyond what is displayed in the first example where this variable is set to OFF
.
SET profile_for_debug = on;PROFILE SELECT * FROM t1 JOIN t2 ON t1.b = t2.b;SHOW PROFILE JSON;
/* The following JSON output has been truncated to show only the additional data provided with set_profile_for_debug set to ON. */
"debug_info": {
"ddl": [
"CREATE DATABASE `db` PARTITIONS 3",
"USING `db` CREATE TABLE `t2` ( `a` bigint(11) NOT NULL AUTO_INCREMENT, `b` int(11) DEFAULT NULL, PRIMARY KEY (`a`)) AUTOSTATS_CARDINALITY_MODE=OFF AUTOSTATS_HISTOGRAM_MODE=OFF SQL_MODE=\'STRICT_ALL_TABLES\'",
"USING `db` CREATE TABLE `t1` ( `a` bigint(11) NOT NULL AUTO_INCREMENT, `b` int(11) DEFAULT NULL, PRIMARY KEY (`a`)) AUTOSTATS_CARDINALITY_MODE=OFF AUTOSTATS_HISTOGRAM_MODE=OFF SQL_MODE=\'STRICT_ALL_TABLES\'"
],
"optimizer_stats": [],
"sampling_rowcount_cache": [
{
"db": "db",
"rowcount": "1",
"table": "t1"
},
{
"db": "db",
"rowcount": "4",
"table": "t2"
}
],
"variables": {
"as_aggregator": 1,
"cardinality_estimation_level": 3,
"client_found_rows": 0,
"collation_server": 2,
"comment from t.py": "t.py normalize_profile_json() is modifying this output - most variables are filtered out of this output, look at t.py for details",
"data_conversion_compatibility_level": 0,
"default_partitions_per_leaf": 3,
"disable_sampling_estimation_with_histograms": 2,
"disable_subquery_merge_with_straight_joins": 2,
"distributed_optimizer_min_join_size_run_initial_heuristics": 18,
"force_bushy_joins": 0,
"interpreter_mode": 4,
"json_extract_string_collation": 3,
"materialize_ctes": 0,
"max_subselect_aggregator_rowcount": 0,
"resource_pool_is_auto": 0,
"resource_pool_statement_selector_function": 4294967300,
"sql_mode": 4194304,
"sql_select_limit": 1
}
},
This example shows how to run PROFILE REPRO
followed by SHOW REPRODUCTION
commands that will replace the SET profile_
; PROFILE <query>
; and SHOW PROFILE JSON
series of commands.
PROFILE REPRO SELECT * FROM t;SHOW REPRODUCTION;
REPRODUCTION INFO
/* The following JSON output has been truncated to show only the additional data provided with set_profile_for_debug set to ON. */
"debug_info":{
"ddl":[
"CREATE DATABASE `test1` PARTITIONS 2",
"USING `test1` CREATE TABLE `t` (\n `id` bigint(11) NOT NULL AUTO_INCREMENT,\n `a` int(11) DEFAULT NULL,\n `b` int(11) DEFAULT NULL,\n UNIQUE KEY `PRIMARY` (`id`) USING HASH,\n SHARD KEY `__SHARDKEY` (`id`),\n KEY `__UNORDERED` () USING CLUSTERED COLUMNSTORE\n) AUTO_INCREMENT=1000000 AUTOSTATS_CARDINALITY_MODE=INCREMENTAL AUTOSTATS_HISTOGRAM_MODE=CREATE AUTOSTATS_SAMPLING=ON SQL_MODE='STRICT_ALL_TABLES'"
],
"variables":{"as_aggregator": 1, "as_leaf": 0, "batch_external_functions": 0, "binary_serialization": 1, "client_found_rows": 1, "collation_server": 2, "datetime_precision_mode": 0, "default_columnstore_table_lock_threshold": 0, "disable_histogram_estimation": 0, "disable_sampling_estimation": 0, "disable_sampling_estimation_with_histograms": 2, "disable_subquery_merge_with_straight_joins": 2, "display_full_estimation_stats": 0, "distributed_optimizer_broadcast_mult": 0, "distributed_optimizer_estimated_restricted_search_cost_bound": 125, "distributed_optimizer_max_join_size": 22, "distributed_optimizer_min_join_size_run_initial_heuristics": 16, "distributed_optimizer_nodes": 0, "distributed_optimizer_old_selectivity_table_threshold": 22, "distributed_optimizer_run_legacy_heuristic": 0, "distributed_optimizer_selectivity_fallback_threshold": 50000000, "distributed_optimizer_unrestricted_search_threshold": 22, "enable_broadcast_left_join": 1, "enable_local_shuffle_group_by": 1, "enable_multipartition_queries": 1, "enable_skiplist_sampling_for_selectivity": 1, "force_bloom_filters": 0, "force_bushy_join_table_limit": 18, "force_bushy_joins": 0, "force_heuristic_rewrites": 0, "force_table_pushdown": 0, "hash_groupby_segment_distinct_values_threshold": 10000, "ignore_insert_into_computed_column": 0, "inlist_precision_limit": 10000, "interpreter_mode": 4, "leaf_pushdown_default": 0, "leaf_pushdown_enable_rowcount": 120000, "materialize_ctes": 1, "max_broadcast_tree_rowcount": 120000, "max_subselect_aggregator_rowcount": 120000, "old_local_join_optimizer": 0, "optimize_constants": 1, "optimize_mpl_before_printing": 0, "optimize_stmt_threshold": 50, "optimizer_beam_width": 10, "optimizer_cross_join_cost": 1.000000, "optimizer_disable_right_join": 0, "optimizer_disable_subselect_to_join": 0, "optimizer_empty_tables_limit": 0, "optimizer_hash_join_cost": 1.000000, "optimizer_merge_join_cost": 1.000000, "optimizer_nested_join_cost": 1.000000, "optimizer_num_partitions": 0, "quadratic_rewrite_size_limit": 200, "query_rewrite_loop_iterations": 1, "reshuffle_group_by_base_cost": 0, "sampling_estimates_for_complex_filters": 1, "singlebox_optimizer_cost_based_threshold": 18, "sql_mode": 4194304, "sql_select_limit": 0, "subquery_merge_with_outer_joins": 3, "cardinality_estimation_level": 3, "data_conversion_compatibility_level": 0, "debug_mode": 0, "default_partitions_per_leaf": 1, "disable_update_delete_distributed_transactions": 0, "enable_alias_space_trim": 0, "enable_spilling": 1, "explicit_defaults_for_timestamp": 1, "json_extract_string_collation": 3, "resource_pool_statement_selector_function": 4294967300, "use_avx2": 1, "use_dstree": 1, "use_joincolumnstore": 1, "node_degree_of_parallelism": 0, "resource_pool_is_auto": 0},
"optimizer_stats":[
{
"version": 2,
"databaseName": "test1",
"tables": [
{
"tableName": "t",
"rowCount": "2048",
"columns": [
{
"columnName": "id",
"nullCount": "0",
"minValue": "",
"maxValue": "",
"cardinality": "2048",
"density": "0x0p+0",
"sampleSize": "0",
"lastUpdated": "1646329049"
},
{
"columnName": "a",
"nullCount": "0",
"minValue": "",
"maxValue": "",
"cardinality": "101",
"density": "0x0p+0",
"sampleSize": "0",
"lastUpdated": "1646329049"
},
{
"columnName": "b",
"nullCount": "0",
"minValue": "",
"maxValue": "",
"cardinality": "101",
"density": "0x0p+0",
"sampleSize": "0",
"lastUpdated": "1646329049"
}
]
}
],
"stats": [
{
"tableName": "t",
"columns": [
{
"columnName": "id"
},
{
"columnName": "a"
},
{
"columnName": "b"
}
]
}
]
}
],
"query_after_rewrites":"SELECT `t`.`id` AS `id`, `t`.`a` AS `a`, `t`.`b` AS `b` FROM `test1`.`t` as `t` LIMIT @@SESSION.`sql_select_limit` \/*!90623 OPTION(CLIENT_FOUND_ROWS=1)*\/"
}
}
Example 3
The INTO OUTFILE file_
clause is useful to output the profile information of a query/plan to a file.profile_
is set to OFF
.
For example, run the following PROFILE
query:
PROFILE SELECT * from Emp;
Now, run the following command to write the JSON profile information to the EmpProfile.
file in the /tmp
directory.
SHOW PROFILE JSON INTO OUTFILE '/tmp/EmpProfile.json';
To view the contents of the EmpProfile.
file, run the following command at the root
prompt:
cat '/tmp/EmpProfile.json';
Example 4
The PROFILE
statement is particularly helpful when evaluating distributed query performance, such as a distributed join.PROFILE
statement can help you understand how such queries are executed so that they can be optimized.profile_
is set to OFF
.
In the following example, a distributed join is executed to return data about customers and their orders.
Suppose we have run the query:
SELECT COUNT(*)FROM orders o JOIN customer cWHERE o.custkey = c.custkey and c.mktsegment = 'BUILDING';
Now we want to diagnose why it is slower than expected.EXPLAIN
statement to understand the execution plan for a query.
EXPLAIN SELECT COUNT(*) FROM orders o JOIN customer c WHERE o.custkey = c.custkey and c.mktsegment = 'BUILDING';
+------------------------------------------------------------------------------------------------------------------------------------------------+
| EXPLAIN |
+------------------------------------------------------------------------------------------------------------------------------------------------+
| Project [CAST(COALESCE($0,0) AS SIGNED) AS `count(*)`] |
| Aggregate [SUM(remote_0.`count(*)`) AS $0] |
| Gather partitions:all est_rows:1 alias:remote_0 |
| Project [`count(*)`] est_rows:1 est_select_cost:87,206,400 |
| Aggregate [COUNT(*) AS `count(*)`] |
| NestedLoopJoin |
| |---IndexRangeScan orders AS o, KEY orders_fk1 (o_custkey) scan:[o_custkey = r1.c_custkey] est_table_rows:150,000,000 est_filtered:150,000,000 |
| TableScan r1 storage:list stream:no est_table_rows:2,725,200 |
| Broadcast [c.c_custkey] AS r1 distribution:direct est_rows:2,725,200 |
| Filter [c.c_mktsegment = ?] |
| TableScan customer AS c, PRIMARY KEY (c_custkey) est_table_rows:150,000,000 est_filtered:2,725,200 |
+------------------------------------------------------------------------------------------------------------------------------------------------+
From this EXPLAIN
statement, it’s clear that a broadcast is required, and that a nested loop join will be performed.PROFILE
statement with the same SELECT
query to gather resource usage metrics.
PROFILE SELECT COUNT(*) FROM orders o JOIN customer c WHERE o.custkey = c.custkey and c.mktsegment = 'BUILDING';
+----------+
| count(*) |
+----------+
| 421 |
+----------+
The PROFILE
statement will output the same results as the inner SELECT
statement, but it has also gathered resource usage metrics.SHOW PROFILE
statement.
SHOW PROFILE;
+---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| PROFILE |
+---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| Project [CAST(COALESCE($0,0) AS SIGNED) AS `count(*)`] actual_rows: 1 exec_time: 0ms start_time: 00:00:00.584 network_traffic: 0.004000 KB |
| Aggregate [SUM(remote_0.`count(*)`) AS $0] actual_rows: 3 exec_time: 0ms start_time: 00:00:00.581 |
| Gather partitions:all est_rows:1 alias:remote_0 actual_rows: 3 exec_time: 0ms start_time: 00:00:00.003 end_time: 00:00:00.583 |
| Project [`count(*)`] est_rows:1 est_select_cost:87,206,400 actual_rows: 3 exec_time: 0ms start_time: [00:00:00.581, 00:00:00.582] network_traffic: 0.012000 KB |
| Aggregate [COUNT(*) AS `count(*)`] actual_rows: 421 exec_time: 0ms start_time: [00:00:00.053, 00:00:00.056] |
| NestedLoopJoin actual_rows: 421 exec_time: 0ms |
| |---IndexRangeScan orders AS o, KEY orders_fk1 (o_custkey) scan:[o_custkey = r1.c_custkey] est_table_rows:150,000,000 est_filtered:150,000,000 actual_rows: 421 exec_time: 532ms start_time: [00:00:00.053, 00:00:00.059] |
| TableScan r1 storage:list stream:no est_table_rows:2,725,200 actual_rows: 122,424 exec_time: 29ms start_time: [00:00:00.004, 00:00:00.005] |
| Broadcast [c.c_custkey] AS r1 distribution:direct est_rows:27,252 actual_rows: 40,808 exec_time: 19ms start_time: 00:00:00.002 network_traffic: 334.326996 KB |
| Filter [c.c_mktsegment = ?] actual_rows: 40,808 exec_time: 97ms start_time: 00:00:00.002 |
| TableScan customer AS c, PRIMARY KEY (c_custkey) est_table_rows:150,000 est_filtered:27,252 actual_rows: 200,000 exec_time: 68ms start_time: 00:00:00.002 |
| Compile Total Time: 238ms
+---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
After the SHOW PROFILE
statement has been executed, you can see from the example above that actual rows, network traffic, and execution time have been appended to the end of the execution operator lines.IndexRangeScan orders
, which takes 532ms.TableScan tpch.
has many fewer rows now than are recorded in statistics, which suggests that our statistics are not up-to-date.
Similarly, we can identify that the most network-consuming operator is Broadcast [c.
and there is no memory-consuming operator (every operator uses only a constant amount of memory).
After running ANALYZE TABLE
, we can rerun the PROFILE
query:
PROFILE SELECT COUNT(*) FROM orders o JOIN customer c where o.custkey = c.custkey and c.mktsegment = 'BUILDING';
+----------+
| count(*) |
+----------+
| 421 |
+----------+
Finally, we can output the profile information for it:
SHOW PROFILE;
+---------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| PROFILE |
+---------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| Project [CAST(COALESCE($0,0) AS SIGNED) AS `count(*)`] actual_rows: 1 exec_time: 0ms start_time: 00:00:00.237 network_traffic: 0.004000 KB |
| Aggregate [SUM(remote_0.`count(*)`) AS $0] actual_rows: 3 exec_time: 0ms start_time: 00:00:00.223 |
| Gather partitions:all est_rows:1 alias:remote_0 actual_rows: 3 exec_time: 0ms start_time: 00:00:00.004 end_time: 00:00:00.236 |
| Project [`count(*)`] est_rows:1 est_select_cost:25,006 actual_rows: 3 exec_time: 0ms start_time: [00:00:00.221, 00:00:00.235] network_traffic: 0.012000 KB |
| Aggregate [COUNT(*) AS `count(*)`] actual_rows: 421 exec_time: 0ms start_time: [00:00:00.140, 00:00:00.141] |
| HashJoin [r1.o_custkey = customer.c_custkey] actual_rows: 421 exec_time: 11ms start_time: [00:00:00.140, 00:00:00.141] memory_usage: 655.359985 KB |
| |---Broadcast [orders.o_custkey] AS r1 distribution:direct est_rows:12,503 actual_rows: 12,503 exec_time: 11ms start_time: 00:00:00.002 network_traffic: 78.333000 KB |
| | TableScan tpch.orders, PRIMARY KEY (o_orderkey) est_table_rows:12,503 est_filtered:12,503 actual_rows: 12,503 exec_time: 13ms start_time: 00:00:00.002 |
| Filter [customer.c_mktsegment = ?] actual_rows: 40,808 exec_time: 52ms start_time: [00:00:00.140, 00:00:00.141] |
| TableScan tpch.customer, PRIMARY KEY (c_custkey) est_table_rows:200,000 est_filtered:40,832 actual_rows: 200,000 exec_time: 41ms start_time: [00:00:00.140, 00:00:00.141] |
+---------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
The new plan is faster in execution time but notice that we introduced a memory-consuming operator HashJoin
, which allocates 655.
PROFILE SELECT name FROM company WHERE name LIKE "C%";
+------------------------------+
| name |
+------------------------------+
| Cutera, Inc. |
| CVB Financial Corporation |
| CVD Equipment Corporation |
| Cyanotech Corporation |
| ... |
| Curis, Inc. |
+------------------------------+
348 rows in set (404 ms)
Now run the SHOW PROFILE JSON
query to view the resource usage metrics in JSON format:
SHOW PROFILE JSON;
+------------------------------+
| PROFILE |
+------------------------------+
| {
"profile":[
{
"executor":"Gather",
"partitions":"all",
"query":"SELECT `company`.`name` AS `name` FROM `trades_0`.`company`
as `company` WHERE (`company`.`name` LIKE 'C%')
OPTION(NO_QUERY_REWRITE=1, INTERPRETER_MODE=LLVM)",
"alias":"remote_0",
"actual_row_count":{ "value":348, "avg":0.000000, "stddev":0.000000,
"max":0, "maxPartition":0 },
"actual_total_time":{ "value":0 },
"start_time":{ "value":0 },
"end_time":{ "value":5 },
...
}
}
1 row in set (290 ms)
The SHOW PLAN
command displays the plan information for the specified plan ID:
SHOW PLAN 5;
+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| PLAN |
+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| Gather partitions:all alias:remote_0 |
| Project [company.symbol, company.name, company.last_sale, company.market_cap, company.IPO_year, company.sector, company.industry, company.summary_quote, company.extra] |
| TableScan trades.company |
+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
3 rows in set (0.00 sec)
Next, get the JSON plan information by running the following command:
SHOW PLAN JSON 5;
This command produces a large amount of text as result.
Example 5
The following example provides resource usage metrics for columnstore query that uses filters.profile_
is set to OFF
.
Run this statement:
PROFILE SELECT * FROM products WHERE Color = 'Blue' and Qty = '5';
Then run SHOW PROFILE JSON
.
Selected output:
..."inputs":[{"executor":"ColumnStoreFilter","keyId":4294968019,"condition":["products.Color = ? AND products.Qty = ?"],"columnstore_filter_predicates":[{"executor":"ColumnStoreFilterPredicate","keyId":4294968020,"condition":["products.Color = ? AND products.Qty = ?"],"columnstore_filter_callback_ordinal":"2","columnstore_filter_execution_type":"regular","columnstore_filter_total_rows_in":{ "value":0, "avg":0.000000, "stddev":0.000000, "max":0, "maxPartition":0 },"columnstore_filter_total_rows_out":{ "value":0, "avg":0.000000, "stddev":0.000000, "max":0, "maxPartition":0 },"columnstore_filter_encoded_rows_in":{ "value":0, "avg":0.000000, "stddev":0.000000, "max":0, "maxPartition":0 },"columnstore_filter_encoded_rows_out":{ "value":0, "avg":0.000000, "stddev":0.000000, "max":0, "maxPartition":0 },"inputs":[]},{"executor":"ColumnStoreFilterPredicate","keyId":4294968020,"condition":[" products.Color = ?"],"columnstore_filter_callback_ordinal":"3","columnstore_filter_execution_type":"regular","columnstore_filter_total_rows_in":{ "value":6, "avg":0.750000, "stddev":1.984313, "max":6, "maxPartition":2 },"columnstore_filter_total_rows_out":{ "value":4, "avg":0.500000, "stddev":1.322876, "max":4, "maxPartition":2 },"columnstore_filter_encoded_rows_in":{ "value":0, "avg":0.000000, "stddev":0.000000, "max":0, "maxPartition":0 },"columnstore_filter_encoded_rows_out":{ "value":0, "avg":0.000000, "stddev":0.000000, "max":0, "maxPartition":0 },"inputs":[]},{"executor":"ColumnStoreFilterPredicate","keyId":4294968020,"condition":[" AND products.Qty = ?"],"columnstore_filter_callback_ordinal":"5","columnstore_filter_execution_type":"regular","columnstore_filter_total_rows_in":{ "value":4, "avg":0.500000, "stddev":1.322876, "max":4, "maxPartition":2 },"columnstore_filter_total_rows_out":{ "value":4, "avg":0.500000, "stddev":1.322876, "max":4, "maxPartition":2 },"columnstore_filter_encoded_rows_in":{ "value":4, "avg":0.500000, "stddev":1.322876, "max":4, "maxPartition":2 },"columnstore_filter_encoded_rows_out":{ "value":4, "avg":0.500000, "stddev":1.322876, "max":4, "maxPartition":2 },"inputs":[]}],"subselects":[],"actual_row_count":{ "value":4, "avg":0.500000, "stddev":1.322876, "max":4, "maxPartition":2 },"actual_total_time":{ "value":0, "avg":0.000000, "stddev":0.000000, "max":0, "maxPartition":0 },"start_time":{ "value":0, "avg":0.000000, "stddev":0.000000, "max":0, "maxPartition":2 },"columnstore_filter_total_rows_in":{ "value":6, "avg":0.750000, "stddev":1.984313, "max":6, "maxPartition":2 },"columnstore_filter_avg_filters_per_row":{ "value":0, "avg":1.666667, "stddev":0.000000, "max":0, "maxPartition":0 },"columnstore_filter_avg_index_filters_per_row":{ "value":0, "avg":0.000000, "stddev":0.000000, "max":0, "maxPartition":0 },"columnstore_filter_avg_bloom_filters_per_row":{ "value":0, "avg":0.000000, "stddev":0.000000, "max":0, "maxPartition":0 },...
Example 6
Here is an example of the spilling related metrics under hash Join operators:
..."inputs":[{"executor":"HashJoin","keyId":458753,"type":"inner","subselects":[],"actual_row_count":{ "value":4194304, "avg":1398101.333333, "stddev":606.633516, "max":1398899, "maxPartition":0 },"actual_total_time":{ "value":1964, "avg":1964.000000, "stddev":0.000000, "max":1964, "maxPartition":0 },"start_time":{ "value":7074, "avg":7486.333333, "stddev":0.000000, "max":8142, "maxPartition":2 },"inputs":[{"executor":"HashTableProbe","keyId":458917,"condition":["r1.a = r0.a"],"spill_outputted_rows":{ "value":4194304, "avg":1398101.333333, "stddev":606.633516, "max":1398899, "maxPartition":0 },"spill_disk_usage":{ "value":134217728, "avg":44739242.666667, "stddev":19412.272498, "max":44764768, "maxPartition":0 },"inputs":[{"executor":"HashTableBuild","keyId":458916,"alias":"r1","actual_row_count":{ "value":4194304, "avg":0.000000, "stddev":0.000000, "max":0, "maxPartition":0 },"actual_total_time":{ "value":4, "avg":4.000000, "stddev":0.000000, "max":4, "maxPartition":0 },"start_time":{ "value":1782, "avg":1866.666667, "stddev":0.000000, "max":1978, "maxPartition":1 },"memory_usage":{ "value":393216, "avg":131072.000000, "stddev":0.000000, "max":131072, "maxPartition":0 },"spill_outputted_rows":{ "value":4194304, "avg":1398101.333333, "stddev":606.633516, "max":1398899, "maxPartition":0 },"spill_disk_usage":{ "value":100663296, "avg":33554432.000000, "stddev":14559.204374, "max":33573576, "maxPartition":0 },...
Related Topics
Last modified: July 30, 2024