[Bug runtime/30131] New: Testcase at_var_timer_profile.exp regressed

[Bug runtime/30131] New: Testcase at_var_timer_profile.exp regressed

[mcermak at redhat dot com]

https://sourceware.org/bugzilla/show_bug.cgi?id=30131

            Bug ID: 30131
           Summary: Testcase at_var_timer_profile.exp regressed
           Product: systemtap
           Version: unspecified
            Status: NEW
          Severity: normal
          Priority: P2
         Component: runtime
          Assignee: systemtap at sourceware dot org
          Reporter: mcermak at redhat dot com
  Target Milestone: ---

Created attachment 14688
  --> https://sourceware.org/bugzilla/attachment.cgi?id=14688&action=edit
test results overview

The testcase at_var_timer_profile.exp demonstrably regressed, specifically for
rhel9, see the attached overview.  The test case was added as part of commit
bd1fcbad9165da8 back in 2013.  Based on my bisection on rhel9, the regression
was caused by a kernel update 5.14.0-178.el9 ---> 5.14.0-178.el9.

Here's the testcase script as of today:
https://sourceware.org/git/?p=systemtap.git;a=blob;f=testsuite/systemtap.base/at_var_timer_profile.stp;h=479f74941a9fd739ea05b0d566c52d8929af7d03;hb=HEAD

Here's how the testcase works fine with 5.14.0-178.el9.x86_64
------------------------------------------------------------------
9 x86_64 # stap
/root/systemtap/testsuite/systemtap.base/at_var_timer_profile.stp -c
./at_var_timer_profile /root/build/testsuite/at_var_timer_profile
/usr/local/bin/stap:/root/build/testsuite/at_var_timer_profile:/usr/local/bin/staprun
/usr/local/bin/stap:/usr/local/bin/staprun
@var("foo", @1)->bar: 42
@var("foo@at_var_timer_profile.c", @1)->bar: 42
@var("foo@at_var_timer_profile.c", @2)->bar: 42
@var("foo", @1)$: {.bar=42}
@var("foo", @1)$$: {.bar=42}
@defined(@var("foo", "badmodle")): NO
@defined(@var("foo", @3)): NO
9 x86_64 # 

Here's how the testcase fails with 5.14.0-179.el9.x86_64
------------------------------------------------------------------
9 x86_64 # stap
/root/systemtap/testsuite/systemtap.base/at_var_timer_profile.stp -c
./at_var_timer_profile /root/build/testsuite/at_var_timer_profile
/usr/local/bin/stap:/root/build/testsuite/at_var_timer_profile:/usr/local/bin/staprun
/usr/local/bin/stap:/usr/local/bin/staprun
ERROR: read fault [man error::fault] at 0x404028 near operator '@var' at
/root/systemtap/testsuite/systemtap.base/at_var_timer_profile.stp:15:42
WARNING: Number of errors: 1, skipped probes: 0
WARNING: /usr/local/bin/staprun exited with status: 1
Pass 5: run failed.  [man error::pass5]
9 x86_64 #

-- 
You are receiving this mail because:
You are the assignee for the bug.

[Bug runtime/30131] Testcase at_var_timer_profile.exp regressed

[mcermak at redhat dot com]

https://sourceware.org/bugzilla/show_bug.cgi?id=30131

--- Comment #1 from Martin Cermak <mcermak at redhat dot com> ---
Created attachment 14689
  --> https://sourceware.org/bugzilla/attachment.cgi?id=14689&action=edit
a demo patch

My sense is that it might be a testcase problem:

> Here's the testcase script as of today:
> https://sourceware.org/git/?p=systemtap.git;a=blob;f=testsuite/systemtap.
> base/at_var_timer_profile.stp;h=479f74941a9fd739ea05b0d566c52d8929af7d03;
> hb=HEAD

The testcase has two probes that fire asynchronously:

global active = 0

probe process.function("sub")
{
  active = 1
}

probe timer.profile {
  if (active && pid() == target()) {
      printf("@var(\"foo\", @1)->bar: %d\n", @var("foo", @1)->bar);
      printf("@var(\"foo@at_var_timer_profile.c\", @1)->bar: %d\n",
             @var("foo@at_var_timer_profile.c", @1)->bar);
      printf("@var(\"foo@at_var_timer_profile.c\", @2)->bar: %d\n",
             @var("foo@at_var_timer_profile.c", @2)->bar);
      printf("@var(\"foo\", @1)$: %s\n", @var("foo", @1)$);
      printf("@var(\"foo\", @1)$$: %s\n", @var("foo", @1)$$);
      printf("@defined(@var(\"foo\", \"badmodle\")): %s\n",
             @defined(@var("foo", "badmodule")) ? "YES" : "NO")
      printf("@defined(@var(\"foo\", @3)): %s\n",
             @defined(@var("foo", @3)) ? "YES" : "NO")
      exit()
  }
}


The failure is caused by a fail to read variables that were available in the
first probe process.function (I've checked that), within the second probe -
timer.profile.  My hypothesis is that the second probe simply fires too late,
and the data are gone by then.  IMHO The mentioned kernel update possibly only
impacted the probe timing, indirectly causing this testcase failure. The
attached patch "fixes the failure" and demonstrates this hypothesis.

-- 
You are receiving this mail because:
You are the assignee for the bug.

[Bug runtime/30131] Testcase at_var_timer_profile.exp regressed

[mcermak at redhat dot com]

https://sourceware.org/bugzilla/show_bug.cgi?id=30131

--- Comment #2 from Martin Cermak <mcermak at redhat dot com> ---
Created attachment 14690
  --> https://sourceware.org/bugzilla/attachment.cgi?id=14690&action=edit
possible patch

Attached patch makes the testcase pass.  It makes the testcase name misleading
though (no timer involved).  Actually I'm not sure the test does the right
thing with this patch :)

-- 
You are receiving this mail because:
You are the assignee for the bug.