Error: sado freezes

[richelbilderbeek]

So these are the parameters that should make sado freeze:

alleles 1 1 1
histbin 0.1 0.1 0.1 0.1
seed 42
pop0 100
type0 0 0 0
end 350
sc 0.6
se 0.5
sk 1.2
c 0.005
sm 0.1
sv 0.02
sq 1.0
eta 1.0
b 4.0
output 1 output.txt
erasure_method swap
initialization_bug 0
gausser_implementation lut
diploid 1
at 0.05

issue_261.txt

[richelbilderbeek]

Steps:

• [x] add a verbose mode
• [x] show the steps the program is in
• [x] find minimal reprex
• [ ] fix

[richelbilderbeek]

Hypothesis: the while loop in sado::get_descendants causes this.

std::vector<sado::species> sado::get_descendants(
  const sp_vert_desc vd, const species_graph& g)
{
  std::vector<sp_vert_desc> v = get_next_generation_vds(vd, g);

  while (1) //#264
  {
    const auto sz_before = v.size();
    //Get the vertex descriptors before all the current vertex descriptors
    v = get_next_generation_vds(v, g);
    const auto sz_after = v.size();
    assert(sz_after >= sz_before);
    if (sz_before == sz_after) break;
  }
  // ...
}

[richelbilderbeek]

It is the complexity of this function that is a problem.

Why did this not show up in the profiling log?

[richelbilderbeek]

Try running with other sim end times:

./sado issue_264.txt --verbose end 100

[richelbilderbeek]

time ./sado issue_264.txt end 40 --no_ml

Flat profile:

Each sample counts as 0.01 seconds.
  %   cumulative   self              self     total           
 time   seconds   seconds    calls   s/call   s/call  name    
 52.65     42.94    42.94 24191845     0.00     0.00  std::vector<sado::indiv, std::allocator<sado::indiv> >::operator=(std::vector<sado::indiv, std::allocator<sado::indiv> > const&)
 22.73     61.48    18.54 24191804     0.00     0.00  std::_Rb_tree_node<sado::id>* std::_Rb_tree<sado::id, sado::id, std::_Identity<sado::id>, std::less<sado::id>, std::allocator<sado::id> >::_M_copy<std::_Rb_tree<sado::id, sado::id, std::_Identity<sado::id>, std::less<sado::id>, std::allocator<sado::id> >::_Reuse_or_alloc_node>(std::_Rb_tree_node<sado::id> const*, std::_Rb_tree_node<sado::id>*, std::_Rb_tree<sado::id, sado::id, std::_Identity<sado::id>, std::less<sado::id>, std::allocator<sado::id> >::_Reuse_or_alloc_node&)

[richelbilderbeek]

Cause by get_last_descendant_generation that creates a load of species.

Call graph:

index % time    self  children    called     name
                                                 <spontaneous>
[1]     99.5    0.00   81.14                 sado::create_reconstructed(boost::adjacency_list<boos
t::vecS, boost::vecS, boost::undirectedS, sado::species, int, boost::no_property, boost::listS>) [
1]
                0.00   80.88       1/1           sado::clear_extinct(boost::adjacency_list<boost::
vecS, boost::vecS, boost::undirectedS, sado::species, int, boost::no_property, boost::listS>&) [3]
                0.00    0.26       1/1           sado::merge_split_species(boost::adjacency_list<b
oost::vecS, boost::vecS, boost::undirectedS, sado::species, int, boost::no_property, boost::listS>
&) [16]
                0.00    0.00       1/295021      boost::adjacency_list<boost::vecS, boost::vecS, b
oost::undirectedS, sado::species, int, boost::no_property, boost::listS>::adjacency_list(boost::ad
jacency_list<boost::vecS, boost::vecS, boost::undirectedS, sado::species, int, boost::no_property,
 boost::listS> const&) [7]
                0.00    0.00       2/1734        sado::remove_cleared_vertices(boost::adjacency_li
st<boost::vecS, boost::vecS, boost::undirectedS, sado::species, int, boost::no_property, boost::li
stS>&) [55]

[richelbilderbeek]

OK, a major speed increase, thanks to has_extant_descendant_impl2:

./sado issue_261.txt end 10 --no_ml

t_end	real before (sec)	user before (sec)	sys before (sec)	real after (sec)	user after (sec)	sys after (sec)
10	3	2	0.06	0	0	0
20	57	25	0.12	1	0.6	0.01
40	471	384	64	3	1.2	0.05
80	?	?	?	7	4	0.5

[richelbilderbeek]

New profile!

Used:

./sado issue_261.txt end 640 --no_ml

Output:

