#114 Enhancing the profiler

open
profiler (3)
7
2014-08-20
2003-10-23
No

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

Discussion

  •  
    Attachments
  • 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&hl=en&lr=&ie=UTF-
    8&selm=bmm7h2%24g30%241%40ork.noris.net&rnum=1

     
    • assigned_to: nobody --> andreas_kupries
     
  • 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
    ?

     
    • priority: 5 --> 7
     
  • 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

    Thanks Frank.

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

     
  • Hemang Lavana
    Hemang Lavana
    2003-10-29

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

     
  • Primary Post on c.l.t.

     
    Attachments
  • Hemang Lavana
    Hemang Lavana
    2003-11-24

    Logged In: YES
    user_id=81875

    > 3. ... This means the ?pattern? will have info commands
    semantics.
    Correct.

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

    > 6. ...my experiments it occurred only with set...
    What does one mean by "profiling the profiler"? 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 "set" command, as
    shown below:

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

    set foo "Hello World"
    puts [::profiler::dump]
    # End ptest.tcl

    hlavana-u5:63> 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>

    # following run is after disabling profiling of profiler itself
    hlavana-u5:64> 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>

    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.

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

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

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

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

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

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

     
  • reworked according to discussion here

     
    Attachments
  • Hemang Lavana
    Hemang Lavana
    2003-12-07

    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.

     
  • Hemang's improvements

     
    Attachments
  • Logged In: YES
    user_id=118601

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

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

     
  • some fixes for 8.3 part

     
    Attachments