Hi all,
The v4 of the extending histogram exprssions series. The previous versions
were posted at:
v3: https://lore.kernel.org/r/[email protected]/
v2: https://lore.kernel.org/r/[email protected]/
v1: https://lore.kernel.org/r/[email protected]/
Patches 4 through 6 are new and adds some optimizations/improvements
suggested by Steven Rostedt.
Removes the Change-Id tags that were inadvertently added in v3.
The cover letter is copied below for convenience.
Thanks,
Kalesh
---
The frequency of the rss_stat trace event is known to be of the same
magnitude as that of the sched_switch event on Android devices. This can
cause flooding of the trace buffer with rss_stat traces leading to a
decreased trace buffer capacity and loss of data.
If it is not necessary to monitor very small changes in rss (as is the
case in Android) then the rss_stat tracepoint can be throttled to only
emit the event once there is a large enough change in the rss size.
The original patch that introduced the rss_stat tracepoint also proposed
a fixed throttling mechanism that only emits the rss_stat event
when the rss size crosses a 512KB boundary. It was concluded that more
generic support for this type of filtering/throttling was need, so that
it can be applied to any trace event. [1]
From the discussion in [1], histogram triggers seemed the most likely
candidate to support this type of throttling. For instance to achieve the
same throttling as was proposed in [1]:
(1) Create a histogram variable to save the 512KB bucket of the rss size
(2) Use the onchange handler to generate a synthetic event when the
rss size bucket changes.
The only missing pieces to support such a hist trigger are:
(1) Support for setting a hist variable to a specific value -- to set
the bucket size / granularity.
(2) Support for division arithmetic operation -- to determine the
corresponding bucket for an rss size.
This series extends histogram trigger expressions to:
(1) Allow assigning numeric literals to hist variable (eg. x=1234)
and using literals directly in expressions (eg. x=size/1234)
(2) Support division and multiplication in hist expressions.
(eg. a=$x/$y*z); and
(3) Fixes expression parsing for non-associative operators: subtraction
and division. (eg. 8-4-2 should be 2 not 6)
The rss_stat event can then be throttled using histogram triggers as
below:
# Create a synthetic event to monitor instead of the high frequency
# rss_stat event
echo 'rss_stat_throttled unsigned int mm_id; unsigned int curr;
int member; long size' >> tracing/synthetic_events
# Create a hist trigger that emits the synthetic rss_stat_throttled
# event only when the rss size crosses a 512KB boundary.
echo 'hist:keys=mm_id,member:bucket=size/0x80000:onchange($bucket)
.rss_stat_throttled(mm_id,curr,member,size)'
>> events/kmem/rss_stat/trigger
------ Test Results ------
Histograms can also be used to evaluate the effectiveness of this
throttling by noting the Total Hits on each trigger:
echo 'hist:keys=common_pid' >> events/sched/sched_switch/trigger
echo 'hist:keys=common_pid' >> events/kmem/rss_stat/trigger
echo 'hist:keys=common_pid'
>> events/synthetic/rss_stat_throttled/trigger
Allowing the above example (512KB granularity) run for 5 minutes on
an arm64 device with 5.10 kernel:
sched_switch : total hits = 147153
rss_stat : total hits = 38863
rss_stat_throttled: total hits = 2409
The synthetic rss_stat_throttled event is ~16x less frequent than the
rss_stat event when using a 512KB granularity.
The results are more pronounced when rss size is changing at a higher
rate in small increments. For instance the following results were obtained
by recording the hits on the above events for a run of Android's
lmkd_unit_test [2], which continually forks processes that map anonymous
memory until there is an oom kill:
sched_switch : total hits = 148832
rss_stat : total hits = 4754802
rss_stat_throttled: total hits = 96214
In this stress test, the synthetic rss_stat_throttled event is ~50x less
frequent than the rss_stat event when using a 512KB granularity.
[1] https://lore.kernel.org/lkml/[email protected]/
[2] https://cs.android.com/android/platform/superproject/+/master:system/memory/lmkd/tests/lmkd_test.cpp
Kalesh Singh (8):
tracing: Add support for creating hist trigger variables from literal
tracing: Add division and multiplication support for hist triggers
tracing: Fix operator precedence for hist triggers expression
tracing/histogram: Simplify handling of .sym-offset in expressions
tracing/histogram: Covert expr to const if both operands are constants
tracing/histogram: Optimize division by a power of 2
tracing/selftests: Add tests for hist trigger expression parsing
tracing/histogram: Document expression arithmetic and constants
Documentation/trace/histogram.rst | 14 +
kernel/trace/trace_events_hist.c | 400 ++++++++++++++----
.../testing/selftests/ftrace/test.d/functions | 4 +-
.../trigger/trigger-hist-expressions.tc | 72 ++++
4 files changed, 412 insertions(+), 78 deletions(-)
create mode 100644 tools/testing/selftests/ftrace/test.d/trigger/trigger-hist-expressions.tc
base-commit: ac8a6eba2a117e0fdc04da62ab568d1b7ca4c8f6
--
2.33.0.1079.g6e70778dc9-goog
The current histogram expression evaluation logic evaluates the
expression from right to left. This can lead to incorrect results
if the operations are not associative (as is the case for subtraction
and, the now added, division operators).
e.g. 16-8-4-2 should be 2 not 10 --> 16-8-4-2 = ((16-8)-4)-2
64/8/4/2 should be 1 not 16 --> 64/8/4/2 = ((64/8)/4)/2
Division and multiplication are currently limited to single operation
expression due to operator precedence support not yet implemented.
Rework the expression parsing to support the correct evaluation of
expressions containing operators of different precedences; and fix
the associativity error by evaluating expressions with operators of
the same precedence from left to right.
Examples:
(1) echo 'hist:keys=common_pid:a=8,b=4,c=2,d=1,w=$a-$b-$c-$d' \
>> event/trigger
(2) echo 'hist:keys=common_pid:x=$a/$b/3/2' >> event/trigger
(3) echo 'hist:keys=common_pid:y=$a+10/$c*1024' >> event/trigger
(4) echo 'hist:keys=common_pid:z=$a/$b+$c*$d' >> event/trigger
Signed-off-by: Kalesh Singh <[email protected]>
Reviewed-by: Namhyung Kim <[email protected]>
---
Changed in v2:
- Add Namhyung's Reviewed-by
kernel/trace/trace_events_hist.c | 210 ++++++++++++++++++++-----------
1 file changed, 140 insertions(+), 70 deletions(-)
diff --git a/kernel/trace/trace_events_hist.c b/kernel/trace/trace_events_hist.c
index 522355a06f58..e10c7d9611e5 100644
--- a/kernel/trace/trace_events_hist.c
+++ b/kernel/trace/trace_events_hist.c
@@ -67,7 +67,9 @@
C(TOO_MANY_SORT_FIELDS, "Too many sort fields (Max = 2)"), \
C(INVALID_SORT_FIELD, "Sort field must be a key or a val"), \
C(INVALID_STR_OPERAND, "String type can not be an operand in expression"), \
- C(EXPECT_NUMBER, "Expecting numeric literal"),
+ C(EXPECT_NUMBER, "Expecting numeric literal"), \
+ C(UNARY_MINUS_SUBEXPR, "Unary minus not supported in sub-expressions"), \
+ C(SYM_OFFSET_SUBEXPR, ".sym-offset not supported in sub-expressions"),
#undef C
#define C(a, b) HIST_ERR_##a
@@ -1644,40 +1646,96 @@ static char *expr_str(struct hist_field *field, unsigned int level)
return expr;
}
-static int contains_operator(char *str)
+/*
+ * If field_op != FIELD_OP_NONE, *sep points to the root operator
+ * of the expression tree to be evaluated.
+ */
+static int contains_operator(char *str, char **sep)
{
enum field_op_id field_op = FIELD_OP_NONE;
- char *op;
+ char *minus_op, *plus_op, *div_op, *mult_op;
+
+
+ /*
+ * Report the last occurrence of the operators first, so that the
+ * expression is evaluated left to right. This is important since
+ * subtraction and division are not associative.
+ *
+ * e.g
+ * 64/8/4/2 is 1, i.e 64/8/4/2 = ((64/8)/4)/2
+ * 14-7-5-2 is 0, i.e 14-7-5-2 = ((14-7)-5)-2
+ */
- op = strpbrk(str, "+-/*");
- if (!op)
- return FIELD_OP_NONE;
+ /*
+ * First, find lower precedence addition and subtraction
+ * since the expression will be evaluated recursively.
+ */
+ minus_op = strrchr(str, '-');
+ if (minus_op) {
+ /* Unfortunately, the modifier ".sym-offset" can confuse things. */
+ if (minus_op - str >= 4 && !strncmp(minus_op - 4, ".sym-offset", 11))
+ goto out;
- switch (*op) {
- case '-':
/*
- * Unfortunately, the modifier ".sym-offset"
- * can confuse things.
+ * Unary minus is not supported in sub-expressions. If
+ * present, it is always the next root operator.
*/
- if (op - str >= 4 && !strncmp(op - 4, ".sym-offset", 11))
- return FIELD_OP_NONE;
-
- if (*str == '-')
+ if (minus_op == str) {
field_op = FIELD_OP_UNARY_MINUS;
- else
- field_op = FIELD_OP_MINUS;
- break;
- case '+':
- field_op = FIELD_OP_PLUS;
- break;
- case '/':
+ goto out;
+ }
+
+ field_op = FIELD_OP_MINUS;
+ }
+
+ plus_op = strrchr(str, '+');
+ if (plus_op || minus_op) {
+ /*
+ * For operators of the same precedence use to rightmost as the
+ * root, so that the expression is evaluated left to right.
+ */
+ if (plus_op > minus_op)
+ field_op = FIELD_OP_PLUS;
+ goto out;
+ }
+
+ /*
+ * Multiplication and division have higher precedence than addition and
+ * subtraction.
+ */
+ div_op = strrchr(str, '/');
+ if (div_op)
field_op = FIELD_OP_DIV;
- break;
- case '*':
+
+ mult_op = strrchr(str, '*');
+ /*
+ * For operators of the same precedence use to rightmost as the
+ * root, so that the expression is evaluated left to right.
+ */
+ if (mult_op > div_op)
field_op = FIELD_OP_MULT;
- break;
- default:
- break;
+
+out:
+ if (sep) {
+ switch (field_op) {
+ case FIELD_OP_UNARY_MINUS:
+ case FIELD_OP_MINUS:
+ *sep = minus_op;
+ break;
+ case FIELD_OP_PLUS:
+ *sep = plus_op;
+ break;
+ case FIELD_OP_DIV:
+ *sep = div_op;
+ break;
+ case FIELD_OP_MULT:
+ *sep = mult_op;
+ break;
+ case FIELD_OP_NONE:
+ default:
+ *sep = NULL;
+ break;
+ }
}
return field_op;
@@ -2003,7 +2061,7 @@ static char *field_name_from_var(struct hist_trigger_data *hist_data,
if (strcmp(var_name, name) == 0) {
field = hist_data->attrs->var_defs.expr[i];
- if (contains_operator(field) || is_var_ref(field))
+ if (contains_operator(field, NULL) || is_var_ref(field))
continue;
return field;
}
@@ -2266,21 +2324,24 @@ static struct hist_field *parse_atom(struct hist_trigger_data *hist_data,
static struct hist_field *parse_expr(struct hist_trigger_data *hist_data,
struct trace_event_file *file,
char *str, unsigned long flags,
- char *var_name, unsigned int level);
+ char *var_name, unsigned int *n_subexprs);
static struct hist_field *parse_unary(struct hist_trigger_data *hist_data,
struct trace_event_file *file,
char *str, unsigned long flags,
- char *var_name, unsigned int level)
+ char *var_name, unsigned int *n_subexprs)
{
struct hist_field *operand1, *expr = NULL;
unsigned long operand_flags;
int ret = 0;
char *s;
+ /* Unary minus operator, increment n_subexprs */
+ ++*n_subexprs;
+
/* we support only -(xxx) i.e. explicit parens required */
- if (level > 3) {
+ if (*n_subexprs > 3) {
hist_err(file->tr, HIST_ERR_TOO_MANY_SUBEXPR, errpos(str));
ret = -EINVAL;
goto free;
@@ -2297,8 +2358,16 @@ static struct hist_field *parse_unary(struct hist_trigger_data *hist_data,
}
s = strrchr(str, ')');
- if (s)
+ if (s) {
+ /* unary minus not supported in sub-expressions */
+ if (*(s+1) != '\0') {
+ hist_err(file->tr, HIST_ERR_UNARY_MINUS_SUBEXPR,
+ errpos(str));
+ ret = -EINVAL;
+ goto free;
+ }
*s = '\0';
+ }
else {
ret = -EINVAL; /* no closing ')' */
goto free;
@@ -2312,7 +2381,7 @@ static struct hist_field *parse_unary(struct hist_trigger_data *hist_data,
}
operand_flags = 0;
- operand1 = parse_expr(hist_data, file, str, operand_flags, NULL, ++level);
+ operand1 = parse_expr(hist_data, file, str, operand_flags, NULL, n_subexprs);
if (IS_ERR(operand1)) {
ret = PTR_ERR(operand1);
goto free;
@@ -2382,60 +2451,61 @@ static int check_expr_operands(struct trace_array *tr,
static struct hist_field *parse_expr(struct hist_trigger_data *hist_data,
struct trace_event_file *file,
char *str, unsigned long flags,
- char *var_name, unsigned int level)
+ char *var_name, unsigned int *n_subexprs)
{
struct hist_field *operand1 = NULL, *operand2 = NULL, *expr = NULL;
unsigned long operand_flags;
int field_op, ret = -EINVAL;
char *sep, *operand1_str;
- if (level > 3) {
+ if (*n_subexprs > 3) {
hist_err(file->tr, HIST_ERR_TOO_MANY_SUBEXPR, errpos(str));
return ERR_PTR(-EINVAL);
}
- field_op = contains_operator(str);
+ /*
+ * ".sym-offset" in expressions has no effect on their evaluation,
+ * but can confuse operator parsing.
+ */
+ if (*n_subexprs == 0) {
+ sep = strstr(str, ".sym-offset");
+ if (sep) {
+ *sep = '\0';
+ if (strpbrk(str, "+-/*") || strpbrk(sep + 11, "+-/*")) {
+ *sep = '.';
+ hist_err(file->tr, HIST_ERR_SYM_OFFSET_SUBEXPR,
+ errpos(sep));
+ return ERR_PTR(-EINVAL);
+ }
+ *sep = '.';
+ }
+ }
+
+ field_op = contains_operator(str, &sep);
if (field_op == FIELD_OP_NONE)
return parse_atom(hist_data, file, str, &flags, var_name);
if (field_op == FIELD_OP_UNARY_MINUS)
- return parse_unary(hist_data, file, str, flags, var_name, ++level);
+ return parse_unary(hist_data, file, str, flags, var_name, n_subexprs);
- switch (field_op) {
- case FIELD_OP_MINUS:
- sep = "-";
- break;
- case FIELD_OP_PLUS:
- sep = "+";
- break;
- case FIELD_OP_DIV:
- sep = "/";
- break;
- case FIELD_OP_MULT:
- sep = "*";
- break;
- default:
- goto free;
- }
+ /* Binary operator found, increment n_subexprs */
+ ++*n_subexprs;
- /*
- * Multiplication and division are only supported in single operator
- * expressions, since the expression is always evaluated from right
- * to left.
- */
- if ((field_op == FIELD_OP_DIV || field_op == FIELD_OP_MULT) && level > 0) {
- hist_err(file->tr, HIST_ERR_TOO_MANY_SUBEXPR, errpos(str));
- return ERR_PTR(-EINVAL);
- }
+ /* Split the expression string at the root operator */
+ if (!sep)
+ goto free;
+ *sep = '\0';
+ operand1_str = str;
+ str = sep+1;
- operand1_str = strsep(&str, sep);
if (!operand1_str || !str)
goto free;
operand_flags = 0;
- operand1 = parse_atom(hist_data, file, operand1_str,
- &operand_flags, NULL);
+
+ /* LHS of string is an expression e.g. a+b in a+b+c */
+ operand1 = parse_expr(hist_data, file, operand1_str, operand_flags, NULL, n_subexprs);
if (IS_ERR(operand1)) {
ret = PTR_ERR(operand1);
operand1 = NULL;
@@ -2447,9 +2517,9 @@ static struct hist_field *parse_expr(struct hist_trigger_data *hist_data,
goto free;
}
- /* rest of string could be another expression e.g. b+c in a+b+c */
+ /* RHS of string is another expression e.g. c in a+b+c */
operand_flags = 0;
- operand2 = parse_expr(hist_data, file, str, operand_flags, NULL, ++level);
+ operand2 = parse_expr(hist_data, file, str, operand_flags, NULL, n_subexprs);
if (IS_ERR(operand2)) {
ret = PTR_ERR(operand2);
operand2 = NULL;
@@ -3883,9 +3953,9 @@ static int __create_val_field(struct hist_trigger_data *hist_data,
unsigned long flags)
{
struct hist_field *hist_field;
- int ret = 0;
+ int ret = 0, n_subexprs = 0;
- hist_field = parse_expr(hist_data, file, field_str, flags, var_name, 0);
+ hist_field = parse_expr(hist_data, file, field_str, flags, var_name, &n_subexprs);
if (IS_ERR(hist_field)) {
ret = PTR_ERR(hist_field);
goto out;
@@ -4026,7 +4096,7 @@ static int create_key_field(struct hist_trigger_data *hist_data,
struct hist_field *hist_field = NULL;
unsigned long flags = 0;
unsigned int key_size;
- int ret = 0;
+ int ret = 0, n_subexprs = 0;
if (WARN_ON(key_idx >= HIST_FIELDS_MAX))
return -EINVAL;
@@ -4039,7 +4109,7 @@ static int create_key_field(struct hist_trigger_data *hist_data,
hist_field = create_hist_field(hist_data, NULL, flags, NULL);
} else {
hist_field = parse_expr(hist_data, file, field_str, flags,
- NULL, 0);
+ NULL, &n_subexprs);
if (IS_ERR(hist_field)) {
ret = PTR_ERR(hist_field);
goto out;
--
2.33.0.1079.g6e70778dc9-goog
The division is a slow operation. If the divisor is a power of 2, use a
shift instead.
Results were obtained using Android's version of perf (simpleperf[1]) as
described below:
1. hist_field_div() is modified to call 2 test functions:
test_hist_field_div_[not]_optimized(); passing them the
same args. Use noinline and volatile to ensure these are
not optimized out by the compiler.
2. Create a hist event trigger that uses division:
events/kmem/rss_stat$ echo 'hist:keys=common_pid:x=size/<divisor>'
>> trigger
events/kmem/rss_stat$ echo 'hist:keys=common_pid:vals=$x'
>> trigger
3. Run Android's lmkd_test[2] to generate rss_stat events, and
record CPU samples with Android's simpleperf:
simpleperf record -a --exclude-perf --post-unwind=yes -m 16384 -g
-f 2000 -o perf.data
== Results ==
Divisor is a power of 2 (divisor == 32):
test_hist_field_div_not_optimized | 8,717,091 cpu-cycles
test_hist_field_div_optimized | 1,643,137 cpu-cycles
If the divisor is a power of 2, the optimized version is ~5.3x faster.
Divisor is not a power of 2 (divisor == 33):
test_hist_field_div_not_optimized | 4,444,324 cpu-cycles
test_hist_field_div_optimized | 5,497,958 cpu-cycles
If the divisor is not a power of 2, as expected, the optimized version is
slightly slower (~24% slower).
[1] https://android.googlesource.com/platform/system/extras/+/master/simpleperf/doc/README.md
[2] https://cs.android.com/android/platform/superproject/+/master:system/memory/lmkd/tests/lmkd_test.cpp
Signed-off-by: Kalesh Singh <[email protected]>
Suggested-by: Steven Rostedt <[email protected]>
---
kernel/trace/trace_events_hist.c | 4 ++++
1 file changed, 4 insertions(+)
diff --git a/kernel/trace/trace_events_hist.c b/kernel/trace/trace_events_hist.c
index db28bcf976f4..364cb3091789 100644
--- a/kernel/trace/trace_events_hist.c
+++ b/kernel/trace/trace_events_hist.c
@@ -304,6 +304,10 @@ static u64 hist_field_div(struct hist_field *hist_field,
if (!val2)
return -1;
+ /* Use shift if the divisor is a power of 2 */
+ if (!(val2 & (val2 - 1)))
+ return val1 >> __ffs64(val2);
+
return div64_u64(val1, val2);
}
--
2.33.0.1079.g6e70778dc9-goog
Adds basic support for division and multiplication operations for
hist trigger variable expressions.
For simplicity this patch only supports, division and multiplication
for a single operation expression (e.g. x=$a/$b), as currently
expressions are always evaluated right to left. This can lead to some
incorrect results:
e.g. echo 'hist:keys=common_pid:x=8-4-2' >> event/trigger
8-4-2 should evaluate to 2 i.e. (8-4)-2
but currently x evaluate to 6 i.e. 8-(4-2)
Multiplication and division in sub-expressions will work correctly, once
correct operator precedence support is added (See next patch in this
series).
For the undefined case of division by 0, the histogram expression
evaluates to (u64)(-1). Since this cannot be detected when the
expression is created, it is the responsibility of the user to be
aware and account for this possibility.
Examples:
echo 'hist:keys=common_pid:a=8,b=4,x=$a/$b' \
>> event/trigger
echo 'hist:keys=common_pid:y=5*$b' \
>> event/trigger
Signed-off-by: Kalesh Singh <[email protected]>
---
Changes in v2:
- Use div64 helper in hist_field_div() to avoid faults on
x86 32-bit machines, per Steven Rostedt
kernel/trace/trace_events_hist.c | 72 +++++++++++++++++++++++++++++++-
1 file changed, 71 insertions(+), 1 deletion(-)
diff --git a/kernel/trace/trace_events_hist.c b/kernel/trace/trace_events_hist.c
index 28f711224944..522355a06f58 100644
--- a/kernel/trace/trace_events_hist.c
+++ b/kernel/trace/trace_events_hist.c
@@ -97,6 +97,8 @@ enum field_op_id {
FIELD_OP_PLUS,
FIELD_OP_MINUS,
FIELD_OP_UNARY_MINUS,
+ FIELD_OP_DIV,
+ FIELD_OP_MULT,
};
/*
@@ -285,6 +287,40 @@ static u64 hist_field_minus(struct hist_field *hist_field,
return val1 - val2;
}
+static u64 hist_field_div(struct hist_field *hist_field,
+ struct tracing_map_elt *elt,
+ struct trace_buffer *buffer,
+ struct ring_buffer_event *rbe,
+ void *event)
+{
+ struct hist_field *operand1 = hist_field->operands[0];
+ struct hist_field *operand2 = hist_field->operands[1];
+
+ u64 val1 = operand1->fn(operand1, elt, buffer, rbe, event);
+ u64 val2 = operand2->fn(operand2, elt, buffer, rbe, event);
+
+ /* Return -1 for the undefined case */
+ if (!val2)
+ return -1;
+
+ return div64_u64(val1, val2);
+}
+
+static u64 hist_field_mult(struct hist_field *hist_field,
+ struct tracing_map_elt *elt,
+ struct trace_buffer *buffer,
+ struct ring_buffer_event *rbe,
+ void *event)
+{
+ struct hist_field *operand1 = hist_field->operands[0];
+ struct hist_field *operand2 = hist_field->operands[1];
+
+ u64 val1 = operand1->fn(operand1, elt, buffer, rbe, event);
+ u64 val2 = operand2->fn(operand2, elt, buffer, rbe, event);
+
+ return val1 * val2;
+}
+
static u64 hist_field_unary_minus(struct hist_field *hist_field,
struct tracing_map_elt *elt,
struct trace_buffer *buffer,
@@ -1592,6 +1628,12 @@ static char *expr_str(struct hist_field *field, unsigned int level)
case FIELD_OP_PLUS:
strcat(expr, "+");
break;
+ case FIELD_OP_DIV:
+ strcat(expr, "/");
+ break;
+ case FIELD_OP_MULT:
+ strcat(expr, "*");
+ break;
default:
kfree(expr);
return NULL;
@@ -1607,7 +1649,7 @@ static int contains_operator(char *str)
enum field_op_id field_op = FIELD_OP_NONE;
char *op;
- op = strpbrk(str, "+-");
+ op = strpbrk(str, "+-/*");
if (!op)
return FIELD_OP_NONE;
@@ -1628,6 +1670,12 @@ static int contains_operator(char *str)
case '+':
field_op = FIELD_OP_PLUS;
break;
+ case '/':
+ field_op = FIELD_OP_DIV;
+ break;
+ case '*':
+ field_op = FIELD_OP_MULT;
+ break;
default:
break;
}
@@ -2361,10 +2409,26 @@ static struct hist_field *parse_expr(struct hist_trigger_data *hist_data,
case FIELD_OP_PLUS:
sep = "+";
break;
+ case FIELD_OP_DIV:
+ sep = "/";
+ break;
+ case FIELD_OP_MULT:
+ sep = "*";
+ break;
default:
goto free;
}
+ /*
+ * Multiplication and division are only supported in single operator
+ * expressions, since the expression is always evaluated from right
+ * to left.
+ */
+ if ((field_op == FIELD_OP_DIV || field_op == FIELD_OP_MULT) && level > 0) {
+ hist_err(file->tr, HIST_ERR_TOO_MANY_SUBEXPR, errpos(str));
+ return ERR_PTR(-EINVAL);
+ }
+
operand1_str = strsep(&str, sep);
if (!operand1_str || !str)
goto free;
@@ -2436,6 +2500,12 @@ static struct hist_field *parse_expr(struct hist_trigger_data *hist_data,
case FIELD_OP_PLUS:
expr->fn = hist_field_plus;
break;
+ case FIELD_OP_DIV:
+ expr->fn = hist_field_div;
+ break;
+ case FIELD_OP_MULT:
+ expr->fn = hist_field_mult;
+ break;
default:
ret = -EINVAL;
goto free;
--
2.33.0.1079.g6e70778dc9-goog
Histogram expressions now support division, and multiplication in
addition to the already supported subtraction and addition operators.
Numeric constants can also be used in a hist trigger expressions
or assigned to a variable and used by refernce in an expression.
Signed-off-by: Kalesh Singh <[email protected]>
Reviewed-by: Namhyung Kim <[email protected]>
---
Changes in v2:
- Add Namhyung's Reviewed-by
Documentation/trace/histogram.rst | 14 ++++++++++++++
1 file changed, 14 insertions(+)
diff --git a/Documentation/trace/histogram.rst b/Documentation/trace/histogram.rst
index 533415644c54..e12699abaee8 100644
--- a/Documentation/trace/histogram.rst
+++ b/Documentation/trace/histogram.rst
@@ -1763,6 +1763,20 @@ using the same key and variable from yet another event::
# echo 'hist:key=pid:wakeupswitch_lat=$wakeup_lat+$switchtime_lat ...' >> event3/trigger
+Expressions support the use of addition, subtraction, multiplication and
+division operators (+-*/).
+
+Note that division by zero always returns -1.
+
+Numeric constants can also be used directly in an expression::
+
+ # echo 'hist:keys=next_pid:timestamp_secs=common_timestamp/1000000 ...' >> event/trigger
+
+or assigned to a variable and referenced in a subsequent expression::
+
+ # echo 'hist:keys=next_pid:us_per_sec=1000000 ...' >> event/trigger
+ # echo 'hist:keys=next_pid:timestamp_secs=common_timestamp/$us_per_sec ...' >> event/trigger
+
2.2.2 Synthetic Events
----------------------
--
2.33.0.1079.g6e70778dc9-goog
Add tests for the parsing of hist trigger expressions; and to
validate expression evaluation.
Signed-off-by: Kalesh Singh <[email protected]>
Reviewed-by: Namhyung Kim <[email protected]>
---
Changes in v3:
- Remove .sym-offset error check tests
Changes in v2:
- Add Namhyung's Reviewed-by
- Update comment to clarify err_pos in "Too many subexpressions" test
.../testing/selftests/ftrace/test.d/functions | 4 +-
.../trigger/trigger-hist-expressions.tc | 72 +++++++++++++++++++
2 files changed, 74 insertions(+), 2 deletions(-)
create mode 100644 tools/testing/selftests/ftrace/test.d/trigger/trigger-hist-expressions.tc
diff --git a/tools/testing/selftests/ftrace/test.d/functions b/tools/testing/selftests/ftrace/test.d/functions
index 000fd05e84b1..1855a63559ad 100644
--- a/tools/testing/selftests/ftrace/test.d/functions
+++ b/tools/testing/selftests/ftrace/test.d/functions
@@ -16,13 +16,13 @@ reset_tracer() { # reset the current tracer
reset_trigger_file() {
# remove action triggers first
- grep -H ':on[^:]*(' $@ |
+ grep -H ':on[^:]*(' $@ | tac |
while read line; do
cmd=`echo $line | cut -f2- -d: | cut -f1 -d"["`
file=`echo $line | cut -f1 -d:`
echo "!$cmd" >> $file
done
- grep -Hv ^# $@ |
+ grep -Hv ^# $@ | tac |
while read line; do
cmd=`echo $line | cut -f2- -d: | cut -f1 -d"["`
file=`echo $line | cut -f1 -d:`
diff --git a/tools/testing/selftests/ftrace/test.d/trigger/trigger-hist-expressions.tc b/tools/testing/selftests/ftrace/test.d/trigger/trigger-hist-expressions.tc
new file mode 100644
index 000000000000..e715641c54d3
--- /dev/null
+++ b/tools/testing/selftests/ftrace/test.d/trigger/trigger-hist-expressions.tc
@@ -0,0 +1,72 @@
+#!/bin/sh
+# SPDX-License-Identifier: GPL-2.0
+# description: event trigger - test histogram expression parsing
+# requires: set_event events/sched/sched_process_fork/trigger events/sched/sched_process_fork/hist error_log
+
+
+fail() { #msg
+ echo $1
+ exit_fail
+}
+
+get_hist_var() { #var_name hist_path
+ hist_output=`grep -m1 "$1: " $2`
+ hitcount=`echo $hist_output | awk '{ for (i=1; i<=NF; ++i) { if ($i ~ "hitcount:") print $(i+1)} }'`
+ var_sum=`echo $hist_output | awk '{ for (i=1; i<=NF; ++i) { if ($i ~ "'$1':") print $(i+1)} }'`
+ var_val=$(( var_sum / hitcount ))
+ echo $var_val
+}
+
+test_hist_expr() { # test_name expression expected_val
+ reset_trigger
+
+ echo "Test hist trigger expressions - $1"
+
+ echo "hist:keys=common_pid:x=$2" > events/sched/sched_process_fork/trigger
+ echo 'hist:keys=common_pid:vals=$x' >> events/sched/sched_process_fork/trigger
+ for i in `seq 1 10` ; do ( echo "forked" > /dev/null); done
+
+ actual=`get_hist_var x events/sched/sched_process_fork/hist`
+
+ if [ $actual != $3 ]; then
+ fail "Failed hist trigger expression evaluation: Expression: $2 Expected: $3, Actual: $actual"
+ fi
+
+ reset_trigger
+}
+
+check_error() { # test_name command-with-error-pos-by-^
+ reset_trigger
+
+ echo "Test hist trigger expressions - $1"
+ ftrace_errlog_check 'hist:sched:sched_process_fork' "$2" 'events/sched/sched_process_fork/trigger'
+
+ reset_trigger
+}
+
+test_hist_expr "Variable assignment" "123" "123"
+
+test_hist_expr "Subtraction not associative" "16-8-4-2" "2"
+
+test_hist_expr "Division not associative" "64/8/4/2" "1"
+
+test_hist_expr "Same precedence operators (+,-) evaluated left to right" "16-8+4+2" "14"
+
+test_hist_expr "Same precedence operators (*,/) evaluated left to right" "4*3/2*2" "12"
+
+test_hist_expr "Multiplication evaluated before addition/subtraction" "4+3*2-2" "8"
+
+test_hist_expr "Division evaluated before addition/subtraction" "4+6/2-2" "5"
+
+# Division by zero returns -1
+test_hist_expr "Handles division by zero" "3/0" "-1"
+
+# err pos for "too many subexpressions" is dependent on where
+# the last subexpression was detected. This can vary depending
+# on how the expression tree was generated.
+check_error "Too many subexpressions" 'hist:keys=common_pid:x=32+^10*3/20-4'
+check_error "Too many subexpressions" 'hist:keys=common_pid:x=^1+2+3+4+5'
+
+check_error "Unary minus not supported in subexpression" 'hist:keys=common_pid:x=-(^1)+2'
+
+exit 0
--
2.33.0.1079.g6e70778dc9-goog
Currently hist trigger expressions don't support the use of numeric
literals:
e.g. echo 'hist:keys=common_pid:x=$y-1234'
--> is not valid expression syntax
Having the ability to use numeric constants in hist triggers supports
a wider range of expressions for creating variables.
Add support for creating trace event histogram variables from numeric
literals.
e.g. echo 'hist:keys=common_pid:x=1234,y=size-1024' >> event/trigger
A negative numeric constant is created, using unary minus operator
(parentheses are required).
e.g. echo 'hist:keys=common_pid:z=-(2)' >> event/trigger
Constants can be used with division/multiplication (added in the
next patch in this series) to implement granularity filters for frequent
trace events. For instance we can limit emitting the rss_stat
trace event to when there is a 512KB cross over in the rss size:
# Create a synthetic event to monitor instead of the high frequency
# rss_stat event
echo 'rss_stat_throttled unsigned int mm_id; unsigned int curr;
int member; long size' >> tracing/synthetic_events
# Create a hist trigger that emits the synthetic rss_stat_throttled
# event only when the rss size crosses a 512KB boundary.
echo 'hist:keys=keys=mm_id,member:bucket=size/0x80000:onchange($bucket)
.rss_stat_throttled(mm_id,curr,member,size)'
>> events/kmem/rss_stat/trigger
A use case for using constants with addition/subtraction is not yet
known, but for completeness the use of constants are supported for all
operators.
Signed-off-by: Kalesh Singh <[email protected]>
---
Changes in v3:
- Remove the limit on the number of constants that can be created,
per Steven Rostedt
Changes in v2:
- Add description of use case for constants in arithmetic
operations in commit message, per Steven Rostedt
- Add Namhyung's Reviewed-by
kernel/trace/trace_events_hist.c | 71 +++++++++++++++++++++++++++++++-
1 file changed, 70 insertions(+), 1 deletion(-)
diff --git a/kernel/trace/trace_events_hist.c b/kernel/trace/trace_events_hist.c
index f01e442716e2..28f711224944 100644
--- a/kernel/trace/trace_events_hist.c
+++ b/kernel/trace/trace_events_hist.c
@@ -66,7 +66,8 @@
C(EMPTY_SORT_FIELD, "Empty sort field"), \
C(TOO_MANY_SORT_FIELDS, "Too many sort fields (Max = 2)"), \
C(INVALID_SORT_FIELD, "Sort field must be a key or a val"), \
- C(INVALID_STR_OPERAND, "String type can not be an operand in expression"),
+ C(INVALID_STR_OPERAND, "String type can not be an operand in expression"), \
+ C(EXPECT_NUMBER, "Expecting numeric literal"),
#undef C
#define C(a, b) HIST_ERR_##a
@@ -89,6 +90,7 @@ typedef u64 (*hist_field_fn_t) (struct hist_field *field,
#define HIST_FIELD_OPERANDS_MAX 2
#define HIST_FIELDS_MAX (TRACING_MAP_FIELDS_MAX + TRACING_MAP_VARS_MAX)
#define HIST_ACTIONS_MAX 8
+#define HIST_CONST_DIGITS_MAX 21
enum field_op_id {
FIELD_OP_NONE,
@@ -152,6 +154,9 @@ struct hist_field {
bool read_once;
unsigned int var_str_idx;
+
+ /* Numeric literals are represented as u64 */
+ u64 constant;
};
static u64 hist_field_none(struct hist_field *field,
@@ -163,6 +168,15 @@ static u64 hist_field_none(struct hist_field *field,
return 0;
}
+static u64 hist_field_const(struct hist_field *field,
+ struct tracing_map_elt *elt,
+ struct trace_buffer *buffer,
+ struct ring_buffer_event *rbe,
+ void *event)
+{
+ return field->constant;
+}
+
static u64 hist_field_counter(struct hist_field *field,
struct tracing_map_elt *elt,
struct trace_buffer *buffer,
@@ -341,6 +355,7 @@ enum hist_field_flags {
HIST_FIELD_FL_CPU = 1 << 15,
HIST_FIELD_FL_ALIAS = 1 << 16,
HIST_FIELD_FL_BUCKET = 1 << 17,
+ HIST_FIELD_FL_CONST = 1 << 18,
};
struct var_defs {
@@ -1516,6 +1531,12 @@ static void expr_field_str(struct hist_field *field, char *expr)
{
if (field->flags & HIST_FIELD_FL_VAR_REF)
strcat(expr, "$");
+ else if (field->flags & HIST_FIELD_FL_CONST) {
+ char str[HIST_CONST_DIGITS_MAX];
+
+ snprintf(str, HIST_CONST_DIGITS_MAX, "%llu", field->constant);
+ strcat(expr, str);
+ }
strcat(expr, hist_field_name(field, 0));
@@ -1689,6 +1710,15 @@ static struct hist_field *create_hist_field(struct hist_trigger_data *hist_data,
goto out;
}
+ if (flags & HIST_FIELD_FL_CONST) {
+ hist_field->fn = hist_field_const;
+ hist_field->size = sizeof(u64);
+ hist_field->type = kstrdup("u64", GFP_KERNEL);
+ if (!hist_field->type)
+ goto free;
+ goto out;
+ }
+
if (flags & HIST_FIELD_FL_STACKTRACE) {
hist_field->fn = hist_field_none;
goto out;
@@ -2090,6 +2120,29 @@ static struct hist_field *create_alias(struct hist_trigger_data *hist_data,
return alias;
}
+static struct hist_field *parse_const(struct hist_trigger_data *hist_data,
+ char *str, char *var_name,
+ unsigned long *flags)
+{
+ struct trace_array *tr = hist_data->event_file->tr;
+ struct hist_field *field = NULL;
+ u64 constant;
+
+ if (kstrtoull(str, 0, &constant)) {
+ hist_err(tr, HIST_ERR_EXPECT_NUMBER, errpos(str));
+ return NULL;
+ }
+
+ *flags |= HIST_FIELD_FL_CONST;
+ field = create_hist_field(hist_data, NULL, *flags, var_name);
+ if (!field)
+ return NULL;
+
+ field->constant = constant;
+
+ return field;
+}
+
static struct hist_field *parse_atom(struct hist_trigger_data *hist_data,
struct trace_event_file *file, char *str,
unsigned long *flags, char *var_name)
@@ -2100,6 +2153,15 @@ static struct hist_field *parse_atom(struct hist_trigger_data *hist_data,
unsigned long buckets = 0;
int ret = 0;
+ if (isdigit(str[0])) {
+ hist_field = parse_const(hist_data, str, var_name, flags);
+ if (!hist_field) {
+ ret = -EINVAL;
+ goto out;
+ }
+ return hist_field;
+ }
+
s = strchr(str, '.');
if (s) {
s = strchr(++s, '.');
@@ -4950,6 +5012,8 @@ static void hist_field_debug_show_flags(struct seq_file *m,
if (flags & HIST_FIELD_FL_ALIAS)
seq_puts(m, " HIST_FIELD_FL_ALIAS\n");
+ else if (flags & HIST_FIELD_FL_CONST)
+ seq_puts(m, " HIST_FIELD_FL_CONST\n");
}
static int hist_field_debug_show(struct seq_file *m,
@@ -4971,6 +5035,9 @@ static int hist_field_debug_show(struct seq_file *m,
field->var.idx);
}
+ if (field->flags & HIST_FIELD_FL_CONST)
+ seq_printf(m, " constant: %llu\n", field->constant);
+
if (field->flags & HIST_FIELD_FL_ALIAS)
seq_printf(m, " var_ref_idx (into hist_data->var_refs[]): %u\n",
field->var_ref_idx);
@@ -5213,6 +5280,8 @@ static void hist_field_print(struct seq_file *m, struct hist_field *hist_field)
if (hist_field->flags & HIST_FIELD_FL_CPU)
seq_puts(m, "common_cpu");
+ else if (hist_field->flags & HIST_FIELD_FL_CONST)
+ seq_printf(m, "%llu", hist_field->constant);
else if (field_name) {
if (hist_field->flags & HIST_FIELD_FL_VAR_REF ||
hist_field->flags & HIST_FIELD_FL_ALIAS)
--
2.33.0.1079.g6e70778dc9-goog
If both operands of a hist trigger expression are constants, convert the
expression to a constant. This optimization avoids having to perform the
same calculation multiple times and also saves on memory since the
merged constants are represented by a single struct hist_field instead
or multiple.
Signed-off-by: Kalesh Singh <[email protected]>
Suggested-by: Steven Rostedt <[email protected]>
---
kernel/trace/trace_events_hist.c | 104 ++++++++++++++++++++++---------
1 file changed, 74 insertions(+), 30 deletions(-)
diff --git a/kernel/trace/trace_events_hist.c b/kernel/trace/trace_events_hist.c
index 34aba07d23f8..db28bcf976f4 100644
--- a/kernel/trace/trace_events_hist.c
+++ b/kernel/trace/trace_events_hist.c
@@ -2411,9 +2411,15 @@ static struct hist_field *parse_unary(struct hist_trigger_data *hist_data,
return ERR_PTR(ret);
}
+/*
+ * If the operands are var refs, return pointers the
+ * variable(s) referenced in var1 and var2, else NULL.
+ */
static int check_expr_operands(struct trace_array *tr,
struct hist_field *operand1,
- struct hist_field *operand2)
+ struct hist_field *operand2,
+ struct hist_field **var1,
+ struct hist_field **var2)
{
unsigned long operand1_flags = operand1->flags;
unsigned long operand2_flags = operand2->flags;
@@ -2426,6 +2432,7 @@ static int check_expr_operands(struct trace_array *tr,
if (!var)
return -EINVAL;
operand1_flags = var->flags;
+ *var1 = var;
}
if ((operand2_flags & HIST_FIELD_FL_VAR_REF) ||
@@ -2436,6 +2443,7 @@ static int check_expr_operands(struct trace_array *tr,
if (!var)
return -EINVAL;
operand2_flags = var->flags;
+ *var2 = var;
}
if ((operand1_flags & HIST_FIELD_FL_TIMESTAMP_USECS) !=
@@ -2453,9 +2461,12 @@ static struct hist_field *parse_expr(struct hist_trigger_data *hist_data,
char *var_name, unsigned int *n_subexprs)
{
struct hist_field *operand1 = NULL, *operand2 = NULL, *expr = NULL;
- unsigned long operand_flags;
+ struct hist_field *var1 = NULL, *var2 = NULL;
+ unsigned long operand_flags, operand2_flags;
int field_op, ret = -EINVAL;
char *sep, *operand1_str;
+ hist_field_fn_t op_fn;
+ bool combine_consts;
if (*n_subexprs > 3) {
hist_err(file->tr, HIST_ERR_TOO_MANY_SUBEXPR, errpos(str));
@@ -2512,11 +2523,38 @@ static struct hist_field *parse_expr(struct hist_trigger_data *hist_data,
goto free;
}
- ret = check_expr_operands(file->tr, operand1, operand2);
+ switch (field_op) {
+ case FIELD_OP_MINUS:
+ op_fn = hist_field_minus;
+ break;
+ case FIELD_OP_PLUS:
+ op_fn = hist_field_plus;
+ break;
+ case FIELD_OP_DIV:
+ op_fn = hist_field_div;
+ break;
+ case FIELD_OP_MULT:
+ op_fn = hist_field_mult;
+ break;
+ default:
+ ret = -EINVAL;
+ goto free;
+ }
+
+ ret = check_expr_operands(file->tr, operand1, operand2, &var1, &var2);
if (ret)
goto free;
- flags |= HIST_FIELD_FL_EXPR;
+ operand_flags = var1 ? var1->flags : operand1->flags;
+ operand2_flags = var2 ? var2->flags : operand2->flags;
+
+ /*
+ * If both operands are constant, the expression can be
+ * collapsed to a single constant.
+ */
+ combine_consts = operand_flags & operand2_flags & HIST_FIELD_FL_CONST;
+
+ flags |= combine_consts ? HIST_FIELD_FL_CONST : HIST_FIELD_FL_EXPR;
flags |= operand1->flags &
(HIST_FIELD_FL_TIMESTAMP | HIST_FIELD_FL_TIMESTAMP_USECS);
@@ -2533,37 +2571,43 @@ static struct hist_field *parse_expr(struct hist_trigger_data *hist_data,
expr->operands[0] = operand1;
expr->operands[1] = operand2;
- /* The operand sizes should be the same, so just pick one */
- expr->size = operand1->size;
+ if (combine_consts) {
+ if (var1)
+ expr->operands[0] = var1;
+ if (var2)
+ expr->operands[1] = var2;
- expr->operator = field_op;
- expr->name = expr_str(expr, 0);
- expr->type = kstrdup_const(operand1->type, GFP_KERNEL);
- if (!expr->type) {
- ret = -ENOMEM;
- goto free;
- }
+ expr->constant = op_fn(expr, NULL, NULL, NULL, NULL);
- switch (field_op) {
- case FIELD_OP_MINUS:
- expr->fn = hist_field_minus;
- break;
- case FIELD_OP_PLUS:
- expr->fn = hist_field_plus;
- break;
- case FIELD_OP_DIV:
- expr->fn = hist_field_div;
- break;
- case FIELD_OP_MULT:
- expr->fn = hist_field_mult;
- break;
- default:
- ret = -EINVAL;
- goto free;
+ expr->operands[0] = NULL;
+ expr->operands[1] = NULL;
+
+ /*
+ * var refs won't be destroyed immediately
+ * See: destroy_hist_field()
+ */
+ destroy_hist_field(operand2, 0);
+ destroy_hist_field(operand1, 0);
+
+ expr->name = expr_str(expr, 0);
+ } else {
+ expr->fn = op_fn;
+
+ /* The operand sizes should be the same, so just pick one */
+ expr->size = operand1->size;
+
+ expr->operator = field_op;
+ expr->type = kstrdup_const(operand1->type, GFP_KERNEL);
+ if (!expr->type) {
+ ret = -ENOMEM;
+ goto free;
+ }
+
+ expr->name = expr_str(expr, 0);
}
return expr;
- free:
+free:
destroy_hist_field(operand1, 0);
destroy_hist_field(operand2, 0);
destroy_hist_field(expr, 0);
--
2.33.0.1079.g6e70778dc9-goog
The '-' in .sym-offset can confuse the hist trigger arithmetic
expression parsing. Simplify the handling of this by replacing the
'sym-offset' with 'symXoffset'. This allows us to correctly evaluate
expressions where the user may have inadvertently added a .sym-offset
modifier to one of the operands in an expression, instead of bailing
out. In this case the .sym-offset has no effect on the evaluation of the
expression. The only valid use of the .sym-offset is as a hist key
modifier.
Signed-off-by: Kalesh Singh <[email protected]>
Suggested-by: Steven Rostedt <[email protected]>
---
kernel/trace/trace_events_hist.c | 43 +++++++++++++-------------------
1 file changed, 17 insertions(+), 26 deletions(-)
diff --git a/kernel/trace/trace_events_hist.c b/kernel/trace/trace_events_hist.c
index e10c7d9611e5..34aba07d23f8 100644
--- a/kernel/trace/trace_events_hist.c
+++ b/kernel/trace/trace_events_hist.c
@@ -68,8 +68,7 @@
C(INVALID_SORT_FIELD, "Sort field must be a key or a val"), \
C(INVALID_STR_OPERAND, "String type can not be an operand in expression"), \
C(EXPECT_NUMBER, "Expecting numeric literal"), \
- C(UNARY_MINUS_SUBEXPR, "Unary minus not supported in sub-expressions"), \
- C(SYM_OFFSET_SUBEXPR, ".sym-offset not supported in sub-expressions"),
+ C(UNARY_MINUS_SUBEXPR, "Unary minus not supported in sub-expressions"),
#undef C
#define C(a, b) HIST_ERR_##a
@@ -1672,10 +1671,6 @@ static int contains_operator(char *str, char **sep)
*/
minus_op = strrchr(str, '-');
if (minus_op) {
- /* Unfortunately, the modifier ".sym-offset" can confuse things. */
- if (minus_op - str >= 4 && !strncmp(minus_op - 4, ".sym-offset", 11))
- goto out;
-
/*
* Unary minus is not supported in sub-expressions. If
* present, it is always the next root operator.
@@ -2138,7 +2133,11 @@ parse_field(struct hist_trigger_data *hist_data, struct trace_event_file *file,
*flags |= HIST_FIELD_FL_HEX;
else if (strcmp(modifier, "sym") == 0)
*flags |= HIST_FIELD_FL_SYM;
- else if (strcmp(modifier, "sym-offset") == 0)
+ /*
+ * 'sym-offset' occurrences in the trigger string are modified
+ * to 'symXoffset' to simplify arithmetic expression parsing.
+ */
+ else if (strcmp(modifier, "symXoffset") == 0)
*flags |= HIST_FIELD_FL_SYM_OFFSET;
else if ((strcmp(modifier, "execname") == 0) &&
(strcmp(field_name, "common_pid") == 0))
@@ -2463,24 +2462,6 @@ static struct hist_field *parse_expr(struct hist_trigger_data *hist_data,
return ERR_PTR(-EINVAL);
}
- /*
- * ".sym-offset" in expressions has no effect on their evaluation,
- * but can confuse operator parsing.
- */
- if (*n_subexprs == 0) {
- sep = strstr(str, ".sym-offset");
- if (sep) {
- *sep = '\0';
- if (strpbrk(str, "+-/*") || strpbrk(sep + 11, "+-/*")) {
- *sep = '.';
- hist_err(file->tr, HIST_ERR_SYM_OFFSET_SUBEXPR,
- errpos(sep));
- return ERR_PTR(-EINVAL);
- }
- *sep = '.';
- }
- }
-
field_op = contains_operator(str, &sep);
if (field_op == FIELD_OP_NONE)
@@ -6004,7 +5985,7 @@ static int event_hist_trigger_func(struct event_command *cmd_ops,
struct synth_event *se;
const char *se_name;
bool remove = false;
- char *trigger, *p;
+ char *trigger, *p, *start;
int ret = 0;
lockdep_assert_held(&event_mutex);
@@ -6052,6 +6033,16 @@ static int event_hist_trigger_func(struct event_command *cmd_ops,
trigger = strstrip(trigger);
}
+ /*
+ * To simplify arithmetic expression parsing, replace occurrences of
+ * '.sym-offset' modifier with '.symXoffset'
+ */
+ start = strstr(trigger, ".sym-offset");
+ while (start) {
+ *(start + 4) = 'X';
+ start = strstr(start + 11, ".sym-offset");
+ };
+
attrs = parse_hist_trigger_attrs(file->tr, trigger);
if (IS_ERR(attrs))
return PTR_ERR(attrs);
--
2.33.0.1079.g6e70778dc9-goog
Hi Kalesh,
On Mon, 25 Oct 2021 13:08:39 -0700
Kalesh Singh <[email protected]> wrote:
> Add tests for the parsing of hist trigger expressions; and to
> validate expression evaluation.
>
> Signed-off-by: Kalesh Singh <[email protected]>
> Reviewed-by: Namhyung Kim <[email protected]>
> ---
>
> Changes in v3:
> - Remove .sym-offset error check tests
>
> Changes in v2:
> - Add Namhyung's Reviewed-by
> - Update comment to clarify err_pos in "Too many subexpressions" test
>
>
> .../testing/selftests/ftrace/test.d/functions | 4 +-
> .../trigger/trigger-hist-expressions.tc | 72 +++++++++++++++++++
> 2 files changed, 74 insertions(+), 2 deletions(-)
> create mode 100644 tools/testing/selftests/ftrace/test.d/trigger/trigger-hist-expressions.tc
>
> diff --git a/tools/testing/selftests/ftrace/test.d/functions b/tools/testing/selftests/ftrace/test.d/functions
> index 000fd05e84b1..1855a63559ad 100644
> --- a/tools/testing/selftests/ftrace/test.d/functions
> +++ b/tools/testing/selftests/ftrace/test.d/functions
> @@ -16,13 +16,13 @@ reset_tracer() { # reset the current tracer
>
> reset_trigger_file() {
> # remove action triggers first
> - grep -H ':on[^:]*(' $@ |
> + grep -H ':on[^:]*(' $@ | tac |
> while read line; do
> cmd=`echo $line | cut -f2- -d: | cut -f1 -d"["`
> file=`echo $line | cut -f1 -d:`
> echo "!$cmd" >> $file
> done
> - grep -Hv ^# $@ |
> + grep -Hv ^# $@ | tac |
> while read line; do
> cmd=`echo $line | cut -f2- -d: | cut -f1 -d"["`
> file=`echo $line | cut -f1 -d:`
If this update has any meaning, please make a separate patch for this part.
> diff --git a/tools/testing/selftests/ftrace/test.d/trigger/trigger-hist-expressions.tc b/tools/testing/selftests/ftrace/test.d/trigger/trigger-hist-expressions.tc
> new file mode 100644
> index 000000000000..e715641c54d3
> --- /dev/null
> +++ b/tools/testing/selftests/ftrace/test.d/trigger/trigger-hist-expressions.tc
> @@ -0,0 +1,72 @@
> +#!/bin/sh
> +# SPDX-License-Identifier: GPL-2.0
> +# description: event trigger - test histogram expression parsing
> +# requires: set_event events/sched/sched_process_fork/trigger events/sched/sched_process_fork/hist error_log
Hmm, are there any way to check the running kernel supports this feature?
Because the latest version of the kselftest is expected to run on the old stable
kernel for testing, the testcase should check whether the kernel supports this
testing feature or not. (That's why the requires tag supports README pattern check)
So, at first if you didn't update the <tracefs>/README, please update it first
to show the new syntax is supported, and add "SOME-PATTERN":README to the
requires tag.
Thank you,
> +
> +
> +fail() { #msg
> + echo $1
> + exit_fail
> +}
> +
> +get_hist_var() { #var_name hist_path
> + hist_output=`grep -m1 "$1: " $2`
> + hitcount=`echo $hist_output | awk '{ for (i=1; i<=NF; ++i) { if ($i ~ "hitcount:") print $(i+1)} }'`
> + var_sum=`echo $hist_output | awk '{ for (i=1; i<=NF; ++i) { if ($i ~ "'$1':") print $(i+1)} }'`
> + var_val=$(( var_sum / hitcount ))
> + echo $var_val
> +}
> +
> +test_hist_expr() { # test_name expression expected_val
> + reset_trigger
> +
> + echo "Test hist trigger expressions - $1"
> +
> + echo "hist:keys=common_pid:x=$2" > events/sched/sched_process_fork/trigger
> + echo 'hist:keys=common_pid:vals=$x' >> events/sched/sched_process_fork/trigger
> + for i in `seq 1 10` ; do ( echo "forked" > /dev/null); done
> +
> + actual=`get_hist_var x events/sched/sched_process_fork/hist`
> +
> + if [ $actual != $3 ]; then
> + fail "Failed hist trigger expression evaluation: Expression: $2 Expected: $3, Actual: $actual"
> + fi
> +
> + reset_trigger
> +}
> +
> +check_error() { # test_name command-with-error-pos-by-^
> + reset_trigger
> +
> + echo "Test hist trigger expressions - $1"
> + ftrace_errlog_check 'hist:sched:sched_process_fork' "$2" 'events/sched/sched_process_fork/trigger'
> +
> + reset_trigger
> +}
> +
> +test_hist_expr "Variable assignment" "123" "123"
> +
> +test_hist_expr "Subtraction not associative" "16-8-4-2" "2"
> +
> +test_hist_expr "Division not associative" "64/8/4/2" "1"
> +
> +test_hist_expr "Same precedence operators (+,-) evaluated left to right" "16-8+4+2" "14"
> +
> +test_hist_expr "Same precedence operators (*,/) evaluated left to right" "4*3/2*2" "12"
> +
> +test_hist_expr "Multiplication evaluated before addition/subtraction" "4+3*2-2" "8"
> +
> +test_hist_expr "Division evaluated before addition/subtraction" "4+6/2-2" "5"
> +
> +# Division by zero returns -1
> +test_hist_expr "Handles division by zero" "3/0" "-1"
> +
> +# err pos for "too many subexpressions" is dependent on where
> +# the last subexpression was detected. This can vary depending
> +# on how the expression tree was generated.
> +check_error "Too many subexpressions" 'hist:keys=common_pid:x=32+^10*3/20-4'
> +check_error "Too many subexpressions" 'hist:keys=common_pid:x=^1+2+3+4+5'
> +
> +check_error "Unary minus not supported in subexpression" 'hist:keys=common_pid:x=-(^1)+2'
> +
> +exit 0
> --
> 2.33.0.1079.g6e70778dc9-goog
>
--
Masami Hiramatsu <[email protected]>
On Tue, Oct 26, 2021 at 5:43 AM Masami Hiramatsu <[email protected]> wrote:
>
> Hi Kalesh,
>
> On Mon, 25 Oct 2021 13:08:39 -0700
> Kalesh Singh <[email protected]> wrote:
>
> > Add tests for the parsing of hist trigger expressions; and to
> > validate expression evaluation.
> >
> > Signed-off-by: Kalesh Singh <[email protected]>
> > Reviewed-by: Namhyung Kim <[email protected]>
> > ---
> >
> > Changes in v3:
> > - Remove .sym-offset error check tests
> >
> > Changes in v2:
> > - Add Namhyung's Reviewed-by
> > - Update comment to clarify err_pos in "Too many subexpressions" test
> >
> >
> > .../testing/selftests/ftrace/test.d/functions | 4 +-
> > .../trigger/trigger-hist-expressions.tc | 72 +++++++++++++++++++
> > 2 files changed, 74 insertions(+), 2 deletions(-)
> > create mode 100644 tools/testing/selftests/ftrace/test.d/trigger/trigger-hist-expressions.tc
> >
> > diff --git a/tools/testing/selftests/ftrace/test.d/functions b/tools/testing/selftests/ftrace/test.d/functions
> > index 000fd05e84b1..1855a63559ad 100644
> > --- a/tools/testing/selftests/ftrace/test.d/functions
> > +++ b/tools/testing/selftests/ftrace/test.d/functions
> > @@ -16,13 +16,13 @@ reset_tracer() { # reset the current tracer
> >
> > reset_trigger_file() {
> > # remove action triggers first
> > - grep -H ':on[^:]*(' $@ |
> > + grep -H ':on[^:]*(' $@ | tac |
> > while read line; do
> > cmd=`echo $line | cut -f2- -d: | cut -f1 -d"["`
> > file=`echo $line | cut -f1 -d:`
> > echo "!$cmd" >> $file
> > done
> > - grep -Hv ^# $@ |
> > + grep -Hv ^# $@ | tac |
> > while read line; do
> > cmd=`echo $line | cut -f2- -d: | cut -f1 -d"["`
> > file=`echo $line | cut -f1 -d:`
>
> If this update has any meaning, please make a separate patch for this part.
Hi Masami,
Thanks for the feedback. The above change is to ensure we remove
triggers in the reverse order that we created them - important when
one trigger depends on another. I can split it out into a separate
patch and will add a README pattern check to the requires tag for
these tests.
Thanks,
Kalesh
>
> > diff --git a/tools/testing/selftests/ftrace/test.d/trigger/trigger-hist-expressions.tc b/tools/testing/selftests/ftrace/test.d/trigger/trigger-hist-expressions.tc
> > new file mode 100644
> > index 000000000000..e715641c54d3
> > --- /dev/null
> > +++ b/tools/testing/selftests/ftrace/test.d/trigger/trigger-hist-expressions.tc
> > @@ -0,0 +1,72 @@
> > +#!/bin/sh
> > +# SPDX-License-Identifier: GPL-2.0
> > +# description: event trigger - test histogram expression parsing
> > +# requires: set_event events/sched/sched_process_fork/trigger events/sched/sched_process_fork/hist error_log
>
> Hmm, are there any way to check the running kernel supports this feature?
> Because the latest version of the kselftest is expected to run on the old stable
> kernel for testing, the testcase should check whether the kernel supports this
> testing feature or not. (That's why the requires tag supports README pattern check)
>
> So, at first if you didn't update the <tracefs>/README, please update it first
> to show the new syntax is supported, and add "SOME-PATTERN":README to the
> requires tag.
>
> Thank you,
>
> > +
> > +
> > +fail() { #msg
> > + echo $1
> > + exit_fail
> > +}
> > +
> > +get_hist_var() { #var_name hist_path
> > + hist_output=`grep -m1 "$1: " $2`
> > + hitcount=`echo $hist_output | awk '{ for (i=1; i<=NF; ++i) { if ($i ~ "hitcount:") print $(i+1)} }'`
> > + var_sum=`echo $hist_output | awk '{ for (i=1; i<=NF; ++i) { if ($i ~ "'$1':") print $(i+1)} }'`
> > + var_val=$(( var_sum / hitcount ))
> > + echo $var_val
> > +}
> > +
> > +test_hist_expr() { # test_name expression expected_val
> > + reset_trigger
> > +
> > + echo "Test hist trigger expressions - $1"
> > +
> > + echo "hist:keys=common_pid:x=$2" > events/sched/sched_process_fork/trigger
> > + echo 'hist:keys=common_pid:vals=$x' >> events/sched/sched_process_fork/trigger
> > + for i in `seq 1 10` ; do ( echo "forked" > /dev/null); done
> > +
> > + actual=`get_hist_var x events/sched/sched_process_fork/hist`
> > +
> > + if [ $actual != $3 ]; then
> > + fail "Failed hist trigger expression evaluation: Expression: $2 Expected: $3, Actual: $actual"
> > + fi
> > +
> > + reset_trigger
> > +}
> > +
> > +check_error() { # test_name command-with-error-pos-by-^
> > + reset_trigger
> > +
> > + echo "Test hist trigger expressions - $1"
> > + ftrace_errlog_check 'hist:sched:sched_process_fork' "$2" 'events/sched/sched_process_fork/trigger'
> > +
> > + reset_trigger
> > +}
> > +
> > +test_hist_expr "Variable assignment" "123" "123"
> > +
> > +test_hist_expr "Subtraction not associative" "16-8-4-2" "2"
> > +
> > +test_hist_expr "Division not associative" "64/8/4/2" "1"
> > +
> > +test_hist_expr "Same precedence operators (+,-) evaluated left to right" "16-8+4+2" "14"
> > +
> > +test_hist_expr "Same precedence operators (*,/) evaluated left to right" "4*3/2*2" "12"
> > +
> > +test_hist_expr "Multiplication evaluated before addition/subtraction" "4+3*2-2" "8"
> > +
> > +test_hist_expr "Division evaluated before addition/subtraction" "4+6/2-2" "5"
> > +
> > +# Division by zero returns -1
> > +test_hist_expr "Handles division by zero" "3/0" "-1"
> > +
> > +# err pos for "too many subexpressions" is dependent on where
> > +# the last subexpression was detected. This can vary depending
> > +# on how the expression tree was generated.
> > +check_error "Too many subexpressions" 'hist:keys=common_pid:x=32+^10*3/20-4'
> > +check_error "Too many subexpressions" 'hist:keys=common_pid:x=^1+2+3+4+5'
> > +
> > +check_error "Unary minus not supported in subexpression" 'hist:keys=common_pid:x=-(^1)+2'
> > +
> > +exit 0
> > --
> > 2.33.0.1079.g6e70778dc9-goog
> >
>
>
> --
> Masami Hiramatsu <[email protected]>
On Tue, 26 Oct 2021 21:43:11 +0900
Masami Hiramatsu <[email protected]> wrote:
> > diff --git a/tools/testing/selftests/ftrace/test.d/trigger/trigger-hist-expressions.tc b/tools/testing/selftests/ftrace/test.d/trigger/trigger-hist-expressions.tc
> > new file mode 100644
> > index 000000000000..e715641c54d3
> > --- /dev/null
> > +++ b/tools/testing/selftests/ftrace/test.d/trigger/trigger-hist-expressions.tc
> > @@ -0,0 +1,72 @@
> > +#!/bin/sh
> > +# SPDX-License-Identifier: GPL-2.0
> > +# description: event trigger - test histogram expression parsing
> > +# requires: set_event events/sched/sched_process_fork/trigger events/sched/sched_process_fork/hist error_log
>
> Hmm, are there any way to check the running kernel supports this feature?
> Because the latest version of the kselftest is expected to run on the old stable
> kernel for testing, the testcase should check whether the kernel supports this
> testing feature or not. (That's why the requires tag supports README pattern check)
>
> So, at first if you didn't update the <tracefs>/README, please update it first
> to show the new syntax is supported, and add "SOME-PATTERN":README to the
> requires tag.
Yes, please update the README in kernel/trace/trace.c readme_msg[].
I'll look at the other patches, and if they are fine, I may just apply them.
-- Steve
On Mon, 25 Oct 2021 13:08:38 -0700
Kalesh Singh <[email protected]> wrote:
> == Results ==
>
> Divisor is a power of 2 (divisor == 32):
>
> test_hist_field_div_not_optimized | 8,717,091 cpu-cycles
> test_hist_field_div_optimized | 1,643,137 cpu-cycles
>
> If the divisor is a power of 2, the optimized version is ~5.3x faster.
>
> Divisor is not a power of 2 (divisor == 33):
>
> test_hist_field_div_not_optimized | 4,444,324 cpu-cycles
> test_hist_field_div_optimized | 5,497,958 cpu-cycles
To optimize this even more, if the divisor is constant, we could make a
separate function to not do the branch, and just shift or divide.
And even if it is not a power of 2, for constants, we could implement a
multiplication and shift, and guarantee an accuracy up to a defined max.
If div is a constant, then we can calculate the mult and shift, and max
dividend. Let's use 20 for shift.
// This works best for small divisors
if (div > max_div) {
// only do a real division
return;
}
shift = 20;
mult = ((1 << shift) + div - 1) / div;
delta = mult * div - (1 << shift);
if (!delta) {
/* div is a power of 2 */
max = -1;
return;
}
max = (1 << shift) / delta;
We would of course need to use 64 bit operations (maybe only do this for 64
bit machines). And perhaps even use bigger shift values to get a bigger max.
Then we could do:
if (val1 < max)
return (val1 * mult) >> shift;
-- Steve
On Tue, 26 Oct 2021 07:28:39 -0700
Kalesh Singh <[email protected]> wrote:
> > If this update has any meaning, please make a separate patch for this part.
>
> Hi Masami,
>
> Thanks for the feedback. The above change is to ensure we remove
> triggers in the reverse order that we created them - important when
> one trigger depends on another. I can split it out into a separate
> patch and will add a README pattern check to the requires tag for
> these tests.
Also make sure to run all the ftracetests. When I ran it with this update,
most of the other histogram tests failed. Even with your patches applied to
the running kernel.
-- Steve
On Tue, Oct 26, 2021 at 2:44 PM Steven Rostedt <[email protected]> wrote:
>
> On Tue, 26 Oct 2021 07:28:39 -0700
> Kalesh Singh <[email protected]> wrote:
>
> > > If this update has any meaning, please make a separate patch for this part.
> >
> > Hi Masami,
> >
> > Thanks for the feedback. The above change is to ensure we remove
> > triggers in the reverse order that we created them - important when
> > one trigger depends on another. I can split it out into a separate
> > patch and will add a README pattern check to the requires tag for
> > these tests.
>
> Also make sure to run all the ftracetests. When I ran it with this update,
> most of the other histogram tests failed. Even with your patches applied to
> the running kernel.
Hi Steve,
On my setup I without any of the changes applied (config hist triggers enabled):
./ftracetests
# of passed: 41
# of failed: 40
# of unresolved: 0
# of untested: 0
# of unsupported: 32
# of xfailed: 0
# of undefined(test bug): 0
Do all the tests pass for you, before any of the changes in this
series? Maybe some of the tests need updating?
- Kalesh
>
> -- Steve
On Tue, Oct 26, 2021 at 12:14 PM Steven Rostedt <[email protected]> wrote:
>
> On Mon, 25 Oct 2021 13:08:38 -0700
> Kalesh Singh <[email protected]> wrote:
>
> > == Results ==
> >
> > Divisor is a power of 2 (divisor == 32):
> >
> > test_hist_field_div_not_optimized | 8,717,091 cpu-cycles
> > test_hist_field_div_optimized | 1,643,137 cpu-cycles
> >
> > If the divisor is a power of 2, the optimized version is ~5.3x faster.
> >
> > Divisor is not a power of 2 (divisor == 33):
> >
> > test_hist_field_div_not_optimized | 4,444,324 cpu-cycles
> > test_hist_field_div_optimized | 5,497,958 cpu-cycles
>
> To optimize this even more, if the divisor is constant, we could make a
> separate function to not do the branch, and just shift or divide.
Ack. I can update to use separate functions for the constant divisors.
>
> And even if it is not a power of 2, for constants, we could implement a
> multiplication and shift, and guarantee an accuracy up to a defined max.
>
>
> If div is a constant, then we can calculate the mult and shift, and max
> dividend. Let's use 20 for shift.
>
> // This works best for small divisors
> if (div > max_div) {
> // only do a real division
> return;
> }
> shift = 20;
> mult = ((1 << shift) + div - 1) / div;
> delta = mult * div - (1 << shift);
> if (!delta) {
> /* div is a power of 2 */
> max = -1;
> return;
> }
> max = (1 << shift) / delta;
I'm still trying to digest the above algorithm. But doesn't this add 2
extra divisions? What am I missing here?
Thanks,
Kalesh
>
> We would of course need to use 64 bit operations (maybe only do this for 64
> bit machines). And perhaps even use bigger shift values to get a bigger max.
>
> Then we could do:
>
> if (val1 < max)
> return (val1 * mult) >> shift;
>
> -- Steve
On Tue, 26 Oct 2021 16:36:03 -0700
Kalesh Singh <[email protected]> wrote:
> On my setup I without any of the changes applied (config hist triggers enabled):
>
> ./ftracetests
>
> # of passed: 41
> # of failed: 40
> # of unresolved: 0
> # of untested: 0
> # of unsupported: 32
> # of xfailed: 0
> # of undefined(test bug): 0
>
> Do all the tests pass for you, before any of the changes in this
> series? Maybe some of the tests need updating?
All my tests past, and I don't push any code if they fail.
I'd like to understand why you have these failures. Are the test from
the kernel you are testing?
-- Steve
On Tue, 26 Oct 2021 16:39:13 -0700
Kalesh Singh <[email protected]> wrote:
> > // This works best for small divisors
> > if (div > max_div) {
> > // only do a real division
> > return;
> > }
> > shift = 20;
> > mult = ((1 << shift) + div - 1) / div;
> > delta = mult * div - (1 << shift);
> > if (!delta) {
> > /* div is a power of 2 */
> > max = -1;
> > return;
> > }
> > max = (1 << shift) / delta;
>
> I'm still trying to digest the above algorithm.
mult = (2^20 + div - 1) / div;
The "div - 1" is to round up.
Basically, it's doing: X / div = X * (2^20 / div) / 2^20
If div is constant, the 2^20 / div is constant, and the "2^20" is the
same as a shift.
So multiplier is 2^20 / div, and the shift is 20.
But because there's rounding errors it is only accurate up to the
difference of:
delta = mult * div / 2^20
That is if mult is a power of two, then there would be no rounding
errors, and the delta is zero, making the max infinite:
max = 2^20 / delta as delta goes to zero.
> But doesn't this add 2 extra divisions? What am I missing here?
The above is only done at parsing not during the trace, where we care
about.
> >
> >
> > We would of course need to use 64 bit operations (maybe only do this for 64
> > bit machines). And perhaps even use bigger shift values to get a bigger max.
> >
> > Then we could do:
> >
> > if (val1 < max)
> > return (val1 * mult) >> shift;
This is done at the time of recording.
Actually, it would be:
if (val1 < max)
return (val1 * mult) >> shift;
else
return val1 / div;
-- Steve
On Tue, Oct 26, 2021 at 5:20 PM Steven Rostedt <[email protected]> wrote:
>
> On Tue, 26 Oct 2021 16:36:03 -0700
> Kalesh Singh <[email protected]> wrote:
>
> > On my setup I without any of the changes applied (config hist triggers enabled):
> >
> > ./ftracetests
> >
> > # of passed: 41
> > # of failed: 40
> > # of unresolved: 0
> > # of untested: 0
> > # of unsupported: 32
> > # of xfailed: 0
> > # of undefined(test bug): 0
> >
> > Do all the tests pass for you, before any of the changes in this
> > series? Maybe some of the tests need updating?
>
> All my tests past, and I don't push any code if they fail.
>
> I'd like to understand why you have these failures. Are the test from
> the kernel you are testing?
The results are from the kernel before I apply any of the patches. I
am testing on an Android emulator (cuttlefish) with 5.15.0-rc6 kernel.
The tests clearly work so it must be something on my end. I'll
investigate and get back to you.
Thanks,
Kalesh
>
> -- Steve
On Tue, Oct 26, 2021 at 5:18 PM Steven Rostedt <[email protected]> wrote:
>
> On Tue, 26 Oct 2021 16:39:13 -0700
> Kalesh Singh <[email protected]> wrote:
>
> > > // This works best for small divisors
> > > if (div > max_div) {
> > > // only do a real division
> > > return;
> > > }
> > > shift = 20;
> > > mult = ((1 << shift) + div - 1) / div;
> > > delta = mult * div - (1 << shift);
> > > if (!delta) {
> > > /* div is a power of 2 */
> > > max = -1;
> > > return;
> > > }
> > > max = (1 << shift) / delta;
> >
> > I'm still trying to digest the above algorithm.
>
> mult = (2^20 + div - 1) / div;
>
> The "div - 1" is to round up.
>
> Basically, it's doing: X / div = X * (2^20 / div) / 2^20
>
> If div is constant, the 2^20 / div is constant, and the "2^20" is the
> same as a shift.
>
> So multiplier is 2^20 / div, and the shift is 20.
>
> But because there's rounding errors it is only accurate up to the
> difference of:
>
> delta = mult * div / 2^20
>
> That is if mult is a power of two, then there would be no rounding
> errors, and the delta is zero, making the max infinite:
>
> max = 2^20 / delta as delta goes to zero.
>
> > But doesn't this add 2 extra divisions? What am I missing here?
>
> The above is only done at parsing not during the trace, where we care
> about.
Hi Steve,
Thanks for the explanation, this cleared it up for me.
- Kalesh
>
> > >
> > >
> > > We would of course need to use 64 bit operations (maybe only do this for 64
> > > bit machines). And perhaps even use bigger shift values to get a bigger max.
> > >
> > > Then we could do:
> > >
> > > if (val1 < max)
> > > return (val1 * mult) >> shift;
>
> This is done at the time of recording.
>
> Actually, it would be:
>
> if (val1 < max)
> return (val1 * mult) >> shift;
> else
> return val1 / div;
>
> -- Steve
On Tue, 26 Oct 2021 18:09:22 -0700
Kalesh Singh <[email protected]> wrote:
> > delta = mult * div / 2^20
> >
> > That is if mult is a power of two, then there would be no rounding
> > errors, and the delta is zero, making the max infinite:
That should have been (as shown in the algorithm)
delta = mult * div - 2 ^ 20
As mult is 2^20 / div; and the above should end up zero if there's no
rounding issues, as it would be:
delta = (2^20 / div) * div - 2^20
-- Steve
On Tue, Oct 26, 2021 at 6:15 PM Steven Rostedt <[email protected]> wrote:
>
> On Tue, 26 Oct 2021 18:09:22 -0700
> Kalesh Singh <[email protected]> wrote:
>
> > > delta = mult * div / 2^20
> > >
> > > That is if mult is a power of two, then there would be no rounding
> > > errors, and the delta is zero, making the max infinite:
>
> That should have been (as shown in the algorithm)
>
> delta = mult * div - 2 ^ 20
>
> As mult is 2^20 / div; and the above should end up zero if there's no
> rounding issues, as it would be:
>
> delta = (2^20 / div) * div - 2^20
Good catch. We're checking if we get back the exact value.
And IIUC max_div is an arbitrary value we decide on that's <= 2^shift?
Is there a rule of thumb for choosing this?
Thanks,
Kalesh
>
> -- Steve
On Tue, 26 Oct 2021 18:31:21 -0700
Kalesh Singh <[email protected]> wrote:
> And IIUC max_div is an arbitrary value we decide on that's <= 2^shift?
> Is there a rule of thumb for choosing this?
The way I came up with the max was to figure out at what point is it no
longer guaranteed to be accurate. That is, what number can make the
mult/shift no longer match the division.
If we have some number div that is not a power of two. At some point:
(X * mult) >> shift != X / div
Now I simply picked
max = 1 << shift / (mult * div - (1 << shift))
Because that will always be within the precision of the actual number.
But I believe we can make max bigger, but because that deals with
truncation, it's not simple math.
That is, the above X / div is truncated and not the real number.
I'm sure there's an algorithm somewhere that can give as the real max.
-- Steve
On Tue, 26 Oct 2021 07:28:39 -0700
Kalesh Singh <[email protected]> wrote:
> On Tue, Oct 26, 2021 at 5:43 AM Masami Hiramatsu <[email protected]> wrote:
> >
> > Hi Kalesh,
> >
> > On Mon, 25 Oct 2021 13:08:39 -0700
> > Kalesh Singh <[email protected]> wrote:
> >
> > > Add tests for the parsing of hist trigger expressions; and to
> > > validate expression evaluation.
> > >
> > > Signed-off-by: Kalesh Singh <[email protected]>
> > > Reviewed-by: Namhyung Kim <[email protected]>
> > > ---
> > >
> > > Changes in v3:
> > > - Remove .sym-offset error check tests
> > >
> > > Changes in v2:
> > > - Add Namhyung's Reviewed-by
> > > - Update comment to clarify err_pos in "Too many subexpressions" test
> > >
> > >
> > > .../testing/selftests/ftrace/test.d/functions | 4 +-
> > > .../trigger/trigger-hist-expressions.tc | 72 +++++++++++++++++++
> > > 2 files changed, 74 insertions(+), 2 deletions(-)
> > > create mode 100644 tools/testing/selftests/ftrace/test.d/trigger/trigger-hist-expressions.tc
> > >
> > > diff --git a/tools/testing/selftests/ftrace/test.d/functions b/tools/testing/selftests/ftrace/test.d/functions
> > > index 000fd05e84b1..1855a63559ad 100644
> > > --- a/tools/testing/selftests/ftrace/test.d/functions
> > > +++ b/tools/testing/selftests/ftrace/test.d/functions
> > > @@ -16,13 +16,13 @@ reset_tracer() { # reset the current tracer
> > >
> > > reset_trigger_file() {
> > > # remove action triggers first
> > > - grep -H ':on[^:]*(' $@ |
> > > + grep -H ':on[^:]*(' $@ | tac |
> > > while read line; do
> > > cmd=`echo $line | cut -f2- -d: | cut -f1 -d"["`
> > > file=`echo $line | cut -f1 -d:`
> > > echo "!$cmd" >> $file
> > > done
> > > - grep -Hv ^# $@ |
> > > + grep -Hv ^# $@ | tac |
> > > while read line; do
> > > cmd=`echo $line | cut -f2- -d: | cut -f1 -d"["`
> > > file=`echo $line | cut -f1 -d:`
> >
> > If this update has any meaning, please make a separate patch for this part.
>
> Hi Masami,
>
> Thanks for the feedback. The above change is to ensure we remove
> triggers in the reverse order that we created them - important when
> one trigger depends on another.
Hi Kalesh,
That's a good reason to make this an independent patch :)
> I can split it out into a separate
> patch and will add a README pattern check to the requires tag for
> these tests.
Thank you!
--
Masami Hiramatsu <[email protected]>
Hi Kalesh,
On Tue, 26 Oct 2021 18:15:34 -0700
Kalesh Singh <[email protected]> wrote:
> On Tue, Oct 26, 2021 at 5:20 PM Steven Rostedt <[email protected]> wrote:
> >
> > On Tue, 26 Oct 2021 16:36:03 -0700
> > Kalesh Singh <[email protected]> wrote:
> >
> > > On my setup I without any of the changes applied (config hist triggers enabled):
> > >
> > > ./ftracetests
> > >
> > > # of passed: 41
> > > # of failed: 40
> > > # of unresolved: 0
> > > # of untested: 0
> > > # of unsupported: 32
> > > # of xfailed: 0
> > > # of undefined(test bug): 0
> > >
> > > Do all the tests pass for you, before any of the changes in this
> > > series? Maybe some of the tests need updating?
> >
> > All my tests past, and I don't push any code if they fail.
> >
> > I'd like to understand why you have these failures. Are the test from
> > the kernel you are testing?
>
> The results are from the kernel before I apply any of the patches. I
> am testing on an Android emulator (cuttlefish) with 5.15.0-rc6 kernel.
> The tests clearly work so it must be something on my end. I'll
> investigate and get back to you.
Interesting. There should be test logs under logs/ directory in the
ftracetest. Can you share the logs/*/ftracetest.log and your kernel kconfig?
Thank you,
--
Masami Hiramatsu <[email protected]>
On Tue, 26 Oct 2021 22:21:23 -0400
Steven Rostedt <[email protected]> wrote:
> I'm sure there's an algorithm somewhere that can give as the real max.
You got me playing with this more ;-)
OK, I added the rounding in the wrong place. I found that we can make
the max_div to be the same as the shift! The bigger the shift, the
bigger the max!
mult = (1 << shift) / div;
max_div = (1 << shift)
But the rounding needs to be with the mult / shift:
return (val * mult + ((1 << shift) - 1)) >> shift;
When val goes pass 1 << shift, then the error will be off by more than
one.
-- Steve
On Tue, Oct 26, 2021 at 8:16 PM Steven Rostedt <[email protected]> wrote:
>
> On Tue, 26 Oct 2021 22:21:23 -0400
> Steven Rostedt <[email protected]> wrote:
>
> > I'm sure there's an algorithm somewhere that can give as the real max.
>
> You got me playing with this more ;-)
>
> OK, I added the rounding in the wrong place. I found that we can make
> the max_div to be the same as the shift! The bigger the shift, the
> bigger the max!
Nice! :)
>
> mult = (1 << shift) / div;
> max_div = (1 << shift)
>
> But the rounding needs to be with the mult / shift:
>
> return (val * mult + ((1 << shift) - 1)) >> shift;
>
>
> When val goes pass 1 << shift, then the error will be off by more than
> one.
Did you mean, val should be such that when we do the (val * mult) we
only get rounding errors less than (1 << shift)?
I think we also need to flip the delta now since we round down initially:
delta = (1 << shift) - (mult * div)
Thanks,
Kalesh
>
> -- Steve
On Tue, Oct 26, 2021 at 8:14 PM Masami Hiramatsu <[email protected]> wrote:
>
> Hi Kalesh,
>
> On Tue, 26 Oct 2021 18:15:34 -0700
> Kalesh Singh <[email protected]> wrote:
>
> > On Tue, Oct 26, 2021 at 5:20 PM Steven Rostedt <[email protected]> wrote:
> > >
> > > On Tue, 26 Oct 2021 16:36:03 -0700
> > > Kalesh Singh <[email protected]> wrote:
> > >
> > > > On my setup I without any of the changes applied (config hist triggers enabled):
> > > >
> > > > ./ftracetests
> > > >
> > > > # of passed: 41
> > > > # of failed: 40
> > > > # of unresolved: 0
> > > > # of untested: 0
> > > > # of unsupported: 32
> > > > # of xfailed: 0
> > > > # of undefined(test bug): 0
> > > >
> > > > Do all the tests pass for you, before any of the changes in this
> > > > series? Maybe some of the tests need updating?
> > >
> > > All my tests past, and I don't push any code if they fail.
> > >
> > > I'd like to understand why you have these failures. Are the test from
> > > the kernel you are testing?
> >
> > The results are from the kernel before I apply any of the patches. I
> > am testing on an Android emulator (cuttlefish) with 5.15.0-rc6 kernel.
> > The tests clearly work so it must be something on my end. I'll
> > investigate and get back to you.
>
> Interesting. There should be test logs under logs/ directory in the
> ftracetest. Can you share the logs/*/ftracetest.log and your kernel kconfig?
>
> Thank you,
>
Hi Masami,
I have attached the config and ftracetest.log here.
Thanks,
Kalesh
>
> --
> Masami Hiramatsu <[email protected]>
On Wed, 27 Oct 2021 23:52:29 +0900
Masami Hiramatsu <[email protected]> wrote:
> > I'm currently going to test the config you sent.
>
> I'm also trying to reproduce it, but it seems to need full qemu mode.
> If you share the above logs, it is easier to check why the tests have
> been failed.
And my build failed with:
make[2]: *** No rule to make target 'kernel/drivers/char/hw_random/tpm-rng.o', needed by 'modules-only.symvers'. Stop.
make[1]: *** [/work/git/linux-test.git/Makefile:1783: modules] Error 2
I'll tweak the config to go further.
-- Steve
On Tue, 26 Oct 2021 21:04:29 -0700
Kalesh Singh <[email protected]> wrote:
> On Tue, Oct 26, 2021 at 8:16 PM Steven Rostedt <[email protected]> wrote:
> >
> > On Tue, 26 Oct 2021 22:21:23 -0400
> > Steven Rostedt <[email protected]> wrote:
> >
> > > I'm sure there's an algorithm somewhere that can give as the real max.
> >
> > You got me playing with this more ;-)
> >
> > OK, I added the rounding in the wrong place. I found that we can make
> > the max_div to be the same as the shift! The bigger the shift, the
> > bigger the max!
>
> Nice! :)
> >
> > mult = (1 << shift) / div;
> > max_div = (1 << shift)
> >
> > But the rounding needs to be with the mult / shift:
> >
> > return (val * mult + ((1 << shift) - 1)) >> shift;
> >
> >
> > When val goes pass 1 << shift, then the error will be off by more than
> > one.
> Did you mean, val should be such that when we do the (val * mult) we
> only get rounding errors less than (1 << shift)?
We get rounding errors when val is greater than (1 << shift) because then
it exposes the bits that are not shifted out.
>
> I think we also need to flip the delta now since we round down initially:
>
> delta = (1 << shift) - (mult * div)
>
Actually, we don't need the delta at all. Just what I showed above.
Pick some arbitrary shift (let's say 20 as that seems to be commonly used,
and works for 32 bit as well) and then we figure out the multiplier.
mult = (1 << shift) / div;
No delta needed. Our max is going to be 1 << shift, and then all we need is:
if (val < (1 << shift))
return (val * mult + ((1 << shift) - 1)) >> shift;
else
return val / div;
All we need to save to do the operation is the shift, the constant div and
the calculated constant mult.
-- Steve
On Wed, 27 Oct 2021 11:01:49 -0400
Steven Rostedt <[email protected]> wrote:
> And my build failed with:
>
> make[2]: *** No rule to make target 'kernel/drivers/char/hw_random/tpm-rng.o', needed by 'modules-only.symvers'. Stop.
> make[1]: *** [/work/git/linux-test.git/Makefile:1783: modules] Error 2
>
> I'll tweak the config to go further.
I got it booted, but also had to disable selinux. I wonder if that caused
any issues?
It did find a minor bug. A warning happens if you try to connect an
event-probe to an event that does not exist. That should not warn.
I'll go fix that, but it would still be good to see the logs.
Thanks,
-- Steve
On Wed, Oct 27, 2021 at 8:50 AM Steven Rostedt <[email protected]> wrote:
>
> On Wed, 27 Oct 2021 11:01:49 -0400
> Steven Rostedt <[email protected]> wrote:
>
> > And my build failed with:
> >
> > make[2]: *** No rule to make target 'kernel/drivers/char/hw_random/tpm-rng.o', needed by 'modules-only.symvers'. Stop.
> > make[1]: *** [/work/git/linux-test.git/Makefile:1783: modules] Error 2
> >
> > I'll tweak the config to go further.
>
> I got it booted, but also had to disable selinux. I wonder if that caused
> any issues?
>
> It did find a minor bug. A warning happens if you try to connect an
> event-probe to an event that does not exist. That should not warn.
>
> I'll go fix that, but it would still be good to see the logs.
Hi Steve and Masami,
Thanks for looking into this. I've attached the full logs here.
- Kalesh
>
> Thanks,
>
> -- Steve
On Tue, 26 Oct 2021 21:27:00 -0700
Kalesh Singh <[email protected]> wrote:
> > Interesting. There should be test logs under logs/ directory in the
> > ftracetest. Can you share the logs/*/ftracetest.log and your kernel kconfig?
> >
> > Thank you,
> >
> Hi Masami,
>
> I have attached the config and ftracetest.log here.
Actually, could you attach the other files in that log?
tar cvjf log.tar.bz2 logs/<date>/
Where <date> is the value for the log that failed.
That will give me more information to why the tests failed.
I'm currently going to test the config you sent.
Thanks!
-- Steve
On Wed, 27 Oct 2021 08:55:39 -0700
Kalesh Singh <[email protected]> wrote:
> Thanks for looking into this. I've attached the full logs here.
Just looking at:
11-add_remove_kprobe.tc-log.vQWAmF
I see the failure of:
+ echo
+ PLACE=_do_fork
+ >>dynamic_events
+ echo 'p:myevent1 _do_fork'
Where "_do_fork" no longer exists and the tests have been updated.
I'm guessing you are running outdated tests. Please make sure that the
tests you run are the latest from the kernel tree.
Thanks!
-- Steve
On Wed, 27 Oct 2021 11:34:16 +0900
Masami Hiramatsu <[email protected]> wrote:
> > Hi Masami,
> >
> > Thanks for the feedback. The above change is to ensure we remove
> > triggers in the reverse order that we created them - important when
> > one trigger depends on another.
>
> Hi Kalesh,
> That's a good reason to make this an independent patch :)
>
> > I can split it out into a separate
> > patch and will add a README pattern check to the requires tag for
> > these tests.
Kalesh,
As you may have noticed, I pulled in all the patches in this series but
this selftests patch. Please rebase your updates as requested by Masami on
top of my for-next branch, which can be found here:
git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/linux-trace.git
Thanks!
-- Steve
On Wed, 27 Oct 2021 10:31:19 -0400
Steven Rostedt <[email protected]> wrote:
> On Tue, 26 Oct 2021 21:27:00 -0700
> Kalesh Singh <[email protected]> wrote:
>
> > > Interesting. There should be test logs under logs/ directory in the
> > > ftracetest. Can you share the logs/*/ftracetest.log and your kernel kconfig?
> > >
> > > Thank you,
> > >
> > Hi Masami,
> >
> > I have attached the config and ftracetest.log here.
Thanks! but it seems that the tests were randomely failed...
>
>
> Actually, could you attach the other files in that log?
>
> tar cvjf log.tar.bz2 logs/<date>/
>
> Where <date> is the value for the log that failed.
>
> That will give me more information to why the tests failed.
>
> I'm currently going to test the config you sent.
I'm also trying to reproduce it, but it seems to need full qemu mode.
If you share the above logs, it is easier to check why the tests have
been failed.
>
> Thanks!
>
> -- Steve
--
Masami Hiramatsu <[email protected]>
Greeting,
FYI, we noticed the following commit (built with gcc-9):
commit: cfece71411dbca5dc5e1fa2d9ce5a3f38e55d4fe ("[PATCH v4 7/8] tracing/selftests: Add tests for hist trigger expression parsing")
url: https://github.com/0day-ci/linux/commits/Kalesh-Singh/tracing-Extend-histogram-triggers-expression-parsing/20211026-042529
in testcase: kernel-selftests
version: kernel-selftests-x86_64-c8c9111a-1_20210929
with following parameters:
group: ftrace
ucode: 0xe2
test-description: The kernel contains a set of "self tests" under the tools/testing/selftests/ directory. These are intended to be small unit tests to exercise individual code paths in the kernel.
test-url: https://www.kernel.org/doc/Documentation/kselftest.txt
on test machine: 4 threads Intel(R) Core(TM) i5-6500 CPU @ 3.20GHz with 32G memory
caused below changes (please refer to attached dmesg/kmsg for entire log/backtrace):
If you fix the issue, kindly add following tag
Reported-by: kernel test robot <[email protected]>
TAP version 13
1..1
# selftests: ftrace: ftracetest
# === Ftrace unit tests ===
# [1] Basic trace file check [PASS]
...
<<< [1] - [67] have same results as parent, i.e. both PASS or both FAIL >>>
...
# [67] event trigger - test multiple actions on hist trigger [PASS]
>>> [68] - [72] can PASS on parent
# [68] event trigger - test inter-event histogram trigger onchange action [FAIL]
# [69] event trigger - test inter-event histogram trigger onmatch action [FAIL]
# [70] event trigger - test inter-event histogram trigger onmatch-onmax action [FAIL]
# [71] event trigger - test inter-event histogram trigger onmax action [FAIL]
# [72] event trigger - test inter-event histogram trigger snapshot action [FAIL]
>>> [73] fail on parent, too
# [73] event trigger - test inter-event histogram trigger eprobe on synthetic event [FAIL]
>>> [74] - [92] can PASS on parent
# [74] event trigger - test synthetic event create remove [FAIL]
# [75] event trigger - test inter-event histogram trigger trace action with dynamic string param [FAIL]
# [76] event trigger - test synthetic_events syntax parser [FAIL]
# [77] event trigger - test synthetic_events syntax parser errors [FAIL]
# [78] event trigger - test inter-event histogram trigger trace action [FAIL]
# [79] event trigger - test event enable/disable trigger [FAIL]
# [80] event trigger - test trigger filter [FAIL]
# [81] event trigger - test histogram expression parsing [FAIL]
# [82] event trigger - test histogram modifiers [FAIL]
# [83] event trigger - test histogram parser errors [FAIL]
# [84] event trigger - test histogram trigger [FAIL]
# [85] event trigger - test multiple histogram triggers [FAIL]
# [86] event trigger - test snapshot-trigger [FAIL]
# [87] event trigger - test stacktrace-trigger [FAIL]
# [88] trace_marker trigger - test histogram trigger [FAIL]
# [89] trace_marker trigger - test snapshot trigger [FAIL]
# [90] trace_marker trigger - test histogram with synthetic event against kernel event [FAIL]
# [91] trace_marker trigger - test histogram with synthetic event [FAIL]
# [92] event trigger - test traceon/off trigger [FAIL]
# [93] (instance) Basic test for tracers [PASS]
...
<<< [93] - [112] have same results as parent, all PASS >>>
...
# [112] (instance) trace_marker trigger - test histogram trigger [PASS]
>>> parent has no [113]
# [113] (instance) trace_marker trigger - test snapshot trigger [PASS]
# tac: failed to create temporary file in '/tmp/ftracetest-dir.o54lNh': No such file or directory
# tac: failed to create temporary file in '/tmp/ftracetest-dir.o54lNh': No such file or directory
# tac: failed to create temporary file in '/tmp/ftracetest-dir.o54lNh': No such file or directory
# tac: failed to create temporary file in '/tmp/ftracetest-dir.o54lNh': No such file or directory
#
#
# # of passed: 85
# # of failed: 26
# # of unresolved: 1
# # of untested: 0
# # of unsupported: 0
# # of xfailed: 1
# # of undefined(test bug): 0
not ok 1 selftests: ftrace: ftracetest # exit=1
To reproduce:
git clone https://github.com/intel/lkp-tests.git
cd lkp-tests
sudo bin/lkp install job.yaml # job file is attached in this email
bin/lkp split-job --compatible job.yaml # generate the yaml file for lkp run
sudo bin/lkp run generated-yaml-file
# if come across any failure that blocks the test,
# please remove ~/.lkp and /lkp dir to run from a clean state.
---
0DAY/LKP+ Test Infrastructure Open Source Technology Center
https://lists.01.org/hyperkitty/list/[email protected] Intel Corporation
Thanks,
Oliver Sang
Hi,
On Fri, 29 Oct 2021 14:48:18 +0800
kernel test robot <[email protected]> wrote:
>
>
> Greeting,
>
> FYI, we noticed the following commit (built with gcc-9):
>
> commit: cfece71411dbca5dc5e1fa2d9ce5a3f38e55d4fe ("[PATCH v4 7/8] tracing/selftests: Add tests for hist trigger expression parsing")
> url: https://github.com/0day-ci/linux/commits/Kalesh-Singh/tracing-Extend-histogram-triggers-expression-parsing/20211026-042529
>
>
> in testcase: kernel-selftests
> version: kernel-selftests-x86_64-c8c9111a-1_20210929
> with following parameters:
>
> group: ftrace
> ucode: 0xe2
>
> test-description: The kernel contains a set of "self tests" under the tools/testing/selftests/ directory. These are intended to be small unit tests to exercise individual code paths in the kernel.
> test-url: https://www.kernel.org/doc/Documentation/kselftest.txt
Thanks! This issue has been found and will be fixed next version.
BTW, I have some questions about this bot;
>
>
> on test machine: 4 threads Intel(R) Core(TM) i5-6500 CPU @ 3.20GHz with 32G memory
>
> caused below changes (please refer to attached dmesg/kmsg for entire log/backtrace):
>
>
>
> If you fix the issue, kindly add following tag
> Reported-by: kernel test robot <[email protected]>
>
>
>
> TAP version 13
> 1..1
> # selftests: ftrace: ftracetest
> # === Ftrace unit tests ===
> # [1] Basic trace file check [PASS]
> ...
> <<< [1] - [67] have same results as parent, i.e. both PASS or both FAIL >>>
At first, I guess the robot just checks the "[number]" instead
of the test description, but the ftracetest doesn't fix the "[number]"
for each test, Thus, it can be different when updated it.
So if you compare the result, please check the descriptions too.
> ...
> # [67] event trigger - test multiple actions on hist trigger [PASS]
>
> >>> [68] - [72] can PASS on parent
> # [68] event trigger - test inter-event histogram trigger onchange action [FAIL]
> # [69] event trigger - test inter-event histogram trigger onmatch action [FAIL]
> # [70] event trigger - test inter-event histogram trigger onmatch-onmax action [FAIL]
> # [71] event trigger - test inter-event histogram trigger onmax action [FAIL]
> # [72] event trigger - test inter-event histogram trigger snapshot action [FAIL]
>
> >>> [73] fail on parent, too
> # [73] event trigger - test inter-event histogram trigger eprobe on synthetic event [FAIL]
>
> >>> [74] - [92] can PASS on parent
> # [74] event trigger - test synthetic event create remove [FAIL]
> # [75] event trigger - test inter-event histogram trigger trace action with dynamic string param [FAIL]
> # [76] event trigger - test synthetic_events syntax parser [FAIL]
> # [77] event trigger - test synthetic_events syntax parser errors [FAIL]
> # [78] event trigger - test inter-event histogram trigger trace action [FAIL]
> # [79] event trigger - test event enable/disable trigger [FAIL]
> # [80] event trigger - test trigger filter [FAIL]
> # [81] event trigger - test histogram expression parsing [FAIL]
> # [82] event trigger - test histogram modifiers [FAIL]
> # [83] event trigger - test histogram parser errors [FAIL]
> # [84] event trigger - test histogram trigger [FAIL]
> # [85] event trigger - test multiple histogram triggers [FAIL]
> # [86] event trigger - test snapshot-trigger [FAIL]
> # [87] event trigger - test stacktrace-trigger [FAIL]
> # [88] trace_marker trigger - test histogram trigger [FAIL]
> # [89] trace_marker trigger - test snapshot trigger [FAIL]
> # [90] trace_marker trigger - test histogram with synthetic event against kernel event [FAIL]
> # [91] trace_marker trigger - test histogram with synthetic event [FAIL]
> # [92] event trigger - test traceon/off trigger [FAIL]
> # [93] (instance) Basic test for tracers [PASS]
> ...
> <<< [93] - [112] have same results as parent, all PASS >>>
> ...
> # [112] (instance) trace_marker trigger - test histogram trigger [PASS]
>
> >>> parent has no [113]
> # [113] (instance) trace_marker trigger - test snapshot trigger [PASS]
And next, some patch series may *ADD* new testcases if the series add
a new feature, so if you find the difference which is not in the
parent commit but it is passed, please ignore that.
> # tac: failed to create temporary file in '/tmp/ftracetest-dir.o54lNh': No such file or directory
> # tac: failed to create temporary file in '/tmp/ftracetest-dir.o54lNh': No such file or directory
> # tac: failed to create temporary file in '/tmp/ftracetest-dir.o54lNh': No such file or directory
> # tac: failed to create temporary file in '/tmp/ftracetest-dir.o54lNh': No such file or directory
And if you find this kind of new error message like above, please report it.
This is more important for us.
> #
> #
> # # of passed: 85
> # # of failed: 26
> # # of unresolved: 1
> # # of untested: 0
> # # of unsupported: 0
> # # of xfailed: 1
> # # of undefined(test bug): 0
> not ok 1 selftests: ftrace: ftracetest # exit=1
Also, please configure your running environment correctly so that all
ftracetest passes. If you unsure how to do, please ask me.
Thank you,
>
>
>
> To reproduce:
>
> git clone https://github.com/intel/lkp-tests.git
> cd lkp-tests
> sudo bin/lkp install job.yaml # job file is attached in this email
> bin/lkp split-job --compatible job.yaml # generate the yaml file for lkp run
> sudo bin/lkp run generated-yaml-file
>
> # if come across any failure that blocks the test,
> # please remove ~/.lkp and /lkp dir to run from a clean state.
>
>
>
> ---
> 0DAY/LKP+ Test Infrastructure Open Source Technology Center
> https://lists.01.org/hyperkitty/list/[email protected] Intel Corporation
>
> Thanks,
> Oliver Sang
>
--
Masami Hiramatsu <[email protected]>
On Fri, 29 Oct 2021 21:00:56 +0900
Masami Hiramatsu <[email protected]> wrote:
> > # # of passed: 85
> > # # of failed: 26
> > # # of unresolved: 1
> > # # of untested: 0
> > # # of unsupported: 0
> > # # of xfailed: 1
> > # # of undefined(test bug): 0
> > not ok 1 selftests: ftrace: ftracetest # exit=1
>
> Also, please configure your running environment correctly so that all
> ftracetest passes. If you unsure how to do, please ask me.
Although I think it's good to test with different configurations, where not
all tests pass. Because then there's times when a test will fail when it
should have been ignored, and that will let us know that there's a bug in
the test.
Or, different configurations might make a test fail that should have
passed, where a missing dependency was made.
I had someone report a bug that I never caught because it only happened
when something was configured off, and because I tested with everything on,
I never hit that bug.
-- Steve
On 29/10/2021 20:00, Masami Hiramatsu wrote:
>
>>
>> TAP version 13
>> 1..1
>> # selftests: ftrace: ftracetest
>> # === Ftrace unit tests ===
>> # [1] Basic trace file check [PASS]
>> ...
>> <<< [1] - [67] have same results as parent, i.e. both PASS or both FAIL >>>
> At first, I guess the robot just checks the "[number]" instead
> of the test description, but the ftracetest doesn't fix the "[number]"
> for each test, Thus, it can be different when updated it.
Hi Masami
Good catch, thanks for these information, we will improve the robot.
Thanks
Zhjian
> So if you compare the result, please check the descriptions too.
>
>> ...
>> # [67] event trigger - test multiple actions on hist trigger [PASS]
>>
>>>>> [68] - [72] can PASS on parent
>> # [68] event trigger - test inter-event histogram trigger onchange action [FAIL]
>> # [69] event trigger - test inter-event histogram trigger onmatch action [FAIL]
>> # [70] event trigger - test inter-event histogram trigger onmatch-onmax action [FAIL]
>> # [71] event trigger - test inter-event histogram trigger onmax action [FAIL]
>> # [72] event trigger - test inter-event histogram trigger snapshot action [FAIL]
>>
>>>>> [73] fail on parent, too
>> # [73] event trigger - test inter-event histogram trigger eprobe on synthetic event [FAIL]
>>
>>>>> [74] - [92] can PASS on parent
>> # [74] event trigger - test synthetic event create remove [FAIL]
>> # [75] event trigger - test inter-event histogram trigger trace action with dynamic string param [FAIL]
>> # [76] event trigger - test synthetic_events syntax parser [FAIL]
>> # [77] event trigger - test synthetic_events syntax parser errors [FAIL]
>> # [78] event trigger - test inter-event histogram trigger trace action [FAIL]
>> # [79] event trigger - test event enable/disable trigger [FAIL]
>> # [80] event trigger - test trigger filter [FAIL]
>> # [81] event trigger - test histogram expression parsing [FAIL]
>> # [82] event trigger - test histogram modifiers [FAIL]
>> # [83] event trigger - test histogram parser errors [FAIL]
>> # [84] event trigger - test histogram trigger [FAIL]
>> # [85] event trigger - test multiple histogram triggers [FAIL]
>> # [86] event trigger - test snapshot-trigger [FAIL]
>> # [87] event trigger - test stacktrace-trigger [FAIL]
>> # [88] trace_marker trigger - test histogram trigger [FAIL]
>> # [89] trace_marker trigger - test snapshot trigger [FAIL]
>> # [90] trace_marker trigger - test histogram with synthetic event against kernel event [FAIL]
>> # [91] trace_marker trigger - test histogram with synthetic event [FAIL]
>> # [92] event trigger - test traceon/off trigger [FAIL]
>> # [93] (instance) Basic test for tracers [PASS]
>> ...
>> <<< [93] - [112] have same results as parent, all PASS >>>
>> ...
>> # [112] (instance) trace_marker trigger - test histogram trigger [PASS]
>>
>>>>> parent has no [113]
>> # [113] (instance) trace_marker trigger - test snapshot trigger [PASS]
> And next, some patch series may *ADD* new testcases if the series add
> a new feature, so if you find the difference which is not in the
> parent commit but it is passed, please ignore that.
>
>> # tac: failed to create temporary file in '/tmp/ftracetest-dir.o54lNh': No such file or directory
>> # tac: failed to create temporary file in '/tmp/ftracetest-dir.o54lNh': No such file or directory
>> # tac: failed to create temporary file in '/tmp/ftracetest-dir.o54lNh': No such file or directory
>> # tac: failed to create temporary file in '/tmp/ftracetest-dir.o54lNh': No such file or directory
> And if you find this kind of new error message like above, please report it.
> This is more important for us.
>
>> #
>> #
>> # # of passed: 85
>> # # of failed: 26
>> # # of unresolved: 1
>> # # of untested: 0
>> # # of unsupported: 0
>> # # of xfailed: 1
>> # # of undefined(test bug): 0
>> not ok 1 selftests: ftrace: ftracetest # exit=1
> Also, please configure your running environment correctly so that all
> ftracetest passes. If you unsure how to do, please ask me.
>
> Thank you,
>
>>
>>
>> To reproduce:
>>
>> git clone https://github.com/intel/lkp-tests.git
>> cd lkp-tests
>> sudo bin/lkp install job.yaml # job file is attached in this email
>> bin/lkp split-job --compatible job.yaml # generate the yaml file for lkp run
>> sudo bin/lkp run generated-yaml-file
>>
>> # if come across any failure that blocks the test,
>> # please remove ~/.lkp and /lkp dir to run from a clean state.
>>
>>
>>
>> ---
>> 0DAY/LKP+ Test Infrastructure Open Source Technology Center
>> https://lists.01.org/hyperkitty/list/[email protected] Intel Corporation
>>
>> Thanks,
>> Oliver Sang
>>
>