[percent_complete] show value as NULL

[jeffrey-yao]

Hi Adam,

I recently noticed that sp_whoisactive seems not displaying the real value of [Percent_Complete] for a restore session.

But if I run my own query

select session_id, command, percent_complete from sys.dm_exec_requests where command like 'restore%',

I can observe [percent_complete] has values keeping changing my environment. I am using SQL Server 2016 SP2+CU7 13.0.5366.0 (X64)

My sp_whoisactive is ver 11.33.

Do you know why?

Thanks a lot Adam for your great sp_whoisactive.

Kind regards, Jeffrey Yao

[MisterZeus]

It might be the code around line 2881, which does the following?

... FROM @sessions AS sp LEFT OUTER LOOP JOIN sys.dm_exec_sessions AS s ON s.session_id = sp.session_id AND s.login_time = sp.login_time LEFT OUTER LOOP JOIN sys.dm_exec_requests AS r ON sp.status <> ''sleeping'' AND r.session_id = sp.session_id AND r.request_id = sp.request_id AND ( ( s.is_user_process = 0 AND sp.is_user_process = 0 ) OR ( r.start_time = s.last_request_start_time AND s.last_request_end_time <= sp.last_request_end_time ) ) ...

[amachanic]

@jeffrey-yao Sorry for the delay in getting back to you on this. Does this happen for every restore?

Is anyone else seeing this?

[jeffrey-yao]

@amachanic , I have not noticed this for some time. But will keep an eye on it and report back. Thanks again for your great contribution to SQL server community.

[imyourdba]

I did also see this when trying to watch a restore in SQL 2017 CU15 (haven't gotten the newer CU's installed yet).

[codykonior]

I have the same problem in SQL 2017 CU19. Commenting out this specific comparison fixes it for me, the others don't.

[codykonior]

My fix was to change the block like this, because I don't know what causes the problem, at least I limit any potential negative impact to just the backup/restore processes.

For the record, I haven't seen this problem with backups though, only with restores (a specific long running full restore).

[amachanic]

Thank you @codykonior for your detective work here. I'd really like to better understand the problem before creating any sort of fix - and at least in my case that means refreshing my memory on where, exactly, these last_request_end_time values come from, and why I added that predicate. (Note to prior self: Please put a comment in there!)

I'll come back to this shortly after I read up a bit. If anyone (@codykonior ?) can collect some actual raw data when this sort of problem is in flight, that would be very helpful.

[mattcargile]

Long time follower, first time poster. I'm finding this "bug" on SQL Server 2014 (14.0.3294.2) during a BACKUP DATABASE while running v11.35. I did like others have done and commented out the last_request_end_time piece of the predicate. I've dug a little big further down into the procedure and hopefully this screenshot will help.

In the screenshot below, the last_batch column corresponds to @sessions/sp.last_request_end_time. You can see the dm_exec_sessions.last_request_end_time is 3 milliseconds greater than the sys_processes.last_batch. The predicate expects them to be equal or opposite.

Additionally, the screenshot doesn't show it but the dm_exec_sessions.login_time does match sysprocesses.login_time at 2020-11-17 22:32:35.727 in my example. I'm not sure if there is any additional data needed. I did extract the full resultset from sysprocesses and dm_exec_sessions.

EDIT 1: Not sure if relevant. The database in my example is 3TB and is the primary in an 2 node async AG. The instance is also in a four node Windows Failover Cluster.

EDIT 2: Another thing that may be of note is we were using the Maintenance Plan in an Agent Job to run the backup. The T-SQL involved includes a preferredReplica check with a call to master.sys.fn_hadr_backup_is_preferred_replica.

[farhang-m]

Hi Adam We use commVault for database backup. Using sp_whoisactive, percent complete is shown as null but sys.dm_exec_request shows the expected value. SQL 2016 SP2- CU11