Analyser les temps de traitement des fonctions Cobol avec le "Profiler"

Cobol offre un analyseur de temps de traitement. Ci joint un lien vers un article de la Micro Focus Community.

Pour l'activer il faut compiler l'exécutable avec une option particulière, lancer le traitement puis extraire les résultats obtenus :

• Modifier le .profile pour exporter, dans en fin de chapitre "VARIABLES D'ENVIRONNEMENT COBOL" la variable COBPRFDIR=$TMPDIR
• Faites une RBZ du programme à analyser avec conservation des sources

Conservation des fichiers de compilation (0/1)  [0]: 1

• Dans $TMP contrôlez la présence des fichiers *.idy et *.cbl
• Retrouvez (dans le log de la RBZ) et adaptez la commande de compilation Cobol "cob"  pour y ajouter l'option -C PROFILE
• Recompilez le programme (exemple avec FFCALDBI) avec l'option -C PROFILE

cob32 -C nolist -vz -C ASSIGN=EXTERNAL ... -C COPYLIST -C NORESEQ -C PROFILE -U /hradev/txt/tmp/FFCALDBI.cbl

• Copiez le généré (suffixe ".so" en général - consulter ${SUFMOD}) dans $SIGACS/prod/gnt
• Conservez le fichier *.idy dans $TMP
• Si le programme concerné est un programme TP, faites un arrêt / démarrage de OpenHR,
• Exécutez votre traitement,

Une fois l'exécution du programme terminée, un fichier *.ipf est créé dans $TMPDIR,

• Pour en lire les données, utilisez la commande cobprof (ici avec une limitation a 25 lignes) :

cobprof FFCALDBI.ipf +LIST | head -25

Total time:    1517240 milliseconds.      Module called once.
% time      time   entries  ms/entry      paragraph
-------------------------------------------------------------------------------
 45.35    688110        26     26466      UTTDP424-XB0B0LEC-XY
 10.99    166750 308687680         0      UTTBPUUU-XB0BBL5J-NC
 10.87    164900 308678970         0      UTTBPUUU-XB0BBL5J-NE
 10.51    159450 308678970         0      UTTBPUUU-XB0BBL5J-NC-900
 10.32    156650 308678970         0      UTTBPUUU-XB0BBL5J-NE-FN
  5.90     89460       151       592      GIP-ECR-01
  0.95     14400  26188434         0      UTTBPUUU-XB0BBL5J-AF
  0.94     14280  26192800         0      UTTBPUUU-XB0BBL5J-AE
  0.93     14150  26188434         0      UTTBPUUU-XB0BBL5J-AE-900
  0.92     13930       340        41      GIPLEC-01
  0.78     11890  26188434         0      UTTBPUUU-XB0BBL5J-AF-FN
  0.13      1950     22757         0      F8LCD
  0.12      1770      5550         0      RECHJOUR-01
  0.09      1410       150         9      VALCOND-DS3
  0.07      1020   1587369         0      RECH-ZYX3-01
  0.06       920      8710         0      UTTBPUUU-XB0BBL5J-PA
  0.06       910       150         6      TRICOND
  0.05       820   1582719         0      RECH-ZYX3-02
  0.04       560       150         4      F5025-2
  0.04       550         1       550      F-SGR2-01-TDP401

NB : En cas de message "Open Fail on .idy for FFCALDBI.idy", c'est que le fichier *.idy a été perdu. Pour pouvoir utiliser cobprof il vous faut le recréer (commande cob).

Vous trouverez :

• Total time : temps CPU total
• paragraph : fonction cobol concernée,
• %time : pourcentage du temps total d'exécution passé dans ladite fonction,
• time : temps en ms
• entries : nombre de passages dans la fonction
• ms/entry : temps moyen par passage

Notez le "Module called once" : le programme a été exécuté une seule fois (les statistiques sont cumulées à chaque exécution - si vous ne souhaitez pas cela, vous devez supprimer/renommer le *.ipf avant chaque exécution).

Si une fonction appelle un sous programme, le temps de ce sous programme est comptabilisé dans la fonction - sauf si ce sous programme est lui même compilé avec l'option "PROFILE".

La validité des résultats fournis par cet utilitaire est toutefois sujette à caution ... En effet, dans mon exemple :

• UTTDP424-XB0B0LEC-XY est une fonction "vide" qui ne fait qu'un "perform" vers UTTBPUUU-XB0BBL5J ... qu'elle prenne 688 secondes pour 26 appels n'est pas compréhensible,
• et si le temps attribué à cette fonction cumule celui des fonctions performées, pourquoi voit-on alors plus bas des références à ces même fonctions UTTBPUUU-XB0BBL5J ?
• Mode "Profiler" activé le traitement complet dure 28 minutes, mais une fois ce mode désactivé (recompilation sans l'option -C PROFILE) le temps de traitement passe à 3 minutes !
• En fait le mode "Profiler" semble extrêmement sensible aux boucles (ici 300.000 passages dans chacune des fonctions UTTBPUUU-XB0BBL5J-NC/NE...) et ralentit significativement le traitement ...

En conclusion, si ce Cobprof vous donne la cause de vos problèmes de performance, tant mieux ... Mais regardez son analyse avec circonspection.

• Limitez son usage a des cas de "simples" (ex : un seul dossier traité).

• Contrôlez que les temps de traitement avec / sans le mode "Profiler" est inchangé.

PS : Pour supprimer ce mode "Profile", refaites une RBZ sur le module concerné.