0

I try to capture some statistic parameters for logging purpose. "SET parameters" are no option (i.e. set statistics time on).

So I tried to query some DMV:

select '3AAAAAAAAAAA';
--no GO-statement here

select 
    total_worker_time/execution_count AS [Avg CPU Time],
    total_elapsed_time as [Elapsed Time],
    total_rows as [Total rows],
    st.text,
    (select cast(text as varchar(4000)) from ::fn_get_sql((select sql_handle from sys.sysprocesses where spid = @@spid)))
from sys.dm_exec_query_stats AS qs
cross apply sys.dm_exec_sql_text(qs.sql_handle) AS st
--where  ???
order by creation_time desc

The information captured here is almost what I need - but:

The query is only listed in the result of the DMV when it run in last executed GO-Block (not in the actual one). This is not what I need. I need something like @@error or @@rowcount what is available within the same GO-block and holds the elapsed time and CPU time. Any ideas how to query this information of the last statment?

If this can be solved: I would like to query the "last" statement execution within the session (@@spid) without writing the statement twice.


Update on question:

This query is working "per session" and would list the requested values (although tirvial querys are missing). Top 1 would always bring back the values of the last Statement (not true if fired via exec @SQL what produces anonther session):

print 'hello';

select top 10 'my personal identifier: 1', * FROM sys.messages;

select top 20 'my personal identifier: 2', * FROM sys.messages;

print 'hello';
select 'hello';

select top 30 'my personal identifier: 3', * FROM sys.tables;

select top 1
    total_worker_time/execution_count AS [Avg CPU Time],
    total_elapsed_time as [Elapsed Time],
    total_rows as [Total rows],
    substring(st.text, (qs.statement_start_offset / 2) + 1, (case when qs.statement_end_offset = -1 then datalength(st.text) else qs.statement_end_offset end - qs.statement_start_offset ) / 2 + 5) as [executing statement] 
from sys.dm_exec_query_stats AS qs
cross apply sys.dm_exec_sql_text(qs.sql_handle) AS st
where st.text = (select cast(text as varchar(4000)) from ::fn_get_sql((select sql_handle from sys.sysprocesses where spid = @@spid)))
order by qs.statement_start_offset desc;

The filter (where-clause) seems to be crude and not very robust. Is there any way to improve this?

Christian4145
  • 513
  • 1
  • 9
  • 31
  • So why not just `SELECT @@ERROR, @@ROWCOUNT` then? – Jeroen Mostert Jan 23 '18 at 11:14
  • Because these variables only give [total rows]. As far as I know there is no system variable holding CPU-time and elapsed time. – Christian4145 Jan 23 '18 at 12:55
  • Oh, I misunderstood your question -- I thought you were confused about how to add `@@ERROR` and `@@ROWCOUNT` to the results, but you just used them as examples of how your ideal solution would work. – Jeroen Mostert Jan 23 '18 at 13:00
  • Note that your results are skewed by the fact that your "query" under test is trivial: try `SELECT TOP(1) * FROM sys.messages` instead, and `WHERE total_rows = 1`. AFAICT this still won't allow you to reliably identify the query (matching on the text is a kludge and won't work over multiple executions). – Jeroen Mostert Jan 23 '18 at 13:47
  • 1
    On my LocalDB instance (SQL Server 2017) it definitely works (with `where st.text = (select cast(text as varchar(4000)) from ::fn_get_sql((select sql_handle from sys.sysprocesses where spid = @@spid)))`), whereas a `SELECT ` doesn't return anything in this case. (Of course, the text returned is that of the whole batch, but that's fixable with the `statement_*_offset` columns.) – Jeroen Mostert Jan 23 '18 at 13:58
  • OK: first "problem" solved. – Christian4145 Jan 23 '18 at 13:59

1 Answers1

0

I try to answer myself (Jeroen Mostert - Thank you very much for your help!) - the question is unanswered (see below):

The follwing function should give you CPU, execution time, I/O, number or rows of the last statement that was executed in the actual session, if the statement is complex enough to invoke a SQL plan generation. That is, after simple print commands the resultset would be enpty. Even so after the execution of stored procedures if they open a new session (i.e. after exec sp_executesql the resultset will be empty).

For the "average" SQL-Statement the following query should result in a rowset holding the information that you would otherwise get via set statistice time on and set statistice io on.

drop function if exists dbo.ufn_lastsql_resources ;
go

CREATE FUNCTION dbo.ufn_lastsql_resources (@session_id int)
RETURNS TABLE  
AS  
return
select 
    top 1

    convert(char(10), getdate(), 121) + ' ' + substring(convert(char(40), getdate(), 121), 12,12) + ',' as [Time stamp], 
    cast(cast((last_worker_time / execution_count / 1000. ) as numeric(9,2)) as varchar(100)) + ','     as [Avg CPU Time in ms],
    cast(cast((last_elapsed_time / 1000. ) as numeric(9,2)) as varchar(100)) + ','                      as [Elapsed Time in ms],
    cast(last_rows as varchar(100)) + ','                                                               as [Total rows],
    cast(substring(st.text, (statement_start_offset / 2) + 1, (case when statement_end_offset = -1 then datalength(st.text) else statement_end_offset end - statement_start_offset ) / 2 + 2) as varchar(4000)) + ',' 
                                                                                                        as [executing statement],

    last_physical_reads + last_logical_reads                                                            as [Reads],
    last_logical_writes                                                                                 as [Writes],

    --last_grant_kb,
    --last_used_grant_kb,
    --last_ideal_grant_kb,

    --last_reserved_threads,
    --last_used_threads

    @session_id                                                                                         as spid

from 
    (
    select qs.*
    from sys.dm_exec_query_stats as qs
    inner join sys.dm_exec_requests as eq 
    on  qs.sql_handle  = eq.sql_handle
    and qs.plan_handle = eq.plan_handle 
    and eq.session_id  = @session_id
    ) a
cross apply sys.dm_exec_sql_text(a.sql_handle) AS st
where 
    substring(st.text, (statement_start_offset / 2) + 1, (case when statement_end_offset = -1 then datalength(st.text) else statement_end_offset end - statement_start_offset ) / 2 + 2) not like '%ufn_lastsql_resources%'
order by 
    last_execution_time desc, statement_start_offset desc
go

Most probably there are more elegant ways to do so. Maybe it is possible to write something that will work properly even with statements that use an option (recompile) or on exec (@sql) Anyway: I seems to work on SQL Server 2016 and 2012. You need VIEW SERVER STATE permission on the Server. To invoke the function, try:

drop table if exists #t1
select top 10 'statement 1' a, * into #t1 from sys.messages
select 1, * from dbo.ufn_lastsql_resources(@@spid) option (recompile)


drop table if exists #t2
select top 20 'statement 2' a, * into #t2 from sys.messages 
--select 2, * from dbo.ufn_lastsql_resources(@@spid)

select top 3 'statement 3' a, * from sys.messages 
select 3, * from dbo.ufn_lastsql_resources(@@spid) option (recompile)

The question remins unanswered, as the way is not working properly. It is not sure to catch the right statement out of the batch (top 1 within the session ordered by last_execution time and last in batch. This seems to be the wrong order. As the plans are reused this is the only way, I figured out to work.)

Christian4145
  • 513
  • 1
  • 9
  • 31