Please start any new threads on our new site at https://forums.sqlteam.com. We've got lots of great SQL Server experts to answer whatever question you can come up with.

 All Forums
 SQL Server 2012 Forums
 SQL Server Administration (2012)
 Trace / Logging Missing SProcs?

Author  Topic 

Kristen
Test

22859 Posts

Posted - 2015-03-18 : 08:27:07
Hi gang.

We have an application which needs splitting into two. I want to remove all the Sprocs that refer to the "removed" part in each system. There is a lot of overlap (common SProcs, and Sprocs where it is not obvious, from name alone, that they are used by Application-A or Application-B).

My thought was to rename any SProc that was a potential target for removal with an "_HOLD" suffix such that it would then fail to execute, but was easy to rename-back (rather than having to recreate - just in case the DB has an old / goofy / customised version ).

I've done the renaming part, and worked out all the commonly used SProcs and renamed them back. I looked in the cache logs etc. but that only gave me last_Execution_time going back a couple of days.

So what I am after now is some easy way to log if an EXEC SPROC fails so I can then rename it (possibly autoMagically via a triggered event so that a RETRY on the page will then work)

My Google searching must be rubbish as I have not found anything the least bit useful.

I looked at the Error column in SQL Server Profiler - which is indeed picking up failed EXEC attempts, but its also recording "1 = Error" for other non critical errors.

Any ideas? Thanks

tkizer
Almighty SQL Goddess

38200 Posts

Posted - 2015-03-18 : 13:42:22
Maybe an XE session, but I suspect Rob has a really good answer for you.

Tara Kizer
SQL Server MVP since 2007
http://weblogs.sqlteam.com/tarad/
Go to Top of Page

Kristen
Test

22859 Posts

Posted - 2015-03-18 : 13:49:35
Thanks Tara. Is he up yet, or is it still early for him?
Go to Top of Page

Kristen
Test

22859 Posts

Posted - 2015-03-18 : 13:51:44
Ah, rats ...

I've posted this in SQL 2012 ... but checking the sever its actually SQL 2008. Sorry.
Go to Top of Page

tkizer
Almighty SQL Goddess

38200 Posts

Posted - 2015-03-18 : 14:13:44
XE existed in 2008.

Tara Kizer
SQL Server MVP since 2007
http://weblogs.sqlteam.com/tarad/
Go to Top of Page

robvolk
Most Valuable Yak

15732 Posts

Posted - 2015-03-18 : 20:59:34
Oh, you!

I agree about using Extended Events, I'm not conversant enough with them to say exactly how, but I'll take a look and see if I can post something tomorrow. It looks like a missing stored procedure throws error 2812, so an XE with that predicate should do the trick.

You mentioned "cache logs", are you talking about sys.dm_exec_procedure_stats? If not, have you tried querying that?
Go to Top of Page

Kristen
Test

22859 Posts

Posted - 2015-03-19 : 03:39:41
quote:
Originally posted by robvolk

are you talking about sys.dm_exec_procedure_stats?



Yup. I've got a list of SProcs used from that. In case anyone wants the code this is what I used:

SELECT
-- SELECT TOP 100
-- [DBName] = DB_NAME(database_id),
-- [SCHEMA_NAME] = OBJECT_SCHEMA_NAME(object_id, database_id),

[last_execution_time]=MAX(S.last_execution_time),
CASE WHEN OBJECT_NAME(S.object_id, S.database_id) = O.name THEN '' ELSE '*' END,
[OBJECT_NAME] = OBJECT_NAME(S.object_id, S.database_id)
, [ProcName] = O.name
-- , *
-- SELECT TOP 10 *

FROM sys.dm_exec_procedure_stats AS S
LEFT OUTER JOIN sys.objects AS O
ON O.object_id = S.object_id
OR O.name LIKE OBJECT_NAME(S.object_id, S.database_id) + '_HOLD'
WHERE 1=1
AND S.database_id = 9999 -- My Database ID
-- AND last_execution_time >= DATEADD(day, -1, GetDate())
GROUP BY
object_name(S.object_id, S.database_id)
, O.name
ORDER BY
-- OBJECT_NAME,
last_execution_time DESC,
ProcName

I also used sys.dm_exec_query_stats which includes SProcs and also Functions and Triggers, which are going to be important to track too (now I think about it!!)

