Tk Library Source Code

Hallo,

this patch refers to my posting at comp.lang.tcl
'Enhancing tcllib profiler' and
tries to improve the profiler. For a most explicit
discussion of my ideas see
there, here I give a short summary.

- 'canonical' names using 'namespace origin' in
TraceHandler
  and some workaround for empty info levels and
tkInit's self deletion (ARRG).

- api extension for tcl 8.4 to add and remove procedure
and commands to
  profiling (::profiler::addCmd {name}
::profiler::removeCmd {name})

- start and stop of arranging procs for profiling.
(BTW, I'm still looking for
  better names for these procedures).
  
This are the points which are still open, IMHO (changed
to comp.lang.tcl)
- tracking renames of commands and procedures. Well, my
first try was not very
  successful.
- automatic workaround for namespace import difficulties.
- leaving the profiler completely, something like
package forget ...
- have a closer look on recursive function calls
- and maybe some day one could measure the coverage, too.

BTW, the diff I add is against profiler version 0.2.1.
Again, if you are interested I can send the complete
file and some tcltests.
<frank/>

File Added - 72541: profiler4.tar.gz

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/>

File Added - 70081: profiler3.tar.gz

Logged In: YES 
user_id=118601

Upload of Hemang's improvements of 
my patch.
Thanks
<frank/>

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 "paused" 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 "leave" 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.

File Added - 69548: profiler2.tar.gz

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 <enable|disable>

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

>> 6. ...my experiments it occurred only with set...
>What does one mean by "profiling the profiler"? Note that
[snipped]
>that the profiling of the profiler itself should not affect
>the stats of my application which is being profiled.
I agree
<philosophy>
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.
</philosophy>
So I disable 'profiling the profiler' in the tracehandler.

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

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

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


>> - To ease the pain of recursive procedure calls...
[snipped]
>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.

>> - Coverage. ...
>I need to give some more thought to coverage.
okay

<frank/>

File Added - 66079: profiler.ema.txt

Logged In: YES 
user_id=118601

Hallo Andreas and Hemang,

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

> 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.

> 4. Again, most profiler APIs work on commands ...
Agree

> 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.

> 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.
> 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).
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.

> 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.

> 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.

> 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.


> 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.

<frank/>

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 "::profiler"} {
         # 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.

File Added - 65538: profiler_devel.tar.gz

Logged In: YES 
user_id=118601

Hallo Andreas,
> 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.
> Having updated documentation (See profiler.man) would be 
> nice too.
Hummpf, is this done manually ??
(That means not generated from the source ?)
> 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.
> start/stop:
>     start => watchForNewProcs
>     stop =>  stopWatching
Sounds good. BTW, init should use and should have an
option to disable it.
And finally, thank you for being interested.
<frank/>

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 => watchForNewProcs
    stop =>  stopWatching
?

File Added - 65160: profiler.diff