Showing posts with label EXPLAIN PLAN. Show all posts
Showing posts with label EXPLAIN PLAN. Show all posts

Thursday, 29 June 2017

Explain Plan in Azure Warehouse (sort of)

Simplistically, the purpose of an explain plan is to reveal how the database plans to deliver results for a given query. In Oracle we have "SQL> EXPLAIN PLAN FOR <QUERY>;" and in SQL Server we have "click->display estimated execution plan" which shows a graphical diagram showing all the details of the execution steps and path. Both are important to diagnose query performance related issues.

In Azure Data warehouse, we have very little. It takes a certain amount of effort to get something readable as the aforementioned SSMS "rclick->display" option does not work in the studio. There are a number of posts on the internet about how to get this information but the results seem somewhat lacklustre: one method is to get the execution plan in an XML format that is not compatible with SSMS - so one is left to look at an XML file. The other option is to go the Azure portal and see the query running via the web console. Both options falls short of what most db developers are accustomed to.

I have found a useful alternative although it is not exactly a traditional explain plan. What it is is the sequence of steps the database is taking to achieve the results.
These steps can be found in the object "sys.dm_pdw_request_steps" - how I use this is shown below.

I can only use the following steps while my query is running. Once the query is done, the steps vanish from the steps table. Therefore, this is more of a technical query progress report showingthe steps that ran, the steps which are running, and the steps which will run. The first key is identify my sessions REQUEST_ID in sys.dm_pdw_exec_requests. I use sys.dm_pdw_exec_requests and I find that the most laborious queries pop in the top results. Once I have those master request and their child requests, I use those to find the segments of steps in the "sys.dm_pdw_request_steps" table.

print ''
print '============================================='
print '============================TOP QUERIES IN DW'
print '============================================='
print ''
go

  select TOP 10
         status,
         request_id as request_id,
         submit_time as submit_time,
         start_time as start_time,
         (total_elapsed_time/1000) as total_elapsed_time,
         substring(command,0,50) command
    from sys.dm_pdw_exec_requests
order by 1 desc,total_elapsed_time DESC
GO

print ''
print '========================================='
print '============================RUNNING STEPS'
print '========================================='
print ''
go


  SELECT DATEDIFF(SECOND, s.start_time, s.end_time) Time_In_Seconds,
         s.request_id AS request,
         s.operation_type AS operation_type,
         s.distribution_type AS distribution_type,
         s.location_type AS location_type,
         s.status AS status,
         s.start_time AS start_time,
         s.end_time AS end_time,
         s.total_elapsed_time AS total_elapsed_time,
         s.row_count AS row_count,
         s.command AS command
    FROM sys.dm_pdw_request_steps s
   WHERE request_id IN (SELECT request_id
                          FROM sys.dm_pdw_exec_requests
                         WHERE status = 'Running'
                           AND total_elapsed_time > 5 ) 
ORDER BY s.request_id, s.step_index;

For simplicity, I reduced the result sets both column and row wise so I can focus on a session that is taking a while to run. Request QID89235213 is a massive query running in parallel across the warehouse. It is inserting data into a table. Its steps can be shown in the RUNNING STEPS block. I can see the time its taken for each step, the number of rows per step and the type of operation it is running. At the time of rendering, the results show that the process is running a ShuffleMoveOperation which is likely processing 66 million records. It still has a number of PENDING steps to process.

=============================================
============================TOP QUERIES IN DW
=============================================

status                           request_id           total_elapsed_time command
-------------------------------- -------------------- ------------------ --------------------------------------------------
Running                          QID89235213                        1881 INSERT INTO Warehouse.tb_FactTable_WHTest                                                      

=========================================
============================RUNNING STEPS
=========================================

