Governo delle istanze\database SQL Server!

Introduzione

L’obiettivo del presente articolo è quello di esporre una nuova metodologia di monitoraggio che ha lo scopo di governare le istanze SQL Server e d’integrare gli strumenti di monitoraggio.

Governare l’istanza SQL Server

Una delle cose necessarie per governare un’istanza e\o dei database SQL Azure, è quella di essere in grado di sapere quali sono i comandi che girano abitualmente sull’istanza e saper di rispondere ai molti quesiti che emergono ogni giorno in fase di amministrazione: problemi di lentezze applicative che vanno declinati nel comprendere se la componente database è la parte lenta o meno nonché se la causa sono stati i blocchi o il carico di quali comandi; stored procedure che degradano di performance nel tempo per le quali capire quale è lo statement lento e da quando ha iniziato a degradare; esigenze di deploy di nuovi database e scelta dell’istanza; richieste di lavoro in fasce orarie non abituali; comandi che ingrandiscono il TLOG e molte altre richieste.

La soluzione

La metodologia di governo per rispondere alle esigenze appena sopra citate, si basa sulla ‘fotografia’ dei comandi in ‘running’ ogni 1 minuto utilizzando le DMVs (in modalità simile a quanto viene effettuato dalla stored sp_whoisactive) per rilevare i comandi in corso di esecuzione sull’istanza\database.

Questa modalità, testata negli anni in ambienti Enterprise, consente di avere un’ottima granularità di registrazione che permette in modo semplice di comprendere i problemi dell’istanza SQL Server e quando essi accadono. Infatti la rilevazione ogni 1 minuto, permette di registrare i comandi lunghi che durano più di 1 minuto nonché i comandi brevi che durano poco, ma che vengono eseguiti spesso.

Governo dell’istanza: alcuni esempi di analisi delle registrazione

Segnalazione di lentezze

Nell’esempio seguente, viene segnalato che il giorno 7 luglio 2023 ci sono stati rallentamenti nella fascia oraria che va dalle 17.42 alle 17.55 sull’istanza “sql04\p04”. Di seguito viene riportato un esempio di registrazione con la fotografia ogni 1 minuto.

