S390x - REL5 stap_testing_200611132049.results]

S390x - REL5 stap_testing_200611132049.results]

[David Wilder]

A number of new errors popped up today when testing on the s390x.  The 
new failures were:

FAIL: BASIC2 wasn't cached
FAIL: OPTION2 wasn't cached
FAIL: RUNTIME2 wasn't cached
FAIL: BASIC4 wasn't cached

I have not investigated the cause yet.

--------------------------------------------------------------------------------------------------------------------------------
Date: 200611132049
User: root
Kernel: Linux 2.6.18-1.2732.el5 #1 SMP Tue Oct 17 18:22:28 EDT 2006 
s390x s390x s390x GNU/Linux

Testsuite summary of failed tests
FAIL: bench (0)
FAIL: BASIC2 wasn't cached
FAIL: OPTION2 wasn't cached
FAIL: RUNTIME2 wasn't cached
FAIL: BASIC4 wasn't cached
FAIL: 
/home/testing/test_dir/stap_testing_redhat-release_200611132049/src/testsuite/systemtap.base/kmodule.stp 
startup (eof)
FAIL: probefunc:kernel.statement(0x000000000002f074) startup (eof)
FAIL: absentstats (0 0)
FAIL: 
/home/testing/test_dir/stap_testing_redhat-release_200611132049/src/testsuite/systemtap.maps/foreach_limit.stp 
timed out
FAIL: buildok/twenty.stp
FAIL: buildok/twentythree.stp
FAIL: profile (timeout)
FAIL: profile
FAIL: queue_demo (timeout)
FAIL: queue_demo
FAIL: 
/home/testing/test_dir/stap_testing_redhat-release_200611132049/src/testsuite/systemtap.stress/current.stp 
compilation
=== systemtap Summary ===

# of expected passes 228
# of unexpected failures 16
# of expected failures 114
# of unknown successes 1
# of known failures 4
# of untested testcases 1
runtest completed at Mon Nov 13 15:00:19 2006


-- 
David Wilder
IBM Linux Technology Center
Beaverton, Oregon, USA 
dwilder@us.ibm.com
(503)578-3789

Re: S390x - REL5 stap_testing_200611132049.results]

[David Smith]

David Wilder wrote:
> A number of new errors popped up today when testing on the s390x.  The 
> new failures were:
> 
> FAIL: BASIC2 wasn't cached
> FAIL: OPTION2 wasn't cached
> FAIL: RUNTIME2 wasn't cached
> FAIL: BASIC4 wasn't cached
> 
> I have not investigated the cause yet.

Hmm, those are all related to the caching functionality/tests that I 
wrote.  This could be a expect buffering problem.  Can I see the full 
log for BASIC2?

-- 
David Smith
dsmith@redhat.com
Red Hat
http://www.redhat.com
256.217.0141 (direct)
256.837.0057 (fax)

Re: S390x - REL5 stap_testing_200611132049.results]

[David Smith]

David Wilder wrote:
> David Smith wrote:
> 
>> David Wilder wrote:
>>
>>> A number of new errors popped up today when testing on the s390x.  
>>> The new failures were:
>>>
>>> FAIL: BASIC2 wasn't cached
>>> FAIL: OPTION2 wasn't cached
>>> FAIL: RUNTIME2 wasn't cached
>>> FAIL: BASIC4 wasn't cached
>>>
>>> I have not investigated the cause yet.
>>
>>
>> Hmm, those are all related to the caching functionality/tests that I 
>> wrote.  This could be a expect buffering problem.  Can I see the full 
>> log for BASIC2?
>>
> I included the full test log.  Let me know if you need something else.

Here's the start of the cache.exp output:

> ------------------------------------------------------------------------
> Running /home/testing/test_dir/stap_testing_redhat-release_200611132049/src/testsuite/systemtap.base/cache.exp ...
> Pass 1: parsed user script and PASS: BASIC1 wasn't cached
> Pass 1: parsed user script and 52 library script(s) in 5730usr/90sys/8488real ms.
> Pass 2: analyzed script: 1 probe(s), 0 function(s), 0 embed(s), 0 global(s) in 90usr/0sys/143real ms.
> Pass 3: translated to C into "/tmp/stapm04SSl/stap_068fff0329d56e3f18c39099d7f15ca8_184.c" in 0usr/0sys/2real ms.
> FAIL: BASIC2 wasn't cached
> Pass 1: parsed user script and 52 library script(s) in 5710usr/100sys/8399real ms.
> Pass 2: analyzed script: 1 probe(s), 0 function(s), 0 embed(s), 0 global(s) in 90usr/0sys/133real ms.
> Pass 3: translated to C into "/tmp/stapQXFRli/stap_649b328956d15729d5a17b8e8ec98b64_189.c" in 0usr/0sys/1real ms.
> PASS: OPTION1 wasn't cached

