Visualiser les pages physiques lues par le moteur de stockage avec les évènements étendues

Voici une façon rigolote (ou non) de visualiser les pages lues par le moteur de stockage lors de l’exécution d’une requête par l’intermédiaire des X Events ou évènements étendues. Ceci m’a permis de comprendre et de vérifier le comportement du moteur de stockage lors d’un index scan (avec lecture anticipée).

Tout d’abord le script suivant va nous aider à récupérer les pages lues par le moteur de stockage avec notre requête de test :

CREATE EVENT SESSION event_physical_page_read
ON SERVER
ADD EVENT sqlserver.physical_page_read
(
ACTION (sqlserver.database_id, sqlserver.sql_text)
WHERE sqlserver.session_id = 54
)
ADD TARGET package0.asynchronous_file_target
(
SET filename = N’C:\perflogs\wait.etx’,
metadatafile = N’C:\perflogs\wait.mta’,
max_file_size = 50,
max_rollover_files = 10
)
WITH
(
  max_dispatch_latency = 1 seconds
);

Les paramètres importants sont :

- ADD EVENT sqlserver.physical_page_read : l’évènement physical_page_read du package sqlserver permet d’obtenir les informations concernant les pages lues physiquement depuis le disque
- ACTION (sqlserver.database_id, sqlserver.sql_text) : on ajoute aux informations par défaut celles concernant la base de données et le texte de la requête SQL cibles. (Ces données proviennent également du package sqlserver)
- WHERE sqlserver.session_id : seules les informations concernant nos requêtes de test nous intéressent ici. Celles-ci seront initiées depuis la session ayant une valeur d’id égale à 54.

- Le reste du script concerne la cible utilisée pour enregistrer les informations. Ici on utilise une cible avec écriture en mode asynchrone avec un fichier en guise de conteneur. Les données enregistrées y seront inscrites avec une latence d’une seconde maximum. Je ne rentre pas dans le détail de la création d’une session d’évènement étendue car ce n’est pas le sujet du billet.

Nous allons maintenant utiliser le script suivant qui exécute deux fois la même requête avec une valeur de paramètre différent de sorte que la dernière requête provoque une lecture anticipée contrairement à la première. Nous activerons dans un premier temps la lecture des statistiques IO et pour chaque requête nous initierons la session étendue event_physical_page_read nouvellement créée.

SET STATISTICS IO ON;

DBCC DROPCLEANBUFFERS;
GO

ALTER EVENT SESSION event_physical_page_read
ON SERVER STATE = START;
GO

DECLARE @id INT;
SET @id = 1;

IF EXISTS (SELECT 1 FROM T_TEST2 WHERE id LIKE  @id)
PRINT ‘1’;
GO

ALTER EVENT SESSION event_physical_page_read
ON SERVER STATE = STOP;
GO

—————————————————-

DBCC DROPCLEANBUFFERS;
GO

ALTER EVENT SESSION event_physical_page_read
ON SERVER STATE = START;
GO

DECLARE @id INT;
SET @id = 800000;

IF EXISTS (SELECT 1 FROM T_TEST2 WHERE id LIKE  @id)
PRINT ‘1’;
GO

ALTER EVENT SESSION event_physical_page_read
ON SERVER STATE = STOP;
GO

La commande STATISTICS IO TIME donne le résultat suivant :

image

… le plan d’exécution des deux requêtes sont identiques :

image

Ce dernier script permet de visualiser les données enregistrées depuis la session d’évènement étendue dans les fichiers wait.etx et wait.mta avec la DMF sys.fn_xe_file_target_read_file.

WITH XEVENT
AS
(
SELECT CAST(event_data AS XML) AS info
FROM sys.fn_xe_file_target_read_file (‘c:\perflogs\wait_*.etx’, ‘c:\perflogs\wait_*.mta’,
                                       NULL, NULL)
)
SELECT
info.value(‘(/event/@timestamp)[1]’, ‘DATETIME2′) AS [date],
info.value(‘(/event/@name)[1]’, ‘VARCHAR(50)’) AS event_name,
info.value(‘(/event/data/value)[1]’, ‘INT’) AS [file_id],
info.value(‘(/event/data/value)[2]’, ‘INT’) AS [page_id],
DB_NAME(info.value(‘(/event/action/value)[1]’, ‘INT’)) AS database_name,
info.value(‘(/event/action/value)[2]’, ‘VARCHAR(1000)’) AS sql_text
FROM XEVENT
WHERE info.exist(‘/event/data[./value != 0]’) = 1
ORDER BY sql_text, [DATE] ,page_id;

