XML datatype instance has too many levels of nested nodes. Maximum allowed depth is 128 levels. Gah!

Yeah, that’s pretty annoying! You’re in a rush to troubleshoot the performance of a stored proc that’s gone rogue, and the tool you are using (something like the SQL statement pictured above) is crashing with this XML error with sys.dm_exec_text_query_plan. You don’t have time to fix the tool properly, so you hack it apart and finally get the query plan text displayed graphically, address the issue and hastily move on to the next burning issue.

This blog post presents an upgraded script to take the pain out of that hacking process.  Let’s face it, when you need to see a query plan, you need to see it quickly, not after half an hour of swearing about  your developers for writing code that compiles to such a complex plan, and Microsoft for, well, just being themselves. So, with no further ado:

/* 
ScriptName:  StoredProcCachedPerformanceDissection.sql
Description: This script returns statement level performance measures and query plans (in xml format where possible) for a given stored proc. 

Having run this script, to view a query plan listed as 'Not possible':
   1. Copy/paste and run the SQLGetQueryPlan statement in the current query window
   2. Save results to a file named anything.sqlplan and open via SSMS
   (You may also need to increase SSMS Query menu => Query options => Execution => general => Set TextSize  (SSMS 2012))
*/

--Parameters section:

DECLARE @SchemaDotObject NVARCHAR(255) = 'dbo.uspGetTrades' --proc should be in current database
      , @HideQueryPlans BIT = 0              --Set to 1 for pasting results to Excel, or for faster results to client
		, @ThresholdMaxElapsedSeconds INT = 60 --Filter out statements running quicker than this for results to client

DECLARE @PosDot INT = charindex('.',@SchemaDotObject )
DECLARE @schemaName NVARCHAR(128) = LEFT (@SchemaDotObject ,@PosDot -1)
      , @objectName NVARCHAR(128) = RIGHT(@SchemaDotObject ,LEN(@SchemaDotObject) -@PosDot )

SET NOCOUNT ON
DECLARE @dbID INT = DB_ID(),
        @objectID INT

SELECT @objectID = p.object_id,
       @schemaName = s.name
FROM   sys.objects p
       JOIN sys.schemas s on p.schema_id = s.schema_id
WHERE  p.name = @objectName
       AND s.name = @schemaName
       
