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 8cbf684..ce119dc 100644
--- a/doc/SPOE.txt
+++ b/doc/SPOE.txt
@@ -176,6 +176,8 @@
- 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 @@
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 @@
* 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 b5f8ce3..9354b55 100644
--- a/include/types/spoe.h
+++ b/include/types/spoe.h
@@ -246,6 +246,8 @@
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 7d5eb3d..760e26c 100644
--- a/src/flt_spoe.c
+++ b/src/flt_spoe.c
@@ -165,6 +165,8 @@
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 @@
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 @@
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 @@
}
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 @@
}
}
+ 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);