Something *really* strange is going on there.  The above output (and the 
part that I cut out) shows that stap didn't do pass 4 for any of the 
cache tests.  That's really odd, since "stap -p4" is hardcoded in that test.

Can you run the following command *twice* and send me the output?

# stap -v -p4 -e "probe begin {}"

The output should look something like:

---------------
# stap -v -p4 -e "probe begin {}"
Pass 1: parsed user script and 53 library script(s) in 
140usr/10sys/165real ms.
Pass 2: analyzed script: 1 probe(s), 0 function(s), 0 embed(s), 0 
global(s) in 10usr/10sys/3real ms.
Pass 3: translated to C into 
"/tmp/stapGSMvEZ/stap_7a5fe045c67645c83d0df1d327d2de1c_122.c" in 
0usr/0sys/0real ms.
Pass 4: compiled C into "stap_7a5fe045c67645c83d0df1d327d2de1c_122.ko" 
in 880usr/140sys/2566real ms.
# stap -v -p4 -e "probe begin {}"
Pass 1: parsed user script and 53 library script(s) in 
140usr/20sys/490real ms.
Pass 2: analyzed script: 1 probe(s), 0 function(s), 0 embed(s), 0 
global(s) in 10usr/0sys/3real ms.
Pass 3: using cached 
/home/dsmith/.systemtap/cache/7a/stap_7a5fe045c67645c83d0df1d327d2de1c_122.c
Pass 4: using cached 
/home/dsmith/.systemtap/cache/7a/stap_7a5fe045c67645c83d0df1d327d2de1c_122.ko
---------------

-- 
David Smith
dsmith@redhat.com
Red Hat
http://www.redhat.com
256.217.0141 (direct)
256.837.0057 (fax)

Re: S390x - REL5 stap_testing_200611132049.results]

[David Wilder]

David Smith wrote:

>
> Something *really* strange is going on there.  The above output (and 
> the part that I cut out) shows that stap didn't do pass 4 for any of 
> the cache tests.  That's really odd, since "stap -p4" is hardcoded in 
> that test.
>
> Can you run the following command *twice* and send me the output?
>
> # stap -v -p4 -e "probe begin {}"
>
> The output should look something like:
>
> ---------------
> # stap -v -p4 -e "probe begin {}"
> Pass 1: parsed user script and 53 library script(s) in 
> 140usr/10sys/165real ms.
> Pass 2: analyzed script: 1 probe(s), 0 function(s), 0 embed(s), 0 
> global(s) in 10usr/10sys/3real ms.
> Pass 3: translated to C into 
> "/tmp/stapGSMvEZ/stap_7a5fe045c67645c83d0df1d327d2de1c_122.c" in 
> 0usr/0sys/0real ms.
> Pass 4: compiled C into "stap_7a5fe045c67645c83d0df1d327d2de1c_122.ko" 
> in 880usr/140sys/2566real ms.
> # stap -v -p4 -e "probe begin {}"
> Pass 1: parsed user script and 53 library script(s) in 
> 140usr/20sys/490real ms.
> Pass 2: analyzed script: 1 probe(s), 0 function(s), 0 embed(s), 0 
> global(s) in 10usr/0sys/3real ms.
> Pass 3: using cached 
> /home/dsmith/.systemtap/cache/7a/stap_7a5fe045c67645c83d0df1d327d2de1c_122.c 
>
> Pass 4: using cached 
> /home/dsmith/.systemtap/cache/7a/stap_7a5fe045c67645c83d0df1d327d2de1c_122.ko 
>
> ---------------
>
Pass 4 is giving an error,  odd that it did not show up in the test 
log.  Here it is:
[....]
mp/stapuYgXg9/.tmp_stap_9001.o /tmp/stapuYgXg9/stap_9001.c
In file included from /usr/local/share/systemtap/runtime/runtime.h:79,
                 from /tmp/stapuYgXg9/stap_9001.c:31:
/usr/local/share/systemtap/runtime/alloc.c:66: error: expected 
declaration specifiers or '...' before '(' token
/usr/local/share/systemtap/runtime/alloc.c: In function 'percpu_free':
/usr/local/share/systemtap/runtime/alloc.c:67: error: number of 
arguments doesn't match prototype
include/linux/percpu.h:51: error: prototype declaration
[...]

 From runtime/alloc.c
