bugGNU Octave - Bugs: bug #56752, Performance slowdown from version...

 
 

bug #56752: Performance slowdown from version 3.2.4 through to current dev branch

Submitted by:  Rik <rik5>
Submitted on:  Mon 12 Aug 2019 03:35:53 PM UTC  
 
Category:  Interpreter Severity:  3 - Normal
Priority:  5 - Normal Item Group:  Performance
Status:  Confirmed Assigned to:  None
Originator Name:  Open/Closed:  Open
Release:  dev Operating System:  Any

Add a New Comment (Rich Markup)
   

You are not logged in

Please log in, so followups can be emailed to you.

 

( Jump to the original submission)

Fri 23 Aug 2019 05:34:12 AM UTC, comment #31: 

I pushed the following changesets

  http://hg.savannah.gnu.org/hgweb/octave/rev/7335ebd4c798
  http://hg.savannah.gnu.org/hgweb/octave/rev/b00ddc40b89a

to add move constructors and move assignment operators for the dim_vector, Array, string_vector, and octave_value classes.  For me, these changes and the others that have been made for performance since bug #56752 was reported drops the time to run the bm_toeplitz.m file from about 39 seconds down to about 26 seconds.  With version 4.4.1, I see a time of about 31 seconds.

John W. Eaton <jwe>
Project Administrator
Tue 20 Aug 2019 11:00:38 PM UTC, comment #30: 

jwe, Dan,

I looked closely at the 9 instances of the ~octave_value_list destructor being called for the simple expression "sin (1);".  I think I understand the problematic coding pattern, but I haven't yet found a solution.

For didactic purposes, assume there is a complicated class (comp_class) which has an extensive constructor/destructor or otherwise uses a lot of resources.  There is also a function main which uses an instance of comp_class, but the initialization of the instance is done by a separate function init to make the code more modular and readable.

main ()
{
  comp_class cobj;

  cobj = init ();

  ...
}

comp_class init (void)
{
  comp_class retval;  // local variable

  retval.xxx = yyy;   // initialization
  ...

  return retval;      // return by value (a comp_class object)
}

The sequence of events for the C++ runtime is

1) local variable cobj is created in main calling comp_class constructor
2) init() is called
3) local variable retval is created in main calling comp_class constructor
4) "return retval;" statement causes comp_class copy constructor to execute copying local variable retval in to a temporary new comp_class object because the function init returns by value.
5) init() routine completes, local variable retval goes out of scope and comp_class destructor is called
6) back in main(), destructor for cobj is called to clear object before assignment.
7) copy assignment operator transfers temporary comp_class object to cobj.
8) temporary value goes out of scope and calls comp_class destructor

That is a huge number of objects created/destroyed to handle what is a fairly simple coding pattern.  This example is not dreamt up, but reflects the coding in pt-eval.cc.  The function tree_evaluator::visit_index_expression is coded like so

octave_value_list first_args;
...
first_args = convert_to_const_vector (al);

where convert_to_const_vector is declared as

octave_value_list
tree_evaluator::convert_to_const_vector (tree_argument_list *arg_list,
                                           const octave_value *object)

One obvious solution would be to discard returning by value.  In that case, perhaps passing a reference to the octave_value_list in to the child function so that it operates directly on the only instance we care to create.  But, this would mean changing a fair number of APIs and potentially a lot of code refactoring.

The next most obvious thing would be to use the C++11 feature of move constructors and move assignment operators.  I added those two functions to ovl.h along with some logging.  Now when I run I get

sin(1);
octave_value_list: move constructor 893
~octave_value_list: 7772
~octave_value_list: 7773
octave_value_list: move assignment 3178
~octave_value_list: 7774
octave_value_list: move assignment 3179
~octave_value_list: 7775
octave_value_list: move assignment 3180
~octave_value_list: 7776
octave_value_1111111111list: move assignment 3181
~octave_value_list: 7777
~octave_value_list: 7778
~octave_value_list: 7779
octave_value_list: move assignment 3182
~octave_value_list: 7780

Clearly, the move routines themselves are getting called by the C++ runtime in both flavors (constructor and assignment).  However, there is no decrease in the number of times (9) the ~octave_value_destructor is called because I couldn't find a clean way to "zero out" the rvalue object that is being moved.  Here is the assignment routine I have at the moment:

  octave_value_list& operator = (octave_value_list&& obj)
  {
    static long int n = 0;
    std::cerr << "octave_value_list: move assignment " << ++n << std::endl;

    if (this == &obj)
      return *this;

    std::swap (m_data, obj.m_data);
    std::swap (m_names, obj.m_names);

    return *this;
  }

Maybe this is actually okay, but it doesn't actually result in any speed-up.  It seems to me that the octave_value class may also need to have move functions written at the same time.  An octave_value is also a "complicated class" and there are many functions which return by value an octave_value instance.  Given that this requires creating a temporary, and the atomic increment/decrement operators are slow, move routines in that class may be more important.

Rik <rik5>
Project Administrator
Sat 17 Aug 2019 04:06:40 PM UTC, comment #29: 

