Odd performance numbers
Jeff McWhirter
In running some performance tests I began to notice some curious results
between running a test at the top level of a script (i.e., not in a
procedure or
control structure) and running the test inside a proc of control structure.
With the following script:
##########################
proc testproc {} {}
puts "top level: [time testproc 100000]"
if {1} {puts "inside if: [time testproc 100000]"}
proc test {} {puts "inside proc: [time testproc 100000]"}
test
##########################
I get (tcl8.3 on both Windows98 and Linux boxes):
top level: 4 microseconds per iteration
inside if: 24 microseconds per iteration
inside proc: 24 microseconds per iteration
Any ideas why the differences?
-Jeff
Jeff McWhirter
Infocetera - Create - Organize -Share
http://www.infocetera.com
Robert J. Peters
> With the following script:
> ##########################
> proc testproc {} {}
>
> puts "top level: [time testproc 100000]"
>
> if {1} {puts "inside if: [time testproc 100000]"}
>
> proc test {} {puts "inside proc: [time testproc 100000]"}
>
> test
> ##########################
>
> I get (tcl8.3 on both Windows98 and Linux boxes):
> top level: 4 microseconds per iteration
> inside if: 24 microseconds per iteration
> inside proc: 24 microseconds per iteration
>
> Any ideas why the differences?
No bright ideas, but I'll throw in another data point (I'm running
Linux on a PC, Tcl 8.3.3).
When I first read your post, I started tclsh and pasted the script
into the interpreter; this reliably gave me something like:
% % top level: 9 microseconds per iteration
% % inside if: 9 microseconds per iteration
% % % % inside proc: 10 microseconds per iteration
which looks different than what you reported; so, I put the script
into a file in order to collect more data by re-running several
times. But, when I ran the script file I get something more like what
you observed:
[hume 13:00 911]% tclsh test.tcl
top level: 1 microseconds per iteration
inside if: 9 microseconds per iteration
inside proc: 9 microseconds per iteration
And one more variation:
[hume 13:01 913]% tclsh
% source test.tcl
top level: 1 microseconds per iteration
inside if: 9 microseconds per iteration
inside proc: 9 microseconds per iteration
My first thought would be that this involves byte-compilation (or the
lack thereof), but the conventional wisdom says that code should run
faster *inside* a proc because of byte-compiling, whereas in this case
the code runs faster *outside* the proc.
Cheers,
Rob
****************************************************************
Robert J. Peters Computation and Neural Systems
rjpe...@klab.caltech.edu Caltech
www.klab.caltech.edu/rjpeters/ Mail Code 139-74
(626) 395-2882 Pasadena, CA 91106
Jeff Hobbs
>
> In running some performance tests I began to notice some curious results
> between running a test at the top level of a script (i.e., not in a
> procedure or control structure) and running the test inside a proc
I've seen this crop up before, and I haven't been able to pin it
down yet. The problem relates specifically to the fact that
'testproc' takes no args. Give it one arg, and all three will
have the same (fast) speed. You might think this odd, since arg
handling should take more time (even if minute), but somehow that
is so. I've never looked hard though, because the difference is
always a small, invariant number (about 20 usecs or so depending
on machine speed).
--
Jeff Hobbs The Tcl Guy
Senior Developer http://www.ActiveState.com/
Tcl Support and Productivity Solutions
miguel sofer
>
> Jeff McWhirter wrote:
> >
> > In running some performance tests I began to notice some curious results
> > between running a test at the top level of a script (i.e., not in a
> > procedure or control structure) and running the test inside a proc
>
> I've seen this crop up before, and I haven't been able to pin it
> down yet. The problem relates specifically to the fact that
> 'testproc' takes no args. Give it one arg, and all three will
> have the same (fast) speed. You might think this odd, since arg
> handling should take more time (even if minute), but somehow that
> is so. I've never looked hard though, because the difference is
> always a small, invariant number (about 20 usecs or so depending
> on machine speed).
>
A further data point:if the single argument is _args_, the speed
difference remains.
This is strange indeed ...
miguel sofer
>
> Jeff McWhirter wrote:
> >
> > In running some performance tests I began to notice some curious results
> > between running a test at the top level of a script (i.e., not in a
> > procedure or control structure) and running the test inside a proc
>
> I've seen this crop up before, and I haven't been able to pin it
> down yet. The problem relates specifically to the fact that
> 'testproc' takes no args. Give it one arg, and all three will
> have the same (fast) speed. You might think this odd, since arg
> handling should take more time (even if minute), but somehow that
> is so. I've never looked hard though, because the difference is
> always a small, invariant number (about 20 usecs or so depending
> on machine speed).
The output of
proc testproc {args} {set x 1}
proc test0 {} {puts "proc test0: [time {testproc} 100000]"}
proc test1 {} {puts "proc test1: [time {testproc } 100000]"}
proc test2 {} {eval {puts "proc test2: [time {testproc} 100000]"}}
puts "top level: [time {testproc } 100000]"
test0
test1
test2
is
[mig@mini unix]$ tclsh test2
top level: 4 microseconds per iteration
proc test0: 20 microseconds per iteration
proc test1: 4 microseconds per iteration
proc test2: 4 microseconds per iteration
I think that the problem in test1 is caused by shimmering of the literal
"testproc":
- it is converted to tclByteCodeType by Tcl_EvalObjEx
- it is converted to tclCommandNameType by Tcl_ExecuteByteCode
So, the difference would be:
- in test0, "testproc" is parsed, compiled and looked up as a
command repeatedly
- at top-level and in test2, "testproc" never becomes a
tclByteCodeType
- in test1, there are two different literals: "testproc " is always
tclByteCodeType, "testproc" is always tclCommandNameType
This would explain why the difference only occurs at calls with no
arguments.
Jeff (nicely multi-valued, can shimmer too ...): Does this make sense?
Jeff McWhirter
Jeff Hobbs wrote in message <3B93E402...@ActiveState.com>...
>I've seen this crop up before, and I haven't been able to pin it
>down yet. The problem relates specifically to the fact that
>'testproc' takes no args. Give it one arg, and all three will
>have the same (fast) speed. You might think this odd, since arg
>handling should take more time (even if minute), but somehow that
>is so. I've never looked hard though, because the difference is
>always a small, invariant number (about 20 usecs or so depending
>on machine speed).
>
I see that, with an arg I get:
puts "top level: [time {list 1} 100000]"
if {1} {puts "inside if: [time {list 1} 100000]"}
I get:
top level: 4 microseconds per iteration
inside if: 3 microseconds per iteration
and with no args:
puts "top level: [time {list} 100000]"
if {1} {puts "inside if: [time {list} 100000]"}
I get:
top level: 2 microseconds per iteration
inside if: 19 microseconds per iteration
Now of course it's only 17 usecs difference but if I call list 1000 times
then it starts becoming real time.
-Jeff
Jeffrey Hobbs
...
Excellent analysis (I'm so happy there are more eyes in the
core nowadays). I'd agree with that. Tough problem, but I
think that I can hack around it. Again, really a need for
Feather to handle this well.
This should perhaps be lodged at SF to not get forgotten.
miguel sofer
>
> This should perhaps be lodged at SF to not get forgotten.
>
Logged at