{"id":58,"date":"2010-02-11T01:43:06","date_gmt":"2010-02-11T01:43:06","guid":{"rendered":"http:\/\/jcrawfor74.wordpress.com\/?p=58"},"modified":"2024-06-24T12:30:36","modified_gmt":"2024-06-24T02:30:36","slug":"sql-server-print-logging-message-function","status":"publish","type":"post","link":"https:\/\/ntsblog.homedev.com.au\/index.php\/2010\/02\/11\/sql-server-print-logging-message-function\/","title":{"rendered":"SQL Server Print logging message function"},"content":{"rendered":"<div id=\"ntsbl-1246319675\" class=\"ntsbl-before-content ntsbl-entity-placement\"><script async src=\"\/\/pagead2.googlesyndication.com\/pagead\/js\/adsbygoogle.js?client=ca-pub-6288941070289539\" crossorigin=\"anonymous\"><\/script><ins class=\"adsbygoogle\" style=\"display:inline-block;width:728px;height:90px;\" \ndata-ad-client=\"ca-pub-6288941070289539\" \ndata-ad-slot=\"9356781486\"><\/ins> \n<script> \n(adsbygoogle = window.adsbygoogle || []).push({}); \n<\/script>\n<\/div>\n<p>I use this to log duration information when I am writing stored procedures with long running code.<br>I find this useful when testing how long things are taking in big procedures<\/p>\n\n\n\n<p>This procedure returns a message with a duration of how long it took to run something<\/p>\n\n\n\n<pre class=\"wp-block-code\"><code lang=\"sql\" class=\"language-sql line-numbers\">CREATE OR ALTER FUNCTION [dbo].[udfGetDurationMsg]\n(@msg nvarchar(max), @start datetime, @end datetime) RETURNS VARCHAR(100)\nAS\nBEGIN\n\tdeclare @duration time\n\tset @duration = Convert(time, @end - @start)\n\treturn @msg + ' - ' + Convert(varchar, @duration)\nEND\nGO<\/code><\/pre>\n\n\n\n<p><\/p>\n\n\n\n<p>I then have two other supporting procedures.<\/p>\n\n\n\n<p><strong>prcPrintMessage<\/strong><\/p>\n\n\n\n<p>This outputs the message immediately using the NOWAIT statement, with a leading timestamp<\/p>\n\n\n\n<pre class=\"wp-block-code\"><code lang=\"sql\" class=\"language-sql line-numbers\">CREATE OR ALTER PROCEDURE [dbo].[prcPrintMessage]\n    @msg nvarchar(max)\nAS\nBEGIN\n    set @msg = '[' + Convert(varchar, GetDate(), 121) + '] ' + @msg\n    RAISERROR(@msg, 0, 0) WITH NOWAIT\n    RETURN 0\nEND<\/code><\/pre>\n\n\n\n<p><strong>prcPrintDurationMessage<\/strong><\/p>\n\n\n\n<pre class=\"wp-block-code\"><code lang=\"sql\" class=\"language-sql line-numbers\">CREATE OR ALTER PROCEDURE [dbo].[prcPrintDurationMessage]\n    @msg nvarchar(max),\n    @start datetime\nAS\nBEGIN\n    set @msg = dbo.udfGetDurationMsg(@msg, @start, GetDate())\n    exec prcPrintMessage @msg\n    RETURN 0\nEND<\/code><\/pre>\n\n\n\n<p>This gives you the ability to create print messages immediately that output with a standard format and the duration. Here is an example of how you would call it.<\/p>\n\n\n\n<pre class=\"wp-block-code\"><code lang=\"sql\" class=\"language-sql line-numbers\">Declare @msg nvarchar(max)\nDeclare @rows int\nDeclare @start datetime = getdate()\n\n-- Do some work\n-- simulate a delay\nWAITFOR DELAY '00:00:01.324'\n\n-- you would maybe do this after an update or merge statement\n--set @rows = @@ROWCOUNT;\nset @rows = 10;\nset @msg = 'Process Completed - ' + Convert(varchar, @rows) + ' rows changed'\nexec prcPrintDurationMessage @msg, @start;\n<\/code><\/pre>\n\n\n\n<p>This would output a printed statement like:<\/p>\n\n\n\n<pre class=\"wp-block-code\"><code class=\"\">[2023-06-02 20:15:18.813] Process Completed - 10 rows changed - 00:00:01.3566667<\/code><\/pre>\n\n\n\n<p>I hope these are useful.<\/p>\n","protected":false},"excerpt":{"rendered":"<p>I use this to log duration information when I am writing stored procedures with long running code.I find this useful when testing how long things [&hellip;]<\/p>\n","protected":false},"author":2,"featured_media":0,"comment_status":"open","ping_status":"open","sticky":false,"template":"","format":"standard","meta":{"jetpack_post_was_ever_published":false,"_jetpack_newsletter_access":"","_jetpack_dont_email_post_to_subs":false,"_jetpack_newsletter_tier_id":0,"_jetpack_memberships_contains_paywalled_content":false,"_jetpack_memberships_contains_paid_content":false,"footnotes":""},"categories":[13],"tags":[],"class_list":["post-58","post","type-post","status-publish","format-standard","hentry","category-sql-server"],"jetpack_featured_media_url":"","jetpack_sharing_enabled":true,"_links":{"self":[{"href":"https:\/\/ntsblog.homedev.com.au\/index.php\/wp-json\/wp\/v2\/posts\/58","targetHints":{"allow":["GET"]}}],"collection":[{"href":"https:\/\/ntsblog.homedev.com.au\/index.php\/wp-json\/wp\/v2\/posts"}],"about":[{"href":"https:\/\/ntsblog.homedev.com.au\/index.php\/wp-json\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"https:\/\/ntsblog.homedev.com.au\/index.php\/wp-json\/wp\/v2\/users\/2"}],"replies":[{"embeddable":true,"href":"https:\/\/ntsblog.homedev.com.au\/index.php\/wp-json\/wp\/v2\/comments?post=58"}],"version-history":[{"count":0,"href":"https:\/\/ntsblog.homedev.com.au\/index.php\/wp-json\/wp\/v2\/posts\/58\/revisions"}],"wp:attachment":[{"href":"https:\/\/ntsblog.homedev.com.au\/index.php\/wp-json\/wp\/v2\/media?parent=58"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/ntsblog.homedev.com.au\/index.php\/wp-json\/wp\/v2\/categories?post=58"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/ntsblog.homedev.com.au\/index.php\/wp-json\/wp\/v2\/tags?post=58"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}