Yo yo yo.

J'avais une base de code, avec pas mal de fonctions déjà implémentées, et puis je me suis dit "ooooomm, faudrait que je trace le temps d'exécution de chacune de ces fonctions, pour savoir où concentrer mes efforts, en faisant telle et telle stat'". Bon alors je vous entends déjà barir au loin "hey mais pauvre naze, y'a plein d'outils de profiling", et c'est vrai. Seulement je voulais faire un truc à ma sauce d'une part (histoire de voir un peu comment ça fonctionne), et surtout pouvoir ajouter les stats qui m'intéressent, faire des trucs aux p'tits oignons quoi. Et puis c'est pas comme si ça prenait des jours à coder.

Alors après avoir cherché un peu, je tombe sur la doc GCC (même le man en parle, à vrai dire) :


void __cyg_profile_func_enter(void *func, void *callsite); 
void __cyg_profile_func_exit(void *func, void *callsite);


Ces fonctions sont appelées respectivement à l'entrée et la sortie de chacune des fonctions de votre programme. Il y a une linuxerie ensuite pour obtenir le nom de l'appelant, ie. passer par dladdr() ou __build_return_address(0). Ensuite vous stockez les infos comme vous voulez, perso j'utilise une hashtable dont les clefs sont les symboles (aka noms de fonctions), avec chaque cellule contenant des stats, sur le nombre d'appel, le temps d'exécution moyen, etc.

J'ai utilisé ça pour un code sur lequel je passe un peu de temps en ce moment, et la sortie ressemble à (le > correspond à l'entrée dans la fonction, le < à la sortie, faudrait rendre le truc plus joli avec un système de pile pour avoir la profondeur d'appel de chacune en fonction d'un décalage horizontal, mais bon, ça viendra après) :


[...]
1297941768.719531 > dfs_mkdir@0x40f534
1297941768.719607 > dfs_mkdir_timeout@0x41398f
1297941769.416415 < dfs_mkdir_timeout@0x41398f -- 696ms
1297941769.416445 < dfs_mkdir@0x40f534 -- 696ms
1297941769.416469 > dfs_getattr@0x40c16c
1297941769.416684 > dfs_namei_timeout@0x413ef7
1297941769.534098 < dfs_namei_timeout@0x413ef7 -- 117ms
1297941769.534161 > dfs_getattr_timeout@0x413690
1297941770.104592 < dfs_getattr_timeout@0x413690 -- 570ms
1297941770.104874 < dfs_getattr@0x40c16c -- 570ms

                                -- report --
symbol dfs_getattr_timeout: #calls: 46, average call duration: 266ms
symbol dfs_opendir_timeout: #calls: 1, average call duration: 780ms
symbol dfs_namei_timeout: #calls: 47, average call duration: 299ms
symbol dfs_chdir_timeout: #calls: 1, average call duration: 0ms
symbol dfs_mkdir: #calls: 1, average call duration: 696ms
symbol dfs_getattr: #calls: 48, average call duration: 275ms
symbol dfs_mkdir_timeout: #calls: 1, average call duration: 696ms


Le code (crados, pas encore nettoyé) est visible ici. Comme je disais, le truc vraiment sympa c'est juste d'avoir à appeler profile_init() et profile_fini() dans mon code. Et encore, on peut faire mieux en générant un .so qu'on charge avec LD_PRELOAD, histoire d'avoir vraiment 0 code impacté. Faut juste compiler les objets avec -fPIC et -finstrument-functions. That's all folks.

OK c'est un profiler du pauvre, mais ici à unix4fun, on est prolos. Et on vous emmerde !