IF @objectid IS NULL BEGIN
       DECLARE @ErrorMessage VARCHAR(255) = 'stored proc ''' + @SchemaDotObject + ''' not found in current database' 
       SELECT @ErrorMessage 'Error'
       RAISERROR(@ErrorMessage,16,1)
END

IF OBJECT_ID('tempdb..#Results') IS NOT NULL DROP TABLE #Results
SELECT Statement = ROW_NUMBER() OVER (ORDER BY QS.statement_start_offset),
		 DatabaseName = DB_NAME(ST.dbid),
       ObjectName = @SchemaDotObject,
       ObjectType = CP.objtype,
       SQLStatement = SUBSTRING(ST.text, QS.statement_start_offset / 2 + 1, 
                              ((CASE WHEN QS.statement_end_offset = -1 THEN (LEN(CONVERT(NVARCHAR(MAX), ST.text)) * 2) 
                                     ELSE QS.statement_end_offset END) - QS.statement_start_offset) / 2 + 1),
	    NVarcharQP = SQP.query_plan ,
       XMLQP = CONVERT(XML , 'Not possible'),            --update this later with real query plan
       SQLGetQueryPlan = CONVERT(NVARCHAR(255), N'N/A'), --update this later with real sql
       MemoryAddress = CP.memory_object_address,
       PlanCreationTime = QS.creation_time,
       PlanLastExecutionTime = QS.last_execution_time,
       ExecutionCount = QS.execution_count,
       LastElapsedSecs = QS.last_elapsed_time / 1000000,
       LastCPUSecs = QS.last_worker_time / 1000000,
       AverageElapsedSecs = CASE WHEN QS.execution_count = 0 THEN NULL
                                 ELSE QS.total_elapsed_time / QS.execution_count / 1000000
                            END,
       AverageCPUSecs = CASE WHEN QS.execution_count = 0 THEN NULL
                             ELSE QS.total_worker_time / QS.execution_count / 1000000
                        END,
       MinElapsedSecs = QS.min_elapsed_time / 1000000,
       MinCPUSecs = QS.min_worker_time / 1000000,
       MaxElapsedSecs = QS.max_elapsed_time / 1000000,
       MaxCPUsecs = QS.max_worker_time / 1000000,
       LastRowCount = QS.last_rows,
       AverageRowCount = CASE WHEN QS.execution_count = 0 THEN NULL
                              ELSE QS.total_rows / QS.execution_count
                         END,
       MinRowCount = QS.min_rows,
       MaxRowCount = QS.max_rows,
       LastPhysicalReadsMB = QS.last_physical_reads / 128,
       AveragePhysicalReadsMB = CASE WHEN QS.execution_count = 0 THEN NULL
                                     ELSE QS.total_physical_reads / QS.execution_count / 128
                                END,
       MinPhysicalReadsMB = QS.min_physical_reads / 128,
       MaxPhysicalReadsMB = QS.max_physical_reads / 128,
       LastLogicalReadsMB = QS.last_logical_reads / 128,
       AverageLogicalReadsMB = CASE WHEN QS.execution_count = 0 THEN NULL
                                    ELSE QS.total_logical_reads / QS.execution_count / 128
                               END,
       MinLogicalReadsMB = QS.min_logical_reads / 128,
       MaxLogicalReadsMB = QS.max_logical_reads / 128,
       LastLogicalWritesMB = QS.last_logical_writes / 128,
       AverageLogicalWritesMB = CASE WHEN QS.execution_count = 0 THEN NULL
                                     ELSE QS.total_logical_writes / QS.execution_count / 128
                                END,
       MinLogicalWritesMB = QS.min_logical_writes / 128,
       MaxLogicalWritesMB = QS.max_logical_writes / 128
into #Results
FROM   sys.dm_exec_cached_plans AS CP
       CROSS APPLY sys.dm_exec_sql_text(CP.plan_handle) AS ST
       LEFT JOIN sys.dm_exec_query_stats QS
              ON CP.plan_handle = QS.plan_handle
       OUTER APPLY sys.dm_exec_text_query_plan(CP.plan_handle, QS.statement_start_offset, QS.statement_end_offset) SQP
WHERE  ST.dbid = @dbid
       AND ST.objectid = @objectid
ORDER  BY CP.memory_object_address DESC,
          QS.statement_start_offset ASC

DECLARE @Statement INT
SELECT @Statement=MAX(Statement) from #Results
WHILE @Statement>0 BEGIN
   BEGIN TRY
      UPDATE #Results SET XMLQP = CONVERT(XML, NVarcharQP) FROM #Results WHERE Statement=@Statement
   END TRY
   BEGIN CATCH
      UPDATE #Results Set SQLGetQueryPlan = N'SELECT NVarcharQP FROM #Results WHERE Statement = ' + CONVERT (NVARCHAR,@Statement ) WHERE Statement=@Statement
   END CATCH;
   SELECT @Statement = @Statement - 1
END

SELECT 
 DatabaseName, ObjectName, ObjectType, Statement, SQLStatement
, CASE WHEN @hideQueryPlans=1 THEN 'hidden' ELSE XMLQP END 'XML Query Plan'
, SQLGetQueryPlan
, MemoryAddress, PlanCreationTime, PlanLastExecutionTime, ExecutionCount
, LastElapsedSecs, LastCPUSecs, AverageElapsedSecs, AverageCPUSecs, MinElapsedSecs, MinCPUSecs, MaxElapsedSecs, MaxCPUsecs
, LastRowCount, AverageRowCount, MinRowCount, MaxRowCount
, LastPhysicalReadsMB, AveragePhysicalReadsMB, MinPhysicalReadsMB, MaxPhysicalReadsMB
, LastLogicalReadsMB, AverageLogicalReadsMB, MinLogicalReadsMB, MaxLogicalReadsMB
, LastLogicalWritesMB, AverageLogicalWritesMB, MinLogicalWritesMB, MaxLogicalWritesMB
FROM #Results
WHERE MaxElapsedSecs > @ThresholdMaxElapsedSeconds
ORDER By Statement

sample output (ignoring the performance metrics):

resul

You should be able to click and instantly view those query plans in a new window. Where the XML Query Plan is listed as “not possible”, that’s because the nvarchar(max) query plan could not be converted to XML, probably because of the depth of nested nodes. Instead copy the SQLGetQueryPlan cell to the query window and execute this line of code:

res2

Save results to anything.sqlplan, and open this new file in SSMS to view the graphical execution plan. Sweet!

P.s. I didn’t write the whole script from scratch. I found the original via google years ago, but cannot remember or find the source to reference. I just made it tolerant of conversion issues, and simplified the process of viewing plans that cannot be stored in xml.

 

Leave a comment