1. 程式人生 > >SQLServer · BUG分析 · Agent 鏈接泄露分析(轉載)

SQLServer · BUG分析 · Agent 鏈接泄露分析(轉載)

空閑 doc ucc object bsp line existing rds 成功

背景

SQLServer Agent作為Windows服務提供給用戶定期執行管理任務,這些任務被稱為Job;考慮應用鏡像的場景如何解決Job同步問題,AWS RDS的做法是不予理會,由用戶維護Job,假如發生切換用戶需要在新的Principal端創建Job;另一種做法是鏡像端保持同步Job,切換後盡量讓用戶無感知不需要多余維護動作,但這種做法在某些情況會遇到非常嚴重的問題——內存耗盡。

問題排查分析

第一次分析

問題發生時實例的ERRORLOG出現:

Error: 701, Severity: 17, State: 123.

並且記錄了 MEMORYSTATUS,根據 MEMORYSTATUS 的信息本身已經可以做推斷,但既然有現場 我們不妨用DAC(Dedicated Administrator Connection)看一下:

SELECT
	TOP 10 [type],
	sum ( single_pages_kb) as [SPA MEM/KB],
	SUM(multi_pages_kb) AS [MPA MEM/KB]
FROM sys.dm_os_memory_clerks
	GROUP BY type
	ORDER BY SUM ( single_pages_kb+multi_pages_kb) DESC ;

內存占用

占用最多的 OBJECTSTORE_SNI_PACKET、MEMORYCLERK_SQLCONNECTIONPOOL 一般跟連接數、network packet size有關;

select
	c.session_id,
	c.net_packet_size,
	s.host_name as client_host_name,
	s.program_name,
	s.client_interface_name
from sys.dm_exec_connections c
join sys.dm_exec_sessions s
	on c.session_id = s.session_id
join sys.endpoints e
	on c.endpoint_id = e.endpoint_id
order by c.net_packet_size desc

net_packet_size

select value_in_use from sys.configurations where configuration_id=1544

select program_name,count(*) as conn_num from sys.sysprocesses where spid>50 group by program_name order by conn_num desc

內存規格

1W+的鏈接保持,根據sys.dm_exec_sessions.program_name可以確認都來自SQLServer Agent,每個session的packet size是4K,實例的max server memory是1G,所以出現內存耗盡;

那麽這1W個鏈接在幹嘛?根據sys.dm_exec_sessions.program_name中暴露的job_id我們找到對應的Job,先看下這個Job要做什麽;

select * from msdb.dbo.sysjobs where job_id=0x825F84340AFD5B4BA1D5AD82A8E76C1A

Job信息

第一次推論

這部分內容涉及業務邏輯我不再貼出,重點是Job_Step使用的DATABASE是鏡像中的(RESTORING),因為鏡像的DB不可用,Schedule又設置的過於頻繁,所以SQLServer Agent沒能及時釋放這部分鏈接導致內存耗盡。

第一次驗證

重新搭建了一個測試環境,制造類似的場景但問題並沒能復現。感興趣的小夥伴可以測試下:鏡像 + Mirror端Job + Job鏈接鏡像庫且頻度調成10s + Job內容不限(為什麽不限後續通過Profiler可以看出)。

借助Profiler和Session相關視圖我們可以看出,當Job-Step的鏈接DB設置為鏡像DB時,會出現:

Error: 18456, Severity: 14, State: 38.

表示賬號校驗成功但數據庫不可訪問或登錄權限不夠,SQLServer Agent會重試多次,但最後都會釋放鏈接,這跟之前的推論不符。

Profiler信息

select program_name,count(*) as conn_num from sys.sysprocesses where spid>50 group by program_name order by conn_num desc

connection

第二次分析

回到原現場,我們再做分析;嘗試復現時我們發現完整的鏈接都無法建立,但這1W個鏈接是如何做到的:

select spid,program_name,loginame,login_time as time,db_name(dbid) as dbname from sys.sysprocesses where spid>50

dbname

根據spid我們看一下未釋放的鏈接最後執行的SQL是什麽:

inputbuffer

