0

We continuously gather data from sys.sm_exec_sessions and sys.dm_exec_requests to be able further investigate our locking and performance issues.

In some cases, I can see that multiple queries to sys.sm_exec_sessions returns the same value of last_request_start_time but different (not-null) values of last_request_end_time.

Is it standard behavior? What does it mean when one request has multiple end times?

Regarding to documentation, I would expect that each change to last_request_start_time should be followed with just one change of last_request_end_time. Am I missing something?

last_request_start_time Time at which the last request on the session began. This includes the currently executing request. Is not nullable.

last_request_end_time Time of the last completion of a request on the session. Is nullable.

Example bellow shows result of five subsequent queries to sys.dm_exec_requests. Each call returns one record. All results shows same sart_time but unique end_time.

select 
    es.session_id,  
    es.program_name,
    es.last_request_start_time,
    es.last_request_end_time
from 
    sys.dm_exec_sessions es 
where 
    es.session_id = 124

1. 124    Worker@72045511    2022-04-04 14:43:19.993    2022-04-04 15:00:58.050
2. 124    Worker@72045511    2022-04-04 14:43:19.993    2022-04-04 15:02:16.333
3. 124    Worker@72045511    2022-04-04 14:43:19.993    2022-04-04 15:02:43.640
4. 124    Worker@72045511    2022-04-04 14:43:19.993    2022-04-04 15:03:02.520
5. 124    Worker@72045511    2022-04-04 14:43:19.993    2022-04-04 15:03:07.887
Michal Rizek
  • 33
  • 6
  • 1
    Well if a process goes parallel (which must be the case if there are multiple rows in `sys.dm_exec_sessions`, the requests all started at the same time, but the individual threads can't all be expected to finish at the same time. Different threads will finish faster than others for a whole variety of reasons. Have you considered using something canned and widely accepted for activity monitoring, like [`sp_whoisactive`](https://github.com/amachanic/sp_whoisactive/releases)? – Aaron Bertrand Apr 04 '22 at 16:04
  • Result in example si actualy result o multiple calls to dm_exec_sessions, not result of one query. So there is just one record for my session in dm_exec_sessions. I edited my question to make that example more clear. – Michal Rizek Apr 05 '22 at 15:42
  • I would still suggest getting process information from `sp_whoisactive` or at least `sys.dm_exec_requests` as opposed to `sys.dm_exec_sessions`. I don't know that I've ever felt comfortable that the sessions DMV was always in sync, in fact you can sometimes see `last_request_end_time` _before_ `last_request_start_time`, which makes even less sense than what you're seeing. – Aaron Bertrand Apr 05 '22 at 15:47
  • Thank you for tip for sp_whoisactive. It acutaly uses dm_exec_sessions and dm_exec_requests too. In production we also use complex queries that work with lot of resources like sp_whoisactive does(dm_exec_requests, sql_text etc.). In my example above i removed all the complexity to make example query as simple as posible while still being able to reproduce that odd behaviour. ps: Having last_end_time before last_start_time makes sense for me. It means that one request has finished and another has started but is still running, desn't it? – Michal Rizek Apr 05 '22 at 16:11
  • Yeah, like I said, I haven't felt a compelling need to trust what's in those columns, and I don't believe the documentation is fully honest about all the potential edge cases (like the two we've already talked about, and possibly others). But your peers aren't going to be able to help you solve this; you're much better off raising a support issue with Microsoft, where you can work with them to fully reproduce the issue. I would love an explanation for these two scenarios as well, but I don't have any answers for you. I would still check in these cases if the task is running, is parallel, etc. – Aaron Bertrand Apr 05 '22 at 16:16
  • If the task is still running and it is parallel, then I could certainly see like I explained in my first comment that some threads report finishing while others keep going, even though the request that started them all obviously hasn't changed. I haven't investigated this to any great extent but I would also pull in info from `sys.dm_exec_requests` and `sys.dm_os_tasks` to see if the session where you're seeing this symptom is in fact still running, if there are multiple requests/tasks associated with it, and if the count of running threads changes along with the timestamps in exec_sessions. – Aaron Bertrand Apr 05 '22 at 16:23

0 Answers0