SELECT [last_execution_time]=MAX(last_execution_time),
CASE WHEN object_name(objectid, dbid) = O.name THEN '' ELSE '*' END,
object_name(objectid, dbid) as ObjectName
, [ProcName] = O.name
-- , text
-- , statement_start_offset, objectid
-- List all Database IDs used: SELECT DISTINCT dbid, [DB Name]=DB_NAME(dbid)
-- SELECT TOP 10 *

FROM sys.dm_exec_query_stats AS qs
CROSS APPLY sys.dm_exec_sql_text(qs.sql_handle)
LEFT OUTER JOIN sys.objects AS O
ON O.object_id = objectid
WHERE 1=1
AND dbid = 27 -- 9999 -- My Database ID
-- AND last_execution_time >= DATEADD(day, -1, GetDate())
GROUP BY
object_name(objectid, dbid)
, O.name
ORDER BY
ObjectName
, last_execution_time DESC
Go to Top of Page

Kristen
Test

22859 Posts

Posted - 2015-03-19 : 06:26:09
I've had a go with Extended Events but not got very far.

I have assumed that I can use system_health XE, is that right?

Only event, currently, in sys.dm_xe_session_targets is 'system_health'

Only event/name that I have is "wait_info" ... for the database in question they go back to 14-March (might be when I recently starting issuing queries against this database, it has been dormant prior to that)

