PROFILE

Provides detailed resources usage metrics about a query.

Syntax

PROFILE select_statement

Remarks

When a PROFILE statement is executed, the associated SELECT statement is also executed. During execution of both queries, resource usage metrics are collected about the SELECT statement. After the queries have executed, the collected metrics can be displayed by executing the SHOW PROFILE statement.

Like the EXPLAIN statement, 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, PROFILE also appends resource usage metrics to the end of each line in the execution tree.

The following metrics are gathered about each when executing a statement using PROFILE:

Not all of the above metrics will be gathered for queries where execution performance may be hindered by gathering such metrics.

Example

The PROFILE statement is particularly helpful when evaluating distributed query performance, such as a distributed join. Distributed joins that require broadcasts or repartitions are expensive, and the PROFILE statement can help you understand how such queries are executed so that they can be optimized.

In the following example, a distributed join is executed to return data about customers and their orders. For demonstration purposes, we loaded simulated statistics for each table.

Suppose we have run the query:

SELECT COUNT(*) 
FROM orders o JOIN customer c 
WHERE o.custkey = c.custkey and c.mktsegment = 'BUILDING';

Now we want to diagnose why it is slower than expected. It’s best to first execute an EXPLAIN statement to understand the execution plan for a query.

memsql> 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. Now you can run the PROFILE statement with the same SELECT query to gather resource usage metrics.

memsql> PROFILE SELECT COUNT(*) FROM orders o JOIN customer c WHERE o.custkey = c.custkey and c.mktsegment = 'BUILDING';
+----------+
| count(*) |
+----------+
| 421      |
+----------+
1 row in set (0.66 sec)

The PROFILE statement will output the same results as the inner SELECT statement, but it has also gathered resource usage metrics. To see the metrics, you must run the SHOW PROFILE statement.

memsql > 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                                                                 |
+---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+

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. We can first identify that most expensive operator is IndexRangeScan orders, which takes 532ms. Then we can see that TableScan tpch.orders 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.custkey] 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:

memsql> PROFILE SELECT COUNT(*) FROM orders o JOIN customer c where o.custkey = c.custkey and c.mktsegment = 'BUILDING';
+----------+
| count(*) |
+----------+
| 421      |
+----------+
1 row in set (0.26 sec)

Finally, we can output the profile information for it:

memsql> 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.359985 KB of memory at run time in the example. That could be something to watch out for if we add more data, since it might limit the total number of queries that can run concurrently.

Related Topics

Was this article useful?