← Back to team overview

canonical-ubuntu-qa team mailing list archive

[Bug 2101887] [NEW] ftrace:test.d--filter--event-filter-function.tc from ubuntu_kselftests_ftrace on linux-nvidia-lowlatency is flaky

 

Public bug reported:

The test case ftrace:test.d--filter--event-filter-function.tc is flaky
for linux-nvidia-lowlatency for noble release. The test fails due to
bursty system behavior and the test selecting the wrong function to
sample: acpi_os_release_object. The sampled function is expected to be
bursty. Increasing the maximum number of retries might fix it.

                9705 	  	22:41:06 DEBUG| [stdout] + . /home/ubuntu/autotest/client/tmp/ubuntu_kselftests_ftrace/src/linux/tools/testing/selftests/ftrace/test.d/filter/event-filter-function.tc
  	  	9706 	  	22:41:06 DEBUG| [stdout] + echo 0
  	  	9707 	  	22:41:06 DEBUG| [stdout] + echo 0
  	  	9708 	  	22:41:06 DEBUG| [stdout] + echo Get the most frequently calling function
  	  	9709 	  	22:41:06 DEBUG| [stdout] Get the most frequently calling function
  	  	9710 	  	22:41:06 DEBUG| [stdout] + echo
  	  	9711 	  	22:41:06 DEBUG| [stdout] + sample_events
  	  	9712 	  	22:41:06 DEBUG| [stdout] + echo 1
  	  	9713 	  	22:41:06 DEBUG| [stdout] + echo 1
  	  	9714 	  	22:41:06 DEBUG| [stdout] + ls
  	  	9715 	  	22:41:06 DEBUG| [stdout] + echo 0
  	  	9716 	  	22:41:06 DEBUG| [stdout] + echo 0
  	  	9717 	  	22:41:06 DEBUG| [stdout] + cat trace
  	  	9718 	  	22:41:06 DEBUG| [stdout] + grep -o call_site=\([^+]*\)
  	  	9719 	  	22:41:06 DEBUG| [stdout] + sed s/call_site=//
  	  	9720 	  	22:41:06 DEBUG| [stdout] + sort
  	  	9721 	  	22:41:06 DEBUG| [stdout] + uniq -c
  	  	9722 	  	22:41:06 DEBUG| [stdout] + sort
  	  	9723 	  	22:41:06 DEBUG| [stdout] + tail -n 1
  	  	9724 	  	22:41:06 DEBUG| [stdout] + sed s/^[ 0-9]*//
  	  	9725 	  	22:41:06 DEBUG| [stdout] + target_func=acpi_os_release_object
  	  	9726 	  	22:41:06 DEBUG| [stdout] + [ -z acpi_os_release_object ]
  	  	9727 	  	22:41:06 DEBUG| [stdout] + echo
  	  	9728 	  	22:41:06 DEBUG| [stdout] + echo Test event filter function name
  	  	9729 	  	22:41:06 DEBUG| [stdout] Test event filter function name
  	  	9730 	  	22:41:06 DEBUG| [stdout] + echo call_site.function == acpi_os_release_object
  	  	9731 	  	22:41:06 DEBUG| [stdout] + sample_events
  	  	9732 	  	22:41:06 DEBUG| [stdout] + echo 1
  	  	9733 	  	22:41:06 DEBUG| [stdout] + echo 1
  	  	9734 	  	22:41:06 DEBUG| [stdout] + ls
  	  	9735 	  	22:41:06 DEBUG| [stdout] + echo 0
  	  	9736 	  	22:41:06 DEBUG| [stdout] + echo 0
  	  	9737 	  	22:41:06 DEBUG| [stdout] + max_retry=10
  	  	9738 	  	22:41:06 DEBUG| [stdout] + grep kmem_cache_free trace
  	  	9739 	  	22:41:06 DEBUG| [stdout] + wc -l
  	  	9740 	  	22:41:06 DEBUG| [stdout] + [ 0 -eq 0 ]
  	  	9741 	  	22:41:06 DEBUG| [stdout] + sample_events
  	  	9742 	  	22:41:06 DEBUG| [stdout] + echo 1
  	  	9743 	  	22:41:06 DEBUG| [stdout] + echo 1
  	  	9744 	  	22:41:06 DEBUG| [stdout] + ls
  	  	9745 	  	22:41:06 DEBUG| [stdout] + echo 0
  	  	9746 	  	22:41:06 DEBUG| [stdout] + echo 0
  	  	9747 	  	22:41:06 DEBUG| [stdout] + max_retry=9
  	  	9748 	  	22:41:06 DEBUG| [stdout] + [ 9 -eq 0 ]
  	  	9749 	  	22:41:06 DEBUG| [stdout] + grep kmem_cache_free trace
  	  	9750 	  	22:41:06 DEBUG| [stdout] + wc -l
  	  	9751 	  	22:41:06 DEBUG| [stdout] + [ 0 -eq 0 ]
  	  	9752 	  	22:41:06 DEBUG| [stdout] + sample_events
  	  	9753 	  	22:41:06 DEBUG| [stdout] + echo 1
  	  	9754 	  	22:41:06 DEBUG| [stdout] + echo 1
  	  	9755 	  	22:41:06 DEBUG| [stdout] + ls
  	  	9756 	  	22:41:06 DEBUG| [stdout] + echo 0
  	  	9757 	  	22:41:06 DEBUG| [stdout] + echo 0
  	  	9758 	  	22:41:06 DEBUG| [stdout] + max_retry=8
  	  	9759 	  	22:41:06 DEBUG| [stdout] + [ 8 -eq 0 ]
  	  	9760 	  	22:41:06 DEBUG| [stdout] + grep kmem_cache_free trace
  	  	9761 	  	22:41:06 DEBUG| [stdout] + wc -l
  	  	9762 	  	22:41:06 DEBUG| [stdout] + [ 0 -eq 0 ]
  	  	9763 	  	22:41:06 DEBUG| [stdout] + sample_events
  	  	9764 	  	22:41:06 DEBUG| [stdout] + echo 1
  	  	9765 	  	22:41:06 DEBUG| [stdout] + echo 1
  	  	9766 	  	22:41:06 DEBUG| [stdout] + ls
  	  	9767 	  	22:41:06 DEBUG| [stdout] + echo 0
  	  	9768 	  	22:41:06 DEBUG| [stdout] + echo 0
  	  	9769 	  	22:41:06 DEBUG| [stdout] + max_retry=7
  	  	9770 	  	22:41:06 DEBUG| [stdout] + [ 7 -eq 0 ]
  	  	9771 	  	22:41:06 DEBUG| [stdout] + grep kmem_cache_free trace
  	  	9772 	  	22:41:06 DEBUG| [stdout] + wc -l
  	  	9773 	  	22:41:06 DEBUG| [stdout] + [ 0 -eq 0 ]
  	  	9774 	  	22:41:06 DEBUG| [stdout] + sample_events
  	  	9775 	  	22:41:06 DEBUG| [stdout] + echo 1
  	  	9776 	  	22:41:06 DEBUG| [stdout] + echo 1
  	  	9777 	  	22:41:06 DEBUG| [stdout] + ls
  	  	9778 	  	22:41:06 DEBUG| [stdout] + echo 0
  	  	9779 	  	22:41:06 DEBUG| [stdout] + echo 0
  	  	9780 	  	22:41:06 DEBUG| [stdout] + max_retry=6
  	  	9781 	  	22:41:06 DEBUG| [stdout] + [ 6 -eq 0 ]
  	  	9782 	  	22:41:06 DEBUG| [stdout] + grep kmem_cache_free trace
  	  	9783 	  	22:41:06 DEBUG| [stdout] + wc -l
  	  	9784 	  	22:41:06 DEBUG| [stdout] + [ 0 -eq 0 ]
  	  	9785 	  	22:41:06 DEBUG| [stdout] + sample_events
  	  	9786 	  	22:41:06 DEBUG| [stdout] + echo 1
  	  	9787 	  	22:41:06 DEBUG| [stdout] + echo 1
  	  	9788 	  	22:41:06 DEBUG| [stdout] + ls
  	  	9789 	  	22:41:06 DEBUG| [stdout] + echo 0
  	  	9790 	  	22:41:06 DEBUG| [stdout] + echo 0
  	  	9791 	  	22:41:06 DEBUG| [stdout] + max_retry=5
  	  	9792 	  	22:41:06 DEBUG| [stdout] + [ 5 -eq 0 ]
  	  	9793 	  	22:41:06 DEBUG| [stdout] + grep kmem_cache_free trace
  	  	9794 	  	22:41:06 DEBUG| [stdout] + wc -l
  	  	9795 	  	22:41:06 DEBUG| [stdout] + [ 0 -eq 0 ]
  	  	9796 	  	22:41:06 DEBUG| [stdout] + sample_events
  	  	9797 	  	22:41:06 DEBUG| [stdout] + echo 1
  	  	9798 	  	22:41:06 DEBUG| [stdout] + echo 1
  	  	9799 	  	22:41:06 DEBUG| [stdout] + ls
  	  	9800 	  	22:41:06 DEBUG| [stdout] + echo 0
  	  	9801 	  	22:41:06 DEBUG| [stdout] + echo 0
  	  	9802 	  	22:41:06 DEBUG| [stdout] + max_retry=4
  	  	9803 	  	22:41:06 DEBUG| [stdout] + [ 4 -eq 0 ]
  	  	9804 	  	22:41:06 DEBUG| [stdout] + grep kmem_cache_free trace
  	  	9805 	  	22:41:06 DEBUG| [stdout] + wc -l
  	  	9806 	  	22:41:06 DEBUG| [stdout] + [ 0 -eq 0 ]
  	  	9807 	  	22:41:06 DEBUG| [stdout] + sample_events
  	  	9808 	  	22:41:06 DEBUG| [stdout] + echo 1
  	  	9809 	  	22:41:06 DEBUG| [stdout] + echo 1
  	  	9810 	  	22:41:06 DEBUG| [stdout] + ls
  	  	9811 	  	22:41:06 DEBUG| [stdout] + echo 0
  	  	9812 	  	22:41:06 DEBUG| [stdout] + echo 0
  	  	9813 	  	22:41:06 DEBUG| [stdout] + max_retry=3
  	  	9814 	  	22:41:06 DEBUG| [stdout] + [ 3 -eq 0 ]
  	  	9815 	  	22:41:06 DEBUG| [stdout] + grep kmem_cache_free trace
  	  	9816 	  	22:41:06 DEBUG| [stdout] + wc -l
  	  	9817 	  	22:41:06 DEBUG| [stdout] + [ 0 -eq 0 ]
  	  	9818 	  	22:41:06 DEBUG| [stdout] + sample_events
  	  	9819 	  	22:41:06 DEBUG| [stdout] + echo 1
  	  	9820 	  	22:41:06 DEBUG| [stdout] + echo 1
  	  	9821 	  	22:41:06 DEBUG| [stdout] + ls
  	  	9822 	  	22:41:06 DEBUG| [stdout] + echo 0
  	  	9823 	  	22:41:06 DEBUG| [stdout] + echo 0
  	  	9824 	  	22:41:06 DEBUG| [stdout] + max_retry=2
  	  	9825 	  	22:41:06 DEBUG| [stdout] + [ 2 -eq 0 ]
  	  	9826 	  	22:41:06 DEBUG| [stdout] + grep kmem_cache_free trace
  	  	9827 	  	22:41:06 DEBUG| [stdout] + wc -l
  	  	9828 	  	22:41:06 DEBUG| [stdout] + [ 0 -eq 0 ]
  	  	9829 	  	22:41:06 DEBUG| [stdout] + sample_events
  	  	9830 	  	22:41:06 DEBUG| [stdout] + echo 1
  	  	9831 	  	22:41:06 DEBUG| [stdout] + echo 1
  	  	9832 	  	22:41:06 DEBUG| [stdout] + ls
  	  	9833 	  	22:41:06 DEBUG| [stdout] + echo 0
  	  	9834 	  	22:41:06 DEBUG| [stdout] + echo 0
  	  	9835 	  	22:41:06 DEBUG| [stdout] + max_retry=1
  	  	9836 	  	22:41:06 DEBUG| [stdout] + [ 1 -eq 0 ]
  	  	9837 	  	22:41:06 DEBUG| [stdout] + grep kmem_cache_free trace
  	  	9838 	  	22:41:06 DEBUG| [stdout] + wc -l
  	  	9839 	  	22:41:06 DEBUG| [stdout] + [ 0 -eq 0 ]
  	  	9840 	  	22:41:06 DEBUG| [stdout] + sample_events
  	  	9841 	  	22:41:06 DEBUG| [stdout] + echo 1
  	  	9842 	  	22:41:06 DEBUG| [stdout] + echo 1
  	  	9843 	  	22:41:06 DEBUG| [stdout] + ls
  	  	9844 	  	22:41:06 DEBUG| [stdout] + echo 0
  	  	9845 	  	22:41:06 DEBUG| [stdout] + echo 0
  	  	9846 	  	22:41:06 DEBUG| [stdout] + max_retry=0
  	  	9847 	  	22:41:06 DEBUG| [stdout] + [ 0 -eq 0 ]
  	  	9848 	  	22:41:06 DEBUG| [stdout] + exit_fail
  	  	9849 	  	22:41:06 DEBUG| [stdout] + exit 1
  	  	9850 	  	22:41:06 DEBUG| [stdout] 
  	  	9851 	  	22:41:06 DEBUG| [stdout] 
  	  	9852 	  	22:41:06 DEBUG| [stdout] # of passed:  1
  	  	9853 	  	22:41:06 DEBUG| [stdout] # of failed:  1
  	  	9854 	  	22:41:06 DEBUG| [stdout] # of unresolved:  0
  	  	9855 	  	22:41:06 DEBUG| [stdout] # of untested:  0
  	  	9856 	  	22:41:06 DEBUG| [stdout] # of unsupported:  0
  	  	9857 	  	22:41:06 DEBUG| [stdout] # of xfailed:  0
  	  	9858 	  	22:41:06 DEBUG| [stdout] # of undefined(test bug):  0
  	  	9859 	  	22:41:06 ERROR| Exception escaping from test:
  	  	9860 	  	Traceback (most recent call last):
  	  	9861 	  	  File "/home/ubuntu/autotest/client/shared/test.py", line 411, in _exec
  	  	9862 	  	    _call_test_function(self.execute, *p_args, **p_dargs)
  	  	9863 	  	  File "/home/ubuntu/autotest/client/shared/test.py", line 823, in _call_test_function
  	  	9864 	  	    return func(*args, **dargs)
  	  	9865 	  	           ^^^^^^^^^^^^^^^^^^^^
  	  	9866 	  	  File "/home/ubuntu/autotest/client/shared/test.py", line 290, in execute
  	  	9867 	  	    self._call_run_once(constraints, profile_only,
  	  	9868 	  	  File "/home/ubuntu/autotest/client/shared/test.py", line 212, in _call_run_once
  	  	9869 	  	    self.run_once(*args, **dargs)
  	  	9870 	  	  File "/home/ubuntu/autotest/client/tests/ubuntu_kselftests_ftrace/ubuntu_kselftests_ftrace.py", line 112, in run_once
  	  	9871 	  	    result = utils.system_output(cmd, retain_output=True)
  	  	9872 	  	             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  	  	9873 	  	  File "/home/ubuntu/autotest/client/shared/utils.py", line 1265, in system_output
  	  	9874 	  	    out = run(command, timeout=timeout, ignore_status=ignore_status,
  	  	9875 	  	          ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  	  	9876 	  	  File "/home/ubuntu/autotest/client/shared/utils.py", line 916, in run
  	  	9877 	  	    raise error.CmdError(command, bg_job.result,
  	  	9878 	  	autotest.client.shared.error.CmdError: Command <./ftracetest -v test.d/filter/event-filter-function.tc> failed, rc=1, Command returned non-zero exit status
  	  	9879 	  	* Command: 
  	  	9880 	  	    ./ftracetest -v test.d/filter/event-filter-function.tc
  	  	9881 	  	Exit status: 1
  	  	9882 	  	Duration: 0.7365949153900146
  	  	9883 	  	
  	  	9884 	  	stdout:
  	  	9885 	  	=== Ftrace unit tests ===
  	  	9886 	  	[1] event filter function - test event filtering on functions    [PASS]
  	  	9887 	  	[2] (instance)  event filter function - test event filtering on functions    [FAIL]

** Affects: ubuntu-kernel-tests
     Importance: Undecided
         Status: New


** Tags: noble nvidia ubuntu-kernel-selftests

-- 
You received this bug notification because you are a member of Canonical
Platform QA Team, which is subscribed to ubuntu-kernel-tests.
https://bugs.launchpad.net/bugs/2101887

Title:
  ftrace:test.d--filter--event-filter-function.tc from
  ubuntu_kselftests_ftrace on linux-nvidia-lowlatency is flaky

Status in ubuntu-kernel-tests:
  New

Bug description:
  The test case ftrace:test.d--filter--event-filter-function.tc is flaky
  for linux-nvidia-lowlatency for noble release. The test fails due to
  bursty system behavior and the test selecting the wrong function to
  sample: acpi_os_release_object. The sampled function is expected to be
  bursty. Increasing the maximum number of retries might fix it.

                  9705 	  	22:41:06 DEBUG| [stdout] + . /home/ubuntu/autotest/client/tmp/ubuntu_kselftests_ftrace/src/linux/tools/testing/selftests/ftrace/test.d/filter/event-filter-function.tc
    	  	9706 	  	22:41:06 DEBUG| [stdout] + echo 0
    	  	9707 	  	22:41:06 DEBUG| [stdout] + echo 0
    	  	9708 	  	22:41:06 DEBUG| [stdout] + echo Get the most frequently calling function
    	  	9709 	  	22:41:06 DEBUG| [stdout] Get the most frequently calling function
    	  	9710 	  	22:41:06 DEBUG| [stdout] + echo
    	  	9711 	  	22:41:06 DEBUG| [stdout] + sample_events
    	  	9712 	  	22:41:06 DEBUG| [stdout] + echo 1
    	  	9713 	  	22:41:06 DEBUG| [stdout] + echo 1
    	  	9714 	  	22:41:06 DEBUG| [stdout] + ls
    	  	9715 	  	22:41:06 DEBUG| [stdout] + echo 0
    	  	9716 	  	22:41:06 DEBUG| [stdout] + echo 0
    	  	9717 	  	22:41:06 DEBUG| [stdout] + cat trace
    	  	9718 	  	22:41:06 DEBUG| [stdout] + grep -o call_site=\([^+]*\)
    	  	9719 	  	22:41:06 DEBUG| [stdout] + sed s/call_site=//
    	  	9720 	  	22:41:06 DEBUG| [stdout] + sort
    	  	9721 	  	22:41:06 DEBUG| [stdout] + uniq -c
    	  	9722 	  	22:41:06 DEBUG| [stdout] + sort
    	  	9723 	  	22:41:06 DEBUG| [stdout] + tail -n 1
    	  	9724 	  	22:41:06 DEBUG| [stdout] + sed s/^[ 0-9]*//
    	  	9725 	  	22:41:06 DEBUG| [stdout] + target_func=acpi_os_release_object
    	  	9726 	  	22:41:06 DEBUG| [stdout] + [ -z acpi_os_release_object ]
    	  	9727 	  	22:41:06 DEBUG| [stdout] + echo
    	  	9728 	  	22:41:06 DEBUG| [stdout] + echo Test event filter function name
    	  	9729 	  	22:41:06 DEBUG| [stdout] Test event filter function name
    	  	9730 	  	22:41:06 DEBUG| [stdout] + echo call_site.function == acpi_os_release_object
    	  	9731 	  	22:41:06 DEBUG| [stdout] + sample_events
    	  	9732 	  	22:41:06 DEBUG| [stdout] + echo 1
    	  	9733 	  	22:41:06 DEBUG| [stdout] + echo 1
    	  	9734 	  	22:41:06 DEBUG| [stdout] + ls
    	  	9735 	  	22:41:06 DEBUG| [stdout] + echo 0
    	  	9736 	  	22:41:06 DEBUG| [stdout] + echo 0
    	  	9737 	  	22:41:06 DEBUG| [stdout] + max_retry=10
    	  	9738 	  	22:41:06 DEBUG| [stdout] + grep kmem_cache_free trace
    	  	9739 	  	22:41:06 DEBUG| [stdout] + wc -l
    	  	9740 	  	22:41:06 DEBUG| [stdout] + [ 0 -eq 0 ]
    	  	9741 	  	22:41:06 DEBUG| [stdout] + sample_events
    	  	9742 	  	22:41:06 DEBUG| [stdout] + echo 1
    	  	9743 	  	22:41:06 DEBUG| [stdout] + echo 1
    	  	9744 	  	22:41:06 DEBUG| [stdout] + ls
    	  	9745 	  	22:41:06 DEBUG| [stdout] + echo 0
    	  	9746 	  	22:41:06 DEBUG| [stdout] + echo 0
    	  	9747 	  	22:41:06 DEBUG| [stdout] + max_retry=9
    	  	9748 	  	22:41:06 DEBUG| [stdout] + [ 9 -eq 0 ]
    	  	9749 	  	22:41:06 DEBUG| [stdout] + grep kmem_cache_free trace
    	  	9750 	  	22:41:06 DEBUG| [stdout] + wc -l
    	  	9751 	  	22:41:06 DEBUG| [stdout] + [ 0 -eq 0 ]
    	  	9752 	  	22:41:06 DEBUG| [stdout] + sample_events
    	  	9753 	  	22:41:06 DEBUG| [stdout] + echo 1
    	  	9754 	  	22:41:06 DEBUG| [stdout] + echo 1
    	  	9755 	  	22:41:06 DEBUG| [stdout] + ls
    	  	9756 	  	22:41:06 DEBUG| [stdout] + echo 0
    	  	9757 	  	22:41:06 DEBUG| [stdout] + echo 0
    	  	9758 	  	22:41:06 DEBUG| [stdout] + max_retry=8
    	  	9759 	  	22:41:06 DEBUG| [stdout] + [ 8 -eq 0 ]
    	  	9760 	  	22:41:06 DEBUG| [stdout] + grep kmem_cache_free trace
    	  	9761 	  	22:41:06 DEBUG| [stdout] + wc -l
    	  	9762 	  	22:41:06 DEBUG| [stdout] + [ 0 -eq 0 ]
    	  	9763 	  	22:41:06 DEBUG| [stdout] + sample_events
    	  	9764 	  	22:41:06 DEBUG| [stdout] + echo 1
    	  	9765 	  	22:41:06 DEBUG| [stdout] + echo 1
    	  	9766 	  	22:41:06 DEBUG| [stdout] + ls
    	  	9767 	  	22:41:06 DEBUG| [stdout] + echo 0
    	  	9768 	  	22:41:06 DEBUG| [stdout] + echo 0
    	  	9769 	  	22:41:06 DEBUG| [stdout] + max_retry=7
    	  	9770 	  	22:41:06 DEBUG| [stdout] + [ 7 -eq 0 ]
    	  	9771 	  	22:41:06 DEBUG| [stdout] + grep kmem_cache_free trace
    	  	9772 	  	22:41:06 DEBUG| [stdout] + wc -l
    	  	9773 	  	22:41:06 DEBUG| [stdout] + [ 0 -eq 0 ]
    	  	9774 	  	22:41:06 DEBUG| [stdout] + sample_events
    	  	9775 	  	22:41:06 DEBUG| [stdout] + echo 1
    	  	9776 	  	22:41:06 DEBUG| [stdout] + echo 1
    	  	9777 	  	22:41:06 DEBUG| [stdout] + ls
    	  	9778 	  	22:41:06 DEBUG| [stdout] + echo 0
    	  	9779 	  	22:41:06 DEBUG| [stdout] + echo 0
    	  	9780 	  	22:41:06 DEBUG| [stdout] + max_retry=6
    	  	9781 	  	22:41:06 DEBUG| [stdout] + [ 6 -eq 0 ]
    	  	9782 	  	22:41:06 DEBUG| [stdout] + grep kmem_cache_free trace
    	  	9783 	  	22:41:06 DEBUG| [stdout] + wc -l
    	  	9784 	  	22:41:06 DEBUG| [stdout] + [ 0 -eq 0 ]
    	  	9785 	  	22:41:06 DEBUG| [stdout] + sample_events
    	  	9786 	  	22:41:06 DEBUG| [stdout] + echo 1
    	  	9787 	  	22:41:06 DEBUG| [stdout] + echo 1
    	  	9788 	  	22:41:06 DEBUG| [stdout] + ls
    	  	9789 	  	22:41:06 DEBUG| [stdout] + echo 0
    	  	9790 	  	22:41:06 DEBUG| [stdout] + echo 0
    	  	9791 	  	22:41:06 DEBUG| [stdout] + max_retry=5
    	  	9792 	  	22:41:06 DEBUG| [stdout] + [ 5 -eq 0 ]
    	  	9793 	  	22:41:06 DEBUG| [stdout] + grep kmem_cache_free trace
    	  	9794 	  	22:41:06 DEBUG| [stdout] + wc -l
    	  	9795 	  	22:41:06 DEBUG| [stdout] + [ 0 -eq 0 ]
    	  	9796 	  	22:41:06 DEBUG| [stdout] + sample_events
    	  	9797 	  	22:41:06 DEBUG| [stdout] + echo 1
    	  	9798 	  	22:41:06 DEBUG| [stdout] + echo 1
    	  	9799 	  	22:41:06 DEBUG| [stdout] + ls
    	  	9800 	  	22:41:06 DEBUG| [stdout] + echo 0
    	  	9801 	  	22:41:06 DEBUG| [stdout] + echo 0
    	  	9802 	  	22:41:06 DEBUG| [stdout] + max_retry=4
    	  	9803 	  	22:41:06 DEBUG| [stdout] + [ 4 -eq 0 ]
    	  	9804 	  	22:41:06 DEBUG| [stdout] + grep kmem_cache_free trace
    	  	9805 	  	22:41:06 DEBUG| [stdout] + wc -l
    	  	9806 	  	22:41:06 DEBUG| [stdout] + [ 0 -eq 0 ]
    	  	9807 	  	22:41:06 DEBUG| [stdout] + sample_events
    	  	9808 	  	22:41:06 DEBUG| [stdout] + echo 1
    	  	9809 	  	22:41:06 DEBUG| [stdout] + echo 1
    	  	9810 	  	22:41:06 DEBUG| [stdout] + ls
    	  	9811 	  	22:41:06 DEBUG| [stdout] + echo 0
    	  	9812 	  	22:41:06 DEBUG| [stdout] + echo 0
    	  	9813 	  	22:41:06 DEBUG| [stdout] + max_retry=3
    	  	9814 	  	22:41:06 DEBUG| [stdout] + [ 3 -eq 0 ]
    	  	9815 	  	22:41:06 DEBUG| [stdout] + grep kmem_cache_free trace
    	  	9816 	  	22:41:06 DEBUG| [stdout] + wc -l
    	  	9817 	  	22:41:06 DEBUG| [stdout] + [ 0 -eq 0 ]
    	  	9818 	  	22:41:06 DEBUG| [stdout] + sample_events
    	  	9819 	  	22:41:06 DEBUG| [stdout] + echo 1
    	  	9820 	  	22:41:06 DEBUG| [stdout] + echo 1
    	  	9821 	  	22:41:06 DEBUG| [stdout] + ls
    	  	9822 	  	22:41:06 DEBUG| [stdout] + echo 0
    	  	9823 	  	22:41:06 DEBUG| [stdout] + echo 0
    	  	9824 	  	22:41:06 DEBUG| [stdout] + max_retry=2
    	  	9825 	  	22:41:06 DEBUG| [stdout] + [ 2 -eq 0 ]
    	  	9826 	  	22:41:06 DEBUG| [stdout] + grep kmem_cache_free trace
    	  	9827 	  	22:41:06 DEBUG| [stdout] + wc -l
    	  	9828 	  	22:41:06 DEBUG| [stdout] + [ 0 -eq 0 ]
    	  	9829 	  	22:41:06 DEBUG| [stdout] + sample_events
    	  	9830 	  	22:41:06 DEBUG| [stdout] + echo 1
    	  	9831 	  	22:41:06 DEBUG| [stdout] + echo 1
    	  	9832 	  	22:41:06 DEBUG| [stdout] + ls
    	  	9833 	  	22:41:06 DEBUG| [stdout] + echo 0
    	  	9834 	  	22:41:06 DEBUG| [stdout] + echo 0
    	  	9835 	  	22:41:06 DEBUG| [stdout] + max_retry=1
    	  	9836 	  	22:41:06 DEBUG| [stdout] + [ 1 -eq 0 ]
    	  	9837 	  	22:41:06 DEBUG| [stdout] + grep kmem_cache_free trace
    	  	9838 	  	22:41:06 DEBUG| [stdout] + wc -l
    	  	9839 	  	22:41:06 DEBUG| [stdout] + [ 0 -eq 0 ]
    	  	9840 	  	22:41:06 DEBUG| [stdout] + sample_events
    	  	9841 	  	22:41:06 DEBUG| [stdout] + echo 1
    	  	9842 	  	22:41:06 DEBUG| [stdout] + echo 1
    	  	9843 	  	22:41:06 DEBUG| [stdout] + ls
    	  	9844 	  	22:41:06 DEBUG| [stdout] + echo 0
    	  	9845 	  	22:41:06 DEBUG| [stdout] + echo 0
    	  	9846 	  	22:41:06 DEBUG| [stdout] + max_retry=0
    	  	9847 	  	22:41:06 DEBUG| [stdout] + [ 0 -eq 0 ]
    	  	9848 	  	22:41:06 DEBUG| [stdout] + exit_fail
    	  	9849 	  	22:41:06 DEBUG| [stdout] + exit 1
    	  	9850 	  	22:41:06 DEBUG| [stdout] 
    	  	9851 	  	22:41:06 DEBUG| [stdout] 
    	  	9852 	  	22:41:06 DEBUG| [stdout] # of passed:  1
    	  	9853 	  	22:41:06 DEBUG| [stdout] # of failed:  1
    	  	9854 	  	22:41:06 DEBUG| [stdout] # of unresolved:  0
    	  	9855 	  	22:41:06 DEBUG| [stdout] # of untested:  0
    	  	9856 	  	22:41:06 DEBUG| [stdout] # of unsupported:  0
    	  	9857 	  	22:41:06 DEBUG| [stdout] # of xfailed:  0
    	  	9858 	  	22:41:06 DEBUG| [stdout] # of undefined(test bug):  0
    	  	9859 	  	22:41:06 ERROR| Exception escaping from test:
    	  	9860 	  	Traceback (most recent call last):
    	  	9861 	  	  File "/home/ubuntu/autotest/client/shared/test.py", line 411, in _exec
    	  	9862 	  	    _call_test_function(self.execute, *p_args, **p_dargs)
    	  	9863 	  	  File "/home/ubuntu/autotest/client/shared/test.py", line 823, in _call_test_function
    	  	9864 	  	    return func(*args, **dargs)
    	  	9865 	  	           ^^^^^^^^^^^^^^^^^^^^
    	  	9866 	  	  File "/home/ubuntu/autotest/client/shared/test.py", line 290, in execute
    	  	9867 	  	    self._call_run_once(constraints, profile_only,
    	  	9868 	  	  File "/home/ubuntu/autotest/client/shared/test.py", line 212, in _call_run_once
    	  	9869 	  	    self.run_once(*args, **dargs)
    	  	9870 	  	  File "/home/ubuntu/autotest/client/tests/ubuntu_kselftests_ftrace/ubuntu_kselftests_ftrace.py", line 112, in run_once
    	  	9871 	  	    result = utils.system_output(cmd, retain_output=True)
    	  	9872 	  	             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
    	  	9873 	  	  File "/home/ubuntu/autotest/client/shared/utils.py", line 1265, in system_output
    	  	9874 	  	    out = run(command, timeout=timeout, ignore_status=ignore_status,
    	  	9875 	  	          ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
    	  	9876 	  	  File "/home/ubuntu/autotest/client/shared/utils.py", line 916, in run
    	  	9877 	  	    raise error.CmdError(command, bg_job.result,
    	  	9878 	  	autotest.client.shared.error.CmdError: Command <./ftracetest -v test.d/filter/event-filter-function.tc> failed, rc=1, Command returned non-zero exit status
    	  	9879 	  	* Command: 
    	  	9880 	  	    ./ftracetest -v test.d/filter/event-filter-function.tc
    	  	9881 	  	Exit status: 1
    	  	9882 	  	Duration: 0.7365949153900146
    	  	9883 	  	
    	  	9884 	  	stdout:
    	  	9885 	  	=== Ftrace unit tests ===
    	  	9886 	  	[1] event filter function - test event filtering on functions    [PASS]
    	  	9887 	  	[2] (instance)  event filter function - test event filtering on functions    [FAIL]

To manage notifications about this bug go to:
https://bugs.launchpad.net/ubuntu-kernel-tests/+bug/2101887/+subscriptions



Follow ups