MINOR: spoe: Add options to store processing times in variables

"set-process-time" and "set-total-time" options have been added to store
processing times in the transaction scope, at each event and group processing,
the current one and the total one. So it is possible to get them.

TODO: documentation

diff --git a/doc/SPOE.txt b/doc/SPOE.txt
index 8cbf6845a1cdea4ba1ec453e6e2806d3295a5000..ce119dc493f8daab284fd5b55ac1f8d66de2f238 100644 (file)
--- a/doc/SPOE.txt
+++ b/doc/SPOE.txt
@@ -176,6 +176,8 @@ spoe-agent <name>
     - option continue-on-error
     - option force-set-var
     - option set-on-error
+    - option set-process-time
+    - option set-total-time
     - option var-prefix
     - register-var-names
     - timeout hello|idle|processing
@@ -308,6 +310,55 @@ option set-on-error <var name>
 
   See also: "option continue-on-error", "option var-prefix".
 
+
+option set-process-time <var name>
+  Define the variable to set to report the processing time of the last event or
+  group.
+
+  Arguments :
+
+    <var name>   is the variable name, without the scope. The name may only
+                 contain characters 'a-z', 'A-Z', '0-9', '.' and '_'.
+
+  This variable will be set in the scope of the transaction. As for all other
+  variables define by the SPOE, it will be prefixed. So, if your variable name
+  is "process_time" and your prefix is "my_spoe_pfx", the variable will be
+  "txn.my_spoe_pfx.process_time".
+
+  When set, the variable is an integer representing the delay to process the
+  event or the group, in milliseconds. From the stream point of view, it is the
+  latency added by the SPOE processing for the last handled event or group.
+
+  If several events or groups are processed for the same stream, this value
+  will be overrideen.
+
+  See also: "option set-total-time".
+
+
+option set-total-time <var name>
+  Define the variable to set to report the total processing time SPOE for a
+  stream.
+
+  Arguments :
+
+    <var name>   is the variable name, without the scope. The name may only
+                 contain characters 'a-z', 'A-Z', '0-9', '.' and '_'.
+
+  This variable will be set in the scope of the transaction. As for all other
+  variables define by the SPOE, it will be prefixed. So, if your variable name
+  is "total_time" and your prefix is "my_spoe_pfx", the variable will be
+  "txn.my_spoe_pfx.total_time".
+
+  When set, the variable is an integer representing the sum of processing times
+  for a stream, in milliseconds. From the stream point of view, it is the
+  latency added by the SPOE processing.
+
+  If several events or groups are processed for the same stream, this value
+  will be updated.
+
+  See also: "option set-process-time".
+
+
 option var-prefix <prefix>
   Define the prefix used when variables are set by an agent.
 
@@ -1142,10 +1193,10 @@ The messages are logged using the stream's logger and use the following format:
         * wT   : the delay before the reponse is received. No fragmentation
                  supported here.
         * resT : the delay to process the response. No fragmentation supported
-                here.
+                 here.
         * pT   : the delay to process the event or the group. From the stream
-                point of view, it is the latency added by the SPOE processing.
-                It is more or less the sum of values above.
+                 point of view, it is the latency added by the SPOE processing.
+                 It is more or less the sum of values above.
 
 For all these time events, -1 means the processing was interrupted before the
 end. So -1 for the queue time means the request was never dequeued. For

diff --git a/include/types/spoe.h b/include/types/spoe.h
index b5f8ce3d0b3550f8007da0348b4482abc430baea..9354b5536dd4a098f6dbd484c245dfc38af53625 100644 (file)
--- a/include/types/spoe.h
+++ b/include/types/spoe.h
@@ -246,6 +246,8 @@ struct spoe_agent {
        char                 *engine_id;      /* engine-id string */
        char                 *var_pfx;        /* Prefix used for vars set by the agent */
        char                 *var_on_error;   /* Variable to set when an error occurred, in the TXN scope */
+       char                 *var_t_process;  /* Variable to set to report the processing time of the last event/group, in the TXN scope */
+       char                 *var_t_total;    /* Variable to set to report the cumulative processing time, in the TXN scope */
        unsigned int          flags;          /* SPOE_FL_* */
        unsigned int          cps_max;        /* Maximum # of connections per second */
        unsigned int          eps_max;        /* Maximum # of errors per second */

diff --git a/src/flt_spoe.c b/src/flt_spoe.c
index 7d5eb3dba135190491d6e2be3dee450ef95d248c..760e26c603564e7447d10da7fdb9859893604b6b 100644 (file)
--- a/src/flt_spoe.c
+++ b/src/flt_spoe.c
@@ -165,6 +165,8 @@ spoe_release_agent(struct spoe_agent *agent)
        free(agent->var_pfx);
        free(agent->engine_id);
        free(agent->var_on_error);
+       free(agent->var_t_process);
+       free(agent->var_t_total);
        list_for_each_entry_safe(msg, msgback, &agent->messages, list) {
                LIST_DEL(&msg->list);
                spoe_release_message(msg);
@@ -2527,6 +2529,30 @@ spoe_update_stats(struct stream *s, struct spoe_agent *agent,
                tv_zero(&ctx->stats.tv_wait);
                tv_zero(&ctx->stats.tv_response);
        }
+
+       if (agent->var_t_process) {
+               struct sample smp;
+
+               memset(&smp, 0, sizeof(smp));
+               smp_set_owner(&smp, s->be, s->sess, s, dir|SMP_OPT_FINAL);
+               smp.data.u.sint = ctx->stats.t_process;
+               smp.data.type   = SMP_T_SINT;
+
+               spoe_set_var(ctx, "txn", agent->var_t_process,
+                            strlen(agent->var_t_process), &smp);
+       }
+
+       if (agent->var_t_total) {
+               struct sample smp;
+
+               memset(&smp, 0, sizeof(smp));
+               smp_set_owner(&smp, s->be, s->sess, s, dir|SMP_OPT_FINAL);
+               smp.data.u.sint = ctx->stats.t_total;
+               smp.data.type   = SMP_T_SINT;
+
+               spoe_set_var(ctx, "txn", agent->var_t_total,
+                            strlen(agent->var_t_total), &smp);
+       }
 }
 
 static void
@@ -3261,6 +3287,8 @@ cfg_parse_spoe_agent(const char *file, int linenum, char **args, int kwm)
                curagent->engine_id      = NULL;
                curagent->var_pfx        = NULL;
                curagent->var_on_error   = NULL;
+               curagent->var_t_process  = NULL;
+               curagent->var_t_total    = NULL;
                curagent->flags          = (SPOE_FL_PIPELINING | SPOE_FL_SND_FRAGMENTATION);
                if (global.nbthread == 1)
                        curagent->flags |= SPOE_FL_ASYNC;
@@ -3499,6 +3527,54 @@ cfg_parse_spoe_agent(const char *file, int linenum, char **args, int kwm)
                        }
                        curagent->var_on_error = strdup(args[2]);
                }
