Archive

Posts Tagged ‘show profile’

Flush Logs #8 : Pause estivale…

July 23rd, 2011 No comments

Il est grand temps pour moi d’aller voir si le soleil m’attend quelque part, une pause s’impose !
MySQL+ reprendra donc une activité normale d’ici quelques semaines, d’ici là, je vous invite à lire ou relire les articles les plus populaires :

Si le coeur vous en dit, n’hésitez pas à laisser un commentaire sur ces articles.

Si vous ne l’avez jamais fait, je vous propose de lire l’à propos de ce site : http://www.mysqlplus.fr/a-propos/

N’oubliez pas de me suivre également sur twitter, de vous abonnez au flux RSS ou par email.

Je n’ai plus qu’une seule chose à écrire : Bonnes vacances !

Categories: Live !, MySQL

[@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