{"id":452551,"date":"2025-03-21T15:00:14","date_gmt":"2025-03-21T15:00:14","guid":{"rendered":"http:\/\/savepearlharbor.com\/?p=452551"},"modified":"-0001-11-30T00:00:00","modified_gmt":"-0001-11-29T21:00:00","slug":"","status":"publish","type":"post","link":"https:\/\/savepearlharbor.com\/?p=452551","title":{"rendered":"<span>Building Flame Diagram for MSSQL stored procedures<\/span>"},"content":{"rendered":"<div><!--[--><!--]--><\/div>\n<div id=\"post-content-body\">\n<div>\n<div class=\"article-formatted-body article-formatted-body article-formatted-body_version-2\">\n<div xmlns=\"http:\/\/www.w3.org\/1999\/xhtml\">\n<p>If your code has many nested executions of stored procedures, you can benefit from building popular &#171;flame diagram&#187; of the execution time which is de facto standard for performance profiling.<\/p>\n<figure class=\"\"><img loading=\"lazy\" decoding=\"async\" src=\"https:\/\/habrastorage.org\/r\/w1560\/getpro\/habr\/upload_files\/13a\/ede\/a66\/13aedea663eb9957549ef74edf161ed2.png\" width=\"511\" height=\"308\" data-src=\"https:\/\/habrastorage.org\/getpro\/habr\/upload_files\/13a\/ede\/a66\/13aedea663eb9957549ef74edf161ed2.png\"\/><\/figure>\n<p>Here is step-by-step guide.<\/p>\n<h2>Creation of a trace<\/h2>\n<p>Start SQL profiler and select the following events:<\/p>\n<figure class=\"full-width\"><img loading=\"lazy\" decoding=\"async\" src=\"https:\/\/habrastorage.org\/r\/w1560\/getpro\/habr\/upload_files\/aed\/633\/d6f\/aed633d6fdc8d3a48e417a814d6f685c.png\" width=\"856\" height=\"252\" data-src=\"https:\/\/habrastorage.org\/getpro\/habr\/upload_files\/aed\/633\/d6f\/aed633d6fdc8d3a48e417a814d6f685c.png\"\/><\/figure>\n<ul>\n<li>\n<p>SP:Starting<\/p>\n<\/li>\n<li>\n<p>SP:Completed<\/p>\n<\/li>\n<\/ul>\n<p>Select the following columns:<\/p>\n<ul>\n<li>\n<p>ObjectName<\/p>\n<\/li>\n<li>\n<p>NestLevel<\/p>\n<\/li>\n<li>\n<p>StartTime<\/p>\n<\/li>\n<li>\n<p>EndTime<\/p>\n<\/li>\n<li>\n<p>Spid<\/p>\n<\/li>\n<\/ul>\n<p>In the filters, select condition based on Spid, which must select one particular Spid. The analysis is checking just one execution flow, so different connections should not mix in a trace.<\/p>\n<p>Save you trace in a database when enough events are recorded. In that database, create the following stored procedure:<\/p>\n<details class=\"spoiler\">\n<summary>\u0421\u043a\u0440\u044b\u0442\u044b\u0439 \u0442\u0435\u043a\u0441\u0442<\/summary>\n<div class=\"spoiler__content\">\n<pre><code class=\"sql\">create procedure flame   @trname sysname, @spname sysname, @start int=0 as   -- Trace must contain Sp:Start, Sp:Completed, StartTime, EndTime, Nestlevel, ObjectName   -- 1 SPID should be recorded   set nocount on   declare @r int, @b int, @e int, @t datetime, @class int, @lev int, @obj varchar(255), @prevt datetime,      @stack varchar(max)='', @prevstack varchar(max)='', @sql varchar(1000)   create table #trace (RowNumber int, EventClass int, StartTime datetime, EndTime datetime, NestLevel int, ObjectName nvarchar(255))   set @sql = 'insert into #trace select RowNumber,EventClass,StartTime,EndTime,Nestlevel,ObjectName from '+@trname+' where EventClass in (42,43)'   exec (@sql)   select (select max(RowNumber) from #trace I where I.EventClass=42 and I.ObjectName=@spname and I.Nestlevel=1 and I.RowNumber&lt;O.RowNumber) as [Start],     O.RowNumber as [End], StartTime, EndTime, datediff(ms, StartTime, endTime) as DurationMs     from #trace O where EventClass=43 and ObjectName=@spname and Nestlevel=1     order by 1   select @b=min(RowNumber) from #trace where EventClass=42 and ObjectName=@spname and NestLevel=1 and RowNumber&gt;=@start   if @b is null begin print 'procedure: start not found' return end   select @e=min(RowNumber) from #trace where EventClass=43 and ObjectName=@spname and RowNumber&gt;@b and Nestlevel=1   if @e is null begin print 'procedure: end not found' return end   select 'Selected', @b as [Start], @e as [End]   DECLARE my_cur CURSOR FOR SELECT RowNumber,EventClass,isnull(EndTime,StartTime),NestLevel,ObjectName      from #trace where RowNumber&gt;=@b and RowNumber&lt;=@e order by RowNumber   OPEN my_cur   FETCH NEXT FROM my_cur INTO @r, @class, @t, @lev, @obj   WHILE @@FETCH_STATUS = 0   BEGIN     if @class=42 set @stack = @stack + ';' + @obj else set @stack=reverse(substring(reverse(@stack),charindex(';', reverse(@stack))+1,100000)) if @prevt is not null print substring(@prevstack,2,100000)+' '+convert(varchar,datediff(ms,@prevt,@t)) set @prevt=@t set @prevstack=@stack     FETCH NEXT FROM my_cur INTO @r, @class, @t, @lev, @obj   END   CLOSE my_cur   DEALLOCATE my_cur GO<\/code><\/pre>\n<\/p>\n<\/div>\n<\/details>\n<h2>Data Generation<\/h2>\n<p>Now run the stored procedure\u00a0<strong>flame\u00a0<\/strong>with the following parameters:<\/p>\n<ul>\n<li>\n<p>trace table name<\/p>\n<\/li>\n<li>\n<p>name of a topmost (NestLevel=1) stored procedure, and entry tot he whole execution tree. . Name is specified without [] and schema name, for [dbo].[myProc] specify just myProc<\/p>\n<\/li>\n<li>\n<p>3rd parameter is optional, by default it is 0. It allows you to choose a particular execution if more than one execution is recorded.<\/p>\n<\/li>\n<\/ul>\n<p>Example:<\/p>\n<figure class=\"full-width\"><img loading=\"lazy\" decoding=\"async\" src=\"https:\/\/habrastorage.org\/r\/w1560\/getpro\/habr\/upload_files\/391\/2ee\/98b\/3912ee98b23381b40331342387f0fde2.png\" width=\"556\" height=\"398\" data-src=\"https:\/\/habrastorage.org\/getpro\/habr\/upload_files\/391\/2ee\/98b\/3912ee98b23381b40331342387f0fde2.png\"\/><\/figure>\n<p>The first result set displays all found executions of the specified stored procedure, RowNumber range, time range and duration in milliseconds.<\/p>\n<p>If we want to plot a particular execution (not the very first one, which is a default), in 3rd parameter specify the starting RowNumber. For example, for the 9th execution specify value 10574<\/p>\n<h2>Plotting a digram<\/h2>\n<p>When everything is ready, check the \u00a0<strong>Messages\u00a0<\/strong>tab and copy all text from there into a  text file, removing text at the very end:<\/p>\n<figure class=\"\"><img loading=\"lazy\" decoding=\"async\" src=\"https:\/\/habrastorage.org\/r\/w1560\/getpro\/habr\/upload_files\/e9a\/69b\/1c1\/e9a69b1c1b1ea8f70e8534bea2312615.png\" width=\"349\" height=\"46\" data-src=\"https:\/\/habrastorage.org\/r\/w1560\/getpro\/habr\/upload_files\/e9a\/69b\/1c1\/e9a69b1c1b1ea8f70e8534bea2312615.png\"\/><\/figure>\n<p>Then go to the site\u00a0<a href=\"https:\/\/www.speedscope.app\" rel=\"noopener noreferrer nofollow\">https:\/\/www.speedscope.app<\/a>\u00a0and upload your text file. Enjoy.<\/p>\n<\/p>\n<\/div>\n<\/div>\n<\/div>\n<p><!----><!----><\/div>\n<p><!----><!----><br \/> \u0441\u0441\u044b\u043b\u043a\u0430 \u043d\u0430 \u043e\u0440\u0438\u0433\u0438\u043d\u0430\u043b \u0441\u0442\u0430\u0442\u044c\u0438 <a href=\"https:\/\/habr.com\/ru\/articles\/893004\/\"> https:\/\/habr.com\/ru\/articles\/893004\/<\/a><\/p>\n","protected":false},"excerpt":{"rendered":"<div><!--[--><!--]--><\/div>\n<div id=\"post-content-body\">\n<div>\n<div class=\"article-formatted-body article-formatted-body article-formatted-body_version-2\">\n<div xmlns=\"http:\/\/www.w3.org\/1999\/xhtml\">\n<p>If your code has many nested executions of stored procedures, you can benefit from building popular &#171;flame diagram&#187; of the execution time which is de facto standard for performance profiling.<\/p>\n<figure class=\"\"><\/figure>\n<p>Here is step-by-step guide.<\/p>\n<h2>Creation of a trace<\/h2>\n<p>Start SQL profiler and select the following events:<\/p>\n<figure class=\"full-width\"><\/figure>\n<ul>\n<li>\n<p>SP:Starting<\/p>\n<\/li>\n<li>\n<p>SP:Completed<\/p>\n<\/li>\n<\/ul>\n<p>Select the following columns:<\/p>\n<ul>\n<li>\n<p>ObjectName<\/p>\n<\/li>\n<li>\n<p>NestLevel<\/p>\n<\/li>\n<li>\n<p>StartTime<\/p>\n<\/li>\n<li>\n<p>EndTime<\/p>\n<\/li>\n<li>\n<p>Spid<\/p>\n<\/li>\n<\/ul>\n<p>In the filters, select condition based on Spid, which must select one particular Spid. The analysis is checking just one execution flow, so different connections should not mix in a trace.<\/p>\n<p>Save you trace in a database when enough events are recorded. In that database, create the following stored procedure:<\/p>\n<details class=\"spoiler\">\n<summary>\u0421\u043a\u0440\u044b\u0442\u044b\u0439 \u0442\u0435\u043a\u0441\u0442<\/summary>\n<div class=\"spoiler__content\">\n<pre><code class=\"sql\">create procedure flame   @trname sysname, @spname sysname, @start int=0 as   -- Trace must contain Sp:Start, Sp:Completed, StartTime, EndTime, Nestlevel, ObjectName   -- 1 SPID should be recorded   set nocount on   declare @r int, @b int, @e int, @t datetime, @class int, @lev int, @obj varchar(255), @prevt datetime,      @stack varchar(max)='', @prevstack varchar(max)='', @sql varchar(1000)   create table #trace (RowNumber int, EventClass int, StartTime datetime, EndTime datetime, NestLevel int, ObjectName nvarchar(255))   set @sql = 'insert into #trace select RowNumber,EventClass,StartTime,EndTime,Nestlevel,ObjectName from '+@trname+' where EventClass in (42,43)'   exec (@sql)   select (select max(RowNumber) from #trace I where I.EventClass=42 and I.ObjectName=@spname and I.Nestlevel=1 and I.RowNumber&lt;O.RowNumber) as [Start],     O.RowNumber as [End], StartTime, EndTime, datediff(ms, StartTime, endTime) as DurationMs     from #trace O where EventClass=43 and ObjectName=@spname and Nestlevel=1     order by 1   select @b=min(RowNumber) from #trace where EventClass=42 and ObjectName=@spname and NestLevel=1 and RowNumber&gt;=@start   if @b is null begin print 'procedure: start not found' return end   select @e=min(RowNumber) from #trace where EventClass=43 and ObjectName=@spname and RowNumber&gt;@b and Nestlevel=1   if @e is null begin print 'procedure: end not found' return end   select 'Selected', @b as [Start], @e as [End]   DECLARE my_cur CURSOR FOR SELECT RowNumber,EventClass,isnull(EndTime,StartTime),NestLevel,ObjectName      from #trace where RowNumber&gt;=@b and RowNumber&lt;=@e order by RowNumber   OPEN my_cur   FETCH NEXT FROM my_cur INTO @r, @class, @t, @lev, @obj   WHILE @@FETCH_STATUS = 0   BEGIN     if @class=42 set @stack = @stack + ';' + @obj else set @stack=reverse(substring(reverse(@stack),charindex(';', reverse(@stack))+1,100000)) if @prevt is not null print substring(@prevstack,2,100000)+' '+convert(varchar,datediff(ms,@prevt,@t)) set @prevt=@t set @prevstack=@stack     FETCH NEXT FROM my_cur INTO @r, @class, @t, @lev, @obj   END   CLOSE my_cur   DEALLOCATE my_cur GO<\/code><\/pre>\n<\/p>\n<\/div>\n<\/details>\n<h2>Data Generation<\/h2>\n<p>Now run the stored procedure\u00a0<strong>flame\u00a0<\/strong>with the following parameters:<\/p>\n<ul>\n<li>\n<p>trace table name<\/p>\n<\/li>\n<li>\n<p>name of a topmost (NestLevel=1) stored procedure, and entry tot he whole execution tree. . Name is specified without [] and schema name, for [dbo].[myProc] specify just myProc<\/p>\n<\/li>\n<li>\n<p>3rd parameter is optional, by default it is 0. It allows you to choose a particular execution if more than one execution is recorded.<\/p>\n<\/li>\n<\/ul>\n<p>Example:<\/p>\n<figure class=\"full-width\"><\/figure>\n<p>The first result set displays all found executions of the specified stored procedure, RowNumber range, time range and duration in milliseconds.<\/p>\n<p>If we want to plot a particular execution (not the very first one, which is a default), in 3rd parameter specify the starting RowNumber. For example, for the 9th execution specify value 10574<\/p>\n<h2>Plotting a digram<\/h2>\n<p>When everything is ready, check the \u00a0<strong>Messages\u00a0<\/strong>tab and copy all text from there into a  text file, removing text at the very end:<\/p>\n<figure class=\"\"><\/figure>\n<p>Then go to the site\u00a0<a href=\"https:\/\/www.speedscope.app\" rel=\"noopener noreferrer nofollow\">https:\/\/www.speedscope.app<\/a>\u00a0and upload your text file. Enjoy.<\/p>\n<\/p>\n<\/div>\n<\/div>\n<\/div>\n<p><!----><!----><\/div>\n<p><!----><!----><br \/> \u0441\u0441\u044b\u043b\u043a\u0430 \u043d\u0430 \u043e\u0440\u0438\u0433\u0438\u043d\u0430\u043b \u0441\u0442\u0430\u0442\u044c\u0438 <a href=\"https:\/\/habr.com\/ru\/articles\/893004\/\"> https:\/\/habr.com\/ru\/articles\/893004\/<\/a><br \/><\/br><\/br><\/p>\n","protected":false},"author":1,"featured_media":0,"comment_status":"open","ping_status":"open","sticky":false,"template":"","format":"standard","meta":{"footnotes":""},"categories":[],"tags":[],"class_list":["post-452551","post","type-post","status-publish","format-standard","hentry"],"_links":{"self":[{"href":"https:\/\/savepearlharbor.com\/index.php?rest_route=\/wp\/v2\/posts\/452551","targetHints":{"allow":["GET"]}}],"collection":[{"href":"https:\/\/savepearlharbor.com\/index.php?rest_route=\/wp\/v2\/posts"}],"about":[{"href":"https:\/\/savepearlharbor.com\/index.php?rest_route=\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"https:\/\/savepearlharbor.com\/index.php?rest_route=\/wp\/v2\/users\/1"}],"replies":[{"embeddable":true,"href":"https:\/\/savepearlharbor.com\/index.php?rest_route=%2Fwp%2Fv2%2Fcomments&post=452551"}],"version-history":[{"count":0,"href":"https:\/\/savepearlharbor.com\/index.php?rest_route=\/wp\/v2\/posts\/452551\/revisions"}],"wp:attachment":[{"href":"https:\/\/savepearlharbor.com\/index.php?rest_route=%2Fwp%2Fv2%2Fmedia&parent=452551"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/savepearlharbor.com\/index.php?rest_route=%2Fwp%2Fv2%2Fcategories&post=452551"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/savepearlharbor.com\/index.php?rest_route=%2Fwp%2Fv2%2Ftags&post=452551"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}