Discussion :

[StringBuilder]

Bonjour à tous,

Je suis en phase de démarrage chez un client.

Le produit est constitué :
- D'un site sous IIS
- D'une base de données sous SQL Server
- D'une série d'outils "serveurs" en mode Windows

Attention, attachez vos ceintures :
- Un seul disque : C:
- Tout tourne sur le même serveur
- Le serveur est virtualisé

C'est bon, tout le monde est encore bien là ?

Depuis un navigateur (depuis un PC distant) je lance un traitement dans l'application Web.
Un traitement qui va générer des assortiments de produits pour des clients.
1/ Je sélectionne 200 produits
2/ Je sélectionne 200 clients
3/ Je clique sur un bouton

Et c'est censé me créer pour chacun des 200 clients un listing de référencement contenant les 200 produits, soit 40 000 lignes.

Une paille pour SQL Server.
Une paille pour une application codée en C#.

Croyais-je.

Au bout de 30 minutes, timeout.

Hmpf.

Je relance, je regarde le gestionnaire des tâches :
- w3wp.exe : 11% du CPU
- sqlservr.exe : 12% du CPU

Sâchant que le CPU est un quad core, aucun coeur ne tourne à 100%, puisque même si IIS et SQL Server tournaient sur le même core (ce qui n'est pas le cas) ils ne boufferaient pas 25% à eux deux.

Bon, alors... réseau : tout est en local, rien à déclarer.

Mémoire : on est large, 2 Go de libre sur 8 Go. Rien à déclarer.

Disque dur : temps d'accès de 1 à 2 ms, pour des lectures/écritures de 30 ko/s... Hmmmm, étrange quand même que ce soit aussi lent...

Les fichiers utilisés sont :
LDF : 30 ko/s
MDF : pour ainsi dire rien du tout
"FlightPlan" (dans un dossier de SQL Server, je découvre) : 30 ko/s

Et le reste c'est epsilon.

Je change le mode de recovery de "full" à "simple", espérant limiter les écritures dans le LDF. Même combat, ça plante au bout de 30 minutes.

Je relance en divisant par deux la volumétrie à traiter.
Cette fois, pas de plantage.
Et là, j'observe quelque chose d'étrange : le LDF arrête tout d'un coup d'être sollicité (juste un peu de lecture), et le MDF patine à 300 ko/s
Soit 10 fois plus rapide que le LDF

Même si ça reste des performances dignes d'un disque des années 80, le fait que selon l'étape de la transaction, on multiplie la vitesse d'accès au disque par 10 m'amène à me poser la question suivante :
- Puis-je en déduire que le goulot d'étranglement vient de l'unité de disque ? Comment le démontrer ?

Si je fais un backup de la base ou du journal (sur le même disque), la vitesse d'écriture est de 600 ko/s

Sur le même serveur de virtualisation, et surtout, sur la même baie de disques, on retrouve d'autres SQL Server (notamment celui de l'ERP ainsi que celui du WMS), qui ne semblent pas poser de problèmes de performances...

Outre l'application qui est complètement pourrie (40 000 insertions + update au lien d'un simple merge résultant d'une produit cartésien entre produits et clients sélectionnés), quelles autres pistes puis-je suivre ?

En fait, je ne m'explique pas que le CPU se tourne les pouces pendant que le disque ne semble pas spécialement sollicité non plus... L'application fait quoi pendant tout ce temps ?

[François M.]

Bonjour

Il faudrait un peu plus de précisions sur la façon dont l'applicatif procède.

- Comment se fait l'accès à la base (PS, ORM, requêtes dans le code ?)
- Combien de transactions pour l'insertion des 40 kLignes ? Une seule ? plusieurs ?

[SQLpro]

1) Commence par dimensionner correctement tes fichiers => 10 Go pour le mdf et 2 Go pour le ldf...
2) donne à SQL Server 60% de la RAM (sp_configure max server memory)

A +

[François M.]

2) donne à SQL Server 60% de la RAM (sp_configure max server memory)

Le serveur n'est pas dédié à l'instance SQL SERVER.

[bvesan]

L'application fait quoi pendant tout ce temps ?

On ne peut pas facilement savoir ce que fait l'appli, mais on peut assez facilement savoir si elle passe beaucoup de temps en base, et de connaître la répartition du temps passé en base.
Grâce au événements d'attente dans SQL Server, il va être possible de disposer de toutes ces infos.

Si vous êtes déjà familiarisé avec le concept d'Attentes, regardez l'évolution des attentes dans sys.dm_os_waiting_tasks et sys.dm_os_wait_stats.
Sinon, j'ai rédigé un article qui expose le sujet: Les Attentes dans SQL Server

