Menu ▾ ▴

#271 Object creation/deletion speed and memory usage

4.0*
open
nobody
None
5
2018-10-09
2015-12-02
Tim Tomkinson
No

Object creation, deletion, and memory usage is ~10x worse in Tcl8.6.4/Itcl4.0.3 than in Tcl8.5.18/Itcl3.4.2.

Demo script:

package require Itcl
namespace import itcl::*

class A {}

set i 0
puts [time {A $i; incr i} 10000]

set i 0
puts [time {delete object $i; incr i} 10000]

Results:

+-------+------------+------------+-----------+
|  Ver  |   Create   |   Delete   |  Memory   |
+-------+------------+------------+-----------+
| 3.4.2 |  6.0635 µs |  3.4106 µs |  6.724 MB |
| 4.0.3 | 50.0183 µs | 40.6675 µs | 86.556 MB |
+-------+------------+------------+-----------+
| ratio |  8.2490    | 11.9238    | 12.872    |
+-------+------------+------------+-----------+

Ticket http://core.tcl.tk/itcl/tktview?name=04470f9067 improved the speed immensely, but the current inefficiency may still hinder any future projects using Itcl.

Related

Bugs: #271

Discussion

<< < 1 2 3 > >> (Page 2 of 3)

  • Don Porter

    Don Porter - 2016-08-19

    Telling me clearly that multiple Tcl threads are involved. I think that's what I needed to know. Thanks. Will try to use that to craft the right demo.

     

  • Don Porter

    Don Porter - 2016-08-19

    I have a test script now. Appears to be something in a method
    that is leaking.

     

  • Don Porter

    Don Porter - 2016-08-23

    Just committed to trunk a patch that plugs all leaks I could find when Itcl is used over the complete lifetime of an interp. Let me know how it works for you, please.

     

  • Don Porter

    Don Porter - 2016-08-23

    a few more patches fixing flaws discovered along the way.

     

  • Don Porter

    Don Porter - 2016-08-23

    I don't have any reason to believe that the changes since the
    release of Itcl 4.0.5 will have any measurable impact on performance.

    These changes serve those who over time create many interps
    (whether in separate threads or not) that use Itcl and then are
    released. Plugging the leaks lets such programs continue without
    the damaging effects of cumulative memory loss.

     

  • Tim Tomkinson

    Tim Tomkinson - 2017-10-27

    This is still a problem with Itcl 4.1.0. Itcl 3.4's object creation time is constant at about 2 µs, while Itcl 4.1.0's time increases linearly (see attachments). Is this going to be too difficult to fix based on Itcl 4's internal design?

     
    Thumbnail
    itcl3.4.png
    Thumbnail
    itcl4.1.0.png

    • Don Porter

      Don Porter - 2017-10-27

      On 10/27/2017 11:19 AM, Tim Tomkinson wrote:

      This is still a problem with Itcl 4.1.0. Itcl 3.4's object creation time
      is constant at about 2 µs, while Itcl 4.1.0's time increases linearly
      (see attachments). Is this going to be too difficult to fix based on
      Itcl 4's internal design?

      Looks like object creation must still be doing something linear in
      the number of existing objects. Any idea what that is?

      --
      | Don Porter Applied and Computational Mathematics Division |
      | donald.porter@nist.gov Information Technology Laboratory |
      | http://math.nist.gov/~DPorter/ NIST |
      |__________|

       

  • Tim Tomkinson

    Tim Tomkinson - 2017-10-29

    It looks like the problem is in the Itcl_PreserveData() and Itcl_ReleaseData() functions in generic/itclUtil.c, which in turn call Tcl_Preserve() and Tcl_Release(). These functions use a linear search, which is why the time is increasing linearly. The Tcl documentation even states, "The mechanism is intended only for short-term use (i.e. while procedures are pending on the stack); it will not work efficiently as a mechanism for long-term reference counts."

    Itcl 3.4 uses a hash table implementation, which explains why its time is constant. A comment in generic/itcl_util.c states:

     *  REFERENCE-COUNTED DATA
 *
 *  The following procedures manage generic reference-counted data.
 *  They are similar in spirit to the Tcl_Preserve/Tcl_Release
 *  procedures defined in the Tcl/Tk core.  But these procedures use
 *  a hash table instead of a linked list to maintain the references,
 *  so they scale better.  Also, the Tcl procedures have a bad behavior
 *  during the "exit" command.  Their exit handler shuts them down
 *  when other data is still being reference-counted and cleaned up.
     

  • Don Porter

    Don Porter - 2017-10-29
     

  • Don Porter

    Don Porter - 2017-10-29

    Well this may not be too bad. The line that creates the trouble is:

    https://core.tcl.tk/itcl/artifact/cf873c608adaa772?ln=272

    Itcl_PreserveData() is crude and inefficient. It needs replacing
    with an appropriate refcounting scheme directly on the ioPtr
    argument.

     

  • Don Porter

    Don Porter - 2017-10-29

    Guess we had the same plans for a Sunday afternoon.
    Will tackle this soon.

     

  • Don Porter

    Don Porter - 2017-10-29

    Improvement committed to trunk. See what you think.

     

  • Don Porter

    Don Porter - 2017-10-30

    ok, now synced.

     

  • Tim Tomkinson

    Tim Tomkinson - 2017-10-30

    That's a lot better! The creation time is now constant, but it's still significantly slower than 3.4.3. I'll look around some more to see if there's anything obvious.

    BTW, the tclconfig directory seems to be missing from the trunk.

     
    Thumbnail
    ObjectCreationTime.png

  • Don Porter

    Don Porter - 2017-10-30

    tclconfig is a separate project

    core.tcl.tk/tclconfig/

    See these instructions

    http://core.tcl.tk/itcl/wiki?name=Tracking+Itcl+Sources

     

  • Tim Tomkinson

    Tim Tomkinson - 2017-10-31

    I don't think this can get much faster given its current design. There are a lot of new calls to the Tcl core that the old code didn't make (e.g. Tcl_NewObjectInstance, dictionary functions, etc.), which is where most of the time is spent. Too bad, but I guess that's the price of progress.

     

  • Trey Jackson

    Trey Jackson - 2018-05-30

    I've been tracking down performance issues with Itcl, and while 4.1.1 (and top of trunk) definitely improve things, there are a couple of simple patterns which exhibit degradation from Itcl 3.2

    local object creation/deletion in Tcl proc: 4.1.1: 48micros 3.2: 11micros, ratio: ~4:1
    call to member method via eval and itcl::code: 4.1.1 4.8micros, 3.2: 1micros, ratio: ~5:1
    a simple singleton pattern: 4.1.1 13.7micros, 3.2: 2 micros. ratio: ~7:1

    other patterns have about a 30-50% performance penalty

    Output of 3.2 run:

    Tcl version: 8.4
    Itcl version: 3.2
    978406 microseconds per iteration for 1000000 method calls, result: 1000000
    970555 microseconds per iteration for 1000000 method calls, from within a namespace, result: 1000000
    9212 microseconds per iteration for 10000 mutual calls
    9867 microseconds per iteration for 10000 mutual calls of different classes
    11 microseconds per iteration for 10000 creation of objects in a proc call
    1 microseconds per iteration for 10000 method calls via itcl::code and uplevel
    1 microseconds per iteration for 10000 method calls via itcl::code and eval
    1 microseconds per iteration for 10000 proc calls across namespace
    1 microseconds per iteration for 10000 method calls via itcl::code and eval
    2 microseconds per iteration for 10000 method calls via itcl::code and uplevel
    2 microseconds per iteration for 10000 method calls via itcl::code and uplevel #0
    2 microseconds per iteration per each 10000 class calls that use singleton

    Output of 4.1.1 run:

    Tcl version: 8.6
    Itcl version: 4.1.1
    1307143 microseconds per iteration for 1000000 method calls, result: 1000000
    1556553 microseconds per iteration for 1000000 method calls, from within a namespace, result: 1000000
    13979 microseconds per iteration for 10000 mutual calls
    13324 microseconds per iteration for 10000 mutual calls of different classes
    48.9271 microseconds per iteration for 10000 creation of objects in a proc call
    2.4827 microseconds per iteration for 10000 method calls via itcl::code and uplevel
    4.8593 microseconds per iteration for 10000 method calls via itcl::code and eval
    0.2884 microseconds per iteration for 10000 proc calls across namespace
    1.7693 microseconds per iteration for 10000 method calls via itcl::code and eval
    1.7845 microseconds per iteration for 10000 method calls via itcl::code and uplevel
    1.7942 microseconds per iteration for 10000 method calls via itcl::code and uplevel #0
    13.7799 microseconds per iteration per each 10000 class calls that use singleton

    Actual script used to generate these numbers:

    !/bin/sh

    --Tcl-- the next line restarts using wish \

    exec tclsh  "$0" "$@"

    if {[info tclversion] == 8.6} {
    if {[info exists ::env(USE_ITCL_34)]} {
    set env(ITCL_LIBRARY) /wv/tjackson/downloads/86_itcl34_install/lib/itcl3.4
    set auto_path [linsert $auto_path 0 /wv/tjackson/downloads/86_itcl34_install/lib/itcl3.4]
    set auto_path [linsert $auto_path 0 /wv/tjackson/downloads/86_itcl34_install/lib/itk3.4]
    set auto_path [linsert $auto_path 0 /wv/tjackson/downloads/86_itcl34_install/lib/iwidgets]

    catch {package require notGoingToExist}

package require Itcl 3.4
namespace eval ::itcl {}

    puts "itcl namespace has been created"

    itcl::class dummy {
  constructor {} {} {}
  destructor {}
  public method foo {} {puts foo}
}
set d [dummy #auto]

    puts "created class Dummy and object $d"

    if {0} {
set env(ITK_LIBRARY) /wv/tjackson/downloads/86_itcl34_install/lib/itk3.4
set ver [package require Itk 3.4]
package provide itk $ver

set ver [package require Iwidgets]
package provide iwidgets $ver
}

    } else {
    if {! [info exists ::env(ITCL_410)]} {
    puts "Itcl 4.1.1!!!!"
    set ::env(ITCL_LIBRARY) /wv/tjackson/downloads/itcl-fossil/itcl/install/usr/local/lib/itcl4.1.1
    set auto_path [linsert $auto_path 0 $::env(ITCL_LIBRARY)]
    }
    }
    }

    puts [package require Itcl]
    itcl::class Test {
    public proc Callme {}
    public proc EntryPoint {}
    }
    itcl::body Test::Callme {} {
    puts "In here"
    }
    itcl::body Test::EntryPoint {} {
    Callme
    }
    Test::EntryPoint

    puts "Tcl version: [info tclversion]"
    puts "Itcl version: [package require Itcl]"
    itcl::class SimpleClass {
    constructor {} {
    set count 0
    }

    private variable count 0

    public method increment {} {
    incr count
    }

    public method get {} {
    return $count
    }
    }

    proc test_simple {{count 10000}} {
    set time [time {
    set o [SimpleClass #auto]
    for {set i 0} {$i < $count} {incr i} {
    $o increment
    }
    }]
    puts "$time for $count method calls, result: [$o get]"
    }
    test_simple 1000000

    proc test_simple_from_namespace {} {
    set time [time {
    set ::o [namespace origin [SimpleClass #auto]    ]
    namespace eval a_namespace {
    for {set i 0} {$i < 1000000} {incr i} {
    $::o increment
    }
    }
    }]
    puts "$time for 1000000 method calls, from within a namespace, result: [$::o get]"
    }

    test_simple_from_namespace

    itcl::class MutualClass {
    constructor {} {
    }

    public method call_other {count} {
    if {$count < 0} {
    return
    }
    incr count -1
    $other call_other $count
    }

    private variable other {}

    public method set_other {o} {
    set other $o
    }
    }

    proc test_mutual_calls_impl {o1 o2 count} {
    $o1 set_other $o2
    $o2 set_other $o1
    set step 100
    while {$count >= $step} {
    $o1 call_other $step
    incr count -$step
    }
    $o1 call_other $count
    }

    proc test_mutual_calls {{count 10000}} {
    set o1 [namespace origin [MutualClass #auto]]
    set o2 [namespace origin [MutualClass #auto]]
    set time [time {test_mutual_calls_impl $o1 $o2 $count}]
    puts "$time for $count mutual calls"
    }
    test_mutual_calls 10000

    itcl::class OtherMutualClass {
    constructor {} {
    }

    public method call_other {count} {
    if {$count < 0} {
    return
    }
    incr count -1
    $other call_other $count
    }

    private variable other {}

    public method set_other {o} {
    set other $o
    }
    }

    proc test_other_mutual_calls {{count 10000}} {
    set o1 [namespace origin [MutualClass #auto]]
    set o2 [namespace origin [OtherMutualClass #auto]]
    set time [time {test_mutual_calls_impl $o1 $o2 $count}]
    puts "$time for $count mutual calls of different classes"
    }
    test_other_mutual_calls 10000

    proc test_object_construction_impl {} {
    itcl::local SimpleClass #auto
    }
    proc noop {} {
    }
    proc test_object_construction {{count 10000}} {
    set time_base [time {noop} $count]
    set time [time {test_object_construction_impl} $count]
    set base [lindex $time_base 0]
    set actual [lindex $time 0]
    puts "[format %g [expr {$actual-$base}]] microseconds per iteration for $count creation of objects in a proc call"
    }
    test_object_construction

    itcl::class ComplexClass {
    constructor {} {} {}

    private variable m_called_priv 0
    private method priv_call {} {
    incr m_called_priv
    }

    public method how_many_calls {} {return $m_called_priv}
    public method get_priv_method {} {
    return [itcl::code $this priv_call]
    }
    }

    proc test_method_call_via_itcl_code_impl_eval {call} {
    eval $call
    }
    proc test_method_call_via_itcl_code_impl_uplevel {call} {
    uplevel #0 $call
    }

    proc test_method_call_via_itcl_code {{count 10000}} {
    set o [itcl::local ComplexClass #auto]
    set thunk [$o get_priv_method]
    set time [time {test_method_call_via_itcl_code_impl_uplevel $thunk} $count]
    puts "$time for $count method calls via itcl::code and uplevel"
    set time [time {test_method_call_via_itcl_code_impl_eval $thunk} $count]
    puts "$time for $count method calls via itcl::code and eval"
    }
    test_method_call_via_itcl_code

    namespace eval caller {}
    namespace eval callee {}

    proc callee::test_proc_call_across_namespace_impl {} {
    expr {2+3}; # do something
    }
    proc caller::test_proc_call_across_namespace {{count 10000}} {
    set time [time {callee::test_proc_call_across_namespace_impl} $count]
    puts "$time for $count proc calls across namespace"
    }
    caller::test_proc_call_across_namespace

    proc caller::test_method_calls_via_itcl_code_impl_from_ns {thunk count} {
    set time [time {eval $thunk} $count]
    puts "$time for $count method calls via itcl::code and eval"
    set time [time {uplevel $thunk} $count]
    puts "$time for $count method calls via itcl::code and uplevel"
    set time [time {uplevel #0 $thunk} $count]
    puts "$time for $count method calls via itcl::code and uplevel #0"
    }
    proc test_method_call_via_itcl_code_from_namespace {{count 10000}} {
    set o [itcl::local ComplexClass #auto]
    set thunk [$o get_priv_method]
    caller::test_method_calls_via_itcl_code_impl_from_ns $thunk $count
    }
    test_method_call_via_itcl_code_from_namespace

    proc caller::proc_calls_across_namespace {{count 10000}} {

    set time [time {callee::test_method_call_via_itcl_code_impl_uplevel $thunk} $count]

    puts "$time for $count method calls via itcl::code and uplevel"

    set time [time {callee::test_method_call_via_itcl_code_impl_eval $thunk} $count]

    puts "$time for $count method calls via itcl::code and eval"

    }

    itcl::class CWithProc {
    public proc GetSingleton {}
    public proc CallSomeMethod {}
    private common m_singletonOptionsMgr

    private method someMethod {}
    private variable m_counter 0
    }

    itcl::body CWithProc::someMethod {} {
    incr m_counter
    }

    proc CWithProc::CallSomeMethod {} {
    set s [GetSingleton]
    $s someMethod
    }

    proc CWithProc::GetSingleton {} {
    if {[info exists m_singletonOptionsMgr]} {
    return $m_singletonOptionsMgr
    }
    set m_singletonOptionsMgr [namespace origin [CWithProc #auto]]

    return $m_singletonOptionsMgr
    }

    proc test_calls_to_singleton_via_class_proc {{count 10000}} {
    set time [time {CWithProc::CallSomeMethod} $count]
    puts "$time per each $count class calls that use singleton"
    }
    test_calls_to_singleton_via_class_proc

     

  • Don Porter

    Don Porter - 2018-06-01

    Demo script doesn't work:

    invalid command name "GetSingleton"
    while executing
    "GetSingleton"
    (procedure "CWithProc::CallSomeMethod" line 2)
    invoked from within
    "CWithProc::CallSomeMethod"
    invoked from within
    "time {CWithProc::CallSomeMethod} $count"
    (procedure "test_calls_to_singleton_via_class_proc" line 2)
    invoked from within
    "test_calls_to_singleton_via_class_proc"
    (file "/home/dgp/sf271.tcl" line 274)

     

  • Don Porter

    Don Porter - 2018-06-01

    Maybe we can try this with one focused, working example at a time?

     

    • Trey Jackson

      Trey Jackson - 2018-06-01

      Fair enough. Here's the singleton example - no code change, works for me with Tcl 8.67 and Itcl 4.1.1 (actually latest fossil version), and in 8.4 3.2

      Note: GetSingleton is defined using [proc], which has always worked for us (Itcl 3.2 or 4.1) - but it does have problems with Itcl 3.4. It's fixed by changing that to [itcl::body]. Perhaps that's the issue you saw (Itcl 3.4?).

      Anyway, output first, then script

      Tcl 8.6.7 Itcl 4.1.1

      12.9345 microseconds per iteration per each 10000 class calls that use singleton

      Tcl 8.4.19 Itcl 3.2

      3 microseconds per iteration per each 10000 class calls that use singleton

      See attached singleton.itcl

       

      Last edit: Trey Jackson 2018-06-01
      singleton.itcl

  • Don Porter

    Don Porter - 2018-06-01

    Indeed these test scripts do not run in Itcl 3.4.4. That's what I'm willing to test.

     

    • Trey Jackson

      Trey Jackson - 2018-06-01

      So, where do I file a bug against 3.4.4? It works in 4.1.1, and 3.2, so it seems like a bug, no?

       

  • Don Porter

    Don Porter - 2018-06-01

    ok, I see. "proc: -> "itcl::body" makes it work ok.

     

  • Don Porter

    Don Porter - 2018-06-01

    I don't think it's a bug, no. I think it's intrustion into an implementation detail.

    If there's documentation otherwise, let me know.

     
<< < 1 2 3 > >> (Page 2 of 3)

Log in to post a comment.