Logger les temps d'exécution / Time Execution Logging

Qui n'a pas rencontré de problème de performance en écrivant des traitements DataWeave un peu complexe? Pour résoudre de tels problèmes, il est nécessaire  de pouvoir faire afficher le temps d'exécution de la procédure problématique et ensuite suivre ce temps d'exécution. Bien des développeurs ignorent que DataWeave possède tout ce qui est nécessaire  pour implémenter une telle fonctionnalité:

1. la méthode now() permet de récupérer une estampille temporelle
2. la méthode log() permet d'émettre un message de log
3. il est possible de passer une fonction comme paramètre d'une autre fonction

Nous allons voir tout ça. Prenons par exemple un traitement qui s'exécute dans un temps non négligeable (elle construit un objet de 10000 champs, mais l'intérêt de l'article n'est pas là).

%dw 2.0

output application/json

---

(0 to 10000) reduce(v, acc={})->(acc ++ ("value"++(v as Number)):v)

Pour monitorer le temps d'exécution de ce traitement, nous allons définir puis utiliser une fonction "eval" que vous pourrez utiliser telle quelle dans vos projet:

%dw 2.0

output application/json

fun Now() = now() then (t)->(t as Number)*1000 + t.milliseconds

fun eval(prs) =

Now() then (t1)-> prs() then (r)->

log(Now() -t1)

then r

---

eval(()->

(0 to 10000) reduce(v, acc={})->(acc ++ ("value"++(v as Number)):v)

)

Quelques commentaires sur cette snippet:

•  D'abord, il a été nécessaire de redéfinir une fonction Now au dessus de la fonction standard now() car "now() as a Number" retourne un nombre de secondes et pas de millisecondes (ce que fait now()).
• La fonction "eval" reçoit une fonction en paramètre qu'elle exécute au milieu d'une séquence de trois appels. Les deux appels qui l'encadrent invoquent Now() et en retirent un délai qui est loggé. Noter que "eval" renvoie la valeur obtenue par évaluation de la fonction passée en paramètre: son comportement est donc complètement générique et transparent.
• Noter le "()->" qui suit l'invocation d'éval. Il sert à transformer l'expression que l'on veux monitorer en une fonction.
• "eval" est utilisé ici pour monitorer toute l'expression. Rien n'empêche de l'utiliser pour monitorer un morceau de l'expression. On peut écrire par exemple:

%dw 2.0

output application/json

fun Now() = now() then (t)->(t as Number)*1000 + t.milliseconds

fun eval(prs) =

Now() then (t1)-> prs() then (r)->

log(Now() -t1)

then r

---

(0 to 10000) reduce(v, acc={})->

    (eval(()->(acc ++ ("value"++(v as Number)):v)))

__________________________________________________________________________

Who hasn't encountered performance problems when writing complex DataWeave processes? To solve such problems, it is necessary to be able to display the execution time of the problematic procedure and then track this execution time. Many developers are unaware that DataWeave has everything needed to implement such a feature:

1. the now() method can be used to retrieve a time stamp
2. the log() method can be used to send a log message
3. a function can be passed as a parameter to another function.

Let's take a look at all this. Let's take, for example, a process that takes a considerable amount of time to run (it builds an object with 10,000 fields, but that's not the point of this article).

%dw 2.0

output application/json

---

(0 to 10000) reduce(v, acc={})->(acc ++ ("value"++(v as Number)):v)

To monitor the execution time of this process, we're going to define and use an "eval" function that you can use as is in your projects:

%dw 2.0

output application/json

fun Now() = now() then (t)->(t as Number)*1000 + t.milliseconds

fun eval(prs) =

Now() then (t1)-> prs() then (r)->

log(Now() -t1)

then r

---

eval(()->

(0 to 10000) reduce(v, acc={})->(acc ++ ("value"++(v as Number)):v)

)

A few comments on this snippet:

•  Firstly, it was necessary to redefine a Now function above the standard now() function, as "now() as a Number" returns a number of seconds and not milliseconds (which is what now() does).
• The "eval" function receives a function as a parameter, which it executes in the middle of a sequence of three calls. The two calls that flank it invoke Now() and retrieve a delay that is logged. Note that "eval" returns the value obtained by evaluating the function passed in parameter: its behavior is therefore completely generic and transparent.
• Note the "()->" that follows the invocation of "eval". It is used to transform the expression you wish to monitor into a function.
• "eval" is used here to monitor the whole expression. Nothing prevents you from using it to monitor a part of the expression. For example, you could write:

%dw 2.0

output application/json

fun Now() = now() then (t)->(t as Number)*1000 + t.milliseconds

fun eval(prs) =

Now() then (t1)-> prs() then (r)->

log(Now() -t1)

then r

---

(0 to 10000) reduce(v, acc={})->

    (eval(()->(acc ++ ("value"++(v as Number)):v)))