[mikedavem]

Ce que tu peux faire c'est commencer par une approche globale en regardant où SQL Server attend de manière générale pendant ton traitement.


Tu réinitialises tes attentes (si possible bien sûr), tu lances ton traitement et tu récupères tes attentes une fois ton traitement fini. Si tu ne peux pas réinitialiser les attentes tu prends un snapshot avant, un snapshot après et tu fais récupères la différence.

Pour les attentes tu peux utiliser ce script:

Code :

Sélectionner tout - Visualiser dans une fenêtre à part

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
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
 
 
-- A exécuter si tu peux réinitialiser les attentes sur le serveur
--DBCC SQLPERF('sys.dm_os_wait_stats', 'clear');
--GO
 
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 (
        N'BROKER_EVENTHANDLER',             N'BROKER_RECEIVE_WAITFOR',
        N'BROKER_TASK_STOP',                N'BROKER_TO_FLUSH',
        N'BROKER_TRANSMITTER',              N'CHECKPOINT_QUEUE',
        N'CHKPT',                           N'CLR_AUTO_EVENT',
        N'CLR_MANUAL_EVENT',                N'CLR_SEMAPHORE',
        N'DBMIRROR_DBM_EVENT',              N'DBMIRROR_EVENTS_QUEUE',
        N'DBMIRROR_WORKER_QUEUE',           N'DBMIRRORING_CMD',
        N'DIRTY_PAGE_POLL',                 N'DISPATCHER_QUEUE_SEMAPHORE',
        N'EXECSYNC',                        N'FSAGENT',
        N'FT_IFTS_SCHEDULER_IDLE_WAIT',     N'FT_IFTSHC_MUTEX',
        N'HADR_CLUSAPI_CALL',               N'HADR_FILESTREAM_IOMGR_IOCOMPLETION',
        N'HADR_LOGCAPTURE_WAIT',            N'HADR_NOTIFICATION_DEQUEUE',
        N'HADR_TIMER_TASK',                 N'HADR_WORK_QUEUE',
        N'KSOURCE_WAKEUP',                  N'LAZYWRITER_SLEEP',
        N'LOGMGR_QUEUE',                    N'ONDEMAND_TASK_QUEUE',
        N'PWAIT_ALL_COMPONENTS_INITIALIZED',
        N'QDS_PERSIST_TASK_MAIN_LOOP_SLEEP',
        N'QDS_CLEANUP_STALE_QUERIES_TASK_MAIN_LOOP_SLEEP',
        N'REQUEST_FOR_DEADLOCK_SEARCH',     N'RESOURCE_QUEUE',
        N'SERVER_IDLE_CHECK',               N'SLEEP_BPOOL_FLUSH',
        N'SLEEP_DBSTARTUP',                 N'SLEEP_DCOMSTARTUP',
        N'SLEEP_MASTERDBREADY',             N'SLEEP_MASTERMDREADY',
        N'SLEEP_MASTERUPGRADED',            N'SLEEP_MSDBSTARTUP',
        N'SLEEP_SYSTEMTASK',                N'SLEEP_TASK',
        N'SLEEP_TEMPDBSTARTUP',             N'SNI_HTTP_ACCEPT',
        N'SP_SERVER_DIAGNOSTICS_SLEEP',     N'SQLTRACE_BUFFER_FLUSH',
        N'SQLTRACE_INCREMENTAL_FLUSH_SLEEP',
        N'SQLTRACE_WAIT_ENTRIES',           N'WAIT_FOR_RESULTS',
        N'WAITFOR',                         N'WAITFOR_TASKSHUTDOWN',
        N'WAIT_XTP_HOST_WAIT',              N'WAIT_XTP_OFFLINE_CKPT_NEW_LOG',
        N'WAIT_XTP_CKPT_CLOSE',             N'XE_DISPATCHER_JOIN',
        N'XE_DISPATCHER_WAIT',              N'XE_TIMER_EVENT')
    AND [waiting_tasks_count] > 0
 )
