Plan de maintenance Backup plus long qu'une action manuelle [Résolu]

[Glouferu]

Bonjour,

j'ai pu constater un problème intriguant sur un Server SQL 2008 (RTM) relatif au temps d’exécution des backups !
J'ai une base qui contient uniquement des vues (elle est donc très petite, seulement 6meg !)

Voici ce que je constate :

• Avec le plan de maintenance -> sauvegarde dure 1h30 en moyenne
• Avec le GUI (clic droit > Backup) -> Sauvegarde dure 4sec !

Je ne comprends pas comment cela est possible ...
Voici le code généré par le composant graphique :

Code :

1
2
3
4
5
6
7
BACKUP DATABASE [MA_BASE_VUES] TO  DISK = N'G:\SauvegardeBI\MA_BASE_VUES\MA_BASE_VUES_backup_2011_12_01_135847_1637505.bak' WITH NOFORMAT, NOINIT,  NAME = N'MA_BASE_VUES_backup_2011_12_01_135847_1637505', SKIP, REWIND, NOUNLOAD,  STATS = 10
GO
declare @backupSetId AS int
SELECT @backupSetId = position FROM msdb..backupset WHERE database_name=N'MA_BASE_VUES' AND backup_set_id=(SELECT max(backup_set_id) FROM msdb..backupset WHERE database_name=N'MA_BASE_VUES' )
IF @backupSetId IS NULL begin raiserror(N'Échec de la vérification. Les informations de sauvegarde pour la base de données «*MA_BASE_VUES*» sont introuvables.', 16, 1) end
RESTORE VERIFYONLY FROM  DISK = N'G:\SauvegardeBI\MA_BASE_VUES\MA_BASE_VUES_backup_2011_12_01_135847_1637505.bak' WITH  FILE = @backupSetId,  NOUNLOAD,  NOREWIND
GO

Avez-vous une idée ? Pouvez-vous m'orienter dans ma recherche?

Par avance,
Merci


P.S.: Je vais lancer une trace sur le server pour voir quelle commande est passé au moteur lorsque j'utilise le GUI.

[SQLpro]

Vous ne donnez que le script de l'IHM... Que faites vous manuellement ? Parce que là il y a en plus une vérification de consistance de la sauvegarde...

De plus cela peut dépendre des contrôles de l'AD effectué au niveau du compte qui effectue la sauvegarde (compte de service de l'Agent SQL d'une part et de MS SQL Server d'autre part).

A +

[Glouferu]

Bonjour SQLPro,

Alors je me suis logué avec le compte de service qui lance SQL Server sur la machine et j'ai demandé à l'aide du GUI de me sauvegarder la base VUE : résultat 4sec.
C'est aussi rapide qu'avec mon compte AD personnel

Ensuite, j'ai lancé une trace pour voir la commande exécutée par le GUI :

Code :

BACKUP DATABASE [MA_BASE_VUES] TO  DISK = N'D:\MA_BASE_VUES_01_12_2011.bak' WITH NOFORMAT, NOINIT,  NAME = N'MA_BASE_VUES-Full Database Backup', SKIP, NOREWIND, NOUNLOAD,  STATS = 10, CHECKSUM

Code :

1
2
3
4
declare @backupSetId AS int
SELECT @backupSetId = position FROM msdb..backupset WHERE database_name=N'MA_BASE_VUES' AND backup_set_id=(SELECT max(backup_set_id) FROM msdb..backupset WHERE database_name=N'MA_BASE_VUES' )
IF @backupSetId IS NULL begin raiserror(N'Échec de la vérification. Les informations de sauvegarde pour la base de données «*MA_BASE_VUES*» sont introuvables.', 16, 1) end
RESTORE VERIFYONLY FROM  DISK = N'D:\MA_BASE_VUES_01_12_2011.bak' WITH  FILE = @backupSetId,  NOUNLOAD,  NOREWIND