[...]
 #ifdef CONFIG_SMP
[...]
66: void _stp_free_percpu(const void *objp)
{
        int i;
        struct percpu_data *p = (struct percpu_data *) (~(unsigned long) 
objp);

        for_each_cpu(i)
                kfree(p->ptrs[i]);
        kfree(p);
}

But earler in alloc.c _stp_free_percpu() is defined:
 
#ifdef CONFIG_SMP
#define _stp_free_percpu(ptr) free_percpu(ptr)
#else
#define _stp_free_percpu(ptr) kfree(ptr)
#endif

I think the #ifdefs are messed up.  Both defines are under  CONFIG_SMP.
If I comment out the first defines it works better, but I am still net 
seeing the
"using cached " message.
 
root@hez235 testing]# stap -v -p4 -e "probe begin {}"
Pass 1: parsed user script and 52 library script(s) in 
1410usr/90sys/1617real ms.
Pass 2: analyzed script: 1 probe(s), 0 function(s), 0 global(s) in 
20usr/0sys/25real ms.
Pass 3: translated to C into "/tmp/stapAeJiJi/stap_9300.c" in 
780usr/2750sys/3863real ms.
Pass 4: compiled C into "stap_9300.ko" in 9440usr/1950sys/12946real ms.
[root@hez235 testing]# stap -v -p4 -e "probe begin {}"
Pass 1: parsed user script and 52 library script(s) in 
1410usr/90sys/1615real ms.
Pass 2: analyzed script: 1 probe(s), 0 function(s), 0 global(s) in 
20usr/0sys/27real ms.
Pass 3: translated to C into "/tmp/stapsDZD66/stap_9388.c" in 
770usr/2760sys/4103real ms.
Pass 4: compiled C into "stap_9388.ko" in 9470usr/1960sys/12527real ms.

   

-- 
David Wilder
IBM Linux Technology Center
Beaverton, Oregon, USA 
dwilder@us.ibm.com
(503)578-3789

Re: S390x - REL5 stap_testing_200611132049.results]

[David Smith]

David Wilder wrote:
> David Smith wrote:
> 
>>
>> Something *really* strange is going on there.  The above output (and 
>> the part that I cut out) shows that stap didn't do pass 4 for any of 
>> the cache tests.  That's really odd, since "stap -p4" is hardcoded in 
>> that test.
>>
>> Can you run the following command *twice* and send me the output?
>>
>> # stap -v -p4 -e "probe begin {}"
>>
>> The output should look something like:
>>
>> ---------------
>> # stap -v -p4 -e "probe begin {}"
>> Pass 1: parsed user script and 53 library script(s) in 
>> 140usr/10sys/165real ms.
>> Pass 2: analyzed script: 1 probe(s), 0 function(s), 0 embed(s), 0 
>> global(s) in 10usr/10sys/3real ms.
>> Pass 3: translated to C into 
>> "/tmp/stapGSMvEZ/stap_7a5fe045c67645c83d0df1d327d2de1c_122.c" in 
>> 0usr/0sys/0real ms.
>> Pass 4: compiled C into "stap_7a5fe045c67645c83d0df1d327d2de1c_122.ko" 
>> in 880usr/140sys/2566real ms.
>> # stap -v -p4 -e "probe begin {}"
>> Pass 1: parsed user script and 53 library script(s) in 
>> 140usr/20sys/490real ms.
>> Pass 2: analyzed script: 1 probe(s), 0 function(s), 0 embed(s), 0 
>> global(s) in 10usr/0sys/3real ms.
>> Pass 3: using cached 
>> /home/dsmith/.systemtap/cache/7a/stap_7a5fe045c67645c83d0df1d327d2de1c_122.c 
>>
>> Pass 4: using cached 
>> /home/dsmith/.systemtap/cache/7a/stap_7a5fe045c67645c83d0df1d327d2de1c_122.ko 
>>
>> ---------------
>>
> Pass 4 is giving an error,  odd that it did not show up in the test 
> log.  Here it is:
> [....]
> mp/stapuYgXg9/.tmp_stap_9001.o /tmp/stapuYgXg9/stap_9001.c
> In file included from /usr/local/share/systemtap/runtime/runtime.h:79,
>                 from /tmp/stapuYgXg9/stap_9001.c:31:
> /usr/local/share/systemtap/runtime/alloc.c:66: error: expected 
> declaration specifiers or '...' before '(' token
> /usr/local/share/systemtap/runtime/alloc.c: In function 'percpu_free':
> /usr/local/share/systemtap/runtime/alloc.c:67: error: number of 
> arguments doesn't match prototype
> include/linux/percpu.h:51: error: prototype declaration
> [...]
> 
>  From runtime/alloc.c
> [...]
> #ifdef CONFIG_SMP
> [...]
> 66: void _stp_free_percpu(const void *objp)
> {
>        int i;
>        struct percpu_data *p = (struct percpu_data *) (~(unsigned long) 
> objp);
> 
>        for_each_cpu(i)
>                kfree(p->ptrs[i]);
>        kfree(p);
> }
> 
> But earler in alloc.c _stp_free_percpu() is defined:
> 
> #ifdef CONFIG_SMP
> #define _stp_free_percpu(ptr) free_percpu(ptr)
> #else
> #define _stp_free_percpu(ptr) kfree(ptr)
> #endif
> 
> I think the #ifdefs are messed up.  Both defines are under  CONFIG_SMP.
> If I comment out the first defines it works better, but I am still net 
> seeing the
> "using cached " message.
> 
> root@hez235 testing]# stap -v -p4 -e "probe begin {}"
> Pass 1: parsed user script and 52 library script(s) in 
> 1410usr/90sys/1617real ms.
> Pass 2: analyzed script: 1 probe(s), 0 function(s), 0 global(s) in 
> 20usr/0sys/25real ms.
> Pass 3: translated to C into "/tmp/stapAeJiJi/stap_9300.c" in 
> 780usr/2750sys/3863real ms.
> Pass 4: compiled C into "stap_9300.ko" in 9440usr/1950sys/12946real ms.
> [root@hez235 testing]# stap -v -p4 -e "probe begin {}"
> Pass 1: parsed user script and 52 library script(s) in 
> 1410usr/90sys/1615real ms.
> Pass 2: analyzed script: 1 probe(s), 0 function(s), 0 global(s) in 
> 20usr/0sys/27real ms.
> Pass 3: translated to C into "/tmp/stapsDZD66/stap_9388.c" in 
> 770usr/2760sys/4103real ms.
> Pass 4: compiled C into "stap_9388.ko" in 9470usr/1960sys/12527real ms.
> 

