Problème étrange de performance (INSERT) sous SQL serveur 2008 R2

[flambour]

Bonjour à tous,

J'ai un problème de performance un peu étrange sur certains serveurs de production récent que je n'ai pas sur mes serveurs de tests.

Un processus faisant énormément d'INSERT consécutifs semble tourner au ralenti sur sur certains serveurs de production (très récent).
Ce même processus sur mon portable avec un SQL SERVEUR local est plus rapide !

En comparant les informations du moniteur d'activité SQL entre un serveur SQL qui fonctionne bien et ceux posant un problème de performance je remarque ceci :

• Attente de ressources : tout est ok sauf la ligne Logging qui a un temps d'attente en ms/s très important sur les serveurs SQL posant problème.
• Aucun problème au niveau du Buffer I/O

Questions :
- à quoi correspond exactement cette catégorie d'attente Logging ?
- que chercher ?
- que vérifier ?

[darkelend]

Ta base est en quel recovery model ? Full ?
Quand tu parles d'insert nombreux, c'est des insert ligne par ligne ?

[flambour]

Envoyé par darkelend

Ta base est en quel recovery model ? Full ?
Quand tu parles d'insert nombreux, c'est des insert ligne par ligne ?

- Mode recovery = Simple
- Insert ligne par ligne

[mikedavem]

Tu peux nous donner le résultat de cette requête :

Code :

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
WITH Waits AS
    (SELECT
        wait_type,
        wait_time_ms / 1000.0 AS WaitS,
        (wait_time_ms - signal_wait_time_ms) / 1000.0 AS ResourceS,
        signal_wait_time_ms / 1000.0 AS SignalS,
        waiting_tasks_count AS WaitCount,
        100.0 * wait_time_ms / SUM (wait_time_ms) OVER() AS Percentage,
        ROW_NUMBER() OVER(ORDER BY wait_time_ms DESC) AS RowNum
    FROM sys.dm_os_wait_stats
    WHERE wait_type NOT IN (
        'CLR_SEMAPHORE', 'LAZYWRITER_SLEEP', 'RESOURCE_QUEUE', 'SLEEP_TASK',
        'SLEEP_SYSTEMTASK', 'SQLTRACE_BUFFER_FLUSH', 'WAITFOR', 'LOGMGR_QUEUE',
        'CHECKPOINT_QUEUE', 'REQUEST_FOR_DEADLOCK_SEARCH', 'XE_TIMER_EVENT', 'BROKER_TO_FLUSH',
        'BROKER_TASK_STOP', 'CLR_MANUAL_EVENT', 'CLR_AUTO_EVENT', 'DISPATCHER_QUEUE_SEMAPHORE',
        'FT_IFTS_SCHEDULER_IDLE_WAIT', 'XE_DISPATCHER_WAIT', 'XE_DISPATCHER_JOIN', 'BROKER_EVENTHANDLER',
        'TRACEWRITE', 'FT_IFTSHC_MUTEX', 'SQLTRACE_INCREMENTAL_FLUSH_SLEEP',
        'BROKER_RECEIVE_WAITFOR', 'ONDEMAND_TASK_QUEUE', 'DBMIRROR_EVENTS_QUEUE',
        'DBMIRRORING_CMD', 'BROKER_TRANSMITTER', 'SQLTRACE_WAIT_ENTRIES',
        'SLEEP_BPOOL_FLUSH', 'SQLTRACE_LOCK')
    )
SELECT
    W1.wait_type AS WaitType,
    CAST (W1.WaitS AS DECIMAL(14, 2)) AS Wait_S,
    CAST (W1.ResourceS AS DECIMAL(14, 2)) AS Resource_S,
    CAST (W1.SignalS AS DECIMAL(14, 2)) AS Signal_S,
    W1.WaitCount AS WaitCount,
    CAST (W1.Percentage AS DECIMAL(4, 2)) AS Percentage,
    CAST ((W1.WaitS / W1.WaitCount) AS DECIMAL (14, 4)) AS AvgWait_S,
    CAST ((W1.ResourceS / W1.WaitCount) AS DECIMAL (14, 4)) AS AvgRes_S,
    CAST ((W1.SignalS / W1.WaitCount) AS DECIMAL (14, 4)) AS AvgSig_S