request      operation_type       distribution_type location_type   status     total_elapsed_time row_coun command
------------ -------------------- ----------------- --------------- ---------- ------------------ -------- ------------------------------
QID89235213  RandomIDOperation    Unspecified       Control         Complete   0                  -1       TEMP_ID_1788
QID89235213  OnOperation          AllDistribution   Compute         Complete   78                 -1       CREATE TABLE [tempdb].[dbo].[
QID89235213  ShuffleMoveOperation Unspecified       DMS             Running    936636             -1       SELECT [T1_1].[EventName] AS
QID89235213  OnOperation          AllDistribution   Compute         Pending    NULL               -1       DROP TABLE [tempdb].[dbo].[TE
QID89235213  OnOperation          AllDistribution   Compute         Pending    NULL               -1       DROP TABLE [tempdb].[dbo].[TE


As the engine completes each step, the query is closer to completion. This helps me know whats happening under the hood of the Azure Warehouse Database.

Wednesday, 13 July 2016

V$SQL_PLAN Formatted Output

A coworker was tasked to make adjustments to a query. He increased the scope of the query by adding 2 new tables and a few new parameters.
The new query was incredibly slow and he needed assistance in finding out why.

In the process of investigating the issue, I reworked a script to create a query plan display similar to DBMS_XPLAN.DISPLAY.
This is handy if one is working backwards in pulling the thread from the struggling session to the query plan.

Usually, if one has the query text on hand, the explain plan can be drawn by using the following form:

set pages 1000
set lines 1000

EXPLAIN PLAN FOR
  <YOUR QUERY HERE>;
  
SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY);

EXAMPLE: EXPLAIN PLAN FOR
   select sysdate from dual;
   
SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY);


OUTPUT:
SQL>
EXPLAIN PLAN FOR
   select sysdate from dual;

SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY);SQL>   2
Explained.

SQL> SQL>

PLAN_TABLE_OUTPUT
-----------------------------------------------------------------
Plan hash value: 1388734953

-----------------------------------------------------------------
| Id  | Operation        | Name | Rows  | Cost (%CPU)| Time     |
-----------------------------------------------------------------
|   0 | SELECT STATEMENT |      |     1 |     2   (0)| 00:00:01 |
|   1 |  FAST DUAL       |      |     1 |     2   (0)| 00:00:01 |
-----------------------------------------------------------------

8 rows selected.

SQL>

But, if I am working the other way around where all I have is an unhappy user with a poor performing session, the following query will allow me to see the query plan responsible for their anguish:

SET LINES 1000
SET PAGES 1000
COLUMN I FORMAT A3


  SELECT /*+ NO_MERGE */ 
         ROWNUM-1||
DECODE(access_predicates,NULL,DECODE(filter_predicates,NULL,'','*'),'*') "I",
         SUBSTR(LPAD(' ',(DEPTH-1))||
OPERATION,1,40)||
DECODE(OPTIONS,NULL,'',' (' 
|| OPTIONS 
|| ')') "Operation",
         SUBSTR(OBJECT_NAME,1,30) "Object Name",
         cardinality "# Rows",
         bytes,
         cost,
         time
    FROM (
         SELECT * 
           FROM gv$sql_plan 
          WHERE sql_id = (
                         SELECT sql_id 
                           FROM gv$session 
                          WHERE sid = <SID_HERE>
                         )
         ) plan
ORDER BY id
/


The above query was found and taken from an ASK TOM response and adjusted here and there for my own purposes (cluster, sid, formatting, removal of filter)


I will need to have identified the users session on production in order to find their SID. Once found, I plug the SID into the <SID_HERE> tag above. I was initially looking for a way to format the output of v$sql_plan and found a number of decent solutions.

The developer had included 2 new tables into their query and had forgotten to join them. The result was a cartesian on a large dataset. Below is a comparison of the 2 outputs of the explain plan of their poor performing query - one is from DBMS_XPLAN.DISPLAY, the other is from the above query.
Once connecting the table, the result set was reduced to a few records as intended.

DBMS_XPLAN.DISPLAY

