This series adds kselftest for histogram trigger expresions and is dependent on the series at [1] and can be applied on top of those after dropping the patch 7 in [1].
[1] https://lore.kernel.org/r/20211025200852.3002369-1-kaleshsingh@google.com/
Kalesh Singh (3): tracing/histogram: Document hist trigger variables tracing/kselftests: Remove triggers with references before their definitions tracing/selftests: Add tests for hist trigger expression parsing (v5)
kernel/trace/trace.c | 11 +++ .../testing/selftests/ftrace/test.d/functions | 9 +++ .../trigger/trigger-hist-expressions.tc | 72 +++++++++++++++++++ 3 files changed, 92 insertions(+) create mode 100644 tools/testing/selftests/ftrace/test.d/trigger/trigger-hist-expressions.tc
Update the tracefs README to describe how hist trigger variables can be created.
Signed-off-by: Kalesh Singh kaleshsingh@google.com --- kernel/trace/trace.c | 11 +++++++++++ 1 file changed, 11 insertions(+)
diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c index bc677cd64224..c41b3786401d 100644 --- a/kernel/trace/trace.c +++ b/kernel/trace/trace.c @@ -5628,6 +5628,7 @@ static const char readme_msg[] = #ifdef CONFIG_HIST_TRIGGERS " hist trigger\t- If set, event hits are aggregated into a hash table\n" "\t Format: hist:keys=<field1[,field2,...]>\n" + "\t [:<var1>=<field|var_ref|numeric_literal>[,<var2>=...]]\n" "\t [:values=<field1[,field2,...]>]\n" "\t [:sort=<field1[,field2,...]>]\n" "\t [:size=#entries]\n" @@ -5639,6 +5640,16 @@ static const char readme_msg[] = "\t common_timestamp - to record current timestamp\n" "\t common_cpu - to record the CPU the event happened on\n" "\n" + "\t A hist trigger variable can be:\n" + "\t - a reference to a field e.g. x=current_timestamp,\n" + "\t - a reference to another variable e.g. y=$x,\n" + "\t - a numeric literal: e.g. ms_per_sec=1000,\n" + "\t - an arithmetic expression: e.g. time_secs=current_timestamp/1000\n" + "\n" + "\t hist trigger aritmethic expressions support addition(+), subtraction(-),\n" + "\t multiplication(*) and division(/) operators. An operand can be either a\n" + "\t variable reference, field or numeric literal.\n" + "\n" "\t When a matching event is hit, an entry is added to a hash\n" "\t table using the key(s) and value(s) named, and the value of a\n" "\t sum called 'hitcount' is incremented. Keys and values\n"
On Wed, 27 Oct 2021 13:59:08 -0700 Kalesh Singh kaleshsingh@google.com wrote:
Update the tracefs README to describe how hist trigger variables can be created.
Signed-off-by: Kalesh Singh kaleshsingh@google.com
This looks good to me.
Acked-by: Masami Hiramatsu mhiramat@kernel.org
Thank you!
kernel/trace/trace.c | 11 +++++++++++ 1 file changed, 11 insertions(+)
diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c index bc677cd64224..c41b3786401d 100644 --- a/kernel/trace/trace.c +++ b/kernel/trace/trace.c @@ -5628,6 +5628,7 @@ static const char readme_msg[] = #ifdef CONFIG_HIST_TRIGGERS " hist trigger\t- If set, event hits are aggregated into a hash table\n" "\t Format: hist:keys=<field1[,field2,...]>\n"
- "\t [:<var1>=<field|var_ref|numeric_literal>[,<var2>=...]]\n" "\t [:values=<field1[,field2,...]>]\n" "\t [:sort=<field1[,field2,...]>]\n" "\t [:size=#entries]\n"
@@ -5639,6 +5640,16 @@ static const char readme_msg[] = "\t common_timestamp - to record current timestamp\n" "\t common_cpu - to record the CPU the event happened on\n" "\n"
- "\t A hist trigger variable can be:\n"
- "\t - a reference to a field e.g. x=current_timestamp,\n"
- "\t - a reference to another variable e.g. y=$x,\n"
- "\t - a numeric literal: e.g. ms_per_sec=1000,\n"
- "\t - an arithmetic expression: e.g. time_secs=current_timestamp/1000\n"
- "\n"
- "\t hist trigger aritmethic expressions support addition(+), subtraction(-),\n"
- "\t multiplication(*) and division(/) operators. An operand can be either a\n"
- "\t variable reference, field or numeric literal.\n"
- "\n" "\t When a matching event is hit, an entry is added to a hash\n" "\t table using the key(s) and value(s) named, and the value of a\n" "\t sum called 'hitcount' is incremented. Keys and values\n"
-- 2.33.0.1079.g6e70778dc9-goog
If an event trigger references a variable defined in another trigger, it has to be removed before the trigger that defines the variable is removed.
Signed-off-by: Kalesh Singh kaleshsingh@google.com --- tools/testing/selftests/ftrace/test.d/functions | 9 +++++++++ 1 file changed, 9 insertions(+)
diff --git a/tools/testing/selftests/ftrace/test.d/functions b/tools/testing/selftests/ftrace/test.d/functions index 000fd05e84b1..bd9e85f4d626 100644 --- a/tools/testing/selftests/ftrace/test.d/functions +++ b/tools/testing/selftests/ftrace/test.d/functions @@ -22,6 +22,15 @@ reset_trigger_file() { file=`echo $line | cut -f1 -d:` echo "!$cmd" >> $file done + + # remove triggers with references next + grep -H '$' $@ | + 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 ^# $@ | while read line; do cmd=`echo $line | cut -f2- -d: | cut -f1 -d"["`
Hi Kalesh,
On Wed, 27 Oct 2021 13:59:09 -0700 Kalesh Singh kaleshsingh@google.com wrote:
If an event trigger references a variable defined in another trigger, it has to be removed before the trigger that defines the variable is removed.
Signed-off-by: Kalesh Singh kaleshsingh@google.com
tools/testing/selftests/ftrace/test.d/functions | 9 +++++++++ 1 file changed, 9 insertions(+)
diff --git a/tools/testing/selftests/ftrace/test.d/functions b/tools/testing/selftests/ftrace/test.d/functions index 000fd05e84b1..bd9e85f4d626 100644 --- a/tools/testing/selftests/ftrace/test.d/functions +++ b/tools/testing/selftests/ftrace/test.d/functions @@ -22,6 +22,15 @@ reset_trigger_file() { file=`echo $line | cut -f1 -d:` echo "!$cmd" >> $file done
- # remove triggers with references next
- grep -H '$' $@ |
- while read line; do
cmd=`echo $line | cut -f2- -d: | cut -f1 -d"["`
- file=`echo $line | cut -f1 -d:`
- echo "!$cmd" >> $file
- done
Why don't you use 'tac'? I love that idea :) Did you find any issue?
I think the function which cleaning up the tracing file should use the 'tac' rollback method, because it is natural, simple and robust. Then the first loop for removing action triggers is not needed anymore.
Thank you,
grep -Hv ^# $@ | while read line; do cmd=`echo $line | cut -f2- -d: | cut -f1 -d"["`
-- 2.33.0.1079.g6e70778dc9-goog
On Wed, Oct 27, 2021 at 2:58 PM Masami Hiramatsu mhiramat@kernel.org wrote:
Hi Kalesh,
On Wed, 27 Oct 2021 13:59:09 -0700 Kalesh Singh kaleshsingh@google.com wrote:
If an event trigger references a variable defined in another trigger, it has to be removed before the trigger that defines the variable is removed.
Signed-off-by: Kalesh Singh kaleshsingh@google.com
tools/testing/selftests/ftrace/test.d/functions | 9 +++++++++ 1 file changed, 9 insertions(+)
diff --git a/tools/testing/selftests/ftrace/test.d/functions b/tools/testing/selftests/ftrace/test.d/functions index 000fd05e84b1..bd9e85f4d626 100644 --- a/tools/testing/selftests/ftrace/test.d/functions +++ b/tools/testing/selftests/ftrace/test.d/functions @@ -22,6 +22,15 @@ reset_trigger_file() { file=`echo $line | cut -f1 -d:` echo "!$cmd" >> $file done
- # remove triggers with references next
- grep -H '$' $@ |
- while read line; do
cmd=`echo $line | cut -f2- -d: | cut -f1 -d"["`
file=`echo $line | cut -f1 -d:`
echo "!$cmd" >> $file
- done
Why don't you use 'tac'? I love that idea :) Did you find any issue?
Hi Masami,
Thanks for the reviews. As with the first set of patches using tac gives a regression here, though I'm not sure why it doesn't work -- I also thought reversing the order would handle any dependencies correctly.
- Kalesh
I think the function which cleaning up the tracing file should use the 'tac' rollback method, because it is natural, simple and robust. Then the first loop for removing action triggers is not needed anymore.
Thank you,
grep -Hv ^# $@ | while read line; do cmd=`echo $line | cut -f2- -d: | cut -f1 -d"["`
-- 2.33.0.1079.g6e70778dc9-goog
-- Masami Hiramatsu mhiramat@kernel.org
On Wed, 27 Oct 2021 16:26:00 -0700 Kalesh Singh kaleshsingh@google.com wrote:
Why don't you use 'tac'? I love that idea :) Did you find any issue?
Hi Masami,
Thanks for the reviews. As with the first set of patches using tac gives a regression here, though I'm not sure why it doesn't work -- I also thought reversing the order would handle any dependencies correctly.
Right, because are triggers not added by list_add_rcu() which adds to the head of the list. If anything, shouldn't things be removed in order?
-- Steve
On Wed, 27 Oct 2021 19:54:54 -0400 Steven Rostedt rostedt@goodmis.org wrote:
On Wed, 27 Oct 2021 16:26:00 -0700 Kalesh Singh kaleshsingh@google.com wrote:
Why don't you use 'tac'? I love that idea :) Did you find any issue?
Hi Masami,
Thanks for the reviews. As with the first set of patches using tac gives a regression here, though I'm not sure why it doesn't work -- I also thought reversing the order would handle any dependencies correctly.
Right, because are triggers not added by list_add_rcu() which adds to the head of the list.
Oops, so are the triggers shown in the reverse order? (newer entry is top, older one is bottom) Then do we need this patch, because we don't care about the dependency.
If anything, shouldn't things be removed in order?
Hmm, I think the trigger itself might better to be changed. If any dependency in the trigger list, it can not be restored from the copied file, like below may fail.
cat events/foo/bar/trigger > /tmp/foo.bar.trigger cat /tmp/foo.bar.trigger > events/foo/bar/trigger
(of course we can use 'tac' to restore it ...)
This is
Thank you,
On Wed, Oct 27, 2021 at 5:43 PM Masami Hiramatsu mhiramat@kernel.org wrote:
On Wed, 27 Oct 2021 19:54:54 -0400 Steven Rostedt rostedt@goodmis.org wrote:
On Wed, 27 Oct 2021 16:26:00 -0700 Kalesh Singh kaleshsingh@google.com wrote:
Why don't you use 'tac'? I love that idea :) Did you find any issue?
Hi Masami,
Thanks for the reviews. As with the first set of patches using tac gives a regression here, though I'm not sure why it doesn't work -- I also thought reversing the order would handle any dependencies correctly.
Right, because are triggers not added by list_add_rcu() which adds to the head of the list.
Oops, so are the triggers shown in the reverse order? (newer entry is top, older one is bottom) Then do we need this patch, because we don't care about the dependency.
In the case of the hist expression tests. they create a variable: echo 'hist:keys=common_pid:x=1+2' >> trigger
Then print its value in another histogram: echo 'hist:keys=common_pid:vals=$x' >> trigger
At least in this case, the triggers are listed from oldest (top) to newest (bottom): cat trigger hist:keys=common_pid:vals=hitcount:x=3:sort=hitcount:size=2048 [active] hist:keys=common_pid:vals=hitcount,$x:sort=hitcount:size=2048 [active]
So we need to remove the trigger with the var ref first.
- Kalesh
If anything, shouldn't things be removed in order?
Hmm, I think the trigger itself might better to be changed. If any dependency in the trigger list, it can not be restored from the copied file, like below may fail.
cat events/foo/bar/trigger > /tmp/foo.bar.trigger cat /tmp/foo.bar.trigger > events/foo/bar/trigger
(of course we can use 'tac' to restore it ...)
This is
Thank you,
-- Masami Hiramatsu mhiramat@kernel.org
On Wed, Oct 27, 2021 at 7:58 PM Kalesh Singh kaleshsingh@google.com wrote:
On Wed, Oct 27, 2021 at 5:43 PM Masami Hiramatsu mhiramat@kernel.org wrote:
On Wed, 27 Oct 2021 19:54:54 -0400 Steven Rostedt rostedt@goodmis.org wrote:
On Wed, 27 Oct 2021 16:26:00 -0700 Kalesh Singh kaleshsingh@google.com wrote:
Why don't you use 'tac'? I love that idea :) Did you find any issue?
Hi Masami,
Thanks for the reviews. As with the first set of patches using tac gives a regression here, though I'm not sure why it doesn't work -- I also thought reversing the order would handle any dependencies correctly.
Right, because are triggers not added by list_add_rcu() which adds to the head of the list.
Oops, so are the triggers shown in the reverse order? (newer entry is top, older one is bottom) Then do we need this patch, because we don't care about the dependency.
In the case of the hist expression tests. they create a variable: echo 'hist:keys=common_pid:x=1+2' >> trigger
Then print its value in another histogram: echo 'hist:keys=common_pid:vals=$x' >> trigger
At least in this case, the triggers are listed from oldest (top) to newest (bottom): cat trigger hist:keys=common_pid:vals=hitcount:x=3:sort=hitcount:size=2048 [active]
I realized the result of the expression can be read directly from the trigger info, now that expressions of constants are squashed to a single constant. So we wouldn't need the second trigger to see the value and can drop this patch. I'll resend a new version.
Thanks, Kalesh
hist:keys=common_pid:vals=hitcount,$x:sort=hitcount:size=2048 [active]
So we need to remove the trigger with the var ref first.
- Kalesh
If anything, shouldn't things be removed in order?
Hmm, I think the trigger itself might better to be changed. If any dependency in the trigger list, it can not be restored from the copied file, like below may fail.
cat events/foo/bar/trigger > /tmp/foo.bar.trigger cat /tmp/foo.bar.trigger > events/foo/bar/trigger
(of course we can use 'tac' to restore it ...)
This is
Thank you,
-- Masami Hiramatsu mhiramat@kernel.org
Add tests for the parsing of hist trigger expressions; and to validate expression evaluation.
Signed-off-by: Kalesh Singh kaleshsingh@google.com --- Changes in v5: - Add README pattern to requires tag, per Masami
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
.../trigger/trigger-hist-expressions.tc | 72 +++++++++++++++++++ 1 file changed, 72 insertions(+) create mode 100644 tools/testing/selftests/ftrace/test.d/trigger/trigger-hist-expressions.tc
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..9690f9f809e7 --- /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 "<var1>=<field|var_ref|numeric_literal>":README + + +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
On Wed, 27 Oct 2021 13:59:10 -0700 Kalesh Singh kaleshsingh@google.com wrote:
Add tests for the parsing of hist trigger expressions; and to validate expression evaluation.
Signed-off-by: Kalesh Singh kaleshsingh@google.com
This looks good to me :)
Acked-by: Masami Hiramatsu mhiramat@kernel.org
Thanks!
Changes in v5:
- Add README pattern to requires tag, per Masami
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
.../trigger/trigger-hist-expressions.tc | 72 +++++++++++++++++++ 1 file changed, 72 insertions(+) create mode 100644 tools/testing/selftests/ftrace/test.d/trigger/trigger-hist-expressions.tc
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..9690f9f809e7 --- /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 "<var1>=<field|var_ref|numeric_literal>":README
+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
On Wed, Oct 27, 2021 at 1:59 PM Kalesh Singh kaleshsingh@google.com wrote:
This series adds kselftest for histogram trigger expresions and is dependent on the series at [1] and can be applied on top of those after dropping the patch 7 in [1].
[1] https://lore.kernel.org/r/20211025200852.3002369-1-kaleshsingh@google.com/
Kalesh Singh (3): tracing/histogram: Document hist trigger variables tracing/kselftests: Remove triggers with references before their definitions tracing/selftests: Add tests for hist trigger expression parsing (v5)
Hi Steve, Masami,
Can you give these changes a try when you can please. I believe it should not cause any regressions now.
Thanks, Kalesh
kernel/trace/trace.c | 11 +++ .../testing/selftests/ftrace/test.d/functions | 9 +++ .../trigger/trigger-hist-expressions.tc | 72 +++++++++++++++++++ 3 files changed, 92 insertions(+) create mode 100644 tools/testing/selftests/ftrace/test.d/trigger/trigger-hist-expressions.tc
-- 2.33.0.1079.g6e70778dc9-goog
linux-kselftest-mirror@lists.linaro.org