FROM Waits AS W1
    INNER JOIN Waits AS W2 ON W2.RowNum <= W1.RowNum
GROUP BY W1.RowNum, W1.wait_type, W1.WaitS, W1.ResourceS, W1.SignalS, W1.WaitCount, W1.Percentage
HAVING SUM (W2.Percentage) - W1.Percentage < 95; -- percentage threshold
GO

et celle-ci :

Code :

1
2
3
4
5
6
7
8
9
10
SELECT 
 DB_NAME(database_id) DB_NAME, file_id,io_stall_read_ms ,num_of_reads
,cast(io_stall_read_ms/(1.0+num_of_reads) AS numeric(10,1)) AS 'avg_read_stall_ms'
,io_stall_write_ms,num_of_writes 
,cast(io_stall_write_ms/(1.0+num_of_writes) AS numeric(10,1)) AS 'avg_write_stall_ms'
,io_stall_read_ms + io_stall_write_ms AS io_stalls 
,num_of_reads + num_of_writes AS total_io
,cast((io_stall_read_ms+io_stall_write_ms)/(1.0+num_of_reads + num_of_writes) AS numeric(10,1)) AS 'avg_io_stall_ms'
FROM sys.dm_io_virtual_file_stats(NULL,NULL)
ORDER BY avg_io_stall_ms DESC

++

[flambour]

Voici les résultats :

Code :

1
2
3
4
5
6
7
8
9
WaitType	Wait_S	Resource_S	Signal_S	WaitCount	Percentage	AvgWait_S	AvgRes_S	AvgSig_S
BACKUPBUFFER	36.17	34.02	2.16	4997	37.67	0.0072	0.0068	0.0004
ASYNC_IO_COMPLETION	31.85	31.85	0.00	3	33.16	10.6157	10.6157	0.0000
PAGEIOLATCH_SH	8.54	8.53	0.01	2976	8.89	0.0029	0.0029	0.0000
BACKUPIO	7.69	7.69	0.01	1331	8.01	0.0058	0.0058	0.0000
IO_COMPLETION	5.29	5.29	0.00	2311	5.51	0.0023	0.0023	0.0000
ASYNC_NETWORK_IO	0.79	0.79	0.00	82	0.82	0.0096	0.0096	0.0000
WRITE_COMPLETION	0.67	0.67	0.00	62	0.70	0.0108	0.0108	0.0000
WRITELOG	0.56	0.56	0.00	59	0.58	0.0094	0.0094	0.0000

Code :

1
2
3
4
5
6
7
8
9
10
11
12
13
DB_NAME	file_id	io_stall_read_ms	num_of_reads	avg_read_stall_ms	io_stall_write_ms	num_of_writes	avg_write_stall_ms	io_stalls	total_io	avg_io_stall_ms
Motoculture	1	63452	3502	18.1	200	27	7.1	63652	3529	18.0
msdb	2	149	22	6.5	104	6	14.9	253	28	8.7
ConnexionDMS	1	161	23	6.7	50	1	25.0	211	24	8.4
model	2	47	5	7.8	70	8	7.8	117	13	8.4
Motoculture	2	65	13	4.6	206	20	9.8	271	33	8.0
ConnexionDMS	2	9	8	1.0	98	5	16.3	107	13	7.6
tempdb	2	12	8	1.3	336	39	8.4	348	47	7.3
master	2	10	11	0.8	220	21	10.0	230	32	7.0
tempdb	1	3810	1863	2.0	9629	1709	5.6	13439	3572	3.8
model	1	182	57	3.1	27	2	9.0	209	59	3.5
master	1	384	119	3.2	13	1	6.5	397	120	3.3
msdb	1	511	173	2.9	14	1	7.0	525	174	3.0

Pour info sur un serveur SQL qui n'a pas le problème la première requête ne contient pas de ligne avec un WaitType = WRITELOG

[darkelend]

Est ce que tu as de la place disponible dans ton fichier mdf ? Quel est la taille de l'agrandissement automatique ?
Est ce que tu as d'autres choses qui tournent sur le serveur lent ? (autres requêtes/autres applis/Sauvegarde ?)

