Archive

Posts Tagged ‘profiling’

[@dbnewz] Comment examiner le profile de vos requêtes ?

April 6th, 2011 3 comments

L’excellent article de dbnewz sur le SQL_NO_CACHE m’a donné l’idée de faire un complément, non pas sur les caches, mais sur un outil permettant d’obtenir des informations sur les ressources consommées par les requêtes, le méconnu show profiles.

Quel rapport avec les caches ? simplement, cet outil vous permet de visualiser toutes les étapes permettant l’exécution des requêtes, et notamment, visualiser si le cache de requête est utilisé.

Pour activer l’outil, rien de plus simple, au niveau de votre session mysql, il suffit simplement d’activer le profiling : set profiling = 1;

Pour les besoins de l’article, j’ai crée deux tables, une InnoDB et une MyISAM :

  • create table test_profile_myisam (id int auto_increment, randomtext varchar(255), primary key (id)) engine=MyIsam;
  • create table test_profile_innodb (id int auto_increment, randomtext varchar(255), primary key (id)) engine=InnoDB;

 

Exemple 1 : select count(*) from table

C’est un exemple intéressant, car un count(*) sur MyISAM est complètement indépendant du fichier de données (.MYD) puisque le nombre de lignes est lu directement dans le fichier descripteur de la table (.frm). Opération rendu possible grâce au verrouillage au niveau de la table de ce moteur.

Le profiling permet ici de constater qu’en effet, une telle commande ne déclenche pas les mêmes actions avec MyISAM et InnoDB :

mysql> set profiling = 1;
Query OK, 0 rows affected (0.00 sec)
mysql> select count(*) from test_profile_myisam;
+----------+
| count(*) |
+----------+
|  1288347 |
+----------+
1 row in set (0.00 sec)
mysql> select count(*) from test_profile_innodb;
+----------+
| count(*) |
+----------+
|  1288347 |
+----------+
1 row in set (2.30 sec)
La commande show profiles, permet d’avoir la liste des requêtes prises en compte par le profiler. Vous constaterez le temps d’exécution bien inférieur dans le cas de MyISAM, et ce n’est pas dû au cache puiqu’ici, j’exécute ces requêtes pour le première fois :
mysql> show profiles;
+----------+------------+------------------------------------------+ 
| Query_ID | Duration   | Query                                    | 
+----------+------------+------------------------------------------+ 
|        1 | 0.00013950 | select count(*) from test_profile_myisam | 
|        2 | 2.30376350 | select count(*) from test_profile_innodb | 
+----------+------------+------------------------------------------+
La commande show profile for query n permet d’avoir l’état d’une requête en particulier :
mysql> show profile for query 1;
+--------------------------------+----------+
| Status                         | Duration |
+--------------------------------+----------+
| starting                       | 0.000048 |
| Waiting for query cache lock   | 0.000012 |
| checking query cache for query | 0.000014 |
| checking privileges on cached  | 0.000009 |
| checking permissions           | 0.000013 |
| sending cached result to clien | 0.000031 |
| logging slow query             | 0.000007 |
| cleaning up                    | 0.000007 |
+--------------------------------+----------+
mysql> show profile for query 2;
+--------------------------------+----------+
| Status                         | Duration |
+--------------------------------+----------+
| starting                       | 0.000038 |
| Waiting for query cache lock   | 0.000009 |
| checking query cache for query | 0.000074 |
| checking permissions           | 0.000018 |
| Opening tables                 | 0.000044 |
| System lock                    | 0.000020 |
| Waiting for query cache lock   | 0.000045 |
| init                           | 0.000024 |
| optimizing                     | 0.000010 |
| statistics                     | 0.000022 |
| preparing                      | 0.000018 |
| executing                      | 0.000012 |
| Sending data                   | 2.246902 |
| end                            | 0.055784 |
| query end                      | 0.000054 |
| closing tables                 | 0.000041 |
| freeing items                  | 0.000028 |
| Waiting for query cache lock   | 0.000012 |
| freeing items                  | 0.000565 |
| Waiting for query cache lock   | 0.000016 |
| freeing items                  | 0.000005 |
| storing result in query cache  | 0.000012 |
| logging slow query             | 0.000006 |
| cleaning up                    | 0.000007 |
+--------------------------------+----------+
Vous constatez ici la différence entre MyISAM et InnoDB pour ce type de sélection particulière.
La requête sur la table MyISAM n’a pas besoin d’ouvrir la table pour la raison évoquée plus haut.
En revanche, le cache de requête étant activé, il est sollicité dans les deux cas.

 