Avant de lire le résultat de la dernière requête, une précision me semble nécessaire sur le comportement du moteur de stockage face à un index scan dans le contexte de la requête exemple du billet. Un scan d’index provoque une lecture des pages de données du niveau feuille de l’index jusqu’à trouver  la valeur de la colonne id qui satisfait au prédicat de notre requête. Mais avant cela une lecture d’une ou plusieurs pages de données de niveau intermédiaire va être initiée pour établir une cartographie des pages de niveau feuille à lire. Une lecture anticipée (read-ahead) peut être alors déclenchée selon le cas. Ce type de lecture permet de lire une seule passe 64 pages contigües (512Ko) et si le nombre de pages à ramener est plus important, une planification est alors établie pour lire des blocs de pages. C’est ce que nous voulons vérifier par l’intermédiaire de la session d’évènement étendue event_physical_page_read.

icon_arrow 1ère requête :

Le résultat de la requête précédente est le suivant : (Je n’ai mis ici que les lignes qui nous intéressent. Le script ordonne les lignes par date dans l’ordre croissant)

image

On peut remarquer qu’une lecture de 8 pages (contigües qui plus est) sont effectuées à chaque fois ([579800 – 579807] et [579736 – 579743]).

La page 579800 correspond en réalité à la première page du niveau intermédiaire de l’index non cluster de la table T_TEST2. (chez moi cet index possède l’id = 2). On peut le vérifier à l’aide du script suivant :

CREATE TABLE #DBCCIND
(
PageFID INT,
PagePID INT,
IAMFID INT,
IAMPID INT,
ObjectID INT,
IndexID INT,
PartitionNumberID INT,
PartitionID BIGINT,
iam_chain_page VARCHAR(100),
PageType INT,
IndexLevel INT,
NextPageFID INT,
NextPagePID INT,
PrevPageFID INT,
PrevPagePID INT
);

INSERT #DBCCIND
EXEC(‘DBCC IND( »TEST »,  »T_TEST2 », 2)’);

SELECT *
FROM #DBCCIND
WHERE IndexLevel = 1
AND PrevPagePID = 0;

qui donne le résultat suivant  :

image

La page 579736, quant à elle, correspond à la première page de niveau feuille :

SELECT *
FROM #DBCCIND
WHERE IndexLevel = 0
AND PrevPagePID = 0;

image

>> Comme expliqué plus haut le moteur de stockage lit d’abord le niveau intermédiaire de l’index et dresse ensuite la liste des pages de niveau feuille à récupérer. L’unité de travail de SQL Server étant l’Extent (8 pages de 8K), il est normal de retrouver une lecture par bloc de 8 pages pour récupérer la page de données qui nous intéresse pour les 2 niveaux de l’index. La lecture de la première page de niveau intermédiaire suffit dans notre cas car elle permet de ramener la première page de niveau feuille qui contient la valeur de colonne id qui satisfait au prédicat de notre requête (id = 1).

 

icon_arrow 2ème requête :

Pour la 2ème requête, la valeur du  paramètre vaut 800 000. Si l’on suit le même raisonnement que tout à l’heure on peut en déduire que le moteur de stockage devra lire plus de pages de niveau intermédiaire pour retrouver la page de niveau feuille qui satisfait au nouveau prédicat. (La lecture se faisait séquentiellement en parcourant le niveau feuille de l’index).

La requête suivante récupère toutes les pages de niveau intermédiaire de l’index non cluster :

SELECT *
FROM #DBCCIND
WHERE IndexLevel = 1;

qui donne le résultat suivant :

image

Avec la commande DBCC PAGE on peut constater que le moteur de stockage doit lire séquentiellement toutes les pages de niveau feuille jusqu’à la page 579961 pour satisfaire notre prédicat. (id = 800 000 est bien compris entre les valeurs de clé 799496 et 800035 . cf ci-dessous).

DBCC TRACEON(3604);
GO
DBCC PAGE(‘TEST’, 1, 579961, 3);

Le résultat est le suivant :

image

Est ce que l’on retrouve cette page dans la liste des pages lues physiquement par le moteur de stockage ? En utilisant le script qui utilise la DMF sys.fn_xe_file_target_read_file on constate que c’est le cas. On peut également vérifier que la page 579800 est présente. Chez moi c’est encore le cas.

image

Le schéma ci-dessous illustre le comportement du moteur de stockage lors du scan de l’index. 

 image

Enjoy !!

David BARBARIN (Mikedavem)
MVP SQL Server

Laisser un commentaire