Osservando la figura sopra, si nota che il problema è dato dalla chiamata alla stored “pp_GE220” che esegue lo statement “Select convert(varchar(50),allTable.IdRow) IdRow, convert(varch…” che è troppo invasivo per l’istanza e viene chiamato troppe volte parallelamente. Queste chiamate vengono fatte principalmente dal “program_name=’ Service_Elab_Analysis_01’”. Guardando la colonna “host_name” si vede che questa chiamata è fatta da più macchine differenti. Andando indietro nel tempo ed osservando le registrazioni, si può comprendere che la stessa stored quando viene eseguita al massimo con 3 session parallele, risponde sempre entro 1 minuto. Ciò significa che questa stored fa troppo carico per essere eseguita troppe volte in parallelo. E’ necessario capire se possibile fare tuning nonché insieme agli owner del database quali sono le esigenze relative alle chiamate.

Integrazione al monitoraggio fatto con gli strumenti Microsoft

Quando gli utenti segnalano delle lentezze è necessario capire se questo è dovuto alla componente database. Per farlo è necessario verificare le registrazioni.

Le registrazioni fatte dagli amministratori sono generalmente relative a counter HW e SQL Server. Queste registrazioni non permettono di individuare i comandi che stavano girando quando sono accadute le lentezze segnalate. Di conseguenza per individuare i comandi, vengono utilizzati i tool di SQL Server Profiler oppure la più recente generazione degli Extened Events. Questi tool hanno però i seguenti limiti:

• Registrano in base ai filtri impostati i comandi in fase di Start oppure End
• Se ci sono tanti comandi che durano poco, non vengono registrati se il filtro Duration è alto
• Se ci sono tanti comandi che durano poco il numero di righe da analizzare è numeroso e difficile
• Se ci sono comandi che durano molto è difficile correlarli al punto nel tempo dove è accaduto il problema
• La registrazione avviene dopo che il problema è stato segnalato in base al tipo di problema segnalato. Lasciare una registrazione continua su tutte le istanze è costoso in termini di gestione e risorse consumate

Altra modalità di analisi è tramite le DMVs di SQL Server. Queste mostrano i comandi che consumano più risorse, ma non è detto che questi siano la causa del problema quando la lentezza è stata segnalata in un preciso punto nel tempo. Quello che accade generalmente è che il problema di lentezza segnalato probabilmente accadrà di nuovo in futuro, sperando che i monitoraggi impostati (con gli strumenti Microsoft appena sopra citati) dopo il problema segnalato, permettano d’individuare la causa, senza la certezza di averlo individuato fino a quando non riaccade.

Utilizzo del Query Store

Lo strumento che maggiormente permette il governo dell’istanza è il query store, in quanto se abilitato sul database (abilitato per default nelle ultime versioni di SQL Server) permette di vedere i comandi che passano sull’istanza, quando sono stati eseguiti, i tempi di impiegati, fino ad arrivare al query plan. Questo strumento non permette di operare le seguenti attività di governo:

• Nelle situazioni segnalate di lentezza non ho una visione d’insieme dei comandi in running e soprattutto non vedo se la causa è data delle blocking session;
• Vengono mostrati i singoli statement, ma se questi sono eseguiti da una stored procedure, non vedo in modo semplice la stored che lo stava lanciando;
• In situazioni di ambienti Enterprise dove ci sono molteplici application server e servizi in esecuzione, non si vedono i dati di “host_name”, “program_name” e “login_name” che fanno le chiamate a stored e\o statement SQL;
• Non c’è unaì repositiory centrale ed una visione d’insieme sui comandi che girano su tutte le istanze ed all’interno di una istanza i comandi sono da mettere in UNION sui vari database per ottenere quanto era in esecuzione in un determinato range temporale. Il troubleshooting delle lentezze in un range temporale non è fattibile con una semplice interrogazione;
• Non è possibile ripondere alla domanda per cui un’istanza ha risposto in un determinato range temporale (vedi paragrafo successivo “Analisi risposta server nel range temporale”);

Il Query Store è pensato principalmente per operare del tuning sui comandi e vedere le regressioni di essi, ma non permette di governare appieno l’istanza in quanto non risponde alle problematiche sopra esplicitate.

Un cambio di approccio nella gestione del problema

Quando viene segnalata una lentezza, generalmente questa accade per più minuti consecutivi, fino a quando si sblocca. Andando a fare una fotografia dei comandi in running ogni 1 minuto è possibile individuare con buona precisione quali erano i comandi in corso in quei minuti, verificare se gli stessi comandi sulla baseline dei giorni precedenti e la concomitanza di essi con altri comandi.

Altri esempi di registrazioni

Rilevazione dei blocchi

Dalla figura sopra, si nota che la colonna “blocking_sessioni_id” è diversa da 0. Alle 5.01 del 30/06/2023 la session_id=127 sta bloccando altre sessioni_id. Questo permette di comprendere se i comandi vanno lunghi a causa di blocchi e non a causa di lentezza dell’istanza SQL Server e\o di problemi hardware.

Comandi più invasivi nelle istanze

I comandi più invasivi per un’istanza possono essere presi con le dynamic views di SQL Server (sys.dm_exec_query_stats) e sono anche interfacciate dai report di SQL Server Management Studio.

Queste estrazioni però vengono fatte dall’avvio dell’istanza oppure da quando si resetta la cache di SQL Server.

Utilizzando le registrazioni delle fotografie ogni 1 minuto, si possono invece interrogare dei range temporali ben precisi.

Il comando sopra estrae tutte le volte che ci sono state più di 10 righe in running nello stesso minuto di registrazione con durata di più di 5 secondi. A livello di parametri ogni istanza\database potrà tarare delle soglie che sono soglie di Alert ovvero situazioni nelle quali si è verificato un problema per cui oltre una certa capacità l’istanza SQL Server inizia ad accodare e rispondere con tempi più lunghi a causa di blocchi oppure di termine delle risorse hardware.

Il risultato nella figura sopra, mostra ad esempio che nella fascia oraria delle 20:47 del giorno 30/6 ci sono state situazioni di blocchi prolungati.

Statement più invasivi nelle stored

A volte l’analisi degli execution plan assegna percentuali alte di utilizzo a degli statement che sono meno invasivi di quelli che realmente rimangono in esecuzione per più tempo all’interno di una sequenza di comandi chiamati da una stored procedure.

Ad esempio nel plan della figura sopra il primo statement occupa il 3%, mentre il secondo il 97%.

Può accadere che il comando al 3% è quello che si vede come “Select T.CfeOPR…” della figura sopra ovvero scoprire che nonostante l’exec plan lo indichi come il meno invasivo è quello su cui è necessario fare il tuning in quanto è quello che rimane in corso per più tempo.

Analisi risposta server nel range temporale

La metodologia di registrazione ogni 1 minuto dei comandi in running, prevede anche di registrare sempre una riga anche se non ci sono comandi in running, marcata con “cmd=UTIL_EXEC_TRACE”. Analizzando la figura sopra, si vede che c’è un buco di registrazione alle 17:44. Questo significa che probabilmente l’istanza in quella fascia oraria non ha risposto entro 1 minuto. Allargando la ricerca sui comandi in corso si può comprendere se questo era dovuto ad un eccessivo carico dell’istanza.

Scelta dell’istanza per una nuova applicazione

Prima di fare il delivery di un nuovo database sull’istanza è bene indagare se questa risponde bene e le fasce orarie di carico. Per farlo è possibile procedere con le indagini riportate nei paragrafi precedenti.

Situazioni di previsione di carico (esempio eventi sportivi oppure elezioni politiche)

Se è necessario che gli utenti abbiano il sistema disponibile in una fascia oraria di lavoro insolita e\o dedicata alla maintenance è bene fare una query nella stessa fascia oraria la settimana precedente e capire quali sono i comandi che girano, da quali macchine e da quali applicazioni vengono chiamati, sfruttando la baseline delle registrazioni precedenti. Questo permette di analizzare in modo semplice il carico dell’istanza SQL Server e capire se ci possono essere situazioni di blocco in tale fascia oraria causati da maintenance piuttosto che attività batch che in tal caso andranno rischedulate.

Applicazioni fuori controllo da parte degli sviluppatori\amministratori

Con il comando sopra si estraggono tutte le rilevazioni dei comandi “’pp_Get%128%’” ed il risultato mostrerà da quali macchine e programmi viene fatta la chiamata nonché i tempi di esecuzione. Paragonando i tempi di esecuzione su una baseline dei giorni precedenti, si riesce anche a comprendere in modo semplice eventuali degradi di perfromance.

Verifiche post tuning

Una volta fatto tuning su un comando è semplice ricercare il comando ad una TimeStamp successivo a quello in cui è stato fatto il rilascio del tuning.

Analisi del carico ai fini di tuning

Analizzando il carico ed in particolare le colonne “[reads],[writes],[logical_reads]” si dovrebbe comprendere i comandi più invasivi che eventualmente necessitano di tuning e\o revisione del design e\o dell’implementazione. Questo approfondimento è importante per comprendere se il problema è causato da un sottodimensionamento hardware.

Inserimento di nuove schedulazioni

Osservando la baseline dei giorni precedenti si capisce quale è l’orario dove arrivano più chiamate all’istanza.

Conclusioni

Dopo aver visto i vari esempi di analisi dei comandi registrati e l’utilità degli stessi, si può orientarsi nel comprendere se la soluzione illustrata può essere utile nella propria realtà lavorativa allo scopo di rispondere in modo semplice alle varie necessità che emergono “day by day” sulle istanze\database SQL Server amministrati. Viene riportato di seguito uno script che implemeta l’estrazione dei comandi in running nel caso si volesse costruire una propria soluzione. In alternativa è anche possibile utilizzare il servizio FREE scaricabile su www.sqleasymonityor.com . La documentazione ed i video a supporto, riportano le istruzioni per installare ed utilizzare il servizio.

Al seguente link viene mostrata un’overview della soluzione:

Al seguente link seguente, vengono riportati in formato video dei casi simili a quelli sopra riportati.

select 
	Util_DtTimeStamp = getdate()
	,cpu_time
	,total_elapsed_time
	,cmd
	,cmdStmt
	,session_id
	,host_name
	,program_name
	,start_time
	,command
	,db
	,blocking_session_id
	,wait_type
	,last_wait_type
	,wait_time
	,wait_resource
	,login_name
	,status
	,last_request_start_time
	,last_request_end_time
	,percent_complete
	,estimated_completion_time
	,scheduler_id
	,reads
	,writes
	,logical_reads
	,row_count
	,granted_query_memory
	,query_plan		
from 
(
	select    
		r.cpu_time,
		r.total_elapsed_time,
		case r.statement_end_offset
			when -1 then NULL
				else object_name(s2.objectid, s2.dbid)
			end as cmd, 
		case r.statement_end_offset
				when -1 then s2.text
				else substring(s2.text, r.statement_start_offset/2, (r.statement_end_offset/2) - (r.statement_start_offset/2))
			end as cmdStmt,
		r.session_id,
		ss.host_name,
		ss.program_name,
		r.start_time,
		--r.status,
		r.command,
		db_name(r.database_id) as db,
		r.blocking_session_id,
		r.wait_type,
		r.last_wait_type,
		r.wait_time,
		r.wait_resource,
		ss.login_name,
		ss.status,
		ss.last_request_start_time,
		ss.last_request_end_time,
		r.percent_complete,
		r.estimated_completion_time,
		r.scheduler_id,
		r.reads,
		r.writes,
		r.logical_reads,
		r.row_count,
		r.granted_query_memory,
		s3.query_plan
	from sys.dm_exec_requests r (nolock)
		left join sys.dm_exec_sessions ss (nolock)
			on r.session_id = ss.session_id 
		cross apply sys.dm_exec_sql_text(r.sql_handle) as s2
		cross apply sys.dm_exec_query_plan (r.plan_handle) as s3
	where r.status <> 'background'
		and r.command <> 'task manager'
		and r.session_id <> @@SPID
		and r.database_id <> db_id('msdb')
	--order by r.cpu_time desc

	UNION ALL 
	--> se ci fossero processi BLOCCANTI non attivi in sys.dm_exec_requests() vengono registrati 
	SELECT cpu_time = spr.cpu,
			total_elapsed_time = 0, 
			cmd = 'CMD -  BLOCCANTE', 
			cmdStmt = cast( isnull(s2.[text],'') as varchar(4000)), 
			session_id = spr.spid, 
			[host_name] = cast(ss.host_name as varchar(128)), 
			[program_name] = cast(ss.program_name as varchar(128)), 
			start_time = '19000101', 
			command = cast(isnull(s2.objectid,'') as varchar(500)), 
			db = cast(Db_name(spr.dbid) as varchar(128)), 
			blocking_session_id = spr.blocked, 
			wait_type = cast(spr.waittype as varchar(256)), 
			last_wait_type = cast(spr.lastwaittype as varchar(256)), 
			spr.waittime, 
			wait_resource = cast(spr.waitresource as varchar(256)), 
			login_name = cast(ss.login_name as varchar(128)), 
			status = cast(ss.status as varchar(256)), 
			ss.last_request_start_time, 
			ss.last_request_end_time, 
			percent_complete = 0, 
			estimated_completion_time = 0, 
			scheduler_id = 0, 
			reads = 0, 
			writes = 0, 
			logical_reads = 0, 
			row_count = 0, 
			granted_query_memory = 0, 
			query_plan = null
	from master..sysprocesses 	spr
		cross apply sys.dm_exec_sql_text(spr.sql_handle) as s2
		LEFT JOIN sys.dm_exec_sessions ss (nolock) 
						ON spr.spid = ss.session_id 
	where spid in 
		(
			select distinct [spid] 
			from master..sysprocesses 
			where blocked=0 --> evito di prendere un bloccante che a sua volta è bloccato
				and spid in
				(
					select blocked
					from master..sysprocesses 
					where 1 = 1
						and blocked != 0
						and blocked in
						(
							select spid 
							from master..sysprocesses 			
						)
				)
		)
) as sq1
	
union all	
--> scrivo almeno 1 rek vuoto x far capire che la stored è stata eseguita
select 
	Util_DtTimeStamp = getdate()
	,cpu_time = 0
	,total_elapsed_time = 0
	,cmd = 'CMD - UTIL_EXEC_TRACE'
	,cmdStmt = ''
	,session_id = 0
	,host_name= ''
	,program_name= ''
	,start_time= '19000101'
	,command= ''
	,db= ''
	,blocking_session_id= 0
	,wait_type= ''
	,last_wait_type= ''
	,wait_time= 0
	,wait_resource= ''
	,login_name= ''
	,status= ''
	,last_request_start_time= '19000101'
	,last_request_end_time= '19000101'
	,percent_complete= 0
	,estimated_completion_time= 0
	,scheduler_id= 0
	,reads=0
	,writes=0
	,logical_reads=0
	,row_count=0
	,granted_query_memory=0
	,query_plan	=null