Yes, you're right.  C++ is a complicated language :(

I wrote my own test case as a .oct file

#include <octave/oct.h>

DEFUN_DLD (tst_const, args, , "")
{
  octave_value_list tmp;

  // These are OK, they resize.
  octave_value x = tmp(2);
  const octave_value y = tmp(3);

  int nargin = args.length ();
  if (nargin > 0)
    {
      const octave_value_list tmp (1, 2);

      // These fail, they don't resize and access beyond the end of the array.
      octave_value x = tmp(3);
      const octave_value y = tmp(4);
    }

  return ovl ();
}

If the object is declared const then Octave shouldn't be silently increasing the size of the array so I think the current behavior--segfault--is correct.

Rik <rik5>
Project Administrator
Fri 16 Aug 2019 09:34:30 PM UTC, comment #28: 

Rik, isn't the same non-const method called in both of these cases?  Overloading on const should be about the value the method is called for, not the return type.

octave_value_list ovl;

octave_value elem3 = ovl(3);  // succeeds
const octave_value elem5c = ovl(5); // exception because 5 is larger than std::vector size??

DEFUN (foobar, args, , "")
{
  octave_value_list tmp;
  // These are OK, they resize.
  octave_value x = tmp(2);
  const octave_value y = tmp(2);
  int nargin = args.length ();
  if (nargin > 0)
    {
      // These fail, they don't resize and access beyond the end of the array.
      octave_value x = args(nargin + 10);
      const octave_value y = args(nargin + 10);
    }
  return ovl ();
}

John W. Eaton <jwe>
Project Administrator
Fri 16 Aug 2019 09:14:18 PM UTC, comment #27: 

I am now using bm.assign.m for profiling.  It is even simpler which I think is required to see what is happening.  The file was attached to this report earlier, but for reference it is:

runs = 5;

cumulate = 0; b = 0; z = 0;
for i = 1:runs
  b = zeros (620, 620);
  tic;
    for j = 1:620
      for k = 1:620
        z = 13;
      end
    end
  timing = toc;
  cumulate = cumulate + timing;
end

## Total time
cumulate

I can see the three for loops in the resulting profile

     88.26% octave::tree_evaluator::visit_simple_for_command
        octave::tree_evaluator::visit_statement_list
      - octave::tree_evaluator::visit_statement
         - 88.23% octave::tree_evaluator::visit_simple_for_command
            - 88.21% octave::tree_evaluator::visit_statement_list
               - octave::tree_evaluator::visit_statement
                  - 87.94% octave::tree_evaluator::visit_simple_for_command
                     - 84.74% octave::tree_evaluator::visit_statement_list
                        - 84.28% octave::tree_evaluator::visit_statement
                           - 83.42% octave::tree_evaluator::evaluate
                              - 80.83% octave::tree_evaluator::evaluate_internal
                                 - 78.06% octave::tree_evaluator::visit_simple_assignment
                                    - 44.86% octave::tree_index_expression::lvalue
                                       - 30.16% octave::tree_evaluator::convert_to_const_vector
                                          + 16.55% octave::tree_evaluator::evaluate
                                          + 2.76% octave_value_list::octave_value_list
                                            2.03% octave_value_list::octave_value_list
                                            1.74% std::__cxx11::_List_base<octave_value_list, std::allocator<octave_value_list> >::_M_clear
                                            1.36% Array<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > >::~Array
                                            0.79% std::vector<octave_value, std::allocator<octave_value> >::vector
                                            0.67% std::vector<octave_value, std::allocator<octave_value> >::~vector
                                            0.55% octave_value::~octave_value
                                       + 2.18% octave::octave_lvalue::set_index
                                         1.37% octave_value::~octave_value
                                         1.26% std::__cxx11::_List_base<octave_value_list, std::allocator<octave_value_list> >::_M_clear
                                         0.73% octave::octave_lvalue::value
                                         0.62% std::vector<octave_value, std::allocator<octave_value> >::operator=
                                         0.59% octave::tree_identifier::lvalue
                                    - 16.15% octave::octave_lvalue::assign
                                       - 15.40% octave_value::assign
                                          - 14.41% octave_value::subsasgn
                                             - 14.05% octave_base_matrix<NDArray>::subsasgn
                                                - 12.12% octave_base_value::numeric_assign
                                                   + 6.83% oct_assignop_assign
                                                     1.09% __strlen_avx2
                                                     1.00% octave::type_info::lookup_assign_op
                                                     0.51% octave_value::~octave_value
                                                  0.52% octave_value::operator=
                                    - 5.99% octave::tree_evaluator::evaluate
                                       - 2.88% octave::tree_evaluator::evaluate_internal
                                            1.08% octave::tree_evaluator::visit_constant
                                            0.65% octave::action_container::run
                                         1.09% octave_value::operator=
                                    + 1.81% std::__cxx11::_List_base<octave::octave_lvalue, std::allocator<octave::octave_lvalue> >::_M_clear
                                    + 1.43% octave::octave_lvalue::~octave_lvalue
                                      1.08% octave_value::operator=
                                      0.78% octave::action_container::run
                                      0.58% octave_value::~octave_value
                                   0.68% octave::action_container::run
                                0.88% octave_value::operator=
                     - 2.37% octave::octave_lvalue::assign
                          0.72% octave::script_stack_frame::varref

