PROFILE command¶
The PROFILE command executes a query, produces output, and collects runtime information for each operator in the execution plan.
When using the ngql CLI, you can use the :planstyle command to switch between execution plan display styles (nest/table/box). The default style is nest. For more information, see Execution plan style setting in the ngql documentation.
MATCH expansion-order changes are disabled by default
The optimizer's ability to change the expansion order of MATCH patterns is controlled by the session-level option enable_reorder, whose default value is false. When reordering is disabled, the planner prefers the textual expansion order when possible, while still using valid fallback plans and specialized traversal operators for supported cases.
To inspect or debug reorder behavior, you can:
- Temporarily enable reordering with
SESSION SET enable_reorder = trueor/*+ SET_VAR(enable_reorder=true) */when you want to compare reordered plans. - Use
EXPLAIN CBOto view the logical plan after the CBO stage. For more information, see EXPLAIN. - Enable CBO trace logging (by setting
enable_cbo_tracetotrue) to view the CBO's detailed decision-making process in the logs. For more information, see SpecifyCBOto view the logical plan after CBO reordering.
Syntax¶
- profile_command
profile_command ::=
'PROFILE' ( 'format' '=' '"' ( 'verbose' | 'default' ) '"' )? gql_query
Parameters¶
format = "verbose" | format = "default"¶
There are two output formats for the execution plan: verbose and default.
-
The
verboseformat is more detailed and is suitable for debugging and optimizing queries. When theformat = verboseoption is specified, the following information is returned:Parameter Description planRepresents the operators in the execution plan. Operators are listed in bottom-to-top execution order. detailsProvides detailed information about the operator, including the data of nodes and edges to be accessed. time(ms)Represents the time spent by the operator in milliseconds. rowsRepresents the number of rows produced by the operator. memory(KiB)Represents the memory usage of the operator. blocked(ms)Represents the total blocking time at runtime. queued(ms)Represents the total queuing time at runtime. consume(ms)Represents the total consume time at runtime. produce(ms)Represents the total produce time at runtime. finish(ms)Represents the total finish time at runtime. batchesRepresents the number of batches computed by the operator. concurrencyRepresents the number of concurrent tasks for the operator. othersRepresents other information about the operator.
-
The
defaultformat is a simplified version of theverboseformat. When both theformat = defaultandformat = "verbose"options are omitted, thedefaultformat is used by default, returning the following information:Parameter Description planRepresents the operators in the execution plan. detailsProvides detailed information about the operator, including the data of nodes and edges to be accessed. time(ms)Represents the time spent by the operator in milliseconds. rowsRepresents the number of rows produced by the operator. memory(KiB)Represents the memory usage of the operator. blocked(ms)Represents the total blocking time at runtime.
gql_query¶
The GQL query whose execution plan is to be displayed.
Examples¶
The following examples are based on the example dataset.
Use default to display a simplified execution plan¶
The following command uses the format="default" option to display the query results and the corresponding execution plan. You can also omit the format="default" option since the default format is default.
View nested execution plan¶
PROFILE format="default" USE movie MATCH (a:Person)-[e]->(b@Movie) LIMIT 1 RETURN b
Returns:
+------------------------------------------------------------------+
| b |
+------------------------------------------------------------------+
| (289214134115893249@Movie:Movie{id:486,name:"Realization Time"}) |
+------------------------------------------------------------------+
Got 1 rows (time spent 19.05ms/20.456376ms)
• [P0]CallbackSink
│ details: Offset:0, Limit:1, Partial:false, Approx
│ :false
│ time(ms): 0.00
│ rows: 1
│ memory(KiB): 0.00
│ blocked(ms): 0.00
│
└── • [P0]Limit
│ details: Offset:0, Limit:1, Partial:false, Approx
│ :false
│ time(ms): 0.03
│ rows: 1
│ memory(KiB): 4.50
│ blocked(ms): 0.00
│
└── • [P0]HashJoinProbe
│ details: Project: b, element_id(b)=_right_node_i
│ d(e)
│ time(ms): 0.20
│ rows: 943
│ memory(KiB): 50.49
│ blocked(ms): 11.82
│
├── • [P0]StorageRemoteAccess
│ │ details: TableScan: {Movie: {name, id}}, b{}
│ │ time(ms): 0.00
│ │ rows: 29
│ │ memory(KiB): 0.00
│ │ blocked(ms): 1.09
│ │
│ └── • [SP0]CallbackSink
│ │ details: TableScan: UNKNOWN, b{}
│ │ time(ms): 0.01
│ │ rows: 158
│ │ memory(KiB): 0.00
│ │ blocked(ms): 0.00
│ │
│ └── • [SP0]NodesScan
│ details: TableScan: UNKNOWN, b{}
│ time(ms): 1.84
│ rows: 158
│ memory(KiB): 85.02
│ blocked(ms): 0.00
│
└── • [P1]HashJoinBuild
│ details: Project: b, element_id(b)=_right_node_i
│ d(e)
│ time(ms): 1.01
│ rows: 240
│ memory(KiB): 450.25
│ blocked(ms): 0.00
│
└── • [P1]StorageRemoteAccess
│ details: in(node_type_id(_left_node_id(e)), [1024
│ ,1025,1026])
│ time(ms): 0.01
│ rows: 7891
│ memory(KiB): 0.00
│ blocked(ms): 9.39
│
└── • [SP0]CallbackSink
│ details: in(node_type_id(_left_node_id(e)), [1024
│ ,1025,1026])
│ time(ms): 0.27
│ rows: 7891
│ memory(KiB): 0.00
│ blocked(ms): 0.00
│
└── • [SP0]Filter
│ details: in(node_type_id(_left_node_id(e)), [1024
│ ,1025,1026])
│ time(ms): 1.80
│ rows: 7891
│ memory(KiB): 4.93
│ blocked(ms): 0.00
│
└── • [SP0]EdgesScan
details: direction: outgoing: true, incoming: fal
se, undirected0: false, undirected1: fal
se, TableScan: UNKNOWN, TableScan: UNKNO
WN, TableScan: UNKNOWN, e{}
time(ms): 10.26
rows: 7891
memory(KiB): 128.44
blocked(ms): 0.00
Execution Plan: [Px] means pipeline-x and [S] means storage side.
Elapsed Time:
parse time : 713 us
build time : 1126 us
optimize time : 1120 us
serialize time: 504 us
total time : 19050 us
The first table shows the query results, and the nested view below shows the execution plan for the query. Each level corresponds to an operator, and the indentation between levels indicates the dependency between operators.
View table execution plan¶
You can use the :planstyle command to switch the execution plan display view to table format. For more information, see Set execution plan display view.
:planstyle table
PROFILE format="default" USE movie MATCH (a:Person)-[e]->(b@Movie) LIMIT 1 RETURN b
Returns:
+--------------------------------------------------------------+
| b |
+--------------------------------------------------------------+
| (289309336360976385@Movie:Movie{id:478,name:"Rest in Pain"}) |
+--------------------------------------------------------------+
Got 1 rows (time spent 13.164ms/14.335678ms)
+---------------------------------+------------------------------------------------------------------------------------------------------+----------+------+-------------+-------------+
| plan | details | time(ms) | rows | memory(KiB) | blocked(ms) |
+---------------------------------+------------------------------------------------------------------------------------------------------+----------+------+-------------+-------------+
| [P0]CallbackSink | Offset:0, Limit:1, Partial:false, Approx:false | 0.01 | 1 | 0.00 | 0.00 |
| └─[P0]Limit | Offset:0, Limit:1, Partial:false, Approx:false | 0.01 | 1 | 0.44 | 0.00 |
| └─[P0]HashJoinProbe | Project: b, element_id(b)=_right_node_id(e) | 0.10 | 777 | 47.93 | 9.23 |
| ├─[P0]StorageRemoteAccess | TableScan: {Movie: {name, id}}, b{} | 0.00 | 25 | 0.00 | 1.58 |
| │ └─[SP0]CallbackSink | TableScan: UNKNOWN, b{} | 0.00 | 25 | 0.00 | 0.00 |
| │ └─[SP0]NodesScan | TableScan: UNKNOWN, b{} | 0.11 | 25 | 85.02 | 0.00 |
| └─[P1]HashJoinBuild | Project: b, element_id(b)=_right_node_id(e) | 0.64 | 240 | 450.25 | 0.00 |
| └─[P1]StorageRemoteAccess | in(node_type_id(_left_node_id(e)), [1024,1025,1026]) | 0.01 | 7891 | 0.00 | 7.43 |
| └─[SP0]CallbackSink | in(node_type_id(_left_node_id(e)), [1024,1025,1026]) | 0.17 | 7891 | 0.00 | 0.00 |
| └─[SP0]Filter | in(node_type_id(_left_node_id(e)), [1024,1025,1026]) | 1.20 | 7891 | 5.39 | 0.00 |
| └─[SP0]EdgesScan | direction: outgoing: true, incoming: false, undirected0: false, undirected1: false, TableScan: UN... | 5.93 | 7891 | 128.44 | 0.00 |
+---------------------------------+------------------------------------------------------------------------------------------------------+----------+------+-------------+-------------+
Execution Plan: [Px] means pipeline-x and [S] means storage side.
Elapsed Time:
parse time : 194 us
build time : 233 us
optimize time : 353 us
serialize time: 70 us
total time : 13164 us
The first table shows the query results, and the second table shows the execution plan in table view. Each row in the table corresponds to an operator. The indentation in the plan column indicates the dependency between operators.
View box execution plan¶
You can use the :planstyle command to switch the execution plan display view to box format. For more information, see Set execution plan display view.
:planstyle box
PROFILE format="default" USE movie MATCH (a:Person)-[e]->(b@Movie) LIMIT 1 RETURN b
Returns:
+------------------------------------------------------------------+
| b |
+------------------------------------------------------------------+
| (289214134115893249@Movie:Movie{id:486,name:"Realization Time"}) |
+------------------------------------------------------------------+
Got 1 rows (time spent 14.299ms/15.133846ms)
┌──────────────────────────────────────┐
│ [P0]CallbackSink │
│ -------------------------------- │
│ Offset:0, Limit:1, Partial:false │
│ , Approx:false │
│ -------------------------------- │
│ time(ms): 0.00 │
│ -------------------------------- │
│ rows: 1 │
│ -------------------------------- │
│ memory(KiB): 0.00 │
│ -------------------------------- │
│ blocked(ms): 0.00 │
└──────────────────┬───────────────────┘
┌──────────────────┴───────────────────┐
│ [P0]Limit │
│ -------------------------------- │
│ Offset:0, Limit:1, Partial:false │
│ , Approx:false │
│ -------------------------------- │
│ time(ms): 0.01 │
│ -------------------------------- │
│ rows: 1 │
│ -------------------------------- │
│ memory(KiB): 4.50 │
│ -------------------------------- │
│ blocked(ms): 0.00 │
└──────────────────┬───────────────────┘
┌──────────────────┴───────────────────┐
│ [P0]HashJoinProbe │
│ -------------------------------- │
│ Project: b, element_id(b)=_righ │
│ t_node_id(e) │
│ -------------------------------- │
│ time(ms): 0.09 │
│ -------------------------------- │────────────────────┐
│ rows: 943 │ │
│ -------------------------------- │ │
│ memory(KiB): 50.49 │ │
│ -------------------------------- │ │
│ blocked(ms): 11.12 │ │
└──────────────────┬───────────────────┘ │
┌──────────────────┴───────────────────┐ ┌──────────────────┴───────────────────┐
│ [P0]StorageRemoteAccess │ │ [P1]HashJoinBuild │
│ -------------------------------- │ │ -------------------------------- │
│ TableScan: {Movie: {name, id}}, │ │ Project: b, element_id(b)=_righ │
│ b{} │ │ t_node_id(e) │
│ -------------------------------- │ │ -------------------------------- │
│ time(ms): 0.00 │ │ time(ms): 0.70 │
│ -------------------------------- │ │ -------------------------------- │
│ rows: 29 │ │ rows: 240 │
│ -------------------------------- │ │ -------------------------------- │
│ memory(KiB): 0.00 │ │ memory(KiB): 450.25 │
│ -------------------------------- │ │ -------------------------------- │
│ blocked(ms): 0.67 │ │ blocked(ms): 0.00 │
└──────────────────┬───────────────────┘ └──────────────────┬───────────────────┘
┌──────────────────┴───────────────────┐ ┌──────────────────┴───────────────────┐
│ [SP0]CallbackSink │ │ [P1]StorageRemoteAccess │
│ -------------------------------- │ │ -------------------------------- │
│ TableScan: UNKNOWN, b{} │ │ in(node_type_id(_left_node_id(e) │
│ │ │ ), [1024,1025,1026]) │
│ -------------------------------- │ │ -------------------------------- │
│ time(ms): 0.02 │ │ time(ms): 0.01 │
│ -------------------------------- │ │ -------------------------------- │
│ rows: 157 │ │ rows: 7891 │
│ -------------------------------- │ │ -------------------------------- │
│ memory(KiB): 0.00 │ │ memory(KiB): 0.00 │
│ -------------------------------- │ │ -------------------------------- │
│ blocked(ms): 0.00 │ │ blocked(ms): 9.73 │
└──────────────────┬───────────────────┘ └──────────────────┬───────────────────┘
┌──────────────────┴───────────────────┐ ┌──────────────────┴───────────────────┐
│ [SP0]NodesScan │ │ [SP0]CallbackSink │
│ -------------------------------- │ │ -------------------------------- │
│ TableScan: UNKNOWN, b{} │ │ in(node_type_id(_left_node_id(e) │
│ │ │ ), [1024,1025,1026]) │
│ -------------------------------- │ │ -------------------------------- │
│ time(ms): 0.79 │ │ time(ms): 0.31 │
│ -------------------------------- │ │ -------------------------------- │
│ rows: 157 │ │ rows: 7891 │
│ -------------------------------- │ │ -------------------------------- │
│ memory(KiB): 85.02 │ │ memory(KiB): 0.00 │
│ -------------------------------- │ │ -------------------------------- │
│ blocked(ms): 0.00 │ │ blocked(ms): 0.00 │
└──────────────────────────────────────┘ └──────────────────┬───────────────────┘
┌──────────────────┴───────────────────┐
│ [SP0]Filter │
│ -------------------------------- │
│ in(node_type_id(_left_node_id(e) │
│ ), [1024,1025,1026]) │
│ -------------------------------- │
│ time(ms): 1.06 │
│ -------------------------------- │
│ rows: 7891 │
│ -------------------------------- │
│ memory(KiB): 5.13 │
│ -------------------------------- │
│ blocked(ms): 0.00 │
└──────────────────┬───────────────────┘
┌──────────────────┴───────────────────┐
│ [SP0]EdgesScan │
│ -------------------------------- │
│ direction: outgoing: true, incom │
│ ing: false, undirected0: false, │
│ undirected1: false, TableScan: U │
│ NKNOWN, TableScan: UNKNOWN, Tabl │
│ eScan: UNKNOWN, e{} │
│ -------------------------------- │
│ time(ms): 5.89 │
│ -------------------------------- │
│ rows: 7891 │
│ -------------------------------- │
│ memory(KiB): 128.44 │
│ -------------------------------- │
│ blocked(ms): 0.00 │
└──────────────────────────────────────┘
Execution Plan: [Px] means pipeline-x and [S] means storage side.
Elapsed Time:
parse time : 171 us
build time : 188 us
optimize time : 311 us
serialize time: 43 us
total time : 14299 us
The first table shows the query results, and the box structure below shows the execution plan. Each box represents an operator, and the connections between boxes indicate that the upper operator depends on the output of the lower operator.
Use verbose to display a detailed execution plan¶
PROFILE format= "verbose" USE movie MATCH (a:Person)-[e]->(b@Movie) LIMIT 1 RETURN b
The above example uses the verbose format by specifying format = "verbose" to display the results and corresponding execution plan for the query USE movie MATCH (a:Person)-[e]->(b@Movie) LIMIT 1 RETURN b.
Returns:
+-----------------------------------------------------------------+
| b |
+-----------------------------------------------------------------+
| (289255176823373825@Movie:Movie{id:485,name:"Cooper's Dreams"}) |
+-----------------------------------------------------------------+
Got 1 rows (time spent 19.451ms/20.555367ms)
• [P0]CallbackSink
│ details: Offset:0, Limit:1, Partial:false, Approx
│ :false
│ time(ms): 0.00
│ rows: 1
│ memory(KiB): 0.00
│ blocked(ms): 0.00
│ queued(ms): 0.07
│ consume(ms): 0.00
│ produce(ms): 0.00
│ finish(ms): 0.00
│ batches: 1
│ concurrency: 1
│
└── • [P0]Limit
│ details: Offset:0, Limit:1, Partial:false, Approx
│ :false
│ time(ms): 0.02
│ rows: 1
│ memory(KiB): 4.50
│ blocked(ms): 0.00
│ queued(ms): 0.00
│ consume(ms): 0.00
│ produce(ms): 0.02
│ finish(ms): 0.00
│ batches: 1
│ concurrency: 1
│
└── • [P0]HashJoinProbe
│ details: Project: b:NodeRef<(Movie)>, element_id
│ (b::NodeRef<(Movie)>)::INT64=(_right_nod
│ e_id(e::EdgeRef<(Actor)-[Act]->(Movie),
│ (Director)-[Direct]->(Movie), (User)-[Wa
│ tch]->(Movie)>))::INT64
│ time(ms): 0.19
│ rows: 486
│ memory(KiB): 32.31
│ blocked(ms): 14.71
│ queued(ms): 0.01
│ consume(ms): 0.02
│ produce(ms): 0.17
│ finish(ms): 0.00
│ batches: 1
│ concurrency: 1
│ others: {"joinProbe":"22/22 100%"}
│
├── • [P0]StorageRemoteAccess
│ │ details: TableScan: {Movie: {name, id}}, b{}
│ │ time(ms): 0.00
│ │ rows: 22
│ │ memory(KiB): 0.00
│ │ blocked(ms): 0.85
│ │ queued(ms): 0.16
│ │ consume(ms): 0.00
│ │ produce(ms): 0.00
│ │ finish(ms): 0.00
│ │ batches: 1
│ │ concurrency: 1
│ │
│ └── • [SP0]CallbackSink
│ │ details: TableScan: {Movie: {name, id}}, b{}
│ │ time(ms): 0.02
│ │ rows: 142
│ │ memory(KiB): 0.00
│ │ blocked(ms): 0.00
│ │ queued(ms): 0.51
│ │ consume(ms): 0.02
│ │ produce(ms): 0.00
│ │ finish(ms): 0.00
│ │ batches: 6
│ │ concurrency: 1
│ │
│ └── • [SP0]NodesScan
│ details: TableScan: {Movie: {name, id}}, b{}
│ time(ms): 0.77
│ rows: 142
│ memory(KiB): 85.02
│ blocked(ms): 0.00
│ queued(ms): 0.00
│ consume(ms): 0.00
│ produce(ms): 0.77
│ finish(ms): 0.00
│ batches: 6
│ concurrency: 1
│
└── • [P1]HashJoinBuild
│ details: Project: b:NodeRef<(Movie)>, element_id
│ (b::NodeRef<(Movie)>)::INT64=(_right_nod
│ e_id(e::EdgeRef<(Actor)-[Act]->(Movie),
│ (Director)-[Direct]->(Movie), (User)-[Wa
│ tch]->(Movie)>))::INT64
│ time(ms): 0.89
│ rows: 240
│ memory(KiB): 450.25
│ blocked(ms): 0.00
│ queued(ms): 0.09
│ consume(ms): 0.36
│ produce(ms): 0.01
│ finish(ms): 0.52
│ batches: 0
│ concurrency: 1
│ others: {"joinDynamicFilter":240,"joinBridge":24
│ 0}
│
└── • [P1]StorageRemoteAccess
│ details: (in((node_type_id((_left_node_id(e::Edge
│ Ref<(Actor)-[Act]->(Movie), (Director)-[
│ Direct]->(Movie), (User)-[Watch]->(Movie
│ )>))::INT64))::INT16, [1024,1025,1026]::
│ LIST<INT16>))::BOOL
│ time(ms): 0.01
│ rows: 7891
│ memory(KiB): 0.00
│ blocked(ms): 12.74
│ queued(ms): 0.27
│ consume(ms): 0.00
│ produce(ms): 0.01
│ finish(ms): 0.00
│ batches: 10
│ concurrency: 1
│
└── • [SP0]CallbackSink
│ details: (in((node_type_id((_left_node_id(e::Edge
│ Ref<(Actor)-[Act]->(Movie), (Director)-[
│ Direct]->(Movie), (User)-[Watch]->(Movie
│ )>))::INT64))::INT16, [1024,1025,1026]::
│ LIST<INT16>))::BOOL
│ time(ms): 0.24
│ rows: 7891
│ memory(KiB): 0.00
│ blocked(ms): 0.00
│ queued(ms): 17.95
│ consume(ms): 0.23
│ produce(ms): 0.01
│ finish(ms): 0.00
│ batches: 30
│ concurrency: 1
│
└── • [SP0]Filter
│ details: (in((node_type_id((_left_node_id(e::Edge
│ Ref<(Actor)-[Act]->(Movie), (Director)-[
│ Direct]->(Movie), (User)-[Watch]->(Movie
│ )>))::INT64))::INT16, [1024,1025,1026]::
│ LIST<INT16>))::BOOL
│ time(ms): 1.34
│ rows: 7891
│ memory(KiB): 3.97
│ blocked(ms): 0.00
│ queued(ms): 0.00
│ consume(ms): 0.01
│ produce(ms): 1.33
│ finish(ms): 0.00
│ batches: 30
│ concurrency: 1
│
└── • [SP0]EdgesScan
details: direction: outgoing: true, incoming: fal
se, undirected0: false, undirected1: fal
se, TableScan: {Watch: {}}, TableScan: {
Direct: {}}, TableScan: {Act: {}}, e{}
time(ms): 6.08
rows: 7891
memory(KiB): 128.44
blocked(ms): 0.00
queued(ms): 0.00
consume(ms): 0.00
produce(ms): 6.08
finish(ms): 0.00
batches: 30
concurrency: 1
Execution Plan: [Px] means pipeline-x and [S] means storage side.
Elapsed Time:
parse time : 416 us
build time : 592 us
optimize time : 583 us
serialize time: 136 us
total time : 19451 us
The first table shows the query results, and the nested view below shows the execution plan for the query. Each level of the nested view corresponds to an operator, and the indentation between levels indicates the dependency between operators.