639 271 -0.209928 -0.214732 0.194134
0.100074 -0.0869245 -0.103834 0.752555 0.0841668 0.0747259
640 275 -0.199843 -0.302883 0.22256
0.114943 -0.107306 -0.103673 0.765257 0.0780724 0.0782136
reconstucted tree:
(:1,:1):639;
ICE default IO error handler doing an exit(), pid = 2422, errno = 32

real    7m17.710s
user    5m4.396s
sys 0m52.096s

Note the ICE default IO error?

Here is the profile:

p230198@fwn-biol-132-102:~/GitHubs/build-sado-Desktop-Release$ head gprof.log -n 20
Flat profile:

Each sample counts as 0.01 seconds.
  %   cumulative   self              self     total           
 time   seconds   seconds    calls   s/call   s/call  name    
 61.21     48.99    48.99 12396345     0.00     0.00  std::vector<sado::indiv, std::allocator<sado::indiv> >::operator=(std::vector<sado::indiv, std::allocator<sado::indiv> > const&)
 16.89     62.51    13.52 12395704     0.00     0.00  std::_Rb_tree_node<sado::id>* std::_Rb_tree<sado::id, sado::id, std::_Identity<sado::id>, std::less<sado::id>, std::allocator<sado::id> >::_M_copy<std::_Rb_tree<sado::id, sado::id, std::_Identity<sado::id>, std::less<sado::id>, std::allocator<sado::id> >::_Reuse_or_alloc_node>(std::_Rb_tree_node<sado::id> const*, std::_Rb_tree_node<sado::id>*, std::_Rb_tree<sado::id, sado::id, std::_Identity<sado::id>, std::less<sado::id>, std::allocator<sado::id> >::_Reuse_or_alloc_node&)
 10.95     71.27     8.76 45001119     0.00     0.00  std::_Rb_tree<sado::id, sado::id, std::_Identity<sado::id>, std::less<sado::id>, std::allocator<sado::id> >::_M_erase(std::_Rb_tree_node<sado::id>*)

[richelbilderbeek]

Time for a plan: determine where the std::vector<individual>copies come from.

context	copies in profile
sim only	?
complete	12M

[richelbilderbeek]

There are hints that I copy-construct the ancestry_graph too often:

index % time    self  children    called     name
[1]     88.4    0.00    3.01     490         sado::get_next_generation_vds(unsigned long, boost::adjacency_list<boost::vecS, boost::vecS, boost::bidirectionalS, sado::species, boost::no_property, boost::no_property, boost::listS> const&) [1]
                0.10    2.79    2940/2970        boost::adjacency_list<boost::vecS, boost::vecS, boost::bidirectionalS, sado::species, boost::no_property, boost::no_property, boost::listS>::adjacency_list(boost::adjacency_list<boost::vecS, boost::vecS, boost::bidirectionalS, sado::species, boost::no_property, boost::no_property, boost::listS> const&) [2]
-----------------------------------------------
[2]     85.5    0.10    2.82    2970         boost::adjacency_list<boost::vecS, boost::vecS, boost::bidirectionalS, sado::species, boost::no_property, boost::no_property, boost::listS>::adjacency_list(boost::adjacency_list<boost::vecS, boost::vecS, boost::bidirectionalS, sado::species, boost::no_property, boost::no_property, boost::listS> const&) [2]
                2.01    0.00  794740/795225      std::vector<sado::individual, std::allocator<sado::individual> >::operator=(std::vector<sado::individual, std::allocator<sado::individual> > const&) [4]
-----------------------------------------------
[3]     59.1    0.00    2.01                 sado::create_reconstructed(boost::adjacency_list<boost::vecS, boost::vecS, boost::bidirectionalS, sado::species, boost::no_property, boost::no_property, boost::listS>) [3]
-----------------------------------------------
[4]     58.9    2.01    0.00  795225         std::vector<sado::individual, std::allocator<sado::individual> >::operator=(std::vector<sado::individual, std::allocator<sado::individual> > const&) [4]
-----------------------------------------------

[richelbilderbeek]

Nah, I think I'd better focus on get_next_generation_vds:

[richelbilderbeek]

After changing get_next_generation_vd

t_end	real before (sec)	user before (sec)	sys before (sec)	real after (sec)	user after (sec)	sys after (sec)	Improvement (O user/N user)
160	22	14	1.8	10	5	0.2	2.8x
320	77	57	9	29	18	0.36	3.1x
640	438	304	52	108	87	0.7	3.5x

[richelbilderbeek]

Interestingly, it results in less (1.2 M -> 0.53M) copies of std::vector<individual>... :confused:

