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

 
 

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

Submitter:  Rik <rik5>
Submitted:  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
Fixed Release:  None Planned Release:  None
* Mandatory Fields

Add a New Comment Rich Markup
   

Jump to the original submission

Mon 11 Nov 2019 03:08:08 PM UTC, comment #57: 

I checked in your changeset here (https://hg.savannah.gnu.org/hgweb/octave/rev/3e8faed1b7d8) since it seems like a good thing regardless of performance benefits (of which there are some).

Rik <rik5>
Group administrator
Mon 11 Nov 2019 09:39:37 AM UTC, comment #56: 

I do wonder why reshape is affected, though, as I don't think I have touched anything that is related to it ...

Carlo de Falco <cdf>
Group Member
Mon 11 Nov 2019 09:25:55 AM UTC, comment #55: 

Re comment #54:

Actually, it seems my test was benchmarking
both "reshape" and "mat2cell" as can be checked by


for ii = 1:100;
  tic;
  n = 1e6;
  x = reshape (1:n, [1000, 1000])';
  t1(ii) = toc;

  tic;
  y = mat2cell (x, [500,20,180,300], [100,90,810]);
  t2(ii)=toc;
endfor


both seem to be affected by the changeset in a non negligible
way, but "reshape" sounds like something that may be used more
often than "mat2cell".


Carlo de Falco <cdf>
Group Member
Mon 11 Nov 2019 07:56:47 AM UTC, comment #54: 

@Rik

Indeed I don't expect this changeset to have an high impact
on general applications, only a few specific operations are
affected

If I test mat2cell, for example, by


for ii = 1:100;tic; n = 1e6; x = reshape (1:n, [1000, 1000])'; y = mat2cell (x, [500,20,180,300], [100,90,810]); t(ii)=toc; endfor


I do see a speedup of more than 20%

Yet I agree with you that code clarity in this case is more important


Carlo de Falco <cdf>
Group Member
Thu 07 Nov 2019 04:28:33 PM UTC, comment #53: 

@Carlo: I think it probably should be pushed, but I'll let jwe make the final decision.

I tested the patch and it compiles fine and doesn't induce any failures in the test suite.  The performance savings were pretty minimal, 2.5%, but the benchmark I was using (bm.toeptlitz.orig.m) might not be the most appropriate.  What I do see that is valuable is the elimination of the NoAlias class which reduces complexity and makes for more straightforward code.

Rik <rik5>
Group administrator
Wed 06 Nov 2019 04:08:06 PM UTC, comment #52: 

@Rik, @JWE, any feedback on the changeset in file #47587 ?
should it be pushed?

Carlo de Falco <cdf>
Group Member
Mon 30 Sep 2019 09:16:12 AM UTC, comment #51: 

Here's the changeset for removing NoAlias
(better late than never) ...

a few comments :

- there was no usage of NoAlias where the wrapped object
  was accessed read-only so in no case I used the const
  version of the call operator but all changes consist
  of using the xelem () method explicitly

- I think I spotted a few instances in data.cc where NoAlias
  was not used but it could have, so xelem could now be used.
  I didn't make any changes to those in order not to clutter
  this changeset

- I ran _run_test_suite_ () with the changeset applied and see
  no extra failures/regressions i the final report


Is it OK to push this?





(file #47587)

Carlo de Falco <cdf>
Group Member
Tue 17 Sep 2019 06:24:43 PM UTC, comment #50: 

@Carlo: That would be great.  My list of NoAlias usages is


corefcn/cellfun.cc:1944:  NoAlias<Cell> retval;
corefcn/cellfun.cc:2001:  NoAlias<Cell> retval;
corefcn/cellfun.cc:2030:  NoAlias< Array<idx_vector>> ra_idx
corefcn/cellfun.cc:2065:  NoAlias<Cell> retval;
corefcn/cellfun.cc:2480:  NoAlias<Cell> y (x.dims ());
corefcn/data.cc:2725:          NoAlias<Matrix> m (1, ndims);
corefcn/data.cc:7852:  NoAlias< Array<octave_idx_type>> r (rm.dims ());
corefcn/xpow.cc:1195:      NoAlias<NDArray> result (a.dims ());
corefcn/xpow.cc:2504:      NoAlias<FloatNDArray> result (a.dims ());
octave-value/ov-cell.cc:1385:  NoAlias<Cell> c (result_dv);
octave-value/ov-flt-re-mat.cc:741:  NoAlias<FloatNDArray> rr (a.dims ());
octave-value/ov-flt-re-mat.cc:752:          NoAlias<FloatComplexNDArray> rc (a.dims ());
octave-value/ov-re-mat.cc:868:  NoAlias<NDArray> rr (a.dims ());
octave-value/ov-re-mat.cc:879:          NoAlias<ComplexNDArray> rc (a.dims ());

array/Array.h:886:class NoAlias : public ArrayClass
array/Array.h:890:  NoAlias () : ArrayClass () { }
array/CMatrix.cc:3613:  NoAlias<ComplexMatrix> retval;
array/CRowVector.cc:426:  NoAlias<ComplexRowVector> retval;
array/Sparse.cc:1510:          NoAlias< Array<octave_idx_type>> lidx (dim_vector (new_nr, new_nc));
array/dMatrix.cc:3005:  NoAlias<Matrix> retval;
array/dRowVector.cc:269:  NoAlias<RowVector> retval;
array/fCMatrix.cc:3644:  NoAlias<FloatComplexMatrix> retval;
array/fCRowVector.cc:428:  NoAlias<FloatComplexRowVector> retval;
array/fMatrix.cc:3011:  NoAlias<FloatMatrix> retval;
array/fRowVector.cc:269:  NoAlias<FloatRowVector> retval;



Rik <rik5>
Group administrator
Tue 17 Sep 2019 02:24:23 PM UTC, comment #49: 


comment #48:

> I'm not hard set on this though.  If anyone feels strongly about it we can leave it.


I also like the idea of removing NoAlias, I can prepare the changeset for this if no one else feels like it.

Carlo de Falco <cdf>
Group Member
Fri 13 Sep 2019 07:38:47 PM UTC, comment #48: 

@jwe: The first part of your answer confirms what I had hoped, that the Array class is already correctly programmed to handle RO access (const) to data members without checking reference counts.  So my vote would be to remove the NoAlias class.

I'm not hard set on this though.  If anyone feels strongly about it we can leave it.

Rik <rik5>
Group administrator
Fri 13 Sep 2019 07:21:30 PM UTC, comment #47: 

Rik: when you write


const Array<int> new_ra (old_ra);
int elt = new_ra(1);


then you call the const elem method which doesn't need to check the reference count because it can't modify the array.

But if you write


Array<int> new_ra (old_ra);
int elt = new_ra(1);


then the non-const elem method is called.  It returns a reference and is not (and could not, at the time these classes were first written) be overloaded based on whether it it is used in an rvalue or lvalue context, so it has to check the reference count and maybe force a copy to provide COW semantics.

Now, with modern C++, is it possible to determine whether the operator is invoked in an lvalue or rvalue context?  If so, then we could just fix this with some changes to the Array class.  But even after reading about ref-qualifiers and looking at some examples, I don't see how to do it.

John W. Eaton <jwe>
Group administrator
Fri 13 Sep 2019 05:05:36 PM UTC, comment #46: 

Regarding NoAlias, the number of instances where it is used is quite small: 9 in liboctave and 14 in libinterp.

Speaking personally, I find the pattern of using a function (xelem) rather than subclassing an object (NoAlias) easier to understand.

jwe has proposed two replacements for NoAlias: 1) using 'const' objects when read-only access is all that is necessary, 2) using xelem when it is desired to write elements without causing a check on reference count and possibly uniquifying the Array.