SELECT
    MAX ([W1].[wait_type]) AS [WaitType],
    CAST (MAX ([W1].[WaitS]) AS DECIMAL (16,2)) AS [Wait_S],
    CAST (MAX ([W1].[ResourceS]) AS DECIMAL (16,2)) AS [Resource_S],
    CAST (MAX ([W1].[SignalS]) AS DECIMAL (16,2)) AS [Signal_S],
    MAX ([W1].[WaitCount]) AS [WaitCount],
    CAST (MAX ([W1].[Percentage]) AS DECIMAL (5,2)) AS [Percentage],
    CAST ((MAX ([W1].[WaitS]) / MAX ([W1].[WaitCount])) AS DECIMAL (16,4)) AS [AvgWait_S],
    CAST ((MAX ([W1].[ResourceS]) / MAX ([W1].[WaitCount])) AS DECIMAL (16,4)) AS [AvgRes_S],
    CAST ((MAX ([W1].[SignalS]) / MAX ([W1].[WaitCount])) AS DECIMAL (16,4)) AS [AvgSig_S]
FROM [Waits] AS [W1]
INNER JOIN [Waits] AS [W2]
    ON [W2].[RowNum] <= [W1].[RowNum]
GROUP BY [W1].[RowNum]
HAVING SUM ([W2].[Percentage]) - MAX ([W1].[Percentage]) < 95; -- percentage threshold
GO

Edit : Désolé Benjamin, je n'avais pas vu que tu avais posté avant moi .. donc cela fait un peu doublon

++

[StringBuilder]

Merci pour toute vos réponses.

Je vais potasser tout ça

Comme premiers éléments de réponse :
- Actuellement, le MDF (qui avait une croissance automatique de 1 Mo...) fait 2,4 Go. Je lui ai passé la croissance auto à 500 Mo.
- Le LDF, lui il avait jamais été sauvegardé, et faisait 42 Go... je l'ai passé à 500 Mo de croissance après l'avoir tronqué (et backupé).

Sinon, tout se fait visiblement dans une seule transaction, puisqu'au bout d'une demi-heure (timeout), aucune donnée n'est en base.
En revanche, 60000 lignes = 60000 insert (plus certainement des update, select et autres joyeusetés)
Les requêtes sont jouées directement depuis le code.
La base de données est accédée avec le drivers OLEDB.
Après redémarrage de l'instance (TEMPDB faisait 40 Go, en croissance 1 Mo à partie de 10 Mo...) SQL Server n'occupait plus que 25% de la mémoire (2 Go). Avant le redémarrage du service, il en bouffait 75% (6 Go) mais il y avait encore pas mal de RAM libre (dans les 1 Go).

Malgré toutes ces abérations, que j'ai corrigé, rien ne change aux perfs, c'est toujours aussi lent...

Je vais ingurgiter vos pistes, et reviens vers vous

[François M.]

Les requêtes sont jouées directement depuis le code.

On peut voir le code ? (la partie accès à la DB uniquement).

La base de données est accédée avec le drivers OLEDB.