+               else if (!strcmp(args[1], "set-process-time")) {
+                       char *tmp;
+
+                       if (!*args[2]) {
+                               ha_alert("parsing [%s:%d]: '%s %s' expects a value.\n",
+                                        file, linenum, args[0],
+                                        args[1]);
+                               err_code |= ERR_ALERT | ERR_FATAL;
+                               goto out;
+                       }
+                       if (alertif_too_many_args(2, file, linenum, args, &err_code))
+                               goto out;
+                       tmp = args[2];
+                       while (*tmp) {
+                               if (!isalnum(*tmp) && *tmp != '_' && *tmp != '.') {
+                                       ha_alert("parsing [%s:%d]: '%s %s' only supports [a-zA-Z_-.] chars.\n",
+                                                file, linenum, args[0], args[1]);
+                                       err_code |= ERR_ALERT | ERR_FATAL;
+                                       goto out;
+                               }
+                               tmp++;
+                       }
+                       curagent->var_t_process = strdup(args[2]);
+               }
+               else if (!strcmp(args[1], "set-total-time")) {
+                       char *tmp;
+
+                       if (!*args[2]) {
+                               ha_alert("parsing [%s:%d]: '%s %s' expects a value.\n",
+                                        file, linenum, args[0],
+                                        args[1]);
+                               err_code |= ERR_ALERT | ERR_FATAL;
+                               goto out;
+                       }
+                       if (alertif_too_many_args(2, file, linenum, args, &err_code))
+                               goto out;
+                       tmp = args[2];
+                       while (*tmp) {
+                               if (!isalnum(*tmp) && *tmp != '_' && *tmp != '.') {
+                                       ha_alert("parsing [%s:%d]: '%s %s' only supports [a-zA-Z_-.] chars.\n",
+                                                file, linenum, args[0], args[1]);
+                                       err_code |= ERR_ALERT | ERR_FATAL;
+                                       goto out;
+                               }
+                               tmp++;
+                       }
+                       curagent->var_t_total = strdup(args[2]);
+               }
                else {
                        ha_alert("parsing [%s:%d]: option '%s' is not supported.\n",
                                 file, linenum, args[1]);
@@ -4013,6 +4089,38 @@ parse_spoe_flt(char **args, int *cur_arg, struct proxy *px,
                }
        }
 
+       if (curagent->var_t_process) {
+               struct arg arg;
+
+               trash.len = snprintf(trash.str, trash.size, "txn.%s.%s",
+                                    curagent->var_pfx, curagent->var_t_process);
+
+               arg.type = ARGT_STR;
+               arg.data.str.str = trash.str;
+               arg.data.str.len = trash.len;
+               if (!vars_check_arg(&arg, err)) {
+                       memprintf(err, "SPOE agent '%s': failed to register variable %s.%s (%s)",
+                                 curagent->id, curagent->var_pfx, curagent->var_t_process, *err);
+                       goto error;
+               }
+       }
+
+       if (curagent->var_t_total) {
+               struct arg arg;
+
+               trash.len = snprintf(trash.str, trash.size, "txn.%s.%s",
+                                    curagent->var_pfx, curagent->var_t_total);
+
+               arg.type = ARGT_STR;
+               arg.data.str.str = trash.str;
+               arg.data.str.len = trash.len;
+               if (!vars_check_arg(&arg, err)) {
+                       memprintf(err, "SPOE agent '%s': failed to register variable %s.%s (%s)",
+                                 curagent->id, curagent->var_pfx, curagent->var_t_process, *err);
+                       goto error;
+               }
+       }
+
        if (LIST_ISEMPTY(&curmphs) && LIST_ISEMPTY(&curgphs)) {
                ha_warning("Proxy '%s': No message/group used by SPOE agent '%s' declared at %s:%d.\n",
                           px->id, curagent->id, curagent->conf.file, curagent->conf.line);