----------------------------------------------------------------------------------------------------
| Id  | Operation                           | Name              |Rows  |Bytes |Cost (%CPU)|Time    |
----------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                    |                   |20367 | 1809K|32160   (1)|00:06:26|
|   1 |  NESTED LOOPS                       |                   |    1 |   46 |    4   (0)|00:00:01|
|   2 |   NESTED LOOPS                      |                   |    1 |   34 |    3   (0)|00:00:01|
|   3 |    TABLE ACCESS BY INDEX ROWID      | TABLE_AAAAAAA     |    1 |   18 |    2   (0)|00:00:01|
|*  4 |     INDEX UNIQUE SCAN               | XXX_XXX_PK        |    1 |      |    1   (0)|00:00:01|
|   5 |    TABLE ACCESS BY INDEX ROWID      | TABLE_BBB         |    1 |   16 |    1   (0)|00:00:01|
|*  6 |     INDEX UNIQUE SCAN               | TABLE_BBB_PK      |    1 |      |    0   (0)|00:00:01|
|   7 |   TABLE ACCESS BY INDEX ROWID       | TABLE_CCC         |    1 |   12 |    1   (0)|00:00:01|
|*  8 |    INDEX UNIQUE SCAN                | TABLE_CCC_PK      |    1 |      |    0   (0)|00:00:01|
|   9 |  SORT ORDER BY                      |                   |20367 | 1809K|32160   (1)|00:06:26|
|  10 |   CONCATENATION                     |                   |      |      |           |        |
|* 11 |    FILTER                           |                   |      |      |           |        |
|* 12 |     FILTER                          |                   |      |      |           |        |
|  13 |      MERGE JOIN CARTESIAN           |                   |  403K|   35M|17206   (1)|00:03:27|
|  14 |       MERGE JOIN CARTESIAN          |                   |    1 |   91 | 3536   (1)|00:00:43|
|  15 |        NESTED LOOPS                 |                   |      |      |           |        |
|  16 |         NESTED LOOPS                |                   |    1 |   87 | 2260   (1)|00:00:28|
|* 17 |          TABLE ACCESS BY INDEX ROWID| TABLE             |    1 |   57 | 2257   (1)|00:00:28|
|* 18 |           INDEX RANGE SCAN          | TABLE_XX_IX       |    1 |      | 2256   (1)|00:00:28|
|* 19 |          INDEX RANGE SCAN           | XX_IX_1           |    1 |      |    2   (0)|00:00:01|
|* 20 |         TABLE ACCESS BY INDEX ROWID | TABLE_CCCCCCCCCCCC|    1 |   30 |    3   (0)|00:00:01|
|  21 |        BUFFER SORT                  |                   |  196 |  784 | 3533   (1)|00:00:43|
|* 22 |         INDEX FULL SCAN             | XX_XX_IX          |  196 |  784 | 1276   (2)|00:00:16|
|  23 |       BUFFER SORT                   |                   | 4545K|      |15931   (1)|00:03:12|
|  24 |        TABLE ACCESS FULL            | TABLE_DDDDD       | 4545K|      |13670   (1)|00:02:45|
|  25 |     TABLE ACCESS BY INDEX ROWID     | TABLE_EEEEEEEEE   |    1 |   14 |    4   (0)|00:00:01|
|* 26 |      INDEX SKIP SCAN                | XX_PK             |    1 |      |    3   (0)|00:00:01|
|* 27 |    FILTER                           |                   |      |      |           |        |
|* 28 |     FILTER                          |                   |      |      |           |        |
|  29 |      MERGE JOIN CARTESIAN           |                   |    1 |   91 |14953   (1)|00:03:00|
|  30 |       MERGE JOIN CARTESIAN          |                   |    1 |   91 | 1283   (2)|00:00:16|
|  31 |        NESTED LOOPS                 |                   |      |      |           |        |
|  32 |         NESTED LOOPS                |                   |    1 |   87 |    7   (0)|00:00:01|
|* 33 |          TABLE ACCESS BY INDEX ROWID| TABLE             |    1 |   57 |    4   (0)|00:00:01|
|* 34 |           INDEX RANGE SCAN          | TABLE_XX_IX       |    1 |      |    3   (0)|00:00:01|
|* 35 |          INDEX RANGE SCAN           | XX_IX_1           |    1 |      |    2   (0)|00:00:01|
|* 36 |         TABLE ACCESS BY INDEX ROWID | TABLE_CCCCCCCCCCCC|    1 |   30 |    3   (0)|00:00:01|
|  37 |        BUFFER SORT                  |                   |  196 |  784 | 1280   (2)|00:00:16|
|* 38 |         INDEX FULL SCAN             | XX_XX_IX          |  196 |  784 | 1276   (2)|00:00:16|
|  39 |       BUFFER SORT                   |                   | 4545K|      |13677   (1)|00:02:45|
|  40 |        TABLE ACCESS FULL            | TABLE_DDDDD       | 4545K|      |13670   (1)|00:02:45|
|  41 |     TABLE ACCESS BY INDEX ROWID     | TABLE_EEEEEEEEE   |    1 |   14 |    4   (0)|00:00:01|
|* 42 |      INDEX SKIP SCAN                | XX_PK             |    1 |      |    3   (0)|00:00:01|
----------------------------------------------------------------------------------------------------

