@@FETCH_STATUS -9

I was working on a performance issue with my application team. They updated me that everything seems to be working fine when SQL services is recycled. It remains fine for 3 or 4 days and then they notice slowness. Once they see this behavior, SQL service will be restarted to solve the issue.

I looked at the perfmon when the issue occurred next time. Disk and CPU counters were normal. But counters related to memory were not that great. After the SQL server restart, the Page Life Expectancy(PLE) was decreasing throughout and reaching below 50 with higher values for Free list stalls/sec and Lazy writes/sec. This proved that something is leaking the memory within SQL server.

I checked the SQL server memory usage further using the below query,

select top 100 (select top 100 cast((cntr_value/1024.0) as decimal(28,2))
from sys.dm_os_performance_counters
where object_name like ‘%Memory Manager%’ and counter_name like ‘Total Server Memory (KB)%’) as ‘Total Server Memory (MB)’, (select top 100 sum(cast(size_in_bytes as decimal(18,2)))/1024/1024 FROM sys.dm_exec_cached_plans)  AS [Plan Cache(MB)], (select top 100 cast((cntr_value/1024.0) as decimal(28,2))
from sys.dm_os_performance_counters where object_name like ‘%Memory Manager%’ and counter_name like ‘Connection Memory (KB)%’) as ‘Connection Memory (MB)’, (select top 100 cast((cntr_value/1024.0) as decimal(28,2)) from sys.dm_os_performance_counters where object_name like ‘%Memory Manager%’ and counter_name like ‘Lock Memory (KB)%’) as ‘Lock Memory (MB)’, (select top 100 cast((cntr_value/1024.0) as decimal(28,2)) from sys.dm_os_performance_counters
where object_name like ‘%Memory Manager%’ and counter_name like ‘SQL Cache Memory (KB)%’) as ‘SQL Cache Memory (MB)’, (select top 100 cast((cntr_value/1024.0) as decimal(28,2)) from sys.dm_os_performance_counters
where object_name like ‘%Memory Manager%’ and counter_name like ‘Optimizer Memory (KB)%’) as ‘Optimizer Memory (MB)’, (select top 100 cast((cntr_value/1024.0) as decimal(28,2)) from sys.dm_os_performance_counters
where object_name like ‘%Cursor Manager b%’ and counter_name like ‘Cursor memory usage%’ and instance_name = ‘_Total’) as ‘Cursor memory usage (MB)’
go

From the output, I was able to see that the memory used by cursor was close to 50GB. Max server memory for this instance was set to 65GB. It was pretty clear that the cursor is leaking the memory. I checked how many cursors are active and how much memory does it occupy using the below query,

select count(*) as total_open_cursors,
convert (numeric(5,2), (select cntr_value/1024.0 from sys.dm_os_performance_counters WHERE counter_name = ‘Cursor memory usage’ and instance_name = ‘_Total’)) as MemUsed_by_Cursors_MB
from sys.dm_exec_cursors (0) c
where is_open=1

It showed that close to 63548 cursors were active with 50GB memory used and growing steadily. I wanted to check what these cursors were doing and hence checked the FETCH_STATUS of these cursors that are active in this instance.

select [fetch_status],count(*) from  sys.dm_exec_cursors (0)
group by [fetch_status]

There were close to 63546 cursors with FETCH_STATUS -9 and 2 with FETCH_STATUS 0. As per https://msdn.microsoft.com/en-us/library/ms187308.aspx, below are the return values for FETCH_STATUS.

Return value Description
0 The FETCH statement was successful.
-1 The FETCH statement failed or the row was beyond the result set.
-2 The row fetched is missing.
-9 The cursor is not performing a fetch operation.

FETCH_STATUS -9 refers that the cursor is active, but not doing any fetch operation. I checked the text for these cursors using the below query,

select t.text,[fetch_status],dormant_duration,session_id,cursor_id,name,properties,creation_time,is_open from  sys.dm_exec_cursors (0) a CROSS APPLY sys.dm_exec_sql_text(a.sql_handle) AS t

The text column from the above querie’s output revealed that each of these cursors were not properly deallocated and this is bloating up the memory usage. We found an issue in the application code where the cursors were not getting properly deallocated which is basically what is causing the -9 issue where no fetch operation is performed. Once the application code was modified to deallocate the cursors properly, the issue was resolved permanently.

