tcllib

Logged In: YES
user_id=118601

Hallo Andreas and Hemang,

Now we getting to an end, hopefully.
But let me add some correction and further improvements.

- the uplevel in ::profiler::add:
set addList [uplevel 1 [list ::info commands $pattern]]
is needed, otherwise the test profile-1.4.1 will fail.

- I add a list for gathering the call level. But right now
there is no
evaluation function for this.

- And finally I make the time measurement more correct by
gathering the time date at the beginning of the trace
handler. ;-)

- To test the Tcl8.3 part I rearranged the code a little
bit, to be able to use and test the 8.3 parts with 8.4+.
(init has an optional parameter to forbid the use of
'trace'). Then I adapt the Handler of
8.3 to conform with the TraceHandler and correct some issues
to get my tests pass for 8.3.

- while working with our application I found out that in the
8.3 mode info procs <profiledProc> does not work as
expected. AFAIK, the interp alias does not make an entry to
'info procs' see profile-1.4.3. Therefore programs using
info proc will not work as expected in profiling mode.
I suggest the following change for addCmd:

# uplevel 1 [list interp alias {} $name {}
::profiler::Handler $name]
set body "\n return \[uplevel 1 \[list ::profiler::Handler
$name\] \$args\]\n"
uplevel 1 [list ::_oldProc $name {args} $body]

I guess using the above removeCmd must be changed, too?!
Note, that this change is not in the currently uploaded sources
'profiler4.tar.gz'.

- Again it would be nice if someone looks through the code
and the changes, because last time Hemangs changes made the
source a lot clearer and better, thanks and a happy new year.

<frank/>

Logged In: YES
user_id=118601

Upload of Hemang's improvements of
my patch.
Thanks
&lt;frank/&gt;

Logged In: YES
user_id=81875

I have made several (minor) changes to your code and have
attached
a new tarfile for the same (hmm, I don't see any attach
button at SF,
so I will mail you the tarfile directly). The tarfile also
contains diffs for profiler.tcl with cvs called
profiler_cvs.diff and one with your last
patch version called profiler_2.diff.

The major changes are as outlined below:

* Fixed code to ensure that it works with tcl8.3 as well:
-- replaced use of eq conditions with [string equal ...]
-- add and remove cmds can be called in tcl8.3
* used switch stmt for watchForNewProcs and returns
an error if the argument is not enable or disable
* watchForNewProcs api should not change &quot;paused&quot; variable,
to cover the following scenario
suspend ;# paused = 1
watchForNewProcs disable
watchForNewProcs enable ;# should still be
paused = 1
resume ;# paused = 0
* Moved disabling of profiler cmds in TraceHandler proc
to top of the proc so that it does not waste cylces in
getting the $caller value
* deleted special handling of set command in resume proc
because it is no longer needed
* created a new removeCmd proc similar to addCmd proc

For EMPTY caller, does it happen only during &quot;leave&quot; traces
since the caller has been deleted? Or does it happen when
the caller's namespace has been deleted? Anyway, I will let
Andreas decide on this issue.

Okay, I now understand the issue of timings for recursive
calls, so levels make sense. For coverage, you may want to
file a RFE and we can take its
discussion there. Also, have you looked at TIP86 (still in
draft state) ... I beleive it can make the coverage feature
very easy to implement.

Hemang.

Logged In: YES
user_id=118601

I have added a reworked version as tar.gz, which contains an
alpha of profiler.man and some of the improvements we
discussed here:
- ::profiler::add pattern
- ::profiler::remove pattern
- ::profiler::watchForNewProcs &lt;enable|disable&gt;

Please have a close look on it.
Todo:
- set time in descendants according to info procs

&gt;&gt; 6. ...my experiments it occurred only with set...
&gt;What does one mean by &quot;profiling the profiler&quot;? Note that
[snipped]
&gt;that the profiling of the profiler itself should not affect
&gt;the stats of my application which is being profiled.
I agree
&lt;philosophy&gt;
Well, it depends on the point of view. Both results are correct
in some sense. For a user of the profiler the second result is
definitely the expected and correct one. For the developper
of the profiler the first one is correct. But I think, and I
guess
you agree, this is only a minor issue and we should keep in mind
what the user needs and provided correct results for him.
&lt;/philosophy&gt;
So I disable 'profiling the profiler' in the tracehandler.

