{"id":462794,"date":"2025-06-10T15:01:36","date_gmt":"2025-06-10T15:01:36","guid":{"rendered":"http:\/\/savepearlharbor.com\/?p=462794"},"modified":"-0001-11-30T00:00:00","modified_gmt":"-0001-11-29T21:00:00","slug":"","status":"publish","type":"post","link":"https:\/\/savepearlharbor.com\/?p=462794","title":{"rendered":"<span>Coloring a T-SQL Procedure Listing with Metric Values<\/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>First, I&#8217;ll show you what this is about so you can decide if it&#8217;s relevant to you.  <\/p>\n<figure class=\"full-width\"><img decoding=\"async\" src=\"https:\/\/habrastorage.org\/r\/w1560\/getpro\/habr\/upload_files\/64e\/352\/f81\/64e352f813e53f882ea97a9b3c79d2f9.png\" width=\"567\" height=\"437\" sizes=\"auto, (max-width: 780px) 100vw, 50vw\" srcset=\"https:\/\/habrastorage.org\/r\/w780\/getpro\/habr\/upload_files\/64e\/352\/f81\/64e352f813e53f882ea97a9b3c79d2f9.png 780w,&#10;       https:\/\/habrastorage.org\/r\/w1560\/getpro\/habr\/upload_files\/64e\/352\/f81\/64e352f813e53f882ea97a9b3c79d2f9.png 781w\" loading=\"lazy\" decode=\"async\"\/><\/figure>\n<p>We append the following metrics to the T-SQL procedure statements:<\/p>\n<ul>\n<li>\n<p>Execution count (<strong>x<\/strong>)<\/p>\n<\/li>\n<li>\n<p>CPU time in milliseconds (<strong>c<\/strong>)<\/p>\n<\/li>\n<li>\n<p>Duration in microseconds (<strong>d<\/strong>)<\/p>\n<\/li>\n<li>\n<p>Number of reads (<strong>r<\/strong>)<\/p>\n<\/li>\n<li>\n<p>Number of writes (<strong>w<\/strong>)<\/p>\n<\/li>\n<li>\n<p><code>@@rowcount<\/code>\u00a0value (<strong>n<\/strong>)<\/p>\n<\/li>\n<\/ul>\n<p>You can display these as absolute values or percentages.<\/p>\n<h3>Data Collection<\/h3>\n<p><strong>Run SQL Profiler<\/strong>\u00a0and select a single event:  <\/p>\n<ul>\n<li>\n<p>SP:StmtCompleted<\/p>\n<\/li>\n<\/ul>\n<p>Choose the following columns:  <\/p>\n<ul>\n<li>\n<p>CPU<\/p>\n<\/li>\n<li>\n<p>Duration<\/p>\n<\/li>\n<li>\n<p>Reads<\/p>\n<\/li>\n<li>\n<p>Writes<\/p>\n<\/li>\n<li>\n<p>StartTime<\/p>\n<\/li>\n<li>\n<p>EndTime<\/p>\n<\/li>\n<li>\n<p>LineNumber<\/p>\n<\/li>\n<li>\n<p>ObjectName<\/p>\n<\/li>\n<li>\n<p>SPID<\/p>\n<\/li>\n<li>\n<p>RowCounts<\/p>\n<\/li>\n<\/ul>\n<p><em>Sometimes,\u00a0<\/em><code><em>RowCounts<\/em><\/code><em>\u00a0data is not collected if\u00a0<\/em><code><em>TextData<\/em><\/code><em>\u00a0is not included.<\/em><\/p>\n<p>In the filters, specify<strong> ObjectName = [your procedure name].<\/strong> Use just the procedure name without schema or brackets (e.g., for [dbo].[MyProc], enter <strong>MyProc<\/strong>). If profiling on dev and you know the SPID, filter by it. For Production, try to limit the trace to a single SPID (though the coloring tool itself doesn\u2019t require this).  <\/p>\n<p>Why <strong>SQL Profiler<\/strong> and Not <strong>Extended Events<\/strong>? <\/p>\n<p>I\u2019ve been asked why I use SQL Profiler instead of Extended Events. You can use Extended Events, but for quick ad-hoc traces, SQL Profiler is often simpler and faster. Be cautious on Production\u2014avoid runaway traces! After running the trace, collect enough data and save it to a table.  <\/p>\n<h2>Environment Setup<\/h2>\n<p>Install Python and the Pygments package<\/p>\n<p><strong>pip install Pygments<\/strong><\/p>\n<p>This provides the <strong>pygmentize <\/strong>command. Download the sqlpig script from my repository:\u00a0<a href=\"https:\/\/github.com\/tzimie\/sqlpig\" rel=\"noopener noreferrer nofollow\">https:\/\/github.com\/tzimie\/sqlpig<\/a>. Originally named SQLpyg (SQL + pygmentize), it later became SQLpig. At the very beginning of the <a href=\"http:\/\/sqlpig.py\" rel=\"noopener noreferrer nofollow\">sqlpig.py<\/a> script, you\u2019ll find a query that you\u2019ll need:<\/p>\n<pre><code class=\"sql\">select ObjectName+'.sql:'+convert(varchar,LineNumber)+':'+   convert(varchar,cnt)+':'+   convert(varchar,CPU)+':'+   convert(varchar,Duration)+':'+   convert(varchar,Reads)+':'+   convert(varchar,Writes)+':'+   convert(varchar,isnull(RowCounts,0)) from (   select ObjectName,LineNumber, count(*) as cnt, sum(CPU) as CPU,sum(Duration) as Duration,     sum(Reads) as Reads, sum(Writes) as Writes, sum(RowCounts) as RowCounts   from {MyTrace} where EventClass=45 and ObjectName is not null   group by ObjectName,LineNumber) Q <\/code><\/pre>\n<h4>Processing the Trace Data<\/h4>\n<p>Replace\u00a0<code>{MyTrace}<\/code>\u00a0with the name of the table where you saved the trace. Execute the script and save its output to a text file (<code>.log<\/code>). You can name this file the same as your procedure or add suffixes like\u00a0<code>short<\/code>\u00a0or\u00a0<code>long<\/code>\u00a0for different executions.<\/p>\n<p>Next, you&#8217;ll need the source code of the procedure. In\u00a0<strong>SQL Server Management Studio<\/strong>, perform an\u00a0<code>ALTER<\/code>\u00a0on the procedure and copy the resulting text into a file named\u00a0<code>procedurename.sql<\/code>.<\/p>\n<p><strong>Important:<\/strong>\u00a0You must remove the header section from the procedure script:<\/p>\n<figure class=\"full-width\"><img decoding=\"async\" src=\"https:\/\/habrastorage.org\/r\/w1560\/getpro\/habr\/upload_files\/5bd\/df9\/ce7\/5bddf9ce790c9834f63ef657fc7ea25b.png\" width=\"618\" height=\"514\" sizes=\"auto, (max-width: 780px) 100vw, 50vw\" srcset=\"https:\/\/habrastorage.org\/r\/w780\/getpro\/habr\/upload_files\/5bd\/df9\/ce7\/5bddf9ce790c9834f63ef657fc7ea25b.png 780w,&#10;       https:\/\/habrastorage.org\/r\/w1560\/getpro\/habr\/upload_files\/5bd\/df9\/ce7\/5bddf9ce790c9834f63ef657fc7ea25b.png 781w\" loading=\"lazy\" decode=\"async\"\/><\/figure>\n<p>The first meaningful line should be either ALTER or the first line of a comment.<\/p>\n<p>You might ask &#8212; why can&#8217;t the script simply read the procedure text and trace data automatically? The issue is that traces are typically captured in production environments where software installation is often restricted. That&#8217;s why we transfer everything to local machines via copy\/paste (when available).<\/p>\n<h2>Processing<\/h2>\n<p>Let&#8217;s run sqlpig:<\/p>\n<figure class=\"full-width\"><img decoding=\"async\" src=\"https:\/\/habrastorage.org\/r\/w1560\/getpro\/habr\/upload_files\/f19\/fb8\/384\/f19fb83843a06cd2056cb4c652f9d170.png\" width=\"814\" height=\"319\" sizes=\"auto, (max-width: 780px) 100vw, 50vw\" srcset=\"https:\/\/habrastorage.org\/r\/w780\/getpro\/habr\/upload_files\/f19\/fb8\/384\/f19fb83843a06cd2056cb4c652f9d170.png 780w,&#10;       https:\/\/habrastorage.org\/r\/w1560\/getpro\/habr\/upload_files\/f19\/fb8\/384\/f19fb83843a06cd2056cb4c652f9d170.png 781w\" loading=\"lazy\" decode=\"async\"\/><\/figure>\n<h4>Applying Metrics to SQL Files<\/h4>\n<p>The metrics from\u00a0<code>myproc.log<\/code>\u00a0are applied to the\u00a0<code>myproc.sql<\/code>\u00a0file and output to\u00a0<code>myproc.html<\/code>. You can specify different metrics:<\/p>\n<ul>\n<li>\n<p><strong>x<\/strong>\u00a0&#8212; Execution count (not of the entire procedure, but of individual statements; if a statement is in a loop, this count may be much higher than the procedure&#8217;s execution count)<\/p>\n<\/li>\n<li>\n<p><strong>c<\/strong>\u00a0&#8212; CPU time in milliseconds<\/p>\n<\/li>\n<li>\n<p><strong>d<\/strong>\u00a0&#8212; Duration in microseconds (more precise than CPU time)<\/p>\n<\/li>\n<li>\n<p><strong>r<\/strong>\u00a0&#8212; Reads<\/p>\n<\/li>\n<li>\n<p><strong>w<\/strong>\u00a0&#8212; Writes<\/p>\n<\/li>\n<li>\n<p><strong>n<\/strong>\u00a0&#8212; Row count from the\u00a0<code>RowCounts<\/code>\u00a0column (this isn&#8217;t always accurate and deserves separate discussion)<\/p>\n<\/li>\n<\/ul>\n<p>Uppercase metrics (<strong>XCDRWN<\/strong>) represent the same metrics but displayed as percentages of the total.<\/p>\n<p>You can combine both percentage and absolute metrics\u2014for example,\u00a0<code>xcCdD<\/code>\u00a0is a valid combination.<\/p>\n<p>The final parameter is the log file name. For a single procedure, you might have results from multiple executions (e.g., short\/long runs).<\/p>\n<figure class=\"full-width\"><img decoding=\"async\" src=\"https:\/\/habrastorage.org\/r\/w1560\/getpro\/habr\/upload_files\/4ca\/43e\/a19\/4ca43ea19c15585335ec4ee6ec7fba8c.png\" width=\"805\" height=\"325\" sizes=\"auto, (max-width: 780px) 100vw, 50vw\" srcset=\"https:\/\/habrastorage.org\/r\/w780\/getpro\/habr\/upload_files\/4ca\/43e\/a19\/4ca43ea19c15585335ec4ee6ec7fba8c.png 780w,&#10;       https:\/\/habrastorage.org\/r\/w1560\/getpro\/habr\/upload_files\/4ca\/43e\/a19\/4ca43ea19c15585335ec4ee6ec7fba8c.png 781w\" loading=\"lazy\" decode=\"async\"\/><\/figure>\n<h4>Potential Issues<\/h4>\n<p>Sometimes, the metric annotations may appear misaligned with the corresponding lines of source code. I&#8217;m gradually working to eliminate edge cases, but for now, you can manually adjust the values in the source code.<\/p>\n<p>shift = 1 # edit this value to readjust position if needed<\/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\/917274\/\"> https:\/\/habr.com\/ru\/articles\/917274\/<\/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>First, I&#8217;ll show you what this is about so you can decide if it&#8217;s relevant to you.  <\/p>\n<figure class=\"full-width\"><\/figure>\n<p>We append the following metrics to the T-SQL procedure statements:<\/p>\n<ul>\n<li>\n<p>Execution count (<strong>x<\/strong>)<\/p>\n<\/li>\n<li>\n<p>CPU time in milliseconds (<strong>c<\/strong>)<\/p>\n<\/li>\n<li>\n<p>Duration in microseconds (<strong>d<\/strong>)<\/p>\n<\/li>\n<li>\n<p>Number of reads (<strong>r<\/strong>)<\/p>\n<\/li>\n<li>\n<p>Number of writes (<strong>w<\/strong>)<\/p>\n<\/li>\n<li>\n<p><code>@@rowcount<\/code>\u00a0value (<strong>n<\/strong>)<\/p>\n<\/li>\n<\/ul>\n<p>You can display these as absolute values or percentages.<\/p>\n<h3>Data Collection<\/h3>\n<p><strong>Run SQL Profiler<\/strong>\u00a0and select a single event:  <\/p>\n<ul>\n<li>\n<p>SP:StmtCompleted<\/p>\n<\/li>\n<\/ul>\n<p>Choose the following columns:  <\/p>\n<ul>\n<li>\n<p>CPU<\/p>\n<\/li>\n<li>\n<p>Duration<\/p>\n<\/li>\n<li>\n<p>Reads<\/p>\n<\/li>\n<li>\n<p>Writes<\/p>\n<\/li>\n<li>\n<p>StartTime<\/p>\n<\/li>\n<li>\n<p>EndTime<\/p>\n<\/li>\n<li>\n<p>LineNumber<\/p>\n<\/li>\n<li>\n<p>ObjectName<\/p>\n<\/li>\n<li>\n<p>SPID<\/p>\n<\/li>\n<li>\n<p>RowCounts<\/p>\n<\/li>\n<\/ul>\n<p><em>Sometimes,\u00a0<\/em><code><em>RowCounts<\/em><\/code><em>\u00a0data is not collected if\u00a0<\/em><code><em>TextData<\/em><\/code><em>\u00a0is not included.<\/em><\/p>\n<p>In the filters, specify<strong> ObjectName = [your procedure name].<\/strong> Use just the procedure name without schema or brackets (e.g., for [dbo].[MyProc], enter <strong>MyProc<\/strong>). If profiling on dev and you know the SPID, filter by it. For Production, try to limit the trace to a single SPID (though the coloring tool itself doesn\u2019t require this).  <\/p>\n<p>Why <strong>SQL Profiler<\/strong> and Not <strong>Extended Events<\/strong>? <\/p>\n<p>I\u2019ve been asked why I use SQL Profiler instead of Extended Events. You can use Extended Events, but for quick ad-hoc traces, SQL Profiler is often simpler and faster. Be cautious on Production\u2014avoid runaway traces! After running the trace, collect enough data and save it to a table.  <\/p>\n<h2>Environment Setup<\/h2>\n<p>Install Python and the Pygments package<\/p>\n<p><strong>pip install Pygments<\/strong><\/p>\n<p>This provides the <strong>pygmentize <\/strong>command. Download the sqlpig script from my repository:\u00a0<a href=\"https:\/\/github.com\/tzimie\/sqlpig\" rel=\"noopener noreferrer nofollow\">https:\/\/github.com\/tzimie\/sqlpig<\/a>. Originally named SQLpyg (SQL + pygmentize), it later became SQLpig. At the very beginning of the <a href=\"http:\/\/sqlpig.py\" rel=\"noopener noreferrer nofollow\">sqlpig.py<\/a> script, you\u2019ll find a query that you\u2019ll need:<\/p>\n<pre><code class=\"sql\">select ObjectName+'.sql:'+convert(varchar,LineNumber)+':'+   convert(varchar,cnt)+':'+   convert(varchar,CPU)+':'+   convert(varchar,Duration)+':'+   convert(varchar,Reads)+':'+   convert(varchar,Writes)+':'+   convert(varchar,isnull(RowCounts,0)) from (   select ObjectName,LineNumber, count(*) as cnt, sum(CPU) as CPU,sum(Duration) as Duration,     sum(Reads) as Reads, sum(Writes) as Writes, sum(RowCounts) as RowCounts   from {MyTrace} where EventClass=45 and ObjectName is not null   group by ObjectName,LineNumber) Q <\/code><\/pre>\n<h4>Processing the Trace Data<\/h4>\n<p>Replace\u00a0<code>{MyTrace}<\/code>\u00a0with the name of the table where you saved the trace. Execute the script and save its output to a text file (<code>.log<\/code>). You can name this file the same as your procedure or add suffixes like\u00a0<code>short<\/code>\u00a0or\u00a0<code>long<\/code>\u00a0for different executions.<\/p>\n<p>Next, you&#8217;ll need the source code of the procedure. In\u00a0<strong>SQL Server Management Studio<\/strong>, perform an\u00a0<code>ALTER<\/code>\u00a0on the procedure and copy the resulting text into a file named\u00a0<code>procedurename.sql<\/code>.<\/p>\n<p><strong>Important:<\/strong>\u00a0You must remove the header section from the procedure script:<\/p>\n<figure class=\"full-width\"><\/figure>\n<p>The first meaningful line should be either ALTER or the first line of a comment.<\/p>\n<p>You might ask &#8212; why can&#8217;t the script simply read the procedure text and trace data automatically? The issue is that traces are typically captured in production environments where software installation is often restricted. That&#8217;s why we transfer everything to local machines via copy\/paste (when available).<\/p>\n<h2>Processing<\/h2>\n<p>Let&#8217;s run sqlpig:<\/p>\n<figure class=\"full-width\"><\/figure>\n<h4>Applying Metrics to SQL Files<\/h4>\n<p>The metrics from\u00a0<code>myproc.log<\/code>\u00a0are applied to the\u00a0<code>myproc.sql<\/code>\u00a0file and output to\u00a0<code>myproc.html<\/code>. You can specify different metrics:<\/p>\n<ul>\n<li>\n<p><strong>x<\/strong>\u00a0&#8212; Execution count (not of the entire procedure, but of individual statements; if a statement is in a loop, this count may be much higher than the procedure&#8217;s execution count)<\/p>\n<\/li>\n<li>\n<p><strong>c<\/strong>\u00a0&#8212; CPU time in milliseconds<\/p>\n<\/li>\n<li>\n<p><strong>d<\/strong>\u00a0&#8212; Duration in microseconds (more precise than CPU time)<\/p>\n<\/li>\n<li>\n<p><strong>r<\/strong>\u00a0&#8212; Reads<\/p>\n<\/li>\n<li>\n<p><strong>w<\/strong>\u00a0&#8212; Writes<\/p>\n<\/li>\n<li>\n<p><strong>n<\/strong>\u00a0&#8212; Row count from the\u00a0<code>RowCounts<\/code>\u00a0column (this isn&#8217;t always accurate and deserves separate discussion)<\/p>\n<\/li>\n<\/ul>\n<p>Uppercase metrics (<strong>XCDRWN<\/strong>) represent the same metrics but displayed as percentages of the total.<\/p>\n<p>You can combine both percentage and absolute metrics\u2014for example,\u00a0<code>xcCdD<\/code>\u00a0is a valid combination.<\/p>\n<p>The final parameter is the log file name. For a single procedure, you might have results from multiple executions (e.g., short\/long runs).<\/p>\n<figure class=\"full-width\"><\/figure>\n<h4>Potential Issues<\/h4>\n<p>Sometimes, the metric annotations may appear misaligned with the corresponding lines of source code. I&#8217;m gradually working to eliminate edge cases, but for now, you can manually adjust the values in the source code.<\/p>\n<p>shift = 1 # edit this value to readjust position if needed<\/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\/917274\/\"> https:\/\/habr.com\/ru\/articles\/917274\/<\/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-462794","post","type-post","status-publish","format-standard","hentry"],"_links":{"self":[{"href":"https:\/\/savepearlharbor.com\/index.php?rest_route=\/wp\/v2\/posts\/462794","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=462794"}],"version-history":[{"count":0,"href":"https:\/\/savepearlharbor.com\/index.php?rest_route=\/wp\/v2\/posts\/462794\/revisions"}],"wp:attachment":[{"href":"https:\/\/savepearlharbor.com\/index.php?rest_route=%2Fwp%2Fv2%2Fmedia&parent=462794"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/savepearlharbor.com\/index.php?rest_route=%2Fwp%2Fv2%2Fcategories&post=462794"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/savepearlharbor.com\/index.php?rest_route=%2Fwp%2Fv2%2Ftags&post=462794"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}