@jwe: Is that an accurate summary?  Is the existing Array class set up correctly so that if I use a const constructor I don't end up with two actual arrays as shown below?


 const ArrayType new_ro_array (existing_array);
 ... intervening code ...
 T element1 = new_ro_array(1);  // Will call new_ro_array.elem()
                                // No problem?


If yes, then I would advocate eliminating NoAlias for readability.

Rik <rik5>
Group administrator
Fri 13 Sep 2019 04:51:35 PM UTC, comment #45: 

@Carlo: I pushed your last patch which simplifies the constructors in Array.h here https://hg.savannah.gnu.org/hgweb/octave/rev/e69da2dae19c.

Rik <rik5>
Group administrator
Fri 13 Sep 2019 09:11:24 AM UTC, comment #44: 

comment #43:

> The shallow copy of the array isn't the real problem.  It's that even if there is no other copy and the reference count is always 1, the usual array indexing operations for non-const instances of our copy-on-write classes must always check the reference count.  The NoAlias class provides a way to override that choice, but it is risky because we have to know that there will never be a copy.  If we know that, then I think it makes sense to just use xelem explicitly.
>
> Another way to avoid the reference count checks is to use const copy-on-write objects wherever possible.  We probably don't follow that advice as much as we should in the Octave sources.
>