I can only identify one point where the string_vector private data member of octave_value_list makes an appearance and it is only 1.36% so not overly large.  There are still slow downs with octave_value caused by the locking.  This sometimes bleeds over in to octave_value_list.  For example, this line

0.62% std::vector<octave_value, std::allocator<octave_value> >::operator=

when probed shows that the actual delay is in the atomic lock of the copy constructor of octave_value.  The same thing seems to be happening when octave_value_lists are destroyed or cleared. The actual slowdown is still the atomic locks.

1.26% std::__cxx11::_List_base<octave_value_list, std::allocator<octave_value_list> >::_M_clear
0.67% std::vector<octave_value, std::allocator<octave_value> >::~vector

Rik <rik5>
Project Administrator
Fri 16 Aug 2019 08:23:33 PM UTC, comment #26: 

Just checked in two small changes to the new octave_value_list implementation at https://hg.savannah.gnu.org/hgweb/octave/rev/254d6e33a1d0.

In the first change, I took advantage of the range constructor for std::vector to make the variable argument template constructor simpler.

   template<template <typename...> class OV_Container>
   octave_value_list (const OV_Container<octave_value>& args)
-    : m_data (args.size ()), m_names ()
-  {
-    auto p = args.begin ();
-
-    for (size_t i = 0; i < m_data.size (); i++)
-      m_data[i] = *p++;
-  }
+    : m_data (args.begin (), args.end ()), m_names () { }

Second change was just about readability.  As with the octave m-file language, Ifind it more readable to test on empty() rather than on numel > 0.

-    if (m_data.size () > 0)
+    if (! m_data.empty ())

Rik <rik5>
Project Administrator
Fri 16 Aug 2019 08:15:08 PM UTC, comment #25: 

> RE comment #23, I suppose we could return a reference to a static
> undefined octave_value object for out of bounds accesses in that
> case, but have we needed it before now?


My guess is that none of Octave core code uses this behavior and there probably are not a lot of .oct files in the wild--the behavior most likely has never been tested.

I was just thinking about good programming practices and the Principle of Least Surprise.  It is very surprising to me that const/non-const versions of a function would behave differently.

Rik <rik5>
Project Administrator
Fri 16 Aug 2019 08:03:51 PM UTC, comment #24: 

RE comment #23, I suppose we could return a reference to a static undefined octave_value object for out of bounds accesses in that case, but have we needed it before now?

I can see a possible way to eliminate the need to have names attached to the octave_value_list but it will require more refactoring than I can do in an hour or two.  If I can do it, I think that's the best solution since it simplifies the octave_value_list object and makes names of arguments passed to functions solely the responsibility of the evaluator.

John W. Eaton <jwe>
Project Administrator
Fri 16 Aug 2019 07:21:42 PM UTC, comment #23: 

Is this safe?

-  const octave_value& elem (octave_idx_type n) const
-  { return data(n); }
+  const octave_value& elem (octave_idx_type n) const { return data[n]; }

The ovl class is a little weird in that if you index a value outside of the current size it automatically resizes.

  octave_value& elem (octave_idx_type n)
  {
    if (n >= length ())
      resize (n + 1);

    return m_data[n];
  }

Wouldn't a programmer expect that the const/non-const version of elem have the same behavior?

octave_value_list ovl;

octave_value elem3 = ovl(3);  // succeeds
const octave_value elem5c = ovl(5); // exception because 5 is larger than std::vector size??

Rik <rik5>
Project Administrator
Fri 16 Aug 2019 05:43:10 PM UTC, comment #22: 

I tried experimenting with reserving capacity for the ovl to expand, but it didn't help.  I tried values of 1 and 3 for the reserver capacity.

  octave_value_list (void)
    : data (), names () { data.reserve (1); }

Rik <rik5>
Project Administrator
Fri 16 Aug 2019 05:09:25 PM UTC, comment #21: 
John W. Eaton <jwe>
Project Administrator
Fri 16 Aug 2019 04:41:03 PM UTC, comment #20: 

@jwe: I tested the preliminary patch for octave_value_list and it looks good.  My benchmarking shows that it takes the runtime from 13.8 seconds to 11.7 seconds, or -21%.  I'm happy to say that I roughly nailed it when I said changing to std::vector might bring about a 25% savings.  Still, if we could figure out how to reduce the number of calls to octave_value_list for ordinary evaluations that would help even more.

This looks so promising that I would immediately polish it up and commit it.  Since you ran 'make check', I assume this didn't cause any regressions.

Once in Mercurial, I want to try a mini-optimization.  My guess is that the size of octave_value_list objects is almost always 0 or 1.  If we change the constructor to always reserve capacity for at least 1 object, do we get another small speed boost?

Rik <rik5>
Project Administrator
Fri 16 Aug 2019 04:34:27 PM UTC, comment #19: 

Rik: Yeah, I'll look at revising the octave_value_list and string_vector classes.

John W. Eaton <jwe>
Project Administrator
Fri 16 Aug 2019 04:07:11 PM UTC, comment #18: 

I could see the string_vector object being created in the profiling reports.  It didn't look like it was a big time sink because, as you note, it is almost never used.

But, we should optimize for the most common code path.  If it is used only 1% of the time then we should default the code to using the path that is taken 99% of the time and special case this 1% path.

Since names is a private data member of the octave_value_list class it should be possible to change the underlying implementation without any caller noticing.

First idea, can it be eliminated completely?  Biggest savings and also makes the class easier to understand.

Second idea, if it can't be eliminated, change the declaration to be a pointer to a string_vector.  For most invocations of the octave_value_list class this will merely require the creation of a NULL pointer which is fast and takes very little memory.  The routines that do make use of it would need to be updated to refer to a pointer, but that would be easy.  For example

  string_vector name_tags (void) const { return names; }

goes to

  string_vector name_tags (void) const { return *names; }

Rik <rik5>
Project Administrator
Fri 16 Aug 2019 03:47:25 PM UTC, comment #17: 

With the version of octave_value_list that uses std::vector I see the following change when running the tests.  To make the timing a bit more meaningful, I timed the run-octave command that runs the tests, not "make check".

With octave_value_list using Array:

  503.05 user 101.32 system 9:19.31 elapsed 108% CPU

With octave_value_list using std::vector:

  488.47 user 95.40 system 9:03.85 elapsed 107% CPU

I also see that the string_vector object that we use to attach names to octave_value_list objects is based on Array.  I'll experiment with changing that as well, or seeing whether we can remove that feature from the octave_value_list object since there are probably only a few places where names are needed.  Maybe with the current structure of the interpreter/evaluator we don't need to attach names to octave_value_list objects?

John W. Eaton <jwe>
Project Administrator
Fri 16 Aug 2019 06:36:04 AM UTC, comment #16: 

I'm attaching a draft of a changeset for using std::vector instead of Octave's Array class to implement octave_value_list.  With it, the original bm_toeplitz example runs in about 28 seconds on my system compared to 38 seconds using Array.

(file #47349)

John W. Eaton <jwe>
Project Administrator
Tue 13 Aug 2019 09:22:20 PM UTC, comment #15: 

Here is another possibility.  I find that octave_value_list is often taking ~1% of an particular leaf function.  If I check the annotated code I see that atomic locking instructions take a very long time.

octave_value_list::octave_value_list  /home/rik/wip/Projects_Mine/octave-dev/libgui/.libs/liboctgui.so.5.0.0
Samples│    _ZN17octave_value_listC2Ev():
       │    OCTINTERP_API
       │    octave_value_list
       │    {
       │    public:
       │
       │      octave_value_list (void)
       │      push   %rbp
    11 │      mov    %rsp,%rbp
     7 │      push   %r12
     1 │      push   %rbx
       │    _ZN17octave_value_listC1Ev():
     1 │      add    $0x10,%rax
       │    _ZN17octave_value_listC2Ev():
    15 │      mov    %rdi,%rbx
       │    _ZN17octave_value_listC1Ev():
     6 │      mov    %rax,(%rdi)
       │
       │    public:
       │
       │      static octave_idx_type dim_max (void);
       │
       │      explicit dim_vector (void) : rep (nil_rep ())
     1 │    → callq  dim_vector::nil_rep()@plt
     3 │      mov    %rax,0x8(%rbx)
       │      { OCTAVE_ATOMIC_INCREMENT (&(count ())); }
   327 │      lock   addq   $0x1,-0x10(%rax)
       │        : dimensions (), rep (nil_rep ()), slice_data (rep->data),
     1 │    → callq  Array<octave_value
       │          slice_len (rep->len)
    10 │      mov    (%rax),%rdx
     7 │      mov    %rax,0x10(%rbx)
       │      mov    %rdx,0x18(%rbx)
       │      mov    0x8(%rax),%rdx
    14 │      mov    %rdx,0x20(%rbx)
       │          return OCTAVE_ATOMIC_INCREMENT (&m_count);
       │        }
       │
       │        count_type operator++ (int)
       │        {
       │          return OCTAVE_ATOMIC_POST_INCREMENT (&m_count);
   297 │      lock   addl   $0x1,0x10(%rax)
     1 │      mov    vtable for Array<std::__cxx11::basic_string<char, std::char_traits<char,%rax
       │      add    $0x10,%rax
    16 │      mov    %rax,0x28(%rbx)
       │      explicit dim_vector (void) : rep (nil_rep ())
       │    → callq  dim_vector::nil_rep()@plt
       │      mov    %rax,0x30(%rbx)
       │      { OCTAVE_ATOMIC_INCREMENT (&(count ())); }
   294 │      lock   addq   $0x1,-0x10(%rax)
       │        : dimensions (), rep (nil_rep ()), slice_data (rep->data),
     1 │    → callq  Array<std::__cxx11::basic_string<char, std::char_traits<char
       │          slice_len (rep->len)

I can change the atomic instructions to ordinary ones by configuring with --disable-atomic-refcount.  The benchmark runtime drops from 14.1 seconds to 11.6 seconds (2.5 seconds) which seems important.

The requirement for atomic refcounting was introduced by communication with the GUI.  This brings up a hard question, is there a better way to implement cross-thread communication?

Rik <rik5>
Project Administrator
Tue 13 Aug 2019 08:52:20 PM UTC, comment #14: 

From the longitudinal benchmarking, there was a step change loss of performance from the 3.8.X series to 4.0.X series.  Looking at the NEWS file for 4.0.0, that release featured the addition of a Qt-based GUI and classdef OO programming.  Running today with --no-gui-libs and --no-gui shows very little difference so I don't think the slowdown is because of the GUI.  That would leave classdef as a large architectural change capable of a 2X slowdown.

I tried quick test by commenting out the classdef section of fcn_info::fcn_info_rep::xfind.  It was meaningful, runtime went from 14 s to 13 s, but at ~7% is no where near large enough to explain the complete slowdown.  Commenting out the code for packages saved an additional 0.75 s which is nice, but also not stupendous.

Rik <rik5>
Project Administrator
Tue 13 Aug 2019 07:08:56 PM UTC, comment #13: 

@jwe: I used bm.toeplitz.orig.m which is the first attachment.  It has a double nested for loop, a double indexing, a function call, and an arithmetic operator.

b(k,j) = abs (j - k) + 1;

Rik <rik5>
Project Administrator
Tue 13 Aug 2019 06:45:14 PM UTC, comment #12: 

Rik:  Thanks for the detailed info.

In comment #11, which .m file were you running, still the original bm_toeplitz.m?

Function lookup is slow.  We have to check for overloaded functions.  See fcn_info::fcn_info_rep::xfind in fcn-info.cc for all the things we look for before finding a built-in function.  Is there some better way to do it?  For example, is there a way to cache a previous lookup and not have to search again if we know that the load path has not changed and no new overloaded functions could possibly be found?

I think the lvalue thing is complicated by having to support the special meaning of "end" inside index expressions.  As I recall, there are some weird cases we try to handle for compatibility.  Maybe there are also better ways of doing that.

John W. Eaton <jwe>
Project Administrator
Tue 13 Aug 2019 06:07:13 PM UTC, comment #11: 

Some code to inspect.  I am CC'ing the Maintainers-List as I think this is of general interest.

- 43.69% octave::tree_evaluator::evaluate_internal
   - 41.90% octave::tree_evaluator::visit_index_expression
      - 14.81% octave::symbol_table::find_function
         + 14.69% octave::symbol_table::fcn_table_find
      - 11.93% octave::tree_evaluator::convert_to_const_vector
         + 8.44% octave::tree_evaluator::evaluate
           0.93% octave_value_list::octave_value_list
           0.65% octave_value_list::octave_value_list
      + 4.56% octave_builtin::call
        1.35% Array<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > >::operator=
        1.14% Array<octave_value>::operator=
        1.04% octave_value_list::octave_value_list
        0.93% Array<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > >::~Array
        0.85% Array<octave_value>::~Array
        0.68% octave::tree_evaluator::is_variable
        0.59% octave_value_list::operator=

I'm not sure how the symbol_table is organized, but it is taking a long time to find functions.  If we are using a std::map from STL which is based on a log2 lookup then perhaps a change to std::unordered_map which is based on hashes and O(1) lookups would help.

There also seems to be a lot of creation, assignment, destruction of objects.  Worst case, we have objects with heavyweight constructors.  Fixing that would require making the constructors/destructors do less, or introducing an entirely different lightweight object.

Second hotspot in lvalue.

- 19.84% octave::tree_index_expression::lvalue
   - 15.48% octave::tree_evaluator::convert_to_const_vector
      + 5.44% octave::tree_evaluator::evaluate
      + 4.60% octave_value_list::octave_value_list
        1.57% octave_value_list::octave_value_list
        0.91% std::__cxx11::_List_base<octave_value_list, std::allocator<octave_value_list> >::_M_clear
     0.54% octave::octave_lvalue::set_index

class octave_value_list is based on the Array class "Array<octave_value> data;" which may, in effect, be a heavyweight constructor.  Perhaps it would be faster to base octave_value_list off one of the list classes in the STL.  Given that one doesn't actually need a lot of insertion/deletion of nodes, std::vector might be a good choice.  I wouldn't go that direction, however, unless there is more proof that this is an issue.

Third hotspot:

- 6.86% octave::octave_lvalue::assign
   - 6.64% octave_value::assign
      - 6.25% octave_value::subsasgn
         - 6.19% octave_base_matrix<NDArray>::subsasgn
            - 5.34% octave_base_value::numeric_assign
               + 3.40% oct_assignop_assign
                 0.68% __strlen_avx2

Rik <rik5>
Project Administrator
Tue 13 Aug 2019 05:09:40 PM UTC, comment #10: 

I finally got one of the profiling tools to work well enough to identify some of the hotspots.  I ended up using the Linux Kernel tool 'perf'.

perf record -g -p <PID>

When running the benchmark bm.toeplitz.orig.m, I find that tree_evaluator and tree_index_expression::lvalue seem to be time consuming routines.

  Children      Self       Samples  Command          Shared Object               Symbol
  -  81.31%     0.27%          160  QThread          liboctinterp.so.7.0.0       [.] octave::tree_evaluator::visit_simple_assignment
   - 81.04% octave::tree_evaluator::visit_simple_assignment
      + 50.98% octave::tree_evaluator::evaluate
      + 19.84% octave::tree_index_expression::lvalue
      + 6.86% octave::octave_lvalue::assign
      + 0.72% octave::octave_lvalue::~octave_lvalue
        0.51% octave::octave_lvalue::octave_lvalue

If, instead of a callgraph, I look directly at which functions are consuming the most time it does seem that there is a lot of time spent allocating/freeing memory and creating/destroying class objects.

  Overhead       Samples  Command          Shared Object               Symbol
+    8.87%          5253  QThread          libc-2.27.so                [.] cfree@GLIBC_2.2.5
+    5.44%          3217  QThread          libc-2.27.so                [.] malloc
+    5.31%          3140  QThread          liboctinterp.so.7.0.0       [.] octave_value::operator=
+    4.95%          2926  QThread          liboctgui.so.5.0.0          [.] octave_value::~octave_value
+    3.05%          1804  QThread          libc-2.27.so                [.] _int_malloc
+    2.61%          1543  QThread          liboctgui.so.5.0.0          [.] Array<std::__cxx11::basic_string<char, std::char_traits<char>, std:
+    2.41%          1427  QThread          liboctgui.so.5.0.0          [.] octave_value_list::octave_value_list
+    2.32%          1365  QThread          liboctgui.so.5.0.0          [.] Array<octave_value>::~Array

Rik <rik5>
Project Administrator
Tue 13 Aug 2019 04:59:39 PM UTC, comment #9: 

@Mike: For consistentcy, I will try and generate a patch for version 3.2.4 so that all of the do_config scripts can have the same form.  That will be a bit later.

Rik <rik5>
Project Administrator
Tue 13 Aug 2019 04:30:57 PM UTC, comment #8: 

Thanks, I was able to build and install 3.2.4 using the perl substitutions in your script.

Mike Miller <mtmiller>
Project Administrator
Mon 12 Aug 2019 10:15:56 PM UTC, comment #7: 

Attached is a new version of do_config_3.2.4 which removes the need to configure with --without-curl.

(file #47342)

Rik <rik5>
Project Administrator
Mon 12 Aug 2019 07:35:06 PM UTC, comment #6: 

Mike M. supplied a series of patches for getting older versions of Octave to compile.  They are attached as octave-old-patches.tar.gz.

It is probably good enough to just test 3.2.4 against dev until most of the discrepancy has been removed.  Ideally, one might then look at the difference to 3.4.X series which had the fastest runtimes in my experience.

(file #47341)

Rik <rik5>
Project Administrator
Mon 12 Aug 2019 07:27:06 PM UTC, comment #5: 

I wrote a series of different benchmarks--each of which is attached--that try to disentagle the root causes of the slowdown.  The executive summary is that there seems to be a slowdown in the performance of regular, and possibly indexed, assignment.

Starting with base script bm.toeplitz.orig.m

runs = 5;

cumulate = 0; b = 0;
for i = 1:runs
  b = zeros (620, 620);
  tic;
    for j = 1:620
      for k = 1:620
        b(k,j) = abs (j - k) + 1;
      end
    end
  timing = toc;
  cumulate = cumulate + timing;
end

## Total time
cumulate

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

First test, remove any loop body.

...
    for j = 1:620
      for k = 1:620
        ## No loop body
      end
    end
...

Results: no loop body:
3.2.4 : .10605
6.0.0 : .15496

Comments: no loop body:
A 50% slowdown, but at 50 milliseconds, not significant compared to the 7
seconds seen for the original script.

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

Test case for straight assignment.

...
    for j = 1:620
      for k = 1:620
        z = 13;
      end
    end
...

Results: assignment:
3.2.4 : 0.17247
6.0.0 : 0.96006

Comments: no loop body:
A 5.6X slowdown between versions.  This seems quite significant.

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

Test case for assignment using 1 index.

...
    for j = 1:620
      for k = 1:620
        b(k) = 13;
      end
    end
...

Results: 1-index assignment:

3.2.4 : 1.3076
6.0.0 : 3.3534

Comments: 1-index assignment:
A 2.6X slowdown between versions, and the absolute magnitude at 2 seconds
is significant.  Note that even in 3.2.4 the step-up from scalar assignment
to matrix assignment is 7.6X.

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

Test case for assignment using 2 indexes.

...
    for j = 1:620
      for k = 1:620
        b(k,j) = 13;
      end
    end
...

Results: 2-index assignment:

3.2.4 : 2.2823
6.0.0 : 4.9126

Comments: 2-index assignment:
A 2.15X slowdown between versions, and the absolute magnitude is verging on
3 seconds which is significant.  This is also 1 second slower than the
1-index case for 3.2.4.  It would be worthwhile to check whether
performance is scaling linearly with number of indices (such as 3-D and 4-D
arrays).  This is also the baseline I use for further comparisons.

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

Test case for single loop versus nested loops.

...
    for j = 1:(620*620)
      b(j) = 13;
    end
...

Results: single loop:

3.2.4 : 1.3396
6.0.0 : 3.3557

Comments: single loop:
This is nearly identical to the results for 1-index assigment.  As such, it
doesn't appear that loops are the problem.  This is also corroborated by
the first result where taking out the loop body proves that the loops run
fast by themselves.

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

Test case for arithmetic expression.

...
    for j = 1:620
      for k = 1:620
        b(k,j) = k + 1;
      end
    end
...

Results: arithmetic op:

3.2.4 : 2.8724
6.0.0 : 5.9112

Comments: arithmetic op:
This is quite close to the results for 2-index assigment.  In fact, the
slowdown is 2.06X versus the 2.15X seen for 2-index assignment.  So it is
likely that all of the variance is due to the issues with assignment.

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

Test case for function called with constant value.

...
    for j = 1:620
      for k = 1:620
        b(k,j) = abs (13);
      end
    end
...

Results: function w/constant value:

3.2.4 : 4.8345
6.0.0 : 10.811

Comments: function w/constant value:
Slowdown is 2.24X.  The slowdown of 2.15X for 2-index assignment would
explain 2.15/2.24 = 96% of this.

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

Test case for function called with 1 lookup.

...
    for j = 1:620
      for k = 1:620
        b(k,j) = abs (13);
      end
    end
...

Results: function w/1 lookup:

3.2.4 : 4.9847
6.0.0 : 10.979

Comments: function w/1 lookup:
Slowdown is 2.20X.  The slowdown of 2.15X for 2-index assignment would
explain 98% of this.

Rik <rik5>
Project Administrator
Mon 12 Aug 2019 07:22:33 PM UTC, comment #4: 

If it can help I translated bm.toeplitz.orig.m to toeplitz_oct.cc it also is attached to the post.


//toeplitz_oct.cc
#include <octave/oct.h>
#include "builtin-defun-decls.h"

DEFUN_DLD (toeplitz_oct, args, nargout,"")
{
        #define OV octave_value
        OV runs ( 5.0);
        OV cumulate (0.0);
        OV b (0.0);
        for (double i = 1.0; i <= runs.double_value(); i++)
        {
                b = Fzeros(ovl(OV(620.0),OV(620.0)),1)(0);
                Ftic(ovl(),0);
                for (double j = 1.0; j <= 620.0; j++)
                {
                        for (double k = 1.0; k <= 620.0; k++)
                        {
                                std::list<octave_value_list> idx ;
        idx.push_back(ovl(OV(k),OV(j)));
                                OV rhs =  Fplus(ovl(Fabs(ovl(Fminus(ovl(OV(j), OV(k)), 1)(0)), 1)(0), OV(1.0)), 1)(0);
                                b.subsasgn( "(" , idx, rhs );
                        }
                }
                octave_value timing (Ftoc(ovl(),1)(0));
                cumulate = Fplus(ovl(cumulate,timing),1)(0);
        }
        return ovl(cumulate);
}

(file #47332)

Anonymous
Mon 12 Aug 2019 04:34:13 PM UTC, comment #3: 

In order for others to be able to replicate these results I am attaching the script I use to configure octave for 3.2.4.

In order to use it, download the official 3.2.4 tarball of source code from octave.org and unpack it.  Copy do_config_3.2.4 to the source directory and run it (you may need to source it if you don't have the 'tcsh' shell installed).  After that, run make.  There will be lots of warnings, but it should complete. 

Check that it works by executing run-octave.  If it is working, install it however you like ('make install' or use 'checkinstall' to create a package).  I installed it in /usr/local but I had to modify my LD_LIBRARY_PATH variable to include /usr/local/lib/octave-3.2.4 to get it to run.

(file #47331)

Rik <rik5>
Project Administrator
Mon 12 Aug 2019 04:24:22 PM UTC, comment #2: 

To test whether the Qt and the GUI have any effect I ran bm.toeplitz.orig.m and run-octave with the following options

-f --no-gui-libs : 13.472
-f --no-gui      : 13.715
-f --gui         : 13.800

The maximal difference from the CLI to the GUI was ~2% increase in runtime which is not significant.

Rik <rik5>
Project Administrator
Mon 12 Aug 2019 04:22:17 PM UTC, comment #1: 

To check whether it is the execution of loops versus the execution of statements in the body of loops, I ran the following empty loop body test.

a = 1; b = 1; tic; for i=1:1000; for j=1:1000;   ; end; end; toc

The script is attached as bm.empty_loop.m

Results were

Version   3.2.4     3.4.3     3.6.4     3.8.2     4.0.3     4.2.1     4.4.1     5.1.0     dev (6.1.0)

          0.053467                                0.0782108 0.0723422 0.128019  0.1248    0.096776

There was a small decline in performance.  However, 50 milliseconds is no where near as important as the 7 seconds seen in the toeplitz benchmark which included assignments, function calls, etc.

(file #47330)

Rik <rik5>
Project Administrator
Mon 12 Aug 2019 03:35:53 PM UTC, original submission:  

There has been a significant slowdown in interpreter performance from version 3.2.4 up to the current day (dev branch that will become 6.1.0 release).

Base testing was done with bm.toeplitz.orig.m script quoted below and attached.

runs = 5;

cumulate = 0; b = 0;
for i = 1:runs
  b = zeros (620, 620);
  tic;
    for j = 1:620
      for k = 1:620
        b(k,j) = abs (j - k) + 1;
      end
    end
  timing = toc;
  cumulate = cumulate + timing;
end

## Total time
cumulate

On the same hardware, running 'octave -f --no-gui' in order to minimize differences due to my local configuration, I recorded the following running times.

Version                        3.2.4        3.4.3        3.6.4        3.8.2        4.0.3        4.2.1        4.4.1        5.1.0        dev (6.1.0)
Benchmark
bm.toeplitz.orig.m        5.8968                                10.055        10.544        13.052        13.481        13.291

As can be seen, over 100% slow down in interpreter from 3.2.4 to dev.

Rik <rik5>
Project Administrator

 

(Note: upload size limit is set to 16384 kB, after insertion of the required escape characters.)

Attach Files:
   
   
Comment:
   

Attached Files
file #47349:  ovl-with-vector-diffs.txt added by jwe (6KiB - text/plain)
file #47342:  do_config_3.2.4 added by rik5 (1KiB - application/octet-stream)
file #47341:  octave-old-patches.tar.gz added by rik5 (7KiB - application/gzip)
file #47337:  bm.1loop.m added by rik5 (203B - text/x-matlab)
file #47338:  bm.fcn_const_val.m added by rik5 (237B - text/x-matlab)
file #47339:  bm.arithmetic_op.m added by rik5 (234B - text/x-matlab)
file #47340:  bm.fcn_1lookup.m added by rik5 (236B - text/x-matlab)
file #47333:  bm.no_loop_body.m added by rik5 (234B - text/x-matlab)
file #47334:  bm.1idx_assign.m added by rik5 (229B - text/x-matlab)
file #47335:  bm.assign.m added by rik5 (233B - text/x-matlab)
file #47336:  bm.idx_assign.m added by rik5 (231B - text/x-matlab)
file #47332:  toeplitz_oct.cc added by None (716B - application/octet-stream)
file #47331:  do_config_3.2.4 added by rik5 (941B - application/octet-stream)
file #47330:  bm.empty_loop.m added by rik5 (65B - text/x-matlab)
file #47329:  bm.toeplitz.orig.m added by rik5 (244B - text/x-matlab)

 

Depends on the following items: None found

Items that depend on this one: None found

 

Carbon-Copy List
  • -email is unavailable- added by jwe (Posted a comment)
  • -email is unavailable- added by rik5 (Submitted the item)
  •  

    Do you think this task is very important?
    If so, you can add your encouragement to it.
    This task has 0 encouragements so far.

    Only project members can vote.

     

     

     

    Follow 15 latest changes.

    Date Changed by Updated Field Previous Value => Replaced by
    2019-08-16 jwe Attached File- => Added ovl-with-vector-diffs.txt, #47349
    2019-08-12 rik5 Attached File- => Added do_config_3.2.4, #47342
    2019-08-12 rik5 Attached File- => Added octave-old-patches.tar.gz, #47341
    2019-08-12 rik5 Attached File- => Added bm.1loop.m, #47337
        Attached File- => Added bm.fcn_const_val.m, #47338
        Attached File- => Added bm.arithmetic_op.m, #47339
        Attached File- => Added bm.fcn_1lookup.m, #47340
    2019-08-12 rik5 Attached File- => Added bm.no_loop_body.m, #47333
        Attached File- => Added bm.1idx_assign.m, #47334
        Attached File- => Added bm.assign.m, #47335
        Attached File- => Added bm.idx_assign.m, #47336
    2019-08-12 None Attached File- => Added toeplitz_oct.cc, #47332
    2019-08-12 rik5 Attached File- => Added do_config_3.2.4, #47331
    2019-08-12 rik5 Attached File- => Added bm.empty_loop.m, #47330
    2019-08-12 rik5 Attached File- => Added bm.toeplitz.orig.m, #47329

    Back to the top


    Powered by Savane 3.5