Exemple 2 : Utilisation des caches

Pour revenir à l’article de dbnewz, voyons ce que donne le profile des requêtes suivantes :
mysql> show profiles; 
+----------+------------+------------------------------------------------------------------------------------+ 
| Query_ID | Duration   | Query                                                                              | 
+----------+------------+------------------------------------------------------------------------------------+ 
|        9 | 0.26231400 | select count(*) from test_profile_innodb where id between 456 and 876              | 
|       10 | 0.00013000 | select count(*) from test_profile_innodb where id between 456 and 876              | 
|       11 | 0.00134325 | select SQL_NO_CACHE count(*) from test_profile_innodb where id between 456 and 876 | 
+----------+------------+------------------------------------------------------------------------------------+
1er lancement :
mysql> select count(*) from test_profile_innodb where id between 456 and 876;
+——————————–+———-+
| Status                         | Duration |
+--------------------------------+----------+
| starting                       | 0.000039 |
| Waiting for query cache lock   | 0.000009 |
| checking query cache for query | 0.000092 |
| checking permissions           | 0.000015 |
| Opening tables                 | 0.000057 |
| System lock                    | 0.000019 |
| Waiting for query cache lock   | 0.000040 |
| init                           | 0.000035 |
| optimizing                     | 0.000016 |
| statistics                     | 0.260992 |
| preparing                      | 0.000041 |
| executing                      | 0.000012 |
| Sending data                   | 0.000781 |
| end                            | 0.000019 |
| query end                      | 0.000024 |
| closing tables                 | 0.000026 |
| freeing items                  | 0.000018 |
| Waiting for query cache lock   | 0.000008 |
| freeing items                  | 0.000037 |
| Waiting for query cache lock   | 0.000008 |
| freeing items                  | 0.000005 |
| storing result in query cache  | 0.000011 |
| logging slow query             | 0.000006 |
| cleaning up                    | 0.000008 |
+--------------------------------+----------+
Second lancement :
mysql> select count(*) from test_profile_innodb where id between 456 and 876;
+--------------------------------+----------+
| Status                         | Duration |
+--------------------------------+----------+
| starting                       | 0.000039 |
| Waiting for query cache lock   | 0.000010 |
| checking query cache for query | 0.000018 |
| checking privileges on cached  | 0.000011 |
| checking permissions           | 0.000015 |
| sending cached result to clien | 0.000026 |
| logging slow query             | 0.000006 |
| cleaning up                    | 0.000006 |
+--------------------------------+----------+
Troisième lancement avec SQL_NO_CACHE :
mysql> select SQL_NO_CACHE count(*) from test_profile_innodb where id between 456 and 876;
+----------------------+----------+
| Status               | Duration |
+----------------------+----------+
| starting             | 0.000124 |
| checking permissions | 0.000020 |
| Opening tables       | 0.000043 |
| System lock          | 0.000021 |
| init                 | 0.000034 |
| optimizing           | 0.000016 |
| statistics           | 0.000134 |
| preparing            | 0.000024 |
| executing            | 0.000011 |
| Sending data         | 0.000808 |
| end                  | 0.000019 |
| query end            | 0.000017 |
| closing tables       | 0.000021 |
| freeing items        | 0.000037 |
| logging slow query   | 0.000007 |
| cleaning up          | 0.000009 |
+----------------------+----------+
Ce qu’explique Stéphane dans son article peut être vérifié dans les résultats du profiling :
  • La première requête n’est pas en cache, son temps d’exécution est plus long, une insertion dans le cache de requête est nécessaire
  • La seconde requête récupère le résultat directement dans le cache de requête : sending cached result to client
  • La troisième requête, pour laquelle j’ai volontairement désactivé l’usage du cache de requête est toujours plus rapide que la première. D’autres caches sont donc entrés en jeux mais ne sont pas visibles ici

 