&gt;&gt; 7. ...I do have empty but VALID results with [info level -1].
[snipped]
&gt;like to take a look.
Sorry, it is in my company application
and I still got no example for this.

&gt;You are defining caller as EMPTY and the profiler is
&gt;defining it as GLOBAL in some places. What is the difference
&gt;between the two?
GLOBAL means the call was at toplevel
EMPTY means the caller is deleted (tkInit) or was empty (see
above)

&gt;&gt; - time in descendants. That's the points that leads me ...
[snipped]
&gt;... The [info proc $name] can be used for this purpose.
I agree.


&gt;&gt; - To ease the pain of recursive procedure calls...
[snipped]
&gt;with it. Can you elaborate on this issue.
Yes, IMHO except the 'atomic' time measurements for each
call, all
other 'aggregate' measurements do not make much sense.
For example you have a tree walker proc, which is typically
implemented
by a recursive descending proc. Therefore the time for the root
node (time to process the whole tree) is quite different from
the time to process a leaf node. Both results are typically
quite
different. And that's where the level come into play. This would
allow the user to make his own statistics depending on his
needs,
whether he wants to profile the whole tree walking or the time
needed to process a node.

&gt;&gt; - Coverage. ...
&gt;I need to give some more thought to coverage.
okay

&lt;frank/&gt;

Logged In: YES
user_id=81875

&gt; 3. ... This means the ?pattern? will have info commands
semantics.
Correct.

&gt; 5. ...I would not merge them together, because pause/resume
&gt; ...
Okay, how about 'watchForNewProcs enable' and
'watchForNewProcs disable'?

&gt; 6. ...my experiments it occurred only with set...
What does one mean by &quot;profiling the profiler&quot;? Note that
once a trace handler is invoked,further trace invocations
from within the handler procs are disabled to prevent
infinite recursion. This means that tcl commands occuring
inside tZero, tMark, enterHandler, leaveHandler, etc cannot
be ever profiled. That leaves other profiler procs such as
stats, print, dump, suspend, resume, etc available for
profiling. Since these procs would not be called so often, I
feel it is reasonable to not profile them.

Consider that I want to profile a single &quot;set&quot; command, as
shown below:

# ptest.tcl
package require profiler
::profiler::init
::profiler::addCmd set

set foo &quot;Hello World&quot;
puts [::profiler::dump]
# End ptest.tcl

hlavana-u5:63&gt; tclsh ptest.tcl
::set {callCount 34 callerDist {GLOBAL 1 ::profiler::dump 2}
compileTime 1648 totalRuntime 16739 averageRuntime 598
stddevRuntime 394 covpercentRuntime 65.9 descendantTime 0
averageDescendantTime 0 descendants {}}
hlavana-u5:64&gt;

# following run is after disabling profiling of profiler itself
hlavana-u5:64&gt; tclsh ptest.tcl
::set {callCount 1 callerDist {GLOBAL 1} compileTime 1702
totalRuntime 1702 averageRuntime 0 stddevRuntime 0
covpercentRuntime 0 descendantTime 0 averageDescendantTime 0
descendants {}}
hlavana-u5:65&gt;

In the first run, it gives a call count of 34, whereas in
2nd run, the call count is accurate value of 1. Thus I feel
that the profiling of the profiler itself should not affect
the stats of my application which is being profiled.

&gt; 7. ...I do have empty but VALID results with [info level -1].
In your original post to c.l.t, you mentioned that this
problem occured with tcltest. Can you provide instructions
on how to replicate the problem with tcltest ... I would
like to take a look.

You are defining caller as EMPTY and the profiler is
defining it as GLOBAL in some places. What is the difference
between the two?

&gt; 9. ... time should taken when entering the TraceHandler.
Yes, in that case the time measurements can be passed as
arguments to tMark. But I personally don't care about slight
offsets in timing values.