(@P1 nvarchar(max),@P2 uniqueidentifier,@P3 int,@P4 int)DECLARE @logTextWithPreAndPost nvarchar(max) set @logTextWithPreAndPost = N‘‘ + @P1 + N‘‘; EXECUTE msdb.dbo.sp_write_sysjobstep_log @job_id = @P2, @step_id = @P3, @[email protected], @[email protected]

看下 msdb.dbo.sp_write_sysjobstep_log這個存儲過程:

exec sp_helptext ‘sp_write_sysjobstep_log‘

	Text
-------------------------------------------------------------------------------
CREATE PROCEDURE sp_write_sysjobstep_log
  @job_id    UNIQUEIDENTIFIER,
  @step_id   INT,
  @log_text  NVARCHAR(MAX),
  @append_to_last INT = 0
AS
BEGIN
  DECLARE @step_uid UNIQUEIDENTIFIER
  DECLARE @log_already_exists int
  SET @log_already_exists = 0

  SET @step_uid = ( SELECT step_uid FROM  msdb.dbo.sysjobsteps
      WHERE (job_id = @job_id)
        AND (step_id = @step_id) )


  IF(EXISTS(SELECT * FROM msdb.dbo.sysjobstepslogs
                      WHERE step_uid = @step_uid ))
  BEGIN
     SET @log_already_exists = 1
  END

  --Need create log if "overwrite is selected or log does not exists.
  IF (@append_to_last = 0) OR (@log_already_exists = 0)
  BEGIN
     -- flag is overwrite

     --if overwrite and log exists, delete it
     IF (@append_to_last = 0 AND @log_already_exists = 1)
     BEGIN
        -- remove previous logs entries
        EXEC sp_delete_jobsteplog @job_id, NULL, @step_id, NULL
     END

     INSERT INTO msdb.dbo.sysjobstepslogs
      (
         log,
         log_size,
         step_uid
      )
      VALUES
      (
         @log_text,
         DATALENGTH(@log_text),
         @step_uid
      )
  END
  ELSE
  BEGIN
     DECLARE @log_id   INT
     --Selecting TOP is just a safety net - there is only one log entry row per step.
     SET @log_id = ( SELECT TOP 1 log_id FROM msdb.dbo.sysjobstepslogs
         WHERE (step_uid = @step_uid)
           ORDER BY log_id DESC )

      -- Append @log_text to the existing log record. Note that if this
      -- action would make the value of the log column longer than
      -- nvarchar(max), then the engine will raise error 599.
      UPDATE msdb.dbo.sysjobstepslogs
        SET
             log .WRITE(@log_text,NULL,0),
             log_size = DATALENGTH(log) + DATALENGTH(@log_text) ,
             date_modified = getdate()
      WHERE log_id = @log_id
  END

  RETURN(@@error) -- 0 means success

END

MSDN 沒有找到詳盡 Document,但看完定義也可以確認它是Job-Step做Advanced配置時會用到的一個存儲過程,作用是把Job-Step日誌寫到表 msdb.dbo.sysjobstepslogs 中,根據參數的不同可能會overwrite或append;

log_to_table

第二次推論

根據之前的信息我們可以推測出,這1W+空閑鏈接是由於執行完Job-Step後,內部更新msdb的日誌表,更新完成後鏈接未釋放。

第二次驗證

構造的場景跟第一次基本相同,只需要增加一點的是Job-Step開啟了log to table。

驗證成功

結果穩定復現,40s左右新增一個鏈接(Schedule 10s 不開啟Step Retry attempts 和 Retry interval),根據msdb.dbo.sysjobstepslogs.log_size和msdb.dbo.sysjobstepslogs.log可以確認日誌的更新頻度在40s。

開啟Profiler、不斷調整Schedule時間、監控msdb.dbo.sysjobstepslogs.log_size大小,可以發現,當調度頻度大於40s時,新增鏈接按照頻度增加,當頻度小於40s時,新增鏈接按照40s一個增加。

結論

如果Job-Step中定義的鏈接 DATABASE 是鏡像庫(RESTORING)且配置了Log To Table,那麽每次做日誌記錄的Session(msdb.dbo.sysjobstepslogs)都不會自動關閉,即Agent在這種場景下存在鏈接泄露。

SQLServer · BUG分析 · Agent 鏈接泄露分析(轉載)