Exemple 3 : Changement de la taille du cache

Nous avons vu à l’exemple précédent que le SQL_NO_CACHE permet de désactiver le cache de requête.
Mais d’autres caches entrent également en jeux comme le précise très justement Stéphane dans son post.

Sachez que la modification de la taille d’un cache peut servir à vider son contenu. C’est le cas avec le cache de clé MyISAM (key_buffer_size) :

mysql> show profiles;
+----------+------------+--------------------------------------------------------------------------------------+
| Query_ID | Duration   | Query                                                                                |
+----------+------------+--------------------------------------------------------------------------------------+
|       13 | 0.00456550 | select SQL_NO_CACHE count(*) from test_profile_myisam where id between 6700 and 9000 |
|       14 | 0.00399675 | select SQL_NO_CACHE count(*) from test_profile_myisam where id between 6700 and 9000 |
|       15 | 0.00612700 | set global key_buffer_size=31*1024*1024                                              |
|       16 | 0.00456225 | select SQL_NO_CACHE count(*) from test_profile_myisam where id between 6700 and 9000 |
+----------+------------+--------------------------------------------------------------------------------------+
On peut le constater dans l’exemple ci-dessus, j’ai envoyé trois fois la même requête en bloquant l’utilisation du cache de requête.
La seconde requête est la plus rapide, la troisième, après modification du cache de clés, est aussi longue que la première.

Exemple 4 : Les ressources utilisées


Pour terminer,  sachez qu’il est également possible d’avoir des informations sur les ressources consommées par les requêtes avec la commande show profiles, par exemple, ici, les ressources CPU : (Attention, cela ne fonctionne pas sur tous les OS) 
mysql> show profile CPU for query 16; 
+----------------------+----------+----------+------------+ 
| Status               | Duration | CPU_user | CPU_system | 
+----------------------+----------+----------+------------+ 
| starting             | 0.000129 | 0.000000 |   0.000000 | 
| checking permissions | 0.000018 | 0.000000 |   0.000000 | 
| Opening tables       | 0.000043 | 0.000000 |   0.000000 | 
| System lock          | 0.000023 | 0.000000 |   0.000000 | 
| init                 | 0.000034 | 0.000000 |   0.000000 | 
| optimizing           | 0.000020 | 0.000000 |   0.000000 | 
| statistics           | 0.000237 | 0.000000 |   0.004000 | 
| preparing            | 0.000034 | 0.000000 |   0.000000 | 
| executing            | 0.000016 | 0.000000 |   0.000000 | 
| Sending data         | 0.003902 | 0.004001 |   0.000000 | 
| end                  | 0.000020 | 0.000000 |   0.000000 | 
| query end            | 0.000013 | 0.000000 |   0.000000 | 
| closing tables       | 0.000022 | 0.000000 |   0.000000 | 
| freeing items        | 0.000036 | 0.000000 |   0.000000 | 
| logging slow query   | 0.000006 | 0.000000 |   0.000000 | 
| cleaning up          | 0.000010 | 0.000000 |   0.000000 | 
+----------------------+----------+----------+------------+

Je vous laisse découvrir la documentation pour tous les détails sur cette commande bien utile.

J’espère que ce post vous aura permis de découvrir ou re-découvrir la notion de profiling avec MySQL.
Si vous avez des retours d’expérience sur cette commande, prenez 3mins pour rédiger un commentaire.
Bonne fin de semaine.
Categories: Admin, MySQL

XtraDB sauvegarde votre cache, et ça marche !

March 9th, 2010 No comments

 

La dernière version de XtraDB, le moteur de stockage proposé par Percona, dispose d’une fonctionnalité plutôt pertinente avec MySQL : La sauvegarde du cache InnoDB (InnoDB Buffer Pool)

Sauvegarder le cache, oui, mais pour quoi faire ?

Vous devez effectivement comprendre l’intérêt de la chose si vous vous êtes déjà frotté à l’administration d’un MySQL mais je dois vous avouer qu’en abordant le sujet pendant la pose café, tout le monde n’était pas forcement convaincu.

En effet, la mise en œuvre d’une telle fonctionnalité soulève une autre question : Pourquoi redémarrer MySQL ?

