Re: precompiled probing scenarios

[David Smith <dsmith@redhat.com>]

Stone, Joshua I wrote:
> On Friday, October 20, 2006 6:50 AM, David Smith wrote:
>> Frank Ch. Eigler wrote:
>>>> Note that currently several tests in the testsuite fail after a
>>>> first run to seed the cache because they don't expect to see the
>>>> skip from pass 2 to pass 5.
>>> How do you mean they fail?  -p3 or -p4 should still work.
>> Here's what goes on.  The '-p3' and '-p4' options still work.  But,
>> several run ('-p5') tests use testsuite/lib/stap_run.exp or
>> testsuite/lib/stap_run2.exp.  Those two tcl files expect to see "Pass
>> [12345]" in the output.  They get confused when only seeing "Pass
>> [125]" and then think the test has timed out.
> 
> Would it make sense to print "dummy" pass 3/4 messages when a cached
> version is used?  Something like:
> 
> Pass 1: parsed user script and 53 library script(s) in
> 310usr/0sys/326real ms.
> Pass 2: analyzed script: 1 probe(s), 0 function(s), 0 global(s) in
> 10usr/0sys/5real ms.
> Pass 3: (cached) in 0usr/0sys/0real ms.
> Pass 4: (cached) in 0usr/0sys/0real ms.
> Pass 5: starting run.

Actually I've found out that the lack of "Pass [34]" wasn't the problem, 
it was the extra cache output messages that was confusing the testsuite.

Here's what the output now looks like (non-cached and cached):

=====
# stap -v -e 'probe begin { log("hi") }'
Pass 1: parsed user script and 53 library script(s) in 
680usr/10sys/692real ms.
Pass 2: analyzed script: 1 probe(s), 1 function(s), 0 global(s) in 
10usr/0sys/11real ms.
Pass 3: translated to C into 
"/tmp/stapYrsXWC/stap_d833fd040735ddde57a23bebb4456542_201.c" in 
140usr/90sys/245real ms.
Pass 4: compiled C into "stap_d833fd040735ddde57a23bebb4456542_201.ko" 
in 5030usr/550sys/5587real ms.
Copying /tmp/stapYrsXWC/stap_d833fd040735ddde57a23bebb4456542_201.ko to 
/home/dsmith/.stap_cache/d/8/stap_d833fd040735ddde57a23bebb4456542_201.ko
Copying /tmp/stapYrsXWC/stap_d833fd040735ddde57a23bebb4456542_201.c to 
/home/dsmith/.stap_cache/d/8/stap_d833fd040735ddde57a23bebb4456542_201.c
Pass 5: starting run.
hi
Pass 5: run completed in 10usr/40sys/4634real ms.
# stap -v -e 'probe begin { log("hi") }'
Pass 1: parsed user script and 53 library script(s) in 
670usr/20sys/692real ms.
Pass 2: analyzed script: 1 probe(s), 1 function(s), 0 global(s) in 
10usr/0sys/11real ms.
Using cached result 
"/home/dsmith/.stap_cache/d/8/stap_d833fd040735ddde57a23bebb4456542_201.ko" 
as "/tmp/stapJFisJO/stap_d833fd040735ddde57a23bebb4456542_201.ko"
Pass 5: starting run.
hi
Pass 5: run completed in 0usr/40sys/1656real ms.
=====

> The timing info doesn't need to be hardcoded zero, I just expect it
> would be very small.
> 
> Side question - do you still use caching when someone calls '-p3' or
> '-p4'?  And with verbosity increased, what would this output, given that
> you're not actually doing the work?  (e.g., you wouldn't have a compiler
> output on a cached pass-4.)

A module only gets added to the cache if pass 4 completes successfully. 
  A module (currently) gets pulled from the cache after pass 2, even if 
'-p3' or '-p4' was specified on the command line.

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