Snowflake users can finally dig deep into query stats with this new function. This data was only available in the query profile visualization, and now you can get it in your SQL world with GET_QUERY_OPERATOR_STATS(). Let’s review the new function, and how to use it to get deeper insights while benchmarking.

The old ways

Previously you could find deep stats only on the query profile visualization UI:

This is a pretty cool view that can help you understand the performance details of each query: How many steps it took, how many rows where the input and output of each step, which step took the most time, how much data was scanned, etc.

What’s new: GET_QUERY_OPERATOR_STATS()

But people wanted more: Many users where not happy getting everything in a cool interactive visualization, they wanted the same data in a table full of columns and numbers.

Snowflake listened. And Snowflake now has the new get_query_operator_stats() function. Check out the docs and the announcement blog:

To get the stats for one query, you just need to run:

select *
from table(get_query_operator_stats(last_query_id()));

That gives you a detailed table with all the stats of the previous query:

What’s missing: Going beyond one query

While that’s pretty cool, now people are asking how to go beyond one query. They don’t want to go one by one, they want to get the stats for all their queries. So let’s use the rest of this post to find out a way to do so.

Using the new query stats to analyze a whole run of TPCH benchmarks

Setup

Mimoune Djouallah has been running benchmarks of several dbs, and Felipe Hoffa took his code to run TPC-H-SF10 over the data that Snowflake already provides on your account. Just make sure to use schema snowflake_sample_data.tpch_sf10 for these queries run.

Then Felipe ran these benchmark queries 4 times: Twice on a Small warehouse, and twice on a XL warehouse.

After running these queries, he used the following query to gather all the basic stats:

create or replace table query_sessions2
as
select *, sum(is_session_start) over(order by start_time) session_id
from (
select query_id, query_text, query_type, warehouse_size, start_time, total_elapsed_time
        , bytes_scanned, rows_produced, compilation_time, execution_time
        , queued_provisioning_time, query_tag
        , regexp_substr(query_text, '--Query(..)', 1,1,'',1)::int qid
        , iff(qid < lag(qid) over(order by start_time) ,1,0) is_session_start
from table(information_schema.query_history(result_limit=>1000))
where bytes_scanned > 1000
and query_text like '%--Query%'
and start_time > '2023-02-06 18:00'
order by start_time desc
);

The above query does this:

• Look for all queries in the recent query history within the classic information_schema.query_history.
• It looks for all the queries annotated with a comment like --Query11. This is how we find the TPCH related queries, and it helps it to extract the id of each query for our convenience.
• We are only interested in queries that scanned more than 1000 bytes (make sure to turn off the results cache to get the queries to actually run every time).
• Then the query uses a combination of each query id and lag() to identify each different benchmark run, and give each run a different session_id.

None of this is new, but it’s pretty convenient to identify each of the benchmarking runs and how long it took:

select warehouse_size, session_id, query_tag, sum(total_elapsed_time), sum(bytes_scanned)
    , count(*), min(start_time) start_time
from query_sessions2
group by 1,2, 3
order by session_id;

Note that I also used the handy alter session set query_tag = ‘small-cold’; to annotate each query with a manual tag.

The table shows that running the 22 queries on a Small warehouse took 32s the 1st time, and 18s the 2nd time. Then on a XL warehouse it took 25s the 1st time, and 13s the 2nd time. We also got to use the session_id we created previously, which makes our stats easier to compute.

You probably already know this: The XL warehouse is faster as it offers more parallelism, and the second run of each is faster as it uses the Snowflake local disk cache. This means that your queries on Snowflake are faster on warm data — which is the typical scenario when you are running a series of queries.

Let’s go deeper — get all the query stats

So now comes the trick to go over these 88 queries (22*4) and get their query stats: A little SQL script.

First let’s create a table that will hold the query stats we are going to collect, plus the convenient TPCH query id and session id we produced earlier:

create or replace table query_operator_stats_cache2
as
select 1::integer qid, 1::integer session_id, ''::string query_tag, *
from table(get_query_operator_stats(last_query_id()))
-- just for the schema
limit 0;

The trick for the above query is to run get_query_operator_stats over a random query to re-use its schema, with a limit 0 as I only want the schema in this case.

Then the following script can go over the 88 queries we ran during our benchmarks, and store the stats for each on the table we just created — plus our convenient query id and session id:

declare
  query_id string;
  query_tag string;
  qid int;
  session_id int;
  c1 cursor for
select query_id, qid, session_id, query_tag
from query_sessions2 
where query_id not in (select query_id from query_operator_stats_cache2);
begin
open c1;
for record in c1 do
fetch c1 into query_id, qid, session_id, query_tag;
insert into query_operator_stats_cache2
select :qid, :session_id, :query_tag, * from table(get_query_operator_stats(:query_id));  
end for;
return query_id;
end;

Note that Felipe had to run it many times, as get_query_operator_stats() can timeout. The query_id not in statement makes sure that each time we run the script, it only add missing data.