Hmm.  It appears from that output that the 'stap' binary you are using 
doesn't have caching support.  If it did, the name of the C file 
wouldn't be 'stap_9388.c', it would be something like 
'stap_6bc3d92354bbb164201d174128e2eca5_122.c'.

Can you check and ensure that the latest systemtap has been compiled and 
installed?  Let's see the output of "stap -V".

-- 
David Smith
dsmith@redhat.com
Red Hat
http://www.redhat.com
256.217.0141 (direct)
256.837.0057 (fax)

Re: S390x - REL5 stap_testing_200611132049.results]

[David Wilder]

David Smith wrote:

>
>>>
>>> # stap -v -p4 -e "probe begin {}"
>>>
>>>
>> Pass 4 is giving an error,  odd that it did not show up in the test 
>> log.  Here it is:
>> [....]
>> mp/stapuYgXg9/.tmp_stap_9001.o /tmp/stapuYgXg9/stap_9001.c
>> In file included from /usr/local/share/systemtap/runtime/runtime.h:79,
>>                 from /tmp/stapuYgXg9/stap_9001.c:31:
>> /usr/local/share/systemtap/runtime/alloc.c:66: error: expected 
>> declaration specifiers or '...' before '(' token
>> /usr/local/share/systemtap/runtime/alloc.c: In function 'percpu_free':
>> /usr/local/share/systemtap/runtime/alloc.c:67: error: number of 
>> arguments doesn't match prototype
>> include/linux/percpu.h:51: error: prototype declaration
>> [...]
>>
>>  From runtime/alloc.c
>> [...]
>> #ifdef CONFIG_SMP
>> [...]
>> 66: void _stp_free_percpu(const void *objp)
>> {
>>        int i;
>>        struct percpu_data *p = (struct percpu_data *) (~(unsigned 
>> long) objp);
>>
>>        for_each_cpu(i)
>>                kfree(p->ptrs[i]);
>>        kfree(p);
>> }
>>
>> But earler in alloc.c _stp_free_percpu() is defined:
>>
>> #ifdef CONFIG_SMP
>> #define _stp_free_percpu(ptr) free_percpu(ptr)
>> #else
>> #define _stp_free_percpu(ptr) kfree(ptr)
>> #endif
>>
>> I think the #ifdefs are messed up.  Both defines are under  CONFIG_SMP.
>> If I comment out the first defines it works better, but I am still 
>> net seeing the
>> "using cached " message.
>>
>
> Hmm.  It appears from that output that the 'stap' binary you are using 
> doesn't have caching support.  If it did, the name of the C file 
> wouldn't be 'stap_9388.c', it would be something like 
> 'stap_6bc3d92354bbb164201d174128e2eca5_122.c'.
>
> Can you check and ensure that the latest systemtap has been compiled 
> and installed?  Let's see the output of "stap -V".
>
Woops,  I thought I had run make install, I guess not.  Here is the 
output running the current version of stap.