&gt; - time in descendants. That's the points that leads me ...

First we need to clarify what should be measured as time in
descendants. I would think that all procs (node) defined in
tcl should be measured as time spent in descendants and all
buit-in commands (leaf) defined in C should not be
considered. The [info proc $name] can be used for this purpose.

&gt; - To ease the pain of recursive procedure calls...
Is there a problem with profiling recursive proc calls? I
just tried a profiling a recursive function fib
(http://mini.net/tcl/2943) and I didnt' see any problems
with it. Can you elaborate on this issue.

&gt; - Coverage. ...
I need to give some more thought to coverage.

Hemang.

Logged In: YES
user_id=118601

Hallo Andreas and Hemang,

&gt; 1. It would have been nice if the entire post to c.l.t ...
Done. Now I understand the cryptic comment. Thanks Andreas

&gt; 3. Most of the profiler APIs ...accept ?pattern? as an
argument.
Well, the ?name? was a fast hack and I agree ?pattern?
would be better, I think this should be easy to add using
[info commands ?pattern?] and call an internal add function?!
This means the ?pattern? will have info commands semantics.

&gt; 4. Again, most profiler APIs work on commands ...
Agree

&gt; 5. At first, start/stop looked very similar in functionality...
I would not merge them together, because pause/resume
having to do with measuring time and start/stop (okay,
misleading names) are for setting up functions for profiling. So
these functions have different concerns and I would not make
one out of them.

&gt; 6. The problem with set cmd mentioned here can also
occur ...
Hmmm, my experiments it occurred only with set, because the
profiler state is changed during tracing set. Well how
wants to profile the profiler?
Generally I think it is better to put such restrictions into
the add command and move this item there. Put it here will
end up in more inaccurate time measurements.
&gt; Also, use of above method will keep the profiler data to
&gt; scripts only and not skew it with data on its internal
&gt; commands (I don't know whether this is good or bad).
Sorry, I do not understand why the profiler is restricted
to scripts this way. But I definitely want to measure how much
time a procedure spends in 'puts' 'append', etc. and what is
even more interesting how many calls where made to this
functions.

&gt; 7. I didn't quite understand the code related to 2nd try ...
The problem is simple, I do have empty but VALID results
with [info level -1]. Believe me, I wrote tons of simple
examples but up to now I cannot track down this effect. But
unfortunately it is present in our application. So take it as
a workaround for our application. As soon as I get a simple
example I'll post on c.l.t and good ideas are welcome.

&gt; 8. the profProc command should be modified to call addCmd
API
I definitely agree, but that's not so easy regarding Tcl 8.3
parts. BTW, init should use start.

&gt; 9. agree about changing tZero for more accurate timings.
Looking into again, while being in leave trace the time should
taken when entering the TraceHandler. But then time
measurement must be moved out of tMark, and that is
somehow ugly, isn't it.


&gt; It's good to see your patch on these improvements,
because ...

First, thank you for getting involved. When I posted on c.l.t I
was a little bit disappointed that was practically no response
to it.
So let me say thanks to Jeff here.

Second allow me to add and elaborate some items.
- time in descendants. That's the points that leads me to the
need of canonical names. But imagine you add '::append'
or '::puts' to profiling and go through a procedure having
appends and puts in it.
This will be measured as time in descendant. Well, normally
that's not what you expect and I guess not what you want?
So I thought about a concept of node and leaf functions
where node functions add to time in descendants and leafs
not. But which functions are leaf functions and how to detect
them automatically?
Somehow leaf functions are atomic, is it possible to detect
them using info body?

- To ease the pain of recursive procedure calls, I think
one should store the level and the time. Having this would
allow more accurate 'level' statistics.

- Coverage. I am thinking of the following workflow:
- use trace execution with enterstep and/or leavestep.
- restrict this trace to the current level.
- 'back match' each 'step' with body and count.
What do you think about that?

- profiler.man I am working on it.

&lt;frank/&gt;

Logged In: YES
user_id=81875

I have few comments below:

1. It would have been nice if the entire post to c.l.t was
attached here because I couldn't understand the need for
these changes just by reading this summary:). Anyway thanks
to Andreas for adding the url here.

2. agree about using 'canonical' names for function names

3. Most of the profiler APIs such as reset, pause, resume
and dump accept ?pattern? as an argument. I think it would
make sense to do the same for addCmd and removeCmd APIs
(instead of the proposed ?name? argument).

4. Again, most profiler APIs work on commands. So the Cmd
suffix looks redundant to me -- perhaps we should just have
::profiler::add and ::profiler::remove rather addCmd and
removeCmd.

5. At first, start/stop looked very similar in functionality
with pause/resume -- I understood its purpose only after
reading the full post on c.l.t. How about merging it with
pause/resume itself so when pause is called, it will stop
for arranging of procs and calling resume will restart
arranging of procs. However, there is one caveat here -- new
procs defined between pause and rename will not be profiled
unless explicity added using addCmd after resume or
implicitly added by resume itself. Another alternative is to
add -nonewprocs option to pause (for stop) and -addallprocs
option to resume (for start).

6. The problem with set cmd mentioned here can also occur
with any other core tcl commands used in the profiler. A
better alternative would be to modify the TraceHandler proc
to look at the caller's namespace scope and ignore profiling
if it is called from the ::profiler namespace. Would the
following work for you (untested code):

proc :: profiler::TraceHandler {name cmd args} {

if {[uplevel 1 namespace current] eq &quot;::profiler&quot;} {
# Do not profile cmds in profiler namespace
return
}
if { [info level] ...

Of course this means that the profiler itself cannot be
profiled but do we really need to do that? Also, use of
above method will keep the profiler data to scripts only and
not skew it with data on its internal commands (I don't know
whether this is good or bad).

7. I didn't quite understand the code related to 2nd try
when info level returns empty. Can you elaborate on the
problem with some examples.

8. the profProc command should be modified to call addCmd
API internally instead of replicating the code.

9. agree about changing tZero for more accurate timings.

It's good to see your patch on these improvements, because
being a user myself, such enhancements can be very useful.
We should definitely discuss the other open issues that you
mentioned and look upon enhancing the profiler package further.

Hemang.

Logged In: YES
user_id=75003

Thanks Frank.

Yes, the documentation is written manually, and not
extracted from the sources.

Logged In: YES
user_id=118601

Hallo Andreas,
&gt; Frank, please attach the tests you have to this report.
I have added my development 'package' with the tests. It
contains the improved 'profiler.tcl' and the tests
'profiler.test' as well as the 'all.tcl' to invoke them
and some devel procedures (which are NOT needed, but
sometimes they are quite nice) in 'profile_devel.tcl'.
BTW, tracking 'puts' in tcltest is quite 'tricky', because
it is redefined, when the option -output is set.
&gt; Having updated documentation (See profiler.man) would be
&gt; nice too.
Hummpf, is this done manually ??
(That means not generated from the source ?)
&gt; I assume that the change in tZero was done to
...
Exactly, I forgot to mention, sorry. Other things I forgot
is that I have done the work only for Tcl 8.4 and later.
And still the empty info level problem with my application
which I cannot track down to a simple example.
&gt; start/stop:
&gt; start =&gt; watchForNewProcs
&gt; stop =&gt; stopWatching
Sounds good. BTW, init should use and should have an
option to disable it.
And finally, thank you for being interested.
&lt;frank/&gt;

Logged In: YES
user_id=75003

Frank, please attach the tests you have to this report.
Having updated documentation (See profiler.man) would be
nice too. I assume that the change in tZero was done to
make the counting a bit more accurate by doing the [pstirng
map] mgmt before the timebase is set.

start/stop:
start =&gt; watchForNewProcs
stop =&gt; stopWatching
?

Logged In: YES
user_id=75003

The url to submitters posting on c.l.t. is
http://groups.google.ca/groups?q=%
27Enhancing+tcllib+profiler&amp;hl=en&amp;lr=&amp;ie=UTF-
8&amp;selm=bmm7h2%24g30%241%40ork.noris.net&amp;rnum=1