@jwe I understand the purpose of NoAlias, but in this context the copy IS the issue.

The pattern that clang++ warned about in Sparse.cc can be summarized as follows



template<class ArrayType> ArrayType foo ( ... ) {

 NoAlias<ArrayType> r (d);

 for (i = 0; i < r.numel (); ++i) {
   r(i) = foobar ();
 }

 return r;
}


Here the use of NoAlias does indeed serve its purpose of optimizing access to
elements of r by avoiding unneeded checks.

But it has an unwanted side effect due to the fact that the return value is not
of type ArrayType but of a derived type.

This prevents the compiler for optimizing away the copy of the temporary object r
when it is returned.

If one wanted to maintain the NoAlias wrapper and avoid the copy, then the compiler
suggest using


 return std::move (r);


Using a const arry here makes no sense as the purpose of the function is to fill its elements.

My solution in https://hg.savannah.gnu.org/hgweb/octave/rev/e1968e40e43f was instead to
allocate r with the base type directly and to use ArrayType::xelem () for faster access
to its elements



template<class ArrayType> ArrayType foo ( ... ) {

 ArrayType r (d);

 for (i = 0; i < r.numel (); ++i) {
   r.xelem (i) = foobar ();
 }

 return r;
}



In comment #41 Rik was wondering whether the same change would need to be done in other
places where NoAlias is used. In comment #42 I was guessing that when the NoAlias<ArrayType>
is not returned by value itself but passed to the octave_value constructor there is not an
automatic optimization that the compiler can do.



Carlo de Falco <cdf>
Group Member
Fri 13 Sep 2019 04:29:22 AM UTC, comment #43: 

The shallow copy of the array isn't the real problem.  It's that even if there is no other copy and the reference count is always 1, the usual array indexing operations for non-const instances of our copy-on-write classes must always check the reference count.  The NoAlias class provides a way to override that choice, but it is risky because we have to know that there will never be a copy.  If we know that, then I think it makes sense to just use xelem explicitly.

Another way to avoid the reference count checks is to use const copy-on-write objects wherever possible.  We probably don't follow that advice as much as we should in the Octave sources.

John W. Eaton <jwe>
Group administrator
Thu 12 Sep 2019 02:59:48 PM UTC, comment #42: 

@Rik, I am not sure whether other uses of NoAlias should also be changed.

All the instances that you found appear to be of the form


octave_value_list retval;
NoAlias<Array<T>> r;
do_stuff ();
retval (0) = r;
return retval;


I am not sure in this case

1) whether retval (0) = r; requires a copy
2) whether avoiding use of NoAlias would allow
   the compiler to avoid the copy

(My guess is the copy does not happen in this case or is at most a shallow copy)

On the other hand I see the implementation of NoAlias itself can be simplified (as suggested by the FIXME comment) as we now require c++11.

Patch to simplify NoAlias is attached.