Each sample counts as 0.01 seconds.
  %   cumulative   self              self     total           
 time   seconds   seconds    calls   s/call   s/call  name    
 40.41      1.39     1.39   530965     0.00     0.00  std::vector<sado::individual, std::allocator<sado::individual> >::operator=(std::vector<sado::individual, std::allocator<sado::individual> > const&)
 13.66      1.86     0.47   530644     0.00     0.00  std::_Rb_tree_node<sado::id>* std::_Rb_tree<sado::id, sado::id, std::_Identity<sado::id>, std::less<sado::id>, std::allocator<sado::id> >::_M_copy<std::_Rb_tree<sado::id, sado::id, std::_Identity<sado::id>, std::less<sado::id>, std::allocator<sado::id> >::_Reuse_or_alloc_node>(std::_Rb_tree_node<sado::id> const*, std::_Rb_tree_node<sado::id>*, std::_Rb_tree<sado::id, sado::id, std::_Identity<sado::id>, std::less<sado::id>, std::allocator<sado::id> >::_Reuse_or_alloc_node&)
 10.76      2.23     0.37  2016393     0.00     0.00  std::_Rb_tree<sado::id, sado::id, std::_Identity<sado::id>, std::less<sado::id>, std::allocator<sado::id> >::_M_erase(std::_Rb_tree_node<sado::id>*)
  9.59      2.56     0.33 67617548     0.00     0.00  std::_Rb_tree<sado::id, sado::id, std::_Identity<sado::id>, std::less<sado::id>, std::allocator<sado::id> >::find(sado::id const&) const
  9.59      2.89     0.33 494739165     0.00     0.00  sado::operator<(sado::id, sado::id)

[richelbilderbeek]

From GUI, using issue_265.txt it freezes here, in create_ancestry_graph:

void sado::qtdialog::show_phylogenies(const results &r)
{
  qDebug() << "create_ancestry_graph";
  const auto g = create_ancestry_graph(r.get_species());

[richelbilderbeek]

No crash observed yet, but I predict it freezes in the while/for loop :sunglasses:

std::vector<sado::sp_vert_desc> sado::collect_younger_nodes(
  const sp_vert_desc vd,
  const ancestry_graph& g)
{
  std::cerr << "collect_younger_nodes start\n";
  assert(!is_tip(vd, g));

  std::cerr << "First get all younger vds\n";
  std::vector<sp_vert_desc> vds{get_next_generation_vds(vd, g)};

  std::cerr << "For each of those younger vertex descriptors (yvd), "
    << "walk towards the present until there is a node\n";
  for (auto& yvd: vds)
  {
    std::cerr << "Even Younger Vertex Descriptor\n";
    for (int i{0}; i!=1'000'000; ++i) //Prevent infinite loop
    //while (1)
    {
      //std::cerr << i;
      const auto eyvds = get_next_generation_vds(yvd, g);
      assert(eyvds.size() != 1 || eyvds[0] != yvd); //No self-loop
      if (eyvds.empty()) break; //A tip
      if (eyvds.size() > 1) break;
      yvd = eyvds[0];
      assert(i != 999'999);
    }
  }
  return vds;
}

[richelbilderbeek]

Boy, do I dislike the way I generate that Newick. I need a Depth-First search there too, and it will be less error-prone as a bonus as well!

[richelbilderbeek]

Fail fast with this file:

no_newick_fast.txt

[richelbilderbeek]

Marked error with FIX_ISSUE_264

[richelbilderbeek]

Cleaned up some stuff, speed improvements for free:

t_end	real before (sec)	user before (sec)	sys before (sec)	real after (sec)	user after (sec)	sys after (sec)	Improvement (O user/N user)
160	10	5	0.2	7	2	0.16	2.5x
320	29	18	0.36	14	4	0.3	4.5x
640	108	87	0.7	34	13	0.5	6.6x
1280	?	?	?	93	53	14	?

[richelbilderbeek]

Just by cleaning up, the profile also changed quite some bit:

From

./sado issue_261.txt end 2560 --no_ml

I got:

reconstructed tree:
(:2560);
ICE default IO error handler doing an exit(), pid = 8597, errno = 32
Segmentation fault (core dumped)

real    4m37.889s
user    3m13.088s
sys 0m3.288s

and

Flat profile:

Each sample counts as 0.01 seconds.
  %   cumulative   self              self     total           
 time   seconds   seconds    calls   s/call   s/call  name    
 20.88      1.31     1.31 393771504     0.00     0.00  std::_Rb_tree<sado::id, sado::id, std::_Identity<sado::id>, std::less<sado::id>, std::allocator<sado::id> >::find(sado::id const&) const
 20.64      2.60     1.29 3015716539     0.00     0.00  sado::operator<(sado::id, sado::id)
 14.40      3.50     0.90                             sado::operator!=(sado::id, sado::id)
 12.64      4.29     0.79   226170     0.00     0.00  std::vector<sado::individual, std::allocator<sado::individual> >::operator=(std::vector<sado::individual, std::allocator<sado::individual> > const&)
  6.08      4.67     0.38 234214079     0.00     0.00  sado::gausser_impl_lut::operator()(double) const