[Tcl-bugs] [ tcl-Bugs-3485833 ] trace - inexplicable large overhead by ensemble commands

[SourceForge.net <no...@so...>]

Bugs item #3485833, was opened at 2012-02-08 10:43
Message generated for change (Comment added) made by dgp
You can respond by visiting: 
https://sourceforge.net/tracker/?func=detail&atid=110894&aid=3485833&group_id=10894

Please note that this message will contain a full copy of the comment thread,
including the initial issue submission, for this request,
not just the latest update.
>Category: 21. [namespace]
Group: current: 8.5.11
Status: Open
Resolution: None
Priority: 5
Private: No
Submitted By: Serg G. Brester (sebres)
>Assigned to: Donal K. Fellows (dkf)
Summary: trace - inexplicable large overhead by ensemble commands

Initial Comment:
Hello, 

I've found that by "execution" trace some ensemble commands produce a lot of overhead... 
without trace it is comparable with not ensemble commands
i have own profiler (to check which code works slowly), that calls somthing like this :

Tcl_CreateObjTrace( interp, level, TCL_ALLOW_INLINE_COMPILATION | ((TCL_TRACE_ANY_EXEC) >> 2),
         &tclexProfilerTraceProc, inDbgObj, NULL );
The C procedure "tclexProfilerTraceProc" i have rewritten to test this, that it performs "return TCL_OK;" only.

Strange is the execution times of "string length" and "::tcl::string::length" are not different, 
but "string range" or "string first" are 100 times slower as its not ensemble commands "::tcl::string::range" or "::tcl::string::first".

That overhead make me not possible, to profile anything code, using ensembles.

Tcl code to be "profiled":
%%%%
set s [string repeat A 50000]; puts ok
puts "--- string range ----"
puts [time {::tcl::string::range $s 2000 2001} 100000]
puts [time {::string range $s 2000 2001} 10000]
puts "--- string first ----"
puts [time {::tcl::string::first A $s 2000} 100000]
puts [time {::string first A $s 2000} 10000]
puts "--- string length ---"
puts [time {::tcl::string::length $s} 100000]
puts [time {::string length $s} 10000]
puts "--- test ------------"
proc ::test1_string_range {s from to} {set a 5}
proc ::test2_string_range {ens s from to} {set a 5}
puts [time {::test1_string_range $s 2000 2001} 10000]
puts [time {::test2_string_range range $s 2000 2001} 10000]
%%%%

Result is :
ok
--- string range ----
1.4 microseconds per iteration
168.8 microseconds per iteration !!!
--- string first ----
1.09 microseconds per iteration
168.8 microseconds per iteration !!!
--- string length ---
0.31 microseconds per iteration
0.0 microseconds per iteration
--- test ------------
1.6 microseconds per iteration
1.5 microseconds per iteration


----------------------------------------------------------------------

>Comment By: Don Porter (dgp)
Date: 2012-02-08 13:25

Message:

The bytecompiled subcommand [string length] is good.

The subcommands that don't compile [string range,first] show
the problem.

I suspect that every iteration of [time] is re-attempting the
compile.  No hard evidence yet.

----------------------------------------------------------------------

Comment By: Don Porter (dgp)
Date: 2012-02-08 13:00

Message:

Another releated Q, is it all ensembles
that have this issue, or only those that
are byte compiled?

----------------------------------------------------------------------

Comment By: Don Porter (dgp)
Date: 2012-02-08 12:59

Message:

ok, reverse the question then.  Is the problem
already corrected on the tip of the core-8-5-branch?

----------------------------------------------------------------------

Comment By: Serg G. Brester (sebres)
Date: 2012-02-08 11:28

Message:
> Don: original release 8.5.11

What is funny - but even tcl proc is "in trace" faster than "ensemble":
%
if {[info command ::org_string] == {}} {
  rename ::string ::org_string
  proc ::string {args} {{*}[lreplace $args 0 0 "::tcl::string::[lindex
$args 0]"]}
}
.... the same test code ....
%

The result is :
ok
--- string range ----
2.04 microseconds per iteration
7.8 microseconds per iteration
--- string first ----
1.87 microseconds per iteration
7.8 microseconds per iteration
--- string length ---
0.32 microseconds per iteration
6.2 microseconds per iteration
--- test ------------
3.1 microseconds per iteration
1.6 microseconds per iteration


----------------------------------------------------------------------

Comment By: Don Porter (dgp)
Date: 2012-02-08 11:10

Message:

Does the 8.5.11 release have this problem,
or only the tip of the core-8-5-branch ?

----------------------------------------------------------------------

Comment By: Serg G. Brester (sebres)
Date: 2012-02-08 10:51

Message:
the difference between execution times of "ensemble" and "not ensemble" is
then greater if string "s" is longer, and vice versa.

----------------------------------------------------------------------

You can respond by visiting: 
https://sourceforge.net/tracker/?func=detail&atid=110894&aid=3485833&group_id=10894