From: SourceForge.net <no...@so...> - 2012-02-08 19:28:03
|
Bugs item #3485833, was opened at 2012-02-08 10:43 Message generated for change (Comment added) made by sebres 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: 46. Traces Group: current: 8.5.11 Status: Open Resolution: None Priority: 5 Private: No Submitted By: Serg G. Brester (sebres) Assigned to: Don Porter (dgp) 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: 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 |