Another look at Ruleby and Ms Manners

I ran Miss Manners with 4, 8, 16 and 32 guests through ruby-prof earlier today. I also merged the output line-wise for each of the runs and added two metrics I thought might help track down the weird behaviour of Miss Manners.

Ruby-prof tracks the number of calls (as calls) and I added the number of calls / the number of calls in the "previous" (rel/prv) run and in the "first" (rel/frst) run. Where the "previous" means 16 for 32, 8 for 16 and 4 for 8 guests. 4 is also the "first", it's factor is always 1.

Here's a selection of the output[1], woolfel style:

|Guests  time (sec)
|    4:   0.942000150680542
|    8:   5.41799998283386
|   16:   102.727999925613
|   32:   3797.01999998093
|
|Guests rel/prv rel/frst    calls  name
|    4:  01.00  00001.00     2880  Ruleby::Core::Node#resolve
|    8:  15.85  00015.85    45650  Ruleby::Core::Node#resolve
|   16:  35.76  00566.79  1632363  Ruleby::Core::Node#resolve
|   32:  42.99  24365.68 70173154  Ruleby::Core::Node#resolve
|
|    4:  01.00  00001.00    16371  Ruleby::Core::MatchResult#==
|    8:  17.15  00017.15   280747  Ruleby::Core::MatchResult#==
|   16:  29.28  00502.21  8221607  Ruleby::Core::MatchResult#==
|   32:  46.92  23563.22 385753525  Ruleby::Core::MatchResult#==
|
|    4:  01.00  00001.00      324  Ruleby::Core::Activation#==
|    8:  23.05  00023.05     7468  Ruleby::Core::Activation#==
|   16:  43.85  01010.79   327496  Ruleby::Core::Activation#==
|   32:  35.75  36139.05 11709052  Ruleby::Core::Activation#==
|
|    4:  01.00  00001.00       44  Ruleby::Core::Activation#<=>
|    8:  11.86  00011.86      522  Ruleby::Core::Activation#<=>
|   16:  17.04  00202.18     8896  Ruleby::Core::Activation#<=>
|   32:  12.36  02499.43   109975  Ruleby::Core::Activation#<=>
|
|    4:  01.00  00001.00      162  Ruleby::Core::Action#==
|    8:  23.05  00023.05     3734  Ruleby::Core::Action#==
|   16:  43.85  01010.79   163748  Ruleby::Core::Action#==
|   32:  35.75  36139.05  5854526  Ruleby::Core::Action#==

There are a few other places worth mentioning as well but they're all effects rather than causes (Hash#==, Array#empty? etc).

I haven't studied these "spots" of the source code in detail yet. I still think that fixing the engine.match method is the way to go, it seems to be doing a lot of extra work. Peter left a comment saying it might be because of how matching is performed in the Rete network. I agree with him that it looks suspicious but I really can't tell. At least not yet, I'll look at it during the weekend though.

[1] I wrote a python script to calculate the extra metrics and to merge the four output files. If you want it, send me an e-mail.

[2007-05-13] Update: I'm starting to believe that Peter's right about the matching. From what I've seen and read in the comments I'd say that Ruleby is performing a lot more work during matching than they need to. I get the feeling that they're not storing as many partial matches as they can and therefore they need to recalculate a lot of things (compare_to_wm and check_references) when a fact filters through the network.