Effectivement, le véritable intérêt de cette sauvegarde est de pouvoir couper son MySQL sans perdre les informations stockées dans le cache. Intérêt évidemment compris de tous dans le cas d’un crash du serveur MySQL.

Dans les faits, XtraDB permet de sauvegarder et restaurer le cache même si il n’y a pas eu d’arrêt de l’instance. Ce qui peut d’ailleurs s’avérer utile dans certaines conditions, après le passage d’un gros batch par exemple, afin de retrouver un cache d’activité transactionnelle standard.

Pour en revenir à la question posée par mon collègue, en dehors du contexte de crash, pourquoi redémarrer MySQL ?

Alors que d’autres éditeurs de bases de données concentrent leurs efforts pour justement limiter au maximum le redémarrage des instances, il semble que MySQL soit plus exposé que les autres à ce type de problématique.

Et effectivement, même si la modification dynamique de paramètres gagne du terrain avec les nouvelles versions, la gestion des fichiers physiques reste problématique dans un environnement de production critique.

Il s’agit donc ici de se poser la question à l’envers et c’est donc pour ces différentes raisons que la sauvegarde du cache de données est pertinente avec MySQL !

Comment ça marche ?

Le pré-requis est évidemment d’installer et d’utiliser le moteur de stockage XtraDB fourni par Percona (lien en fin d’article).

Pour comprendre le fonctionnement de cette sauvegarde, j’ai réalisé un petit test en utilisant le compteur Innodb_buffer_pool_pages_data qui indique combien de pages du cache sont utilisées :

1 – Arrêt et relance de l’instance MySQL (Tous les caches sont vidés)

2 – Je contrôle l’état de mon cache :

mysql> show global status like ‘Innodb_buffer_pool_pages_data’;
+-------------------------------+-------+ 
| Variable_name                 | Value | 
+-------------------------------+-------+ 
| Innodb_buffer_pool_pages_data | 14    | 
+-------------------------------+-------+

3 – Je fais une requête simple sur ma table ETAT :

mysql> select * from capdata_innodb.ETAT;

4 -Nouvelle vérification du cache, à ce stade, la table ETAT a bien été montée dans le cache (au moins une partie de ses données) :

mysql> show global status like ‘Innodb_buffer_pool_pages_data’;
+-------------------------------+-------+ 
| Variable_name                 | Value | 
+-------------------------------+-------+ 
| Innodb_buffer_pool_pages_data | 17    | 
+-------------------------------+-------+

5 – Je lance une sauvegarde du cache :

mysql> select * from information_schema.XTRADB_ADMIN_COMMAND /*!XTRA_LRU_DUMP*/;
+------------------------------+ 
| result_message               | 
+------------------------------+ 
| XTRA_LRU_DUMP was succeeded. | 
+------------------------------+

6 – Arrêt et relance de l’instance MySQL (Tous les caches sont vidés)

7 – Vérification du cache :

mysql> show global status like ‘Innodb_buffer_pool_pages_data’;
+-------------------------------+-------+ 
| Variable_name                 | Value | 
+-------------------------------+-------+ 
| Innodb_buffer_pool_pages_data | 14    | 
+-------------------------------+-------+

8 -Restauration du cache :

mysql> select * from information_schema.XTRADB_ADMIN_COMMAND /*!XTRA_LRU_RESTORE*/;
+---------------------------------+ 
| result_message                  | 
+---------------------------------+ 
| XTRA_LRU_RESTORE was succeeded. | 
+---------------------------------+

9 – Dernière vérification du cache :

mysql> show global status like ‘Innodb_buffer_pool_pages_data’;
+-------------------------------+-------+ 
| Variable_name                 | Value | 
+-------------------------------+-------+ 
| Innodb_buffer_pool_pages_data | 17    | 
+-------------------------------+-------+

Le cache a bien été restauré, à vous le warm restart facile !

Percona a réalisé un petit benchmark comparatif dont voici le résultat :

Retrouvez toutes les informations sur le moteur XtraDB ici : http://www.percona.com/docs/wiki/percona-xtradb:start

Source : CapData Team Blog

Categories: Admin, MySQL