I tried to reproduce this issue on my lab machine with Max Server Memory set at 500 MB .

create database JB_Cursor
go

use JB_Cursor
go

create table JB_count(
sno int primary key identity (1,1),
sname varchar(255))

Executed the below query,

DECLARE db_cursor CURSOR  FOR
SELECT name  FROM sys.databases
OPEN db_cursor

DECLARE DatabaseBackup_cursor CURSOR FOR
select name from master..sysobjects
OPEN DatabaseBackup_cursor
FETCH NEXT FROM DatabaseBackup_cursor
WHILE @@FETCH_STATUS = 0
BEGIN
FETCH NEXT FROM DatabaseBackup_cursor
END

CLOSE DatabaseBackup_cursor
DEALLOCATE DatabaseBackup_cursor

CLOSE db_cursor
DEALLOCATE db_cursor

Executed the below query in a different query window,

select getdate() as time_checked,
max (c.creation_time) as maxc,
min(c.creation_time) minc,
count(*) as total_open_cursors,
–convert(numeric(5,2), (count(*) * 1.0/datediff(mi,min(c.creation_time),getdate()))) as open_cursors_created_per_minute,
convert (numeric(5,2), (select cntr_value/1024.0 from sys.dm_os_performance_counters
WHERE counter_name = ‘Cursor memory usage’ and instance_name = ‘_Total’)) as MemUsed_by_Cursors_MB
from sys.dm_exec_cursors (0) c
where is_open=1 and [fetch_status] = -9
go
select fetch_status,dormant_duration,* from  sys.dm_exec_cursors (0)

From the output you will see that db_cursor will have a fetch_status as -9. This is because cursor db_cursor doesn’t perform a fetch and just waits on the cursor DatabaseBackup_cursor to complete.

The below query will reproduce the issue we are looking for,

set nocount on
declare @i int
Declare @cursorname VARCHAR(1000)
Declare @cursorname1 VARCHAR(1000)
Declare @cursorname2 VARCHAR(1000)
set @i=1

while(@i<20000)
begin
set @cursorname = ‘db_cursor’ + cast(@i as varchar)
set @cursorname2 = ‘DatabaseBackup_cursor’ + cast(@i as varchar)

set @cursorname1=’Declare @name varchar(255)
DECLARE ‘+@cursorname+’ CURSOR  FOR
SELECT name  FROM sys.databases
OPEN ‘+@cursorname+’

DECLARE ‘+@cursorname2+’ CURSOR FOR
select name from master..sysobjects
OPEN ‘+@cursorname2+’
FETCH NEXT FROM ‘+@cursorname2+’ into @name
WHILE @@FETCH_STATUS = 0
BEGIN
insert into JB_count values (@name)
FETCH NEXT FROM ‘+@cursorname2+’ into @name
END

CLOSE ‘+@cursorname2+’
DEALLOCATE ‘+@cursorname2+’

–CLOSE ‘+@cursorname+’
–DEALLOCATE ‘+@cursorname+’   —-Not closing or deallocating the cursor just to reproduce the issue.

exec (@cursorname1)
set @i=@i+1
end

Open a new query window and execute the below,

select count(*) as total_open_cursors,
convert (numeric(5,2), (select cntr_value/1024.0 from sys.dm_os_performance_counters WHERE counter_name = ‘Cursor memory usage’ and instance_name = ‘_Total’)) as MemUsed_by_Cursors_MB
from sys.dm_exec_cursors (0) c
where is_open=1 and [fetch_status] = -9
go
select [fetch_status],count(*) as [Cursor_Count] from  sys.dm_exec_cursors (0)
group by [fetch_status]
go
select t.text,[fetch_status],dormant_duration,session_id,cursor_id,name,properties,creation_time,is_open from  sys.dm_exec_cursors (0) a CROSS APPLY
sys.dm_exec_sql_text(a.sql_handle) AS t
go

This is what I saw in my lab machine,

blog3_1

Out of 500 MB, Cursors alone is using close to 350 MB memory. The resolution for this issue in our example would be to uncomment the deallocate statement.

Thank You,
Vivek Janakiraman

Disclaimer:
The views expressed on this blog are mine alone and do not reflect the views of my company or anyone else. All postings on this blog are provided “AS IS” with no warranties, and confers no rights.

Advertisements

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s