QUERY : V$SQL_PLAN
I   Operation                                Object Name            # Rows    BYTES     COST     TIME
--- ---------------------------------------- ------------------  --------- -------- -------- --------
0   SELECT STATEMENT                                                                   32160
1   NESTED LOOPS                                                         1       46        4        1
2    NESTED LOOPS                                                        1       34        3        1
3     TABLE ACCESS (BY INDEX ROWID)          SUP_LOCATIONS               1       18        2        1
4*     INDEX (UNIQUE SCAN)                   SUP_AZL_PK                  1                 1        1
5     TABLE ACCESS (BY INDEX ROWID)          SUP_ZONES                   1       16        1        1
6*     INDEX (UNIQUE SCAN)                   SUP_ZONES_PK                1                 0
7    TABLE ACCESS (BY INDEX ROWID)           SUP_AREAS                   1       12        1        1
8*    INDEX (UNIQUE SCAN)                    SUP_AREAS_PK                1                 0
9   SORT (ORDER BY)                                                  20367  1853397    32160      386
10   CONCATENATION                                                                    
11*   FILTER                                                                          
12*    FILTER                                                                         
13      MERGE JOIN (CARTESIAN)                                      403484 36717044    17206      207
14       MERGE JOIN (CARTESIAN)                                          1       91     3536       43
15        NESTED LOOPS                                                                
16         NESTED LOOPS                                                  1       87     2260       28
17*         TABLE ACCESS (BY INDEX ROWID)    ITEMS                       1       57     2257       28
18*          INDEX (RANGE SCAN)              ITEMS_CT_N1                 1              2256       28
19*         INDEX (RANGE SCAN)               CT_IX_1                     1                 2        1
20*        TABLE ACCESS (BY INDEX ROWID)     CARGO_TRANSACTIONS          1       30        3        1
21        BUFFER (SORT)                                                196      784     3533       43
22*        INDEX (FULL SCAN)                 AH_VN_IX                  196      784     1276       16
23       BUFFER (SORT)                                             4545904             15931      192
24        TABLE ACCESS (FULL)                ADMIN_ITEMS           4545904             13670      165
25     TABLE ACCESS (BY INDEX ROWID)         SUP_COMMODITIES             1       14        4        1
26*     INDEX (SKIP SCAN)                    SC_PK                       1                 3        1
27*   FILTER                                                                          
28*    FILTER                                                                         
29      MERGE JOIN (CARTESIAN)                                           1       91    14953      180
30       MERGE JOIN (CARTESIAN)                                          1       91     1283       16
31        NESTED LOOPS                                                                
32         NESTED LOOPS                                                  1       87        7        1
33*         TABLE ACCESS (BY INDEX ROWID)    ITEMS                       1       57        4        1
34*          INDEX (RANGE SCAN)              ITEMS_CT_N1                 1                 3        1
35*         INDEX (RANGE SCAN)               CT_IX_1                     1                 2        1
36*        TABLE ACCESS (BY INDEX ROWID)     CARGO_TRANSACTIONS          1       30        3        1
37        BUFFER (SORT)                                                196      784     1280       16
38*        INDEX (FULL SCAN)                 AH_VN_IX                  196      784     1276       16
39       BUFFER (SORT)                                             4545904             13677      165
40        TABLE ACCESS (FULL)                ADMIN_ITEMS           4545904             13670      165
41     TABLE ACCESS (BY INDEX ROWID)         SUP_COMMODITIES             1       14        4        1
42*     INDEX (SKIP SCAN)                    SC_PK                       1                 3        1

43 rows selected.