Je pense donc que ce n'est pas un problème de droit ni même d'option au niveau du plan de sauvegarde (d'autant plus que cette base est tellement petite qu'une vérification d'intégrité est quasiment instantané).

La différence que je vois se trouve au niveau de l'option REWIND : Options sont utilisées uniquement pour les périphériques À BANDES. S'il ne s'agit pas d'un périphérique à bandes, ces options sont ignorées.


Je suis quand même sceptique


Cdt,

[mikedavem]

On peut avoir l'historique du plan de sauvegarde avec le détail de duréée pour chaque étape ? Une capture d'écran

++

[Ptit_Dje]

Et le résultat de la query de la query suivante ?

Code :

1
2
3
4
5
6
7
8
9
10
11
12
13
 
USE msdb
go
SELECT 
  database_name
, backup_start_date
, backup_finish_date
, datediff(second, backup_start_date, backup_finish_date) AS duration_sec
, type
, user_name
FROM backupset
WHERE database_name = 'MA_BASE_VUES'
ORDER BY backup_start_date DESC

[Glouferu]

Bonjour,

j'ai utilisé la requête qui utilise la table "backupset" et les temps annoncés correspondent avec l'utilisation du GUI.

Maintenant, quand je compare les temps d’exécution des backups (avec la base msdb) et les temps de fin d'execution du plan de maintenance, nous voyons un écart significatif !

Pour exemple :

Code :

1
2
3
4
5
6
7
8
9
10
11
BASE_8 -|- 2011-12-01 17:18:56.000 -|- 2011-12-01 17:20:37.000 -|- 101 -|- D -|- NT AUTHORITY\SYSTEM
BASE_7 -|- 2011-12-01 17:18:54.000 -|- 2011-12-01 17:18:56.000 -|- 2 -|- D -|- NT AUTHORITY\SYSTEM
BASE_6 -|- 2011-12-01 17:18:53.000 -|- 2011-12-01 17:18:54.000 -|- 1 -|- D -|- NT AUTHORITY\SYSTEM
BASE_5 -|- 2011-12-01 17:18:52.000 -|- 2011-12-01 17:18:53.000 -|- 1 -|- D -|- NT AUTHORITY\SYSTEM
BASE_4 -|- 2011-12-01 17:18:39.000 -|- 2011-12-01 17:18:49.000 -|- 10 -|- D -|- NT AUTHORITY\SYSTEM
BASE_3 -|- 2011-12-01 17:12:01.000 -|- 2011-12-01 17:15:38.000 -|- 217 -|- D -|- NT AUTHORITY\SYSTEM
BASE_2 -|- 2011-12-01 15:16:04.000 -|- 2011-12-01 16:22:10.000 -|- 3966 -|- D -|- NT AUTHORITY\SYSTEM
MA_BASE_VUE -|- 2011-12-01 15:16:03.000 -|- 2011-12-01 15:16:04.000 -|- 1 -|- D -|- NT AUTHORITY\SYSTEM
BASE_1 -|- 2011-12-01 11:59:02.000 -|- 2011-12-01 13:47:50.000 -|- 6528 -|- D -|- NT AUTHORITY\SYSTEM
 
 -|-  -|- Total -|- 3,0075 -|-  -|- Heures

La somme des temps d’exécution des backups en seconde donne plus de 3h !


Maintenant, quand je regarde les logs d’exécution du plan de maintenance ou du Job, je vois :

Code :

1
2
3
12/01/2011 11:59:00, BackUp.Subplan_1,Success,0,MONSERVER,BackUp.Subplan_1,(Job outcome),,The job succeeded. 
The Job was invoked BY Schedule 233 (BackUp.Subplan_1). 
The last step TO run was step 1 (Subplan_1).,05:22:42,0,0,,,,0

Donc cette ligne de log dit : Backup commencé a 11h59, durée : 5h22 !

Il y a donc une différence de 2 heures entre la données de la base MSDB et les logs du job.
Cette différence serait-elle du aux restore headeron trop long ? Et non comptabilisé ?


Cdt,


P.S.: Je vais lancer les backups d'aujourd'hui avec une procédure stockée sans vérification d'intégrité.

[Ptit_Dje]

De ce que je peux voir, le resultat de la query que je vous ai donne n'est pas filtre sur la base de donnee specifique.

On peut voir que le backup de votre base de donee BASE_2 prend 3966 secondes (un peu plus d'une heure) et celui de votre DB BASE_1 (un peu moins de 2 heures).

Par contre celui de votre base: MA_BASE_VUE prend 1 seconde, ce qui est comparable a ce que vous avez lorsque vous faite un backup via le GUI.

Ce qui me fait penser qu'a chaque fois que vous executer votre plan de backup, vous backupez toute votre instance...

Pouvez vous verifier mes assumptions ?

[Glouferu]

Envoyé par Ptit_Dje

Ce qui me fait penser qu'a chaque fois que vous executer votre plan de backup, vous backupez toute votre instance...

Pouvez vous verifier mes assumptions ?

Oui, le plan de maintenance va sauvegarder toutes les bases du Serveur SQL.

La requête que vous m'avez fourni sur la table "backupset", filtré sur la base "MA_BASE_VUE" me retourne des temps de backup de 1sec par jour ! Et ce depuis des mois ... et les logs SQL montrent que cela prend beaucoup plus de temps

[Glouferu]

Envoyé par mikedavem

On peut avoir l'historique du plan de sauvegarde avec le détail de duréée pour chaque étape ? Une capture d'écran

++

Bonjour mikedavem,

voici l'imprim écran :



Du coup, mon DBA me dit que le backup pour la base MA_BASE_VUE dure environ 1h30... (en voyant ces logs)

Cdt,

[Ptit_Dje]

Envoyé par Glouferu

Oui, le plan de maintenance va sauvegarder toutes les bases du Serveur SQL.

La requête que vous m'avez fourni sur la table "backupset", filtré sur la base "MA_BASE_VUE" me retourne des temps de backup de 1sec par jour ! Et ce depuis des mois ... et les logs SQL montrent que cela prend beaucoup plus de temps

Ce qui signifie donc que le backup de votre base prend 1 seconde

Dans vos logs, du plan de maintenance, on voit bien que votre db (MA_BASE_VUE) est la 2eme sur le plan a etre backupee, le plan commancant par la db BASE_1 -> 1h30 apres que vous lanciez le plan de sauvegarde (cf la remarque de votre DBA).

Je pense que vous devriez discuter avec lui

[Glouferu]

Envoyé par Ptit_Dje

Ce qui signifie donc que le backup de votre base prend 1 seconde

Dans vos logs, du plan de maintenance, on voit bien que votre db (MA_BASE_VUE) est la 2eme sur le plan a etre backupee, le plan commancant par la db BASE_1 -> 1h30 apres que vous lanciez le plan de sauvegarde (cf la remarque de votre DBA).

Je pense que vous devriez discuter avec lui

J'en ai déjà parlé avec lui ce matin. Le problème c'est que lorsqu'il voit les logs sql (cf screenshot ci-dessus), lui me dit que la sauvegarde de MA_BASE_VUE commence à 15h16 et fini à 16h22 ... soit environ 1h15.

D'autant plus que le plan de maintenance BACKUP met bien 5h22 à s'executer alors que le cumule des temps de sauvegarde base par base nous dit que les sauvegarde ont durées un peu plus de 3 heures.

Il y aurait donc d'après lui, 2h pendant lesquelles le plan de maintenance fait quelque chose... sans vraiment savoir quoi


Cdt

[Ptit_Dje]

de 11:59 a 13:47, c'est flou...

13:47 c'est le backup de la db BASE_1 (complete a 50%)
15:16 c'est le backup de la db BASE_1 fini
1H30 + ou - pour faire 50%

13:47 - 1:30 = + ou - 12:15
Ca peut plus ou moins correspondre avec le debut de le backup de votre BASE_1.

A verifier si votre plan de maintenance n'a pas d'autres taches, ca doit correspondre grosso-modo a cela.


De 15:16 a 16:22 c'est les premiers 50% de backup de la base_2.

Bon week-end !

[Glouferu]

Merci beaucoup pour vos réponses, je vais essayer de lui en parler...

Bon weekend a tous

[mikedavem]

Eventuellement que vous donne la requête suivante : (On pourra peut être voir la tâche qui vous pose problème)
Remplacez 'MaintenancePlan' par le nom de votre plan de maintenance

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
SELECT 
 p.name AS plan_name,
 sp.subplan_name,
 spl.start_time AS plan_start_time,
 spl.end_time AS plan_end_time,
 spld.succeeded,
 spld.line1 AS description_sub_plan,
 spld.start_time AS task_start_time,
 spld.end_time AS task_end_time
FROM msdb.dbo.sysmaintplan_plans p 
INNER JOIN msdb.dbo.sysmaintplan_subplans sp 
ON p.id = sp.plan_id 
INNER JOIN msdb.dbo.sysmaintplan_log spl 
ON sp.subplan_id = spl.subplan_id 
INNER JOIN msdb.dbo.sysmaintplan_logdetail AS spld
 ON spl.task_detail_id = spld.task_detail_id
WHERE p.name = 'MaintenancePlan'
 AND spl.start_time = (SELECT MAX(spl.start_time)
		     FROM msdb.dbo.sysmaintplan_plans p 
		     INNER JOIN msdb.dbo.sysmaintplan_subplans sp 
		      ON p.id = sp.plan_id 
                               INNER JOIN msdb.dbo.sysmaintplan_log spl 
		      ON sp.subplan_id = spl.subplan_id 
		     WHERE p.name = 'MaintenancePlan')

++

[Glouferu]

Envoyé par mikedavem

Eventuellement que vous donne la requête suivante : (On pourra peut être voir la tâche qui vous pose problème)
Remplacez 'MaintenancePlan' par le nom de votre plan de maintenance

Code :

++

Bonjour Mikedavem,

Ta requête me remonte exactement le même descriptif que je peux avoir au niveau des logs sur les plan de maintenance (pas au niveau des jobs).
Elle m'indique que le subplan "Back Up Database Task (mon_serveur)" a durée 5h21.

Typiquement, ce qui m’embête c'est que je suis incapable d'expliquer a mon DBA et mes responsables pourquoi entre la fin du backup "MA_BASE_VUE" et "BASE_2 il y a autant de temps qui s'écoule (car logiquement, une fois un base sauvegardée, il passe à la suivante).

-> Pour moi ce comportement doit pouvoir s'explique par la commande RESTORE HEADERON. Mais cette dernière ne devrait pas durer 1h30 sur une base de 5meg.
Je pense donc que le RESTORE HEADERON a lieu sur la base "BASE_1" pendant la sauvegarde de la base "MA_BASE_VUE".

Mikedavem, connais-tu une instruction permettant d'avoir un suivi ou un historique de l'instruction RESTORE HEADERON ?

En outre, je vais désactiver l'option de vérification des fichiers de backup pour voir si ces temps transitoires disparaissent.


Encore Merci.

Cdt,
Glouferu.

[mikedavem]

Ok.

Vous pouvez utiliser la requête suivante pour voir la progression de votre RESTORE VERIFYONLY :

Code :

1
2
3
SELECT command, STATUS, percent_complete, start_time, total_elapsed_time / 1000 AS total_elapsed_time_second
FROM sys.dm_exec_requests
WHERE command LIKE 'restore%'

PS : Vous pouvez aussi alimenter une table de travail via cette requête si vous vous lancer cela dans un job par exemple. Il ne vous restera plus qu'à extraire les informations de la table de travail en question.

++

[Ptit_Dje]

Envoyé par Glouferu

Typiquement, ce qui m’embête c'est que je suis incapable d'expliquer a mon DBA et mes responsables pourquoi entre la fin du backup "MA_BASE_VUE" et "BASE_2 il y a autant de temps qui s'écoule (car logiquement, une fois un base sauvegardée, il passe à la suivante).

C'est remonte avec la query suivante que vous avez execute:

Code :

1
2
3
4
5
6
7
8
9
10
11
12
USE msdb
go
SELECT 
  database_name
, backup_start_date
, backup_finish_date
, datediff(second, backup_start_date, backup_finish_date) AS duration_sec
, type
, user_name
FROM backupset
--WHERE database_name = 'MA_BASE_VUES'
ORDER BY backup_start_date DESC

Et vos resultats:

BASE_2 -|- 2011-12-01 15:16:04.000 -|- 2011-12-01 16:22:10.000 -|- 3966 -|- D -|- NT AUTHORITY\SYSTEM
MA_BASE_VUE -|- 2011-12-01 15:16:03.000 -|- 2011-12-01 15:16:04.000 -|- 1 -|- D -|- NT AUTHORITY\SYSTEM

On voit que le backup de votre BASE_2 commence a la fin de votre backup de la base MA_BASE_VUE.
Il faut pas chercher plus loin.

[mikedavem]

Votre problème se trouve plus entre les sauvegardes des bases BASE_1 et MA_BASE_VUE. Mais ce n'est pas vraiment un problème en soi.

La sauvegarde de votre base de données BASE_1 prend environ 1h47 si je regarde vos logs (2011-12-01 11:59:02.000 -|- 2011-12-01 13:47:50.000). Si vous avez activer l'option "vérification de la sauvegarde" le temps passé entre cette sauvegarde et la suivante MA_BASE_VUE peut être normal. (2011-12-01 13:47:50.000 - 2011-12-01 15:16:03.000 soit 1H30 gross modo). C'est à ce moment là où votre plan de maintenance prend du temps.

La base de données BASE_2 prend du temps apparement sur la sauvegarde et la vérification (si cette option est activée encore une fois). 2011-12-01 15:16:04.000 -|- 2011-12-01 16:22:10.000 - 17:12:01.000 soit 1h15 de sauvegarde + un peu plus de 3/4h pour la vérification ... ceci semble normal à priori.

Le reste des sauvegardes + vérification s'effectuent plutôt rapidement par rapport aux 2 autres.

++

[Glouferu]

Bonjour,

j'ai désactivé la vérification d'intégrité des backups hier et voici les chiffres :

BASE_8 -|- 2011-12-05 15:34:51.000 -|- 2011-12-05 15:36:12.000 -|- 81 -|- D -|- NT AUTHORITY\SYSTEM
BASE_7 -|- 2011-12-05 15:34:49.000 -|- 2011-12-05 15:34:51.000 -|- 2 -|- D -|- NT AUTHORITY\SYSTEM
BASE_6 -|- 2011-12-05 15:34:48.000 -|- 2011-12-05 15:34:49.000 -|- 1 -|- D -|- NT AUTHORITY\SYSTEM
BASE_5 -|- 2011-12-05 15:34:47.000 -|- 2011-12-05 15:34:48.000 -|- 1 -|- D -|- NT AUTHORITY\SYSTEM
BASE_4 -|- 2011-12-05 15:34:42.000 -|- 2011-12-05 15:34:46.000 -|- 4 -|- D -|- NT AUTHORITY\SYSTEM
BASE_3 -|- 2011-12-05 15:31:47.000 -|- 2011-12-05 15:34:42.000 -|- 175 -|- D -|- NT AUTHORITY\SYSTEM
BASE_2 -|- 2011-12-05 14:26:56.000 -|- 2011-12-05 15:31:46.000 -|- 3890 -|- D -|- NT AUTHORITY\SYSTEM
MA_BASE_VUE -|- 2011-12-05 14:26:50.000 -|- 2011-12-05 14:26:56.000 -|- 6 -|- D -|- NT AUTHORITY\SYSTEM
BASE_1 -|- 2011-12-05 12:02:03.000 -|- 2011-12-05 14:26:47.000 -|- 8684 -|- D -|- NT AUTHORITY\SYSTEM

Le temps parasites proviennent bien de cette option qui n’apparaît pas clairement dans les logs.


Merci pour votre aide

Cdt,

[SQLpro]

Il est amusant de constater que ce que je vous disait dans mon post : http://www.developpez.net/forums/d11...e/#post6376068
le premier de réponse :
"Parce que là il y a en plus une vérification de consistance de la sauvegarde..."

A +