Odd performance numbers 
Author Message
 Odd performance numbers

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.*-*-*.com/



Sat, 21 Feb 2004 03:24:52 GMT  
 Odd performance numbers

Quote:

> 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

www.klab.caltech.edu/rjpeters/                  Mail Code 139-74
(626) 395-2882                                Pasadena, CA 91106



Sat, 21 Feb 2004 04:05:45 GMT  
 Odd performance numbers

Quote:

> 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



Sat, 21 Feb 2004 04:11:46 GMT  
 Odd performance numbers

Quote:


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



Sat, 21 Feb 2004 06:23:29 GMT  
 Odd performance numbers

Quote:


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

    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?



Sat, 21 Feb 2004 07:52:09 GMT  
 Odd performance numbers

Quote:

>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



Sat, 21 Feb 2004 10:15:49 GMT  
 Odd performance numbers
        ...

Quote:
> 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

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

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.

--
  Jeff Hobbs                     The Tcl Guy
  Senior Developer               http://www.ActiveState.com/
      Tcl Support and Productivity Solutions



Sat, 21 Feb 2004 12:27:41 GMT  
 Odd performance numbers

Quote:

> This should perhaps be lodged at SF to not get forgotten.

Logged at


Sat, 21 Feb 2004 21:02:56 GMT  
 
 [ 8 post ] 

 Relevant Pages 

1. number representations (was: even vs. odd numbers)

2. Odd performance results

3. Even/odd week number

4. determine whether a number is odd or even

5. odd number problem

6. odd number...

7. even vs. odd numbers

8. IVF odd behaviour: subroutine vs function returning floating point number

9. odd number?

10. odd compiler complaints with large numbers

11. Number of arguments and performance

12. Numbers Numbers Numbers

 

 
Powered by phpBB® Forum Software