Analyzing the table scans

Now that we have stored the detailed query stats for 88 queries, we can have fun analyzing them. For example, this view will isolate the stats of only the table scan steps:

create or replace view analyze_table_scans2
as
select qid, query_id, session_id, query_tag
 , operator_attributes:table_name::string tablename
 , array_size(operator_attributes:columns) table_ncols
 , execution_time_breakdown:overall_percentage::float time_percent
 , execution_time_breakdown:local_disk_io::float local_disk_io
 , execution_time_breakdown:processing::float processing
 , execution_time_breakdown:synchronization::float synchronization
 , operator_statistics:io:bytes_scanned::int bytes_scanned
 , operator_statistics:io:percentage_scanned_from_cache::float percentage_scanned_from_cache
 , operator_statistics:network:network_bytes::int network_bytes
 , operator_statistics:pruning:partitions_scanned::int scanned 
 , operator_statistics:pruning:partitions_total::int total
 , scanned/total ratio
from query_operator_stats_cache2
where operator_type = 'TableScan';

With easy access to these stats, now we can focus on any aspect — for example on what percentage of data was scanned from the local disk cache on each session:

select session_id, query_tag, avg(percentage_scanned_from_cache)
from analyze_table_scans2
group by 1, 2
order by session_id;

Looking at these results we get to learn something new: The second run was faster for the S and XL session, because in both second runs the data was “warm” and available to be scanned from cache. But only the 2nd run on the XL warehouse was able to get 100% of data out of the local disk cache — the S warehouse still had to go fetch some of it on the warm run.

This shows that the XL warehouse is not only faster because it offers more parallelism to run each query — but it also has a larger local disk cache that — in this case — is able to hold all the data scanned warm between rounds.

Then with the detailed stats, you can find out what tables had to be re-read from cold-storage, and in which queries:

select qid, tablename, percentage_scanned_from_cache, bytes_scanned
from analyze_table_scans2
where session_id=1
order by percentage_scanned_from_cache;

Here you can see that it’s the table LINEITEM that had to be re-read from cold storage during the 2nd run in the small warehouse — within query #19, #12, #1, and #3 — but in all cases it was only a small percentage of that table. Meanwhile on the XL warehouse all the warm data stayed cached on the local disk.

Improving performance: Partition pruning

There’s something interesting happening in all these queries — we can see that there almost no partition pruning happened:

select sum(scanned) partitions_scanned, sum(total) partitions_total, partitions_scanned/partitions_total ratio
from analyze_table_scans2
order by qid, session_id, tablename;

Turns out the tables shared by Snowflake on the snowflake_sample_data.tpch_sf10 schema have not been optimized for querying.

To fix these, Felipe rematerialized the 2 biggest tables in his own schema — this time ordering the rows by date:

create table lineitem as
select *
from snowflake_sample_data.tpch_sf10.lineitem
order by l_shipdate;

create table orders as
select *
from snowflake_sample_data.tpch_sf10.orders
order by o_orderdate;

Then he created views so the original queries could find the existing smaller tables when being run in the new schema:

create view part as select *
from snowflake_sample_data.tpch_sf10.part;
create view supplier as select *
from snowflake_sample_data.tpch_sf10.supplier;
create view partsupp as select *
from snowflake_sample_data.tpch_sf10.partsupp;
create view nation as select *
from snowflake_sample_data.tpch_sf10.nation;
create view region as select *
from snowflake_sample_data.tpch_sf10.region;
create view customer asselect *
from snowflake_sample_data.tpch_sf10.customer;

With this done, he was able to get faster results, thanks to some effective partition pruning:

select session_id
    , sum(scanned) partitions_scanned
    , sum(total) partitions_total
    , partitions_scanned/partitions_total ratio
    , count(distinct qid) queries
from analyze_table_scans2
group by 1
order by 1

Even better, time within a Small warehouse for a cold run went from 32.4s down to 28.6s — a 11% performance increase.

select warehouse_size, session_id, query_tag, sum(total_elapsed_time), sum(bytes_scanned)
    , count(*), min(start_time) start_time
from query_sessions2
group by 1,2, 3
order by session_id;

Lessons learned

• You can use the new get_query_operator_stats() to get deep stats for your queries.
• Within these deep stats you can find information like the # of partitions scanned by each query.
• Storing tables ordered by date can help a lot with pruning — as in this specific case.
• Snowflake should re-materialize the shared sample tpch_sf10 tables, so anyone benchmarking them can get faster results with no effort.
• Even when Snowflake had not optimized these tables for the benchmark, Mimoune Djouallah found out that Snowflake was the fastest of the benchmarked candidates. Snowflake is fast — and with small changes we can make it even faster.
• Note that any benchmarks shown here reflect an arbitrary set up at an arbitrary point of time. Your numbers might vary.

Source: Felipe Hoffa on Medium