2

I've been trying to track down the source of my tempdb log filling up every few weeks where the tempdb log space used will continue to grow until it reaches 99% and stays there for hours while the log file grows. After adding in some additional logging and email alerts, I think I identified the source of the problem, at least for this incident, not sure if the cause is the same in past incidents.

dbcc opentran in the tempdb reported this:

Oldest active transaction:
    SPID (server process ID): 47s
    UID (user ID) : -1
    Name          : sort_init
    LSN           : (41:3017:42)
    Start time    : Dec 19 2020 10:03:20:410AM
    SID           : 0x01
DBCC execution completed. If DBCC printed error messages, contact your system administrator.

The spid is 47s which I discovered is a system spid. I ran sp_WhoIsActive with @show_system_spids = 1 which brought back data on the process. After running sp_WhoIsActive over the course of an hour, tempdb_allocations ended up at 4,221,088, tempdb_current was 4,128,656, open_tran_count was 1 (throughout the entire incident) and sql_text was always null. After running out of ideas, I ended up restarting SQL Server. Several times prior to restarting SQL server, I issued a checkpoint in tempdb but that didn't help, likely since the transaction from the system process was still active.

The Start time from the dbcc opentran output is 10:03am and it was 1:00pm when I restarted SQL Server. I ran dbcc opentran a few times over the course of an hour and the same output was returned each time.

In this particular case, the server was rebooted and it restarted at 10:02:54 -- 26 seconds before this long running system process started at 10:03:20. Past incidents don't appear to have happened immediately after a system reboot. I don't have many details on past incidents, but at least the last time this occurred 9 days ago, in the sp_WhoIsActive output I collected (without @show_system_spids set to 1) there were no long running processes captured which likely means it was a similar system process running / filling up the tempdb log. This 99% full tempdb log incident 9 days ago was ongoing for 7 hours.

Nothing stands out in the SQL Server log and Windows logs. I'm running Microsoft SQL Server 2017 (RTM-CU15-GDR) (KB4505225) - 14.0.3192.2 (X64).

Is there a way to determine what a system SPID is doing? Or any tips on how I can better troubleshoot this problem when it happens next time? The only clue from this incident is the Name value of sort_init in the dbcc opentran output which could be helpful but seems generic at the same time.

Improve this question
3
  • You're almost 2 years behind on patches - I'd start with a CU update. Do the SQL Server logs have an indication of what it was doing around 10:03?
    – LowlyDBA - John M
    Commented Dec 19, 2020 at 19:52
  • @LowlyDBA true haven't updated for a while, I'll give that a try. I looked through the SQL Server logs and don't see anything that stands out. Records logged around +/- 10:03 are normal startup messages.
    – Ben Amada
    Commented Dec 19, 2020 at 20:49
  • Upgraded to SQL 2017 CU22 (the latest). Will continue monitoring to see if this happens again. It could be up to a few weeks based on how frequently this occurs -- on average about once a month.
    – Ben Amada
    Commented Dec 20, 2020 at 18:48

1 Answer 1

Reset to default
1

There are some newer DMVs designed specifically for troubleshooting what is happening in TEMPDB. Take a look at sys.dm_db_session_space_usage and sys.dm_db_task_space_usage. See this link for a discussion of those DMSVs

Improve this answer
1
  • 1
    Thanks @Lee, I'm using sys.dm_db_task_space_usage via the first query in this answer. You're right, this is useful and while this problem was occurring, the DMV/query reported the System SPID was using a lot of tempdb space. sp_WhoIsActive reported similar tempdb usage by the session. The main thing that was missing was the APPLYs to sys.dm_exec_sql_text and sys.dm_exec_query_plan didn't report back any query text or plans (they were both null). So I couldn't tell what the system SPID was doing.
    – Ben Amada
    Commented Dec 21, 2020 at 11:25

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge you have read our privacy policy.

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