[flambour]

Envoyé par darkelend

Est ce que tu as de la place disponible dans ton fichier mdf ? Quel est la taille de l'agrandissement automatique ?
Est ce que tu as d'autres choses qui tournent sur le serveur lent ? (autres requêtes/autres applis/Sauvegarde ?)

Oui j'ai de la place, la base est correctement dimensionné, la taille de l'agrandissement automatique est de 50Mo.
Le serveur ne fait rien d'autre quand ce traitement tourne.

[flambour]

Help,

Voici les résultat après un reboot serveur SQL puis execution du fameux traitement d'import posant problème.

Code :

1
2
WaitType	Wait_S	Resource_S	Signal_S	WaitCount	Percentage	AvgWait_S	AvgRes_S	AvgSig_S
WRITELOG	39806.61	39516.84	289.77	8160627	97.48	0.0049	0.0048	0.0000

Code :

1
2
3
4
5
6
7
database_name	database_id	FILE_ID	avg_read_latency	avg_write_latency	avg_total_latency	io_stall	size_on_disk_mbytes	physical_name
msdb	4	2	10	22	20	2263	5.062500	H:\Mssql\MSSQL10_50.MSSQLSERVER\MSSQL\DATA\MSDBLog.ldf
ConnexionDMS	5	2	11	22	20	783	1.000000	H:\MSSQL\MSSQL10_50.MSSQLSERVER\MSSQL\DATA\ConnexionDMS_1.ldf
model	3	2	2	21	18	822	0.750000	H:\Mssql\MSSQL10_50.MSSQLSERVER\MSSQL\DATA\modellog.ldf
master	1	2	2	13	13	2350	1.250000	H:\Mssql\MSSQL10_50.MSSQLSERVER\MSSQL\DATA\mastlog.ldf
tempdb	2	2	4	8	8	2692	1.000000	H:\Mssql\MSSQL10_50.MSSQLSERVER\MSSQL\DATA\templog.ldf
Motoculture	6	2	1	4	4	33403726	500.000000	h:\\Mssql\\MSSQL10_50.MSSQLSERVER\\MSSQL\\DATA\\Motoculture.ldf

Il n'y a que du WRITELOG, est-ce significatif ?

[dbaffaleuf]

pour info ce thread est également suivi sur le forum MSDN:
http://social.msdn.microsoft.com/For...5-6b027f888c5c

[dbaffaleuf]

Et voir ausi du côté de ce wp de sqlcat http://msdn.microsoft.com/en-us/library/dd425070.aspx qui explique l'utilisation du TF610 pour accélérer les insert / select, vérifier les conditions d'utilisation avec le tableau "Summarizing Minimal Logging Conditions"

[elsuket]

Bonjour,

Si nous regardons la documentation de la DMV sys.dm_os_wait_stats, la description de WRITELOG est :

Se produit lors de l'attente d'un vidage du journal.Les opérations courantes qui provoquent des vidages du journal sont les points de vérification et les validations des transactions.

Ce qui signifie que la validation des INSERTs dans le ficiherdu journal des transactions n'est pas assez rapide pour supporter la vitesse des INSERT.
Ceci est validé par le chiffre que vous avez dans la colonne avg_write_latency, qui n'est pas dans la requête que vous a donné Mikedavem. Je suppose dans ce cas que votre base de données est Motoculture.

Pouvez-vous nous dire combien de lignes vous retourne DBCC LOGINFO('Motoculture'), et ce que retourne la requête suivante ?

Code :

1
2
3
4
5
6
7
8
9
10
USE Motoculture
GO
 
SELECT	name
	, physical_name
	, size * 8 AS size_KB
	, growth
	, is_percent_growth
FROM	sys.database_files
WHERE	type_desc = 'LOG'

@++

[SQLpro]

Lorsque le fichier du JT est plein à 70% un CHECKPOINT est envoyé pour forcer les écritures des pages sales dans les disques physique ceci afin de reprendre du mou dans le journal.

Agrandissez de façon drastique votre JT (20 à 30 % du volume global de la base) ou passez en mode FULL.

A +