For the snowflake query history profile view, is there a reason why the profile graph doesn't show the current node execution time?

user_307798 0
Viewed 161

I'm not using "Snowsight" yet, and trying to determine troubleshoot query performance by looking at how long each node took.

In clicking around, I can see that the profile view says "Node Execution Time" on the right in the node details area, but no time is printed for the node execution time (it prints percentages instead):

query profile

Is this an oversight? Or will it be added in the future?

I tried looking at the same query profile in snowsight, however, it says that the node only took 616ms (which I thought was odd because this was the longest node (in time) and the entire query took 4m 25s. How can the poorest performing node in a 4m+ query take only 616ms?).

It appears that snowsight is starting to show the node execution time (yay!) but it feels like the actual execution time is wrong.

snowsight query profile

I even went through every node in the snowsight query profile view and looked at each node execution time. They don't add up to 4m 25s (which I didn't expect them to because snowflake is going to run some of the nodes in parallel). However, they only add up to 945ms total (yet the query took 4m 25s).

It appears that I'm missing something, or the query profile view in snowsight isn't showing me all the right information?

(I know there are a few questions in here. In trying to read over the docs it appears that execution time is supposed to include processing by the CPU, Disk IO, Network transfer, etc, etc, so I'm still trying to iron out why in the snowsight view the total execution time of each node adds up to be less than 1 second, yet the entire query took 4m+)

snowflake-cloud-data-platform
3 Answers

Let me answer this question with an exploding join query:

select median(a.r / b.r)
from (
    select random() r 
    from table(generator(rowcount => 10000))
) a, (
    select random() r
    from table(generator(rowcount => 10000))
) b

It looks simple, but it generated 100,000,000 rows that had to be held in memory to obtain the median.

The query profile view shows that the most expensive node took only 99ms, but the whole query took 36s:

enter image description here

The explanation is in the bottom block at the right:

Bytes spilled to local storage: 730.41MB

When too much memory is required to process results, bytes are spilled to local and remote storage — making the queries way slower.

Note that in this case this query takes the same time in an S or XL warehouse: There's not much parallelization to be had, and most of the time is spent writing the 100M rows to temporary SSD storage to find the median.

Note that the same query takes only 6s over the same 100M rows if we ask for AVG() instead of MEDIAN():

enter image description here

(If you share your query in a new question we can dig into possible optimizations for it)

user_1324380

To summarize what Felipe said, the node execution time does not include blocking on I/O operations, like waiting for data transfer or network operations.

user_4532380

Also, you may confuse the time shown in the worksheet or SQL tool you are using, which typically also include the time to return the rows.

user_123397390
Related