Pourquoi ce choix plus que bizarre ? (pour du code .NET accèdant à SQl Server, c'est absurde).

Après redémarrage de l'instance (TEMPDB faisait 40 Go, en croissance 1 Mo à partie de 10 Mo...) SQL Server n'occupait plus que 25% de la mémoire (2 Go). Avant le redémarrage du service, il en bouffait 75% (6 Go) mais il y avait encore pas mal de RAM libre (dans les 1 Go).

Si tempdb monte à 40 Go, faire des accroissements par 1Mo est débile .... (par ailleurs vérifier que le compte de service SQL SERVER possède le privilège SE_MANAGE_VOLUME_NAME ce qui permet d'accroitre la vitesse des accroissements, en ne mettant pas à 0 binaire les accroissements disque du MDF de la tempdb).

Malgré toutes ces abérations, que j'ai corrigé, rien ne change aux perfs, c'est toujours aussi lent...

Poste le code qui fait les requêtes SQL.

[SQLpro]

.... Je lui ai passé la croissance auto à 500 Mo.
.... je l'ai passé à 500 Mo de croissance après l'avoir tronqué (et backupé).

NON, NON, NON et NON ! Il faut éviter toute opération de croissance pendant les transactions. Donc taille correctement tes fichiers dès le départ POUR N'AVOIR JAMAIS AUCUNE OPÉRATION DE CROISSANCE pendant la durée de vie de la base !



Sinon, tout se fait visiblement dans une seule transaction, puisqu'au bout d'une demi-heure (timeout), aucune donnée n'est en base.
En revanche, 60000 lignes = 60000 insert (plus certainement des update, select et autres joyeusetés)
[/QUOTE]Désactive les index non sémantiques avant et réactive les après

Les requêtes sont jouées directement depuis le code.
La base de données est accédée avec le drivers OLEDB.
Après redémarrage de l'instance (TEMPDB faisait 40 Go, en croissance 1 Mo à partie de 10 Mo...)

Même topo pour tempdb = DIMENSIONNEMENT !!!

SQL Server n'occupait plus que 25% de la mémoire (2 Go). Avant le redémarrage du service, il en bouffait 75% (6 Go) mais il y avait encore pas mal de RAM libre (dans les 1 Go).

Malgré toutes ces abérations, que j'ai corrigé, rien ne change aux perfs, c'est toujours aussi lent...

Je vais ingurgiter vos pistes, et reviens vers vous

Fixe la RAM à 5 GO

A +

[StringBuilder]

C'est du code éditeur, j'y ai pas accès... J'ai juste des DLL dans mon dossier web

Mais y'a rien dans la base de données au niveau PS, donc c'est forcément le code qui fait ça.

Quant aux choix bizarres, on n'est plus à ça près, tu peux me croire
Le choix de OLEDB doit venir du fait que l'application peut aussi bien travailler avec SQL Server qu'Oracle.
Et visiblement, les développeurs ne connaissent pas les interfaces IConnection, ICommand, IDataReader, ... et ont donc décidé d'utiliser les objets OleDb*... une ânerie parmi tant d'autres...

Voici ce que donne la requête de mikedavem, mais je sais pas comment l'interpréter.

Code :

Sélectionner tout - Visualiser dans une fenêtre à part

1
2
3
4
5
6
7
8
9
10
11
 
WaitType                                                     Wait_S                                  Resource_S                              Signal_S                                WaitCount            Percentage                              AvgWait_S                               AvgRes_S                                AvgSig_S
------------------------------------------------------------ --------------------------------------- --------------------------------------- --------------------------------------- -------------------- --------------------------------------- --------------------------------------- --------------------------------------- ---------------------------------------
OLEDB                                                        1369.72                                 1369.72                                 0.00                                    163210               31.95                                   0.0084                                  0.0084                                  0.0000
LCK_M_S                                                      1234.10                                 1234.10                                 0.00                                    6                    28.79                                   205.6827                                205.6825                                0.0002
MSQL_DQ                                                      521.85                                  521.85                                  0.00                                    5564                 12.17                                   0.0938                                  0.0938                                  0.0000
PREEMPTIVE_COM_QUERYINTERFACE                                521.83                                  521.83                                  0.00                                    5564                 12.17                                   0.0938                                  0.0938                                  0.0000
WRITELOG                                                     308.47                                  298.46                                  10.02                                   334228               7.20                                    0.0009                                  0.0009                                  0.0000
PAGEIOLATCH_SH                                               155.06                                  154.86                                  0.20                                    44001                3.62                                    0.0035                                  0.0035                                  0.0000
 
(6*ligne(s) affectée(s))

Sinon, pour les tailles, j'ai tout passé en dur, avec des valeurs fortes pour l'agrandissement le jour où.

[StringBuilder]

Ceci dit, plus le temps passe, et plus je me dis que les optimisations possibles sont dans la main de l'éditeur...

Pendant mon benchmark, le programme d'import m'a recopié des données d'un ERP dans des tables (autrement pus complexe), et le disque s'est affolé avec une vitesse brute de 300 Mo/s pendant quelques instants... On est loin des pauvres 30 Ko/s qui pataugent de mon process... C'est donc pas SQL Server qui galère, mais bien en amont, l'application web...

[François M.]

Ceci dit, plus le temps passe, et plus je me dis que les optimisations possibles sont dans la main de l'éditeur.....

Il est hautement probable que les accès à la DB soient codés avec les pieds.

[mikedavem]

Il est hautement probable que les accès à la DB soient codés avec les pieds.

Fort probable vu les types d'attentes récupérés ici

Est-ce que ce sont des requêtes distribués effectués sur ce serveur via un serveur lié ? Les types attentes PREEMPTIVE_COM_QUERYINTERFACE et MSQL_DQ tendent à penser que oui. Par ailleurs tu as visiblement des temps d'attentes importants sur LCK_M_S et je pense que ton problème se situe ici (blocages intempestifs) et il faut chercher la cause (lock escalation, mauvais design de requêtes, ...).

Tu peux déjà essayer par identifier les ressources associées au verrouillage en utilisant la requête suivante pendant l'exécution de ta requête:

Code :

Sélectionner tout - Visualiser dans une fenêtre à part

1
2
3
4
5
6
select * 
from 
sys.dm_os_waiting_tasks t
inner join sys.dm_exec_connections c 
 on c.session_id = t.blocking_session_id
cross apply sys.dm_exec_sql_text(c.most_recent_sql_handle) as h1

++

[StringBuilder]

J'ai pas pu vider les stats avant (en fait, je sais pas faire).

Et le programme d'import qui récupère des données d'un ERP le fait par l'intermédiaire d'une vue sur une série de serveurs lié (y'a 5 serveurs d'ERP répartis à travers le monde, et la vue tape sur les 5), d'où les délais d'attente liés au réseau. Mais c'est hors contexte, dans mon traitement je ne touche qu'à des tables locales.

[mikedavem]

Tu peux réinitailiser comme cela:

Code :

Sélectionner tout - Visualiser dans une fenêtre à part

1
2
DBCC SQLPERF('sys.dm_os_wait_stats', 'clear');
GO

++

[StringBuilder]

Fort probable vu les types d'attentes récupérés ici

Est-ce que ce sont des requêtes distribués effectués sur ce serveur via un serveur lié ? Les types attentes PREEMPTIVE_COM_QUERYINTERFACE et MSQL_DQ tendent à penser que oui. Par ailleurs tu as visiblement des temps d'attentes importants sur LCK_M_S et je pense que ton problème se situe ici (blocages intempestifs) et il faut chercher la cause (lock escalation, mauvais design de requêtes, ...).

Tu peux déjà essayer par identifier les ressources associées au verrouillage en utilisant la requête suivante pendant l'exécution de ta requête:

Code :

Sélectionner tout - Visualiser dans une fenêtre à part

1
2
3
4
5
6
select * 
from 
sys.dm_os_waiting_tasks t
inner join sys.dm_exec_connections c 
 on c.session_id = t.blocking_session_id
cross apply sys.dm_exec_sql_text(c.most_recent_sql_handle) as h1

++

La requête ne retourne rien.

Ça semble conforter mon analyse : en fait, c'est pas SQL Server qui patine, ni les accès à la base, mais l'application en amont... Reste à comprendre maintenant pourquoi IIS ne consomme pas plus de CPU... Il bouffe pas non plus de RAM et ne fait aucun accès disque... Y'a des boucles de wait() ou quoi ?

[StringBuilder]

Ca fait 10-15 minutes que le process tourne :

Code :

Sélectionner tout - Visualiser dans une fenêtre à part

1
2
3
4
5
6
7
8
 
WaitType                                                     Wait_S                                  Resource_S                              Signal_S                                WaitCount            Percentage                              AvgWait_S                               AvgRes_S                                AvgSig_S
------------------------------------------------------------ --------------------------------------- --------------------------------------- --------------------------------------- -------------------- --------------------------------------- --------------------------------------- --------------------------------------- ---------------------------------------
WRITELOG                                                     23.39                                   22.60                                   0.79                                    23085                82.92                                   0.0010                                  0.0010                                  0.0000
SOS_SCHEDULER_YIELD                                          1.98                                    0.18                                    1.81                                    66692                7.02                                    0.0000                                  0.0000                                  0.0000
ASYNC_NETWORK_IO                                             1.80                                    0.83                                    0.97                                    32023                6.37                                    0.0001                                  0.0000                                  0.0000
 
(3*ligne(s) affectée(s))

J'ai essayé, pour le fun, de lancer un 7zip sur un fichier de 500 Mo pour solliciter le disque et le CPU.
Ca n'a rien changé :
- au temps CPU de w3wp.exe
- au temps CPU de sqlservr.exe
- au débit disque dans le LDF

Bref, ce programme passe son temps à roupiller...

[aieeeuuuuu]

Bonjour,

Moi je vois bien la chose comme ceci :

deux boucles imbriquées (une pour les clients, une pour les produits) qui génèrent donc 200 * 200 = 40000 requêtes.
Le fin du fin, tout ceci est sans doute englobé dans une transaction gérée coté client.

du coup, le temps passé est essentiellement perdu dans les overhead dus a tout ces échanges réseau (même si c'est physiquement sur la même machine).
Ce qui explique que ni la cpu coté appli, ni celle coté BDD ne soit trop sollicitée : au final tout le monde passe son temps à attendre tout le monde !

[François M.]

Bonjour

@STringBuilder :

Peux tu poster le DLL des trois tables utilisées ?
Comment est générée la liste de produits par client ? (sur quelles règles ? y-a-t-il des appels externes faits pour établir cette liste ? en effet, on imagine mal un programme dont le boulot soit uniquement de faire un produit cartésien vers une autre table).

[mikedavem]

Les types d'attentes et temps associées liées à ta requête / batch ne donne effectivement rien de significatif côté SQL Server.
Je pencherai également vu de loin pour un mauvais design côté applicatif pour le coup

++