[root@hez235 obj]# ./stap -v -p4 -e "probe begin {}"
Pass 1: parsed user script and 52 library script(s) in 
5740usr/130sys/6472real ms.
Pass 2: analyzed script: 1 probe(s), 0 function(s), 0 embed(s), 0 
global(s) in 80usr/0sys/102real ms.
Pass 3: translated to C into 
"/tmp/stapMeHOHh/stap_f087f4375cd915e8f124ba8ee388fbb9_177.c" in 
10usr/10sys/2real ms.
Pass 4: compiled C into "stap_f087f4375cd915e8f124ba8ee388fbb9_177.ko" 
in 7580usr/1360sys/10365real ms.
[root@hez235 obj]# ./stap -v -p4 -e "probe begin {}"
Pass 1: parsed user script and 52 library script(s) in 
5720usr/130sys/6756real ms.
Pass 2: analyzed script: 1 probe(s), 0 function(s), 0 embed(s), 0 
global(s) in 90usr/10sys/97real ms.
Pass 3: using cached 
/root/.systemtap/cache/f0/stap_f087f4375cd915e8f124ba8ee388fbb9_177.c
Pass 4: using cached 
/root/.systemtap/cache/f0/stap_f087f4375cd915e8f124ba8ee388fbb9_177.ko

Looks better,  But I still needed to comment out the extra defines for 
_stp_free_percpu() in alloc.c. 

-- 
David Wilder
IBM Linux Technology Center
Beaverton, Oregon, USA 
dwilder@us.ibm.com
(503)578-3789

Re: S390x - REL5 stap_testing_200611132049.results]

[David Smith]

David Wilder wrote:
> David Smith wrote:
>> Hmm.  It appears from that output that the 'stap' binary you are using 
>> doesn't have caching support.  If it did, the name of the C file 
>> wouldn't be 'stap_9388.c', it would be something like 
>> 'stap_6bc3d92354bbb164201d174128e2eca5_122.c'.
>>
>> Can you check and ensure that the latest systemtap has been compiled 
>> and installed?  Let's see the output of "stap -V".
>>
> Woops,  I thought I had run make install, I guess not.  Here is the 
> output running the current version of stap.
> 
> [root@hez235 obj]# ./stap -v -p4 -e "probe begin {}"
> Pass 1: parsed user script and 52 library script(s) in 
> 5740usr/130sys/6472real ms.
> Pass 2: analyzed script: 1 probe(s), 0 function(s), 0 embed(s), 0 
> global(s) in 80usr/0sys/102real ms.
> Pass 3: translated to C into 
> "/tmp/stapMeHOHh/stap_f087f4375cd915e8f124ba8ee388fbb9_177.c" in 
> 10usr/10sys/2real ms.
> Pass 4: compiled C into "stap_f087f4375cd915e8f124ba8ee388fbb9_177.ko" 
> in 7580usr/1360sys/10365real ms.
> [root@hez235 obj]# ./stap -v -p4 -e "probe begin {}"
> Pass 1: parsed user script and 52 library script(s) in 
> 5720usr/130sys/6756real ms.
> Pass 2: analyzed script: 1 probe(s), 0 function(s), 0 embed(s), 0 
> global(s) in 90usr/10sys/97real ms.
> Pass 3: using cached 
> /root/.systemtap/cache/f0/stap_f087f4375cd915e8f124ba8ee388fbb9_177.c
> Pass 4: using cached 
> /root/.systemtap/cache/f0/stap_f087f4375cd915e8f124ba8ee388fbb9_177.ko

Great.  Now it looks like basic caching functionality is working for you.

> Looks better,  But I still needed to comment out the extra defines for 
> _stp_free_percpu() in alloc.c.

You might want to try a "make install" with an unmodified alloc.c just 
to see if the real problem was with mismatches between old/new stap, 
tapsets, and runtime.

-- 
David Smith
dsmith@redhat.com
Red Hat
http://www.redhat.com
256.217.0141 (direct)
256.837.0057 (fax)