I've tried calling a non-existent SProc and can't see its name anywhere in the XML data (or I'm looking in the wrong place!)


Go to Top of Page

robvolk
Most Valuable Yak

15732 Posts

Posted - 2015-03-19 : 12:02:24
System health doesn't capture that particular error, but I've tested the folloing event session (modified from system health) that checks for error 2812:
CREATE EVENT SESSION [MissingProcedure] ON SERVER 
ADD EVENT sqlserver.error_reported(
ACTION(package0.callstack,sqlserver.database_id,sqlserver.session_id,sqlserver.sql_text,sqlserver.tsql_stack)
WHERE ([error_number]=2812))
ADD TARGET package0.event_file(SET filename=N'MissingProc.xel',max_file_size=(5),max_rollover_files=(4)),
ADD TARGET package0.ring_buffer(SET max_events_limit=(5000),max_memory=(1024))
WITH (MAX_MEMORY=1024 KB,EVENT_RETENTION_MODE=ALLOW_SINGLE_EVENT_LOSS,MAX_DISPATCH_LATENCY=120 SECONDS,MAX_EVENT_SIZE=0 KB,MEMORY_PARTITION_MODE=NONE,TRACK_CAUSALITY=OFF,STARTUP_STATE=ON);
GO
ALTER EVENT SESSION [MissingProcedure] ON SERVER STATE=START;
You can then View Target Data from either the ring buffer or file targets (you could also remove one of the targets if you choose).

Test code:
EXEC No_Such_Procedure
If you view the target you'll see a message "Could not find stored procedure 'No_Such_Procedure'."

I think that event notifications could pick this up too, if you look for USER_ERROR_MESSAGE or TRC_ERRORS_AND_WARNINGS, but you'd have to make your activation procedure toss all the non-2812 errors, plus set up queues and services. Probably easier to just poll the event session periodically.
Go to Top of Page

Kristen
Test

22859 Posts

Posted - 2015-03-19 : 14:17:14
Thanks for your help Rob, but I'm struggling with this I'm afraid. Perhaps SQL 2008 has some differently named attributes ...

I've got this far

IF EXISTS(SELECT * FROM sys.server_event_sessions WHERE name='MissingProcedure')
DROP EVENT session MissingProcedure ON SERVER;
GO
CREATE EVENT SESSION [MissingProcedure] ON SERVER
ADD EVENT sqlserver.error_reported
(
ACTION
(
package0.callstack,
sqlserver.database_id,
sqlserver.session_id,
sqlserver.sql_text,
sqlserver.tsql_stack
)
-- WHERE ([error_number]=2812)
WHERE ([error]=2812)
)
ADD TARGET
-- package0.event_file
package0.asynchronous_file_target
(
SET filename=N'MissingProcedure.xel',
max_file_size=(5),
max_rollover_files=(4)
),
ADD TARGET package0.ring_buffer
(
SET
-- max_events_limit=(5000), -- the customizable attribute, "max_events_limit", does not exist
max_memory=(1024)
)
WITH (
MAX_MEMORY=1024 KB,
EVENT_RETENTION_MODE=ALLOW_SINGLE_EVENT_LOSS,
MAX_DISPATCH_LATENCY=120 SECONDS,
MAX_EVENT_SIZE=0 KB,
MEMORY_PARTITION_MODE=NONE,
TRACK_CAUSALITY=OFF,
STARTUP_STATE=ON
);
GO
ALTER EVENT SESSION [MissingProcedure] ON SERVER STATE=START;


It creates without error but the SERVER STATE=START statement gives

Server: Msg 25602, Level 17, State 21, Line 1
The target, "CE79811F-1A80-40E1-8F5D-7445A3F375E7.package0.asynchronous_file_target", encountered a configuration error during initialization. Object cannot be added to the event session.

which I am guessing is either than I need to add a path (for which SQL Service has permissions), or my guess of asynchronous_file_target is not a suitable replacement for your original of event_file!!


SELECT DISTINCT OC.name
FROM sys.dm_xe_object_columns AS OC
WHERE 1=1
AND OC.object_name = 'error_reported'
--
ORDER BY
OC.name

gives:

CHANNEL
error
ID
KEYWORD
message
severity
state
user_defined
UUID
VERSION

and it was on that basis that I swapped your "error_number" with "error" - might be a false assumption though!!
Go to Top of Page

robvolk
Most Valuable Yak

15732 Posts

Posted - 2015-03-19 : 15:03:36
Ugh, yeah, there were changes to the available packages between 2008 and 2012. I'm not sure what the older versions are, I don't have 2008 handy, but you will find all you need here:

http://sqlblog.com/blogs/jonathan_kehayias/archive/2010/12/01/a-xevent-a-day-31-days-of-extended-events.aspx

Since they're dated 2010 you will be fine. Jonathan is the go-to person for extended events, those blogs are the starting point.
Go to Top of Page

Kristen
Test

22859 Posts

Posted - 2015-03-19 : 15:19:29
Thanks Rob.

I hear that XE is the coming replacement for SQL Profiler etc. Happy with that, but the knowledge required to operate the thing and associated learning curve is like the North Face of the Eiger ... which I think is a Bad Thing.

I've built SELECT queries for every sys.dm_xe_XXX that I could find ... and that didn't tell me what parameters are valid (nor did the DOCs). Seems trivial to me to provide a Lookup Table of some sort that hackers like me could use to check what parameters etc. would be available to me ... or the DOCs need to detail every Nut, Screw, Washer and Bolt !

I'll report back after I've visited Jonathan emporium
Go to Top of Page

robvolk
Most Valuable Yak

15732 Posts

Posted - 2015-03-19 : 15:59:35
I hear you, fortunately Jonathan has that covered:

https://www.sqlskills.com/blogs/jonathan/converting-sql-trace-to-extended-events-in-sql-server-2012/

Plus more here:

https://www.sqlskills.com/blogs/jonathan/category/extended-events/

Not all trace events are available prior to 2012 (great excuse to upgrade!), but a number of them are. The first set of articles I believe covers that and shows how to map the ones that exist.

XE is one of those things you can probably knock out in a weekend or two if you knuckle down and just do it. That's what I've been telling myself, anyway.
Go to Top of Page

Kristen
Test

22859 Posts

Posted - 2015-03-24 : 10:26:07
Quick update:

Pro temp I've gone for a temporary workaround. A very significant percentage of the SProc calls from my app are routed through a single function in the application. I've hijacked the error handler on that to call an SProc with the name of the SProc that raised the error. That checks if the SProc name Exists, Exists but is suffixed "_HOLD", in which case it returns a code for "OnHold and successfully renamed" or "On Hold but rename failed", and a final code for "Looked under everything and still couldn't find it"

If it becomes sufficiently important to me I'll pursue that programming further so that a successful rename causes the original SQL EXEC to be re-issued. Right now I just generate a critical error which displays the result from the "Exists Check", and if it says "On Hold but Renamed OK" I just press refresh and away I go

Slight downside was that I have had to elevate the Permissions on the Login (shared by all connections to the APP) to db_OWner so that it is allowed to call sp_Rename. Its only a DEV APP, but I would prefer that it only had EXECUTE on specifically granted SProcs ...

... unless you know a way around that??

It was a right PITA that sp_Rename does a RAISERROR Belt&Braces warning whatever (The "Caution: Changing any part of an object name could break scripts and stored procedures" one). My code is designed to assume that such things are actually critical rather than just being there because sys.dependancies is pants and SQL can't work out if there is a real problem, or not. A @RunSilent parameter would have been a good addition to the brief that was given to the Summer Intern that wrote sp_Rename ...

Don't suppose you've looked at the Source for sp_Rename? Who writes double negatives like:

IF NOT (@MyParameter IS NULL)

rather than

IF (@MyParameter IS NOT NULL)

or have I shot myself in the foot and that two are not identical? (or should that be not not different? )
Go to Top of Page

robvolk
Most Valuable Yak

15732 Posts

Posted - 2015-03-24 : 16:08:21
I gave up a long time ago trying to decipher system procedures. I know a lot of them originated with Sybase and have been relatively untouched. MS is backwards-compatible to a fault, there's a shitload of really really bad design in the system (sysjobhistory is one of my pet peeves). And it's fair to say that the procedures were written by non-SQL folks, lots of C-looking constructs in there, unnecessary cursors, IF 0=Some_Expression_I_Hope_Will_Short_Circuit, etc.

Only suggestion I have on the renaming part is to defer it. Either stick it in a table and have a job run periodically to rename it, or if you're daring, put it in a service broker queue and write an activation procedure to process it. Either one will pull the error out of your current process, if that's important to you, and you can run them under different credentials.

And if you're thinking of service broker, probably easiest to set up an event notification to fire on error, and have the activation proc check the number for 2812 and act accordingly. That way you don't have to hook anything new into your app, and the activation can run on elevated privileges rather than the app login.
Go to Top of Page

Kristen
Test

22859 Posts

Posted - 2015-03-26 : 22:06:50
Hadn't though of that, its a good idea as then "anything" I write that detects a _HOLD Sproc (my APP, my APP running on PRODUCTION, an Extended Event) can just add a Request to the Queue, then no worry about each such task having to have God-like permissions. Thanks.
Go to Top of Page

robvolk
Most Valuable Yak

15732 Posts

Posted - 2015-03-27 : 09:14:47
Just to give you a heads up, I started playing with the event notification and had a hell of a time getting it work correctly. It's still pretty random for me.

I got a suggestion from someone about using an alert on error 2812, but I don't think it will return the error message with the text you need. They also suggested parsing the error log immediately after the alert to get it. It's workable, and might be easier overall than the event notification, unless you're a wizard at EN.
Go to Top of Page

Kristen
Test

22859 Posts

Posted - 2015-03-27 : 16:03:53
Thanks Rob. Rather confirms my fear that mastering this stuff, in future, is going to require Rocket science as a minimum ...

I'm sure XPath is something that can be learnt. I haven't tried that hard, but one of my pot-boiler projects is to spider specific sites for some data. It would be so much easier to do this using PHP or PERL or something like that and XPath to find the bits on the page that are of interest to me, and which I can then stuff - easily!! - into a database table. That would probably help with any other XML stuff, such as XE, that I then fell over ...

I may just be getting old!, but XPath is as opaque to me as it is possible to get without actually being pitch black!
Go to Top of Page

Kristen
Test

22859 Posts

Posted - 2015-03-27 : 16:07:29
P.S. If it is going to be "hard" I think I would be better off working up a solution in my APP. Calling an Sproc, from my App, goes through one of only 2 or 3 functions to communicate with SQL, so "trapping" any failed SProc calls is not hard, and I can then take some action accordingly.

Currently I'm getting a handy error message, but it would not be that hard to change the code to a) rename the Sproc (its doing that now) but more importantly b) retry the original call. I think that would be entirely benign, and would mean we could just rename all SProcs with the suffix "_HOLD" then do our normal coverage test and then see how many "_HOLD" Sprocs we have left!!

Slightly troubling that sp_rename (quite reasonably) tickles the Modified On date, so I would lose the knowledge of "When's the last time we changed this", so I might choose to restore the DB after the coverage test to reclaim that information.
Go to Top of Page
   

- Advertisement -