(file #47491)

Anonymous
Wed 11 Sep 2019 05:35:39 PM UTC, comment #41: 

@Carlo: I pushed your other changeset here https://hg.savannah.gnu.org/hgweb/octave/rev/90dfdf0d09ad.

Should the other instances of NoAlias be investigated and replaced as well?  Using grep in libinterp/ I see


corefcn/cellfun.cc:1944:  NoAlias<Cell> retval;
corefcn/cellfun.cc:2001:  NoAlias<Cell> retval;
corefcn/cellfun.cc:2030:  NoAlias< Array<idx_vector>> ra_idx
corefcn/cellfun.cc:2065:  NoAlias<Cell> retval;
corefcn/cellfun.cc:2480:  NoAlias<Cell> y (x.dims ());
corefcn/data.cc:2725:          NoAlias<Matrix> m (1, ndims);
corefcn/data.cc:7852:  NoAlias< Array<octave_idx_type>> r (rm.dims ());
corefcn/xpow.cc:1195:      NoAlias<NDArray> result (a.dims ());
corefcn/xpow.cc:2504:      NoAlias<FloatNDArray> result (a.dims ());
octave-value/ov-cell.cc:1385:  NoAlias<Cell> c (result_dv);
octave-value/ov-flt-re-mat.cc:741:  NoAlias<FloatNDArray> rr (a.dims ());
octave-value/ov-flt-re-mat.cc:752:          NoAlias<FloatComplexNDArray> rc (a.dims ());
octave-value/ov-re-mat.cc:868:  NoAlias<NDArray> rr (a.dims ());
octave-value/ov-re-mat.cc:879:          NoAlias<ComplexNDArray> rc (a.dims ());


Rik <rik5>
Group administrator
Wed 11 Sep 2019 04:17:02 PM UTC, comment #40: 

@Rik, Thanks.

Is it OK to push also the changeset  file #47475 for tril.cc?
that one is a full changeset so it should be easier ;-)

I already checked that it does not break anything that was not already broken (I get a few test failure in make check, but the patch does not add any new ones)




Carlo de Falco <cdf>
Group Member
Wed 11 Sep 2019 03:25:44 PM UTC, comment #39: 

I pushed Carlo's patch for Sparse.cc here (https://hg.savannah.gnu.org/hgweb/octave/rev/e1968e40e43f) after adding a commit message and verify with 'make check' that nothing had been broken.

Rik <rik5>
Group administrator
Tue 10 Sep 2019 03:51:02 PM UTC, comment #38: 

@Carlo: Your reasoning seems sound.  In particular, with regard to the second issue in Sparse.cc, I have routinely been substituting xelem() for elem() in changesets that I prepare when it is safe to do so.

Rik <rik5>
Group administrator
Tue 10 Sep 2019 02:00:14 PM UTC, comment #37: 

I recently posted the changeset

file #47475

on the mailing list thread from which this ticket was generated.

The changeset was motivated by a "-Wreturn-std-move" warning given by clang++
when compiling tril.cc.

The rationale behind the changeset is that returning a derived
type instead of just an Array<> object causes a copy that the
compiler does not seem to be able to optimize away.

As the use of the NoAlias<Array<>> wrapper is not really useful in the particular case being addressed by the changeset, the trivial solution is to just avoid the creation of NoAlias<Array<>> altogether.

file #47476

Addresses instead a similar but not identical case occurring in Sparse.cc
here the NoAlias<Array<>> template was actually useful to make access to array
elements faster.

The solution adopted in file #47476 is to avoid NoAlias<Array<>> and use the Array<T>::xelem() method directly, but someone may think of a better or more
elegant solution in this case.

Posting the patches here so they don't get forgotten/lost.






(file #47476)

Carlo de Falco <cdf>
Group Member
Thu 05 Sep 2019 04:11:34 PM UTC, comment #36: 

@jwe: You asked a specific question about convert_to_const_vector.  This function isn't seen in the profiles of bm.assign.m.  It is seen in bm.toeplitz.orig.m.  The excerpt from profiling below shows that the function and its children are taking ~20% of runtime, but most of that is the children.  The running time for the function convert_to_const_vector itself is small at <1% of runtime.


-   20.23%     0.93%  octave-cli  liboctinterp.so.7.0.0  [.] octave::tree_evaluator::convert_to_const_vector
   - 19.30% octave::tree_evaluator::convert_to_const_vector
      - 8.94% octave::tree_binary_expression::evaluate
         - 6.02% octave::tree_identifier::evaluate
            - 4.27% octave::tree_identifier::evaluate_n
                 0.87% octave::tree_evaluator::varval
              0.65% Array<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > >::~Array
         + 1.59% do_binary_op
      - 6.43% octave::tree_identifier::evaluate
         - 4.52% octave::tree_identifier::evaluate_n
              0.89% octave::tree_evaluator::varval
              0.52% octave_value::~octave_value
           0.68% Array<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > >::~Array
      - 2.42% octave_value_list::octave_value_list
           0.69% std::vector<octave_value, std::allocator<octave_value> >::_M_default_append
        0.53% std::__cxx11::_List_base<octave_value, std::allocator<octave_value> >::_M_clear



Rik <rik5>
Group administrator
Thu 05 Sep 2019 04:55:34 AM UTC, comment #35: 

I ran profiling on the more narrow bm.assign.m for which the relevant hotspot is

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


The results are



-   92.74%     1.47%  octave-cli  liboctinterp.so.7.0.0  [.] octave::tree_evaluator::visit_simple_for_command
   - 91.27% octave::tree_evaluator::visit_simple_for_command
        octave::tree_evaluator::visit_statement_list
      - octave::tree_evaluator::visit_statement
         - 90.88% octave::tree_evaluator::visit_simple_for_command
              octave::tree_evaluator::visit_statement_list
            - octave::tree_evaluator::visit_statement
               - 89.30% octave::tree_evaluator::visit_simple_for_command
                  - 67.65% octave::tree_evaluator::visit_statement_list
                     - 65.17% octave::tree_evaluator::visit_statement
                        - 44.61% octave::tree_simple_assignment::evaluate
                           - 13.86% octave::octave_lvalue::assign
                              - 3.94% octave::script_stack_frame::varref
                                   1.82% octave::script_stack_frame::get_val_offsets_with_insert
                                3.87% octave_value::storable_value
                                0.50% octave::base_value_stack_frame::varref
                             4.03% std::__cxx11::_List_base<octave::octave_lvalue, std::allocator<octave::octave_lvalue> >::_M_clear
                             3.41% octave_value::~octave_value
                             1.92% std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >::_M_construct<char const*>
                             1.06% cfree@GLIBC_2.2.5
                             0.59% std::__cxx11::_List_base<octave_value_list, std::allocator<octave_value_list> >::_M_clear
                          4.79% octave::tree_identifier::lvalue
                          4.04% octave_value::~octave_value
                          2.65% octave::tree_constant::evaluate
                          0.74% operator new
                          0.69% malloc
                          0.68% octave::tree_statement::column
                          0.50% std::_Function_handler<void (), std::_Bind<octave::tree_simple_assignment::evaluate(octave::tree_evaluator&, int)::{lambda(std::__cxx11::list<octave::octave_lvalue, std::allocat
                  - 14.70% octave::octave_lvalue::assign
                       4.48% octave_value::storable_value
                     - 3.21% octave::script_stack_frame::varref
                          octave::script_stack_frame::get_val_offsets_with_insert
                    2.82% octave_value::~octave_value
                    0.75% cfree@GLIBC_2.2.5
                    0.57% operator new
                    0.54% octave_value::octave_value
   + 1.47% 0x6de258d4c544155


octave_value objects seem reasonably heavy.  Just running the destructor ~octave_value consumed ~10.5% of runtime.

The Self section which is the second column of these four entries seems high (adds up to 46.7% of run time)


+   44.99%    17.18%  octave-cli  liboctinterp.so.7.0.0  [.] octave::tree_simple_assignment::evaluate
+   28.56%    10.76%  octave-cli  liboctinterp.so.7.0.0  [.] octave::octave_lvalue::assign
+   10.70%    10.70%  octave-cli  liboctinterp.so.7.0.0  [.] octave_value::~octave_value
+    8.35%     8.01%  octave-cli  liboctinterp.so.7.0.0  [.] octave_value::storable_value



Rik <rik5>
Group administrator
Wed 04 Sep 2019 10:17:52 PM UTC, comment #34: 

I pushed some more changes in an attempt to improve the performance of single unwind-protect actions:

  http://hg.savannah.gnu.org/hgweb/octave/rev/2f8428b61bd6
  http://hg.savannah.gnu.org/hgweb/octave/rev/25627c524ad8
  http://hg.savannah.gnu.org/hgweb/octave/rev/d171d356767b

Now I see the following timings on my system:


          bm_assign     bm_toeplitz

   3.2.4:   0.19735      11.278
   3.4.3:   0.17148       9.2246
   3.6.4:   0.21437       9.5798
   3.8.2:   0.25326      15.447
   4.0.3:   0.51134      27.710
   4.2.2:   0.53206      26.772
   4.4.1:   1.5782       31.758
   5.1.0:   1.7119       36.593
  before:   1.9624       30.399
     now:   0.62128      18.524


The "before" line is changeset 64289bf338da:


  user:        John W. Eaton <jwe@octave.org>
  date:        Wed Aug 14 00:19:34 2019 -0400
  summary:     use separate variable for interrupting command editor event loop (bug #56738)


I think that is prior to any changes related to this issue.

Could you try another profiling run with these changes?  The convert_to_const_vector function uses unwind_protect, so the latest changes might have made a difference.

John W. Eaton <jwe>
Group administrator
Wed 04 Sep 2019 12:43:17 AM UTC, comment #33: 

I have re-run the benchmark with code profiling.  See results below.

Interesting hotspots still seem to be octave::symbol_table::find_function at 24.82% (basically 1/4) of runtime.  Maybe we need an O(1) cache that gets used UNLESS something like a new class has been created or a timestamp has changed.  The function octave::tree_evaluator::convert_to_const_vector at 11.21% also seems large.  The function octave::tree_index_expression::lvalue takes 16% of run time, but 60% of that 16% is due to convert_to_const_vector so it seems worth working on that first.  Little things like constructors and destructors taking on order 1% of run time seem innocuous, but I haven't added them all up to see if we still need to make improvements (lighter weight constructors) for octave_value and octave_value_list.



-   86.91%     1.73%  octave-cli  liboctinterp.so.7.0.0  [.] octave::tree_simple_assignment::evaluate
   - 85.18% octave::tree_simple_assignment::evaluate
      - 56.49% octave::tree_binary_expression::evaluate
         - 53.78% octave::tree_index_expression::evaluate
            - 51.81% octave::tree_index_expression::evaluate_n
               - 24.82% octave::symbol_table::find_function
                  - 24.72% octave::symbol_table::fcn_table_find
                     - 21.80% octave::fcn_info::fcn_info_rep::find
                        - 20.80% octave::fcn_info::fcn_info_rep::xfind
                           - 7.86% octave::fcn_info::fcn_info_rep::find_method
                              - 6.35% octave::fcn_info::fcn_info_rep::load_class_method
                                   1.36% __memmove_avx_unaligned_erms
                                 + 1.30% octave::cdef_manager::find_method_symbol
                                   0.80% octave::load_path::package_info::find_method
                           - 4.51% octave::fcn_info::fcn_info_rep::load_class_constructor
                              - 2.76% octave::fcn_info::fcn_info_rep::find_user_function
                                 - 2.17% octave::load_path::package_info::find_fcn
                                      1.27% std::_Rb_tree<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std
                                      0.67% __memcmp_avx2_movbe
                           - 2.15% octave::fcn_info::fcn_info_rep::find_autoload
                                0.84% __memcmp_avx2_movbe
                                0.76% octave::tree_evaluator::lookup_autoload
                           - 1.74% octave::fcn_info::fcn_info_rep::find_user_function
                              + 1.16% octave::load_path::package_info::find_fcn
                           + 1.72% octave::fcn_info::fcn_info_rep::find_package
                             0.62% octave_value::~octave_value
                       1.12% std::_Rb_tree<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<cha
                       0.90% __memcmp_avx2_movbe
               - 11.21% octave::tree_evaluator::convert_to_const_vector
                  - 8.69% octave::tree_binary_expression::evaluate
                     - 5.79% octave::tree_identifier::evaluate
                        - 4.18% octave::tree_identifier::evaluate_n
                             0.82% octave::tree_evaluator::varval
                             0.52% octave_value::~octave_value
                          0.59% Array<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > >::~Array
                       1.31% do_binary_op
                    1.04% octave_value_list::octave_value_list
               - 6.22% octave_builtin::call
                    1.40% Fabs
                    1.34% octave::action_container::run
                  + 0.86% octave::call_stack::push
                    0.64% octave_value_list::make_storable_values
               + 1.11% octave::tree_evaluator::is_variable
                 0.70% Array<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > >::~Array
                 0.70% Array<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > >::operator=
                 0.65% octave::tree_evaluator::varval
                 0.60% octave_value_list::operator=
                 0.54% Array<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > >::operator=
                 0.52% octave::action_container::run
           1.20% do_binary_op
      - 15.96% octave::tree_index_expression::lvalue
         - 9.86% octave::tree_evaluator::convert_to_const_vector
            - 5.97% octave::tree_identifier::evaluate
               - 4.34% octave::tree_identifier::evaluate_n
                    0.84% octave::tree_evaluator::varval
                    0.58% octave_value::~octave_value
                 0.62% Array<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > >::~Array
              1.60% octave_value_list::octave_value_list
         + 1.00% octave::octave_lvalue::set_index
           0.80% std::__cxx11::_List_base<octave_value_list, std::allocator<octave_value_list> >::_M_clear
           0.54% octave_value::~octave_value
      - 7.99% octave::octave_lvalue::assign
         - 7.07% octave_value::assign
            - 6.57% octave_value::subsasgn
               - 6.22% octave_base_matrix<NDArray>::subsasgn
                  - 5.56% octave_base_value::numeric_assign
                     - 4.22% oct_assignop_assign
                        - 3.00% octave_base_matrix<NDArray>::assign
                           - 0.82% Array<double>::Array
                                0.51% dim_vector::safe_numel
      - 1.02% std::__cxx11::_List_base<octave::octave_lvalue, std::allocator<octave::octave_lvalue> >::_M_clear
           0.71% std::__cxx11::_List_base<octave_value_list, std::allocator<octave_value_list> >::_M_clear
        0.87% octave::action_container::run
        0.63% std::__cxx11::_List_base<octave_value_list, std::allocator<octave_value_list> >::_M_clear




Rik <rik5>
Group administrator
Tue 03 Sep 2019 10:17:05 PM UTC, comment #32: 

I pushed the following changesets to improve performance of the evaluator:

http://hg.savannah.gnu.org/hgweb/octave/rev/5bf76ab4cce3
http://hg.savannah.gnu.org/hgweb/octave/rev/a2d3fa82b730
http://hg.savannah.gnu.org/hgweb/octave/rev/fcaecdbc8d8a

There is still much room for improvement.  I'll write more on the mailing list.

John W. Eaton <jwe>
Group administrator
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>
Group 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>
Group 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>
Group 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>
Group 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>
Group 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>
Group 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>
Group 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>
Group 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>
Group 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>
Group administrator
Fri 16 Aug 2019 05:09:25 PM UTC, comment #21: 
John W. Eaton <jwe>
Group 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>
Group 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>
Group 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>
Group 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>
Group 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>
Group 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>
Group 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>
Group 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>
Group 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>
Group 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>
Group 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>
Group 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>
Group 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>
Group Member
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>
Group 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>
Group 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

+verbatim+
-verbatim-


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

 

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

Attach Files:
   
   
Comment:
   

Attached Files
file #47587:  open_13F4F3id.txt added by cdf (21KiB - text/plain - remove NoAlias<T>)
file #47491:  open_0qtoU59a.txt added by None (1KiB - text/plain - patch to simplify constructor in NoAlias)
file #47476:  patch.txt added by cdf (815B - text/plain)
file #47475:  open_spTJFglc.txt added by None (745B - text/plain - avoid non necessary copy when creating triu matrix)
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 cdf (Updated the item)
  • -email is unavailable- added by jwe (Posted a comment)
  • -email is unavailable- added by rik5 (Submitted the item)
  •  

    There are 0 votes so far. Votes easily highlight which items people would like to see resolved in priority, independently of the priority of the item set by tracker managers.

    Only group members can vote.

     

    Follow 19 latest changes.

    Date Changed by Updated Field Previous Value => Replaced by
    2019-09-30 cdf Attached File- Added open_13F4F3id.txt, #47587
    2019-09-12 None Attached File- Added open_0qtoU59a.txt, #47491
    2019-09-10 cdf Attached File- Added patch.txt, #47476
    2019-09-10 None Attached File- Added open_spTJFglc.txt, #47475
    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.13-3230.
    Corresponding source code