0

After configuring XE on November 23, 2020 to capture some errors I could count 2,163,665 occurrences of the same error coming from requests of a legacy app (that probably won’t be corrected so soon). The errors can be classified on the 1st and 2nd steps for Processing a SQL Statement:

  1. The DBMS first parses the SQL statement. It breaks the statement up into individual words, called tokens, makes sure that the statement has a valid verb and valid clauses, and so on. Syntax errors and misspellings can be detected in this step.
  2. The DBMS validates the statement. It checks the statement against the system catalog. Do all the tables named in the statement exist in the database? Do all of the columns exist and are the column names unambiguous? Does the user have the required privileges to execute the statement? Certain semantic errors can be detected in this step.

The doc also says that Parsing a SQL statement does not require access to the database and can be done very quickly, but the amount of requests being fired at the server made me think I should verify.

I’d like to measure the resource consumption impact caused by those wrong requests being rejected on those steps. Is there a way to do so?

5
  • How many are "TONS"? I think you will need thousands of these errors per second to have a significant resource impact. You could capture rpc and sql_batch completed events filtered by result = Error and additional filters for the problem app to capture CPU. – Dan Guzman Feb 22 at 11:50
  • if an event errors does it actually complete ? I don't know but I am doubtful. Is it right that some of this application works correctly but a few things don't ? Maybe what you need is a no-op plan guide - but I think that is a change request :-) – Stephen Morris - Mo64 Feb 22 at 12:09
  • @DanGuzman, I'd say it's not even close to thousands of errors per sec because it's a small environment, I said tons because of the frequency that was flooding the XE capture making it really difficult for me to find anything useful until I filtered out those errors. About your suggestion, I'm not sure I follow your idea. Where do I use that filter? – Ronaldo Feb 22 at 12:19
  • @StephenMorris-Mo64 I'd guess it always complete because it returns the error message and that's one (undesired) way of completing. "Is it right that some of this application works correctly but a few things don't ?" Yes, the application still works, but this specific request causing the error is continually being sent to the server (and I have no idea of what's broken on the app). – Ronaldo Feb 22 at 12:30
  • @DanGuzman I just verified and the XE was configured on my server on 2020-11-23 and it captured 2,163,665 events of the error I mentioned. I know SQL Server can handle that easily (it's been doing it with no problem long before I noticed the errors with XE), but it's good to know what's going on on the server and have a baseline of its load. – Ronaldo Feb 22 at 13:02
1

I see from your comment that the errors are not happening so frequently as to be a performance concern.

To answer the question asked, you could create a filtered XE trace to capture detail sql_batch_completed and rpc_completed events where result is Error. The events can then be summarized by a time interval for aggregated stats.

The example below summarizes the CPU and logical reads by one minute interval from a trace file target.

--example trace
CREATE EVENT SESSION [errors] ON SERVER 
ADD EVENT sqlserver.rpc_completed(SET collect_statement=(1)
    WHERE ([result]=(1))),
ADD EVENT sqlserver.sql_batch_completed(
    WHERE ([result]=(1)))
ADD TARGET package0.event_file(SET filename=N'C:\TraceFiles\errors',max_rollover_files=(2))
WITH (MAX_MEMORY=4096 KB,EVENT_RETENTION_MODE=ALLOW_SINGLE_EVENT_LOSS,MAX_DISPATCH_LATENCY=30 SECONDS,MAX_EVENT_SIZE=0 KB,MEMORY_PARTITION_MODE=NONE,TRACK_CAUSALITY=OFF,STARTUP_STATE=OFF);
GO

--example aggregation query
WITH
    event_data AS (
        SELECT CAST(event_data AS XML) AS event_data_xml
        FROM fn_xe_file_target_read_file('C:\TraceFiles\errors*.xel',NULL,NULL,NULL)
    )
    , event_data_fields AS (
        SELECT 
              DATEADD(minute,DATEDIFF(minute,'',event_data_xml.value('(/event/@timestamp)[1]', 'datetime2')),'') AS interval
            , event_data_xml.value('(/event/data[@name="duration"]/value)[1]', 'bigint') AS duration
            , event_data_xml.value('(/event/data[@name="cpu_time"]/value)[1]', 'bigint') AS cpu_time
            , event_data_xml.value('(/event/data[@name="logical_reads"]/value)[1]', 'bigint') AS logical_reads
        FROM event_data
    )
SELECT
      interval
    , SUM(duration) AS duration
    , SUM(cpu_time) AS cpu_time
    , SUM(logical_reads) AS logical_reads
FROM event_data_fields
GROUP BY interval
ORDER BY interval;
2
  • Dan Guzman, thanks a lot! I've been using the EVENT sqlserver.error_reported and I'm not sure it has a value for cpu_time (still learning XE). I just tested your code on my desktop and it seems to be exactly what I was looking for. Also, I see this will be useful to count the total of correct requests my server receives if I change the result = (1) to result = (0) according to the possible values for the Error column for the RPC:Completed Event Class. Am I right? – Ronaldo Feb 22 at 17:03
  • @Ronaldo, be aware that the trace can become quite large for all successful queries on an active server and expensive to query the XML. If you only need a count, play around with the XE histogram target. – Dan Guzman Feb 22 at 22:48

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.