ObserverMode::NewBest sometimes logs everything

[Glitchy-Tozier]

Originated in #150.

I assume this is likely due to differences in cost, which are beyond the digits that are printed to the screen. If your changes in the modify function are scaled with your small temperature, your movements will be small and therefore also the differences in cost are likely to be very small.

They are not.

In case it helps you in any way, here's the modify()-function (the important thing to note is that 1 in switch_n_keys`. It always is the same):

/// This function is called by the annealing function
fn modify(&self, param: &Self::Param, _temp: f64) -> Result<Self::Param, Error> {
    // in the following, the 1 will be replaced by something `temp`-depending
    Ok(self.layout_generator.switch_n_keys(&param, 1))
}

Here's a new weird thing, that might help us here and/or in #150:

I have modified the apply()-function so that the cost also gets printed:

fn apply(&self, param: &Self::Param) -> Result<Self::Output, Error> {
    let layout = self.layout_generator.generate_layout(&param);
    let evaluation_result = self.evaluator.evaluate_layout(&layout);
    println!(
        "\nprintln from inside `apply()`: Cost: {}",
        evaluation_result.total_cost()
    );
    Ok(evaluation_result.total_cost())
}

This led to some interesting results:

If everything works fine (except for #150, of course), this now is the output:

Nov 28 21:17:18.569 INFO Simulated Annealing, max_iters: 10000, initial_temperature: 0.01, stall_iter_accepted_limit: 1000, stall_iter_best_limit: 18446744073709551615, reanneal_fixed: 18446744073709551615, reanneal_accepted: 18446744073709551615, reanneal_best: 18446744073709551615

println from inside `apply()`: Cost: 302.38946704551745
Nov 28 21:17:18.730 INFO iter: 0, cost: 302.38946704551745, best_cost: 302.38946704551745, cost_func_count: 1, grad_func_count: 0, jacobian_func_count: 0, hessian_func_count: 0, modify_func_count: 1, t: 0.014426950408889635, new_be: true, acc: true, st_i_be: 0, st_i_ac: 0, ra_i_fi: 1, ra_i_be: 0, ra_i_ac: 0, ra_fi: false, ra_be: false, ra_ac: false, time: 0.16084857200000002

println from inside `apply()`: Cost: 354.9768532415309

println from inside `apply()`: Cost: 410.09772736186335

println from inside `apply()`: Cost: 367.4044741850139

println from inside `apply()`: Cost: 410.09772736186335

println from inside `apply()`: Cost: 350.38469036232476

Everything's fine. However, when the bug comes through, the cost I print is different to the cost: xxx.xxxxxx!

Here's what that looks like (It's from the same run as the log above, 2 seconds later):

println from inside `apply()`: Cost: 521.3696739653349

println from inside `apply()`: Cost: 521.3696739653349

println from inside `apply()`: Cost: 313.8450673510879

println from inside `apply()`: Cost: 295.33550136191883
Nov 28 21:17:26.889 INFO iter: 53, cost: 295.33550136191883, best_cost: 295.33550136191883, cost_func_count: 54, grad_func_count: 0, jacobian_func_count: 0, hessian_func_count: 0, modify_func_count: 54, t: 0.0024954251462921185, new_be: true, acc: true, st_i_be: 0, st_i_ac: 0, ra_i_fi: 54, ra_i_be: 0, ra_i_ac: 0, ra_fi: false, ra_be: false, ra_ac: false, time: 0.152392312

println from inside `apply()`: Cost: 339.67181210599335
Nov 28 21:17:27.042 INFO iter: 54, cost: 295.33550136191883, best_cost: 295.33550136191883, cost_func_count: 55, grad_func_count: 0, jacobian_func_count: 0, hessian_func_count: 0, modify_func_count: 55, t: 0.0024842549839846914, new_be: false, acc: false, st_i_be: 1, st_i_ac: 1, ra_i_fi: 55, ra_i_be: 1, ra_i_ac: 1, ra_fi: false, ra_be: false, ra_ac: false, time: 0.152383283

println from inside `apply()`: Cost: 299.38582556906636
Nov 28 21:17:27.193 INFO iter: 55, cost: 295.33550136191883, best_cost: 295.33550136191883, cost_func_count: 56, grad_func_count: 0, jacobian_func_count: 0, hessian_func_count: 0, modify_func_count: 56, t: 0.002473379469500514, new_be: false, acc: false, st_i_be: 2, st_i_ac: 2, ra_i_fi: 56, ra_i_be: 2, ra_i_ac: 2, ra_fi: false, ra_be: false, ra_ac: false, time: 0.15151519500000002

println from inside `apply()`: Cost: 413.5866054481487
Nov 28 21:17:27.348 INFO iter: 56, cost: 295.33550136191883, best_cost: 295.33550136191883, cost_func_count: 57, grad_func_count: 0, jacobian_func_count: 0, hessian_func_count: 0, modify_func_count: 57, t: 0.0024627854581449446, new_be: false, acc: false, st_i_be: 3, st_i_ac: 3, ra_i_fi: 57, ra_i_be: 3, ra_i_ac: 3, ra_fi: false, ra_be: false, ra_ac: false, time: 0.154809378

println from inside `apply()`: Cost: 321.9215115455845
Nov 28 21:17:27.521 INFO iter: 57, cost: 295.33550136191883, best_cost: 295.33550136191883, cost_func_count: 58, grad_func_count: 0, jacobian_func_count: 0, hessian_func_count: 0, modify_func_count: 58, t: 0.002452460618098304, new_be: false, acc: false, st_i_be: 4, st_i_ac: 4, ra_i_fi: 58, ra_i_be: 4, ra_i_ac: 4, ra_fi: false, ra_be: false, ra_ac: false, time: 0.17310577300000002

println from inside `apply()`: Cost: 466.6913064856249
Nov 28 21:17:27.672 INFO iter: 58, cost: 295.33550136191883, best_cost: 295.33550136191883, cost_func_count: 59, grad_func_count: 0, jacobian_func_count: 0, hessian_func_count: 0, modify_func_count: 59, t: 0.002442393366759723, new_be: false, acc: false, st_i_be: 5, st_i_ac: 5, ra_i_fi: 59, ra_i_be: 5, ra_i_ac: 5, ra_fi: false, ra_be: false, ra_ac: false, time: 0.150597045

[stefan-k]

Those are two different things.

I agree that too much is logged for some reason. I will have a look at this.

However, the "new weird thing" is expected and basically the way SA works. For instance: A new parameter vector is created using modify. Evaluation with apply leads to a large cost function value which, with a certain percentage, may lead to rejection of the parameter vector. If it is rejected, then the previous parameter vector and hence the lower cost function value are passed to the next iteration. That this is the case here is indicated in the logs with acc: false (which means that the new parameter vector was not accepted). This is why what you print in apply does not match the logs.

[Glitchy-Tozier]

For instance: A new parameter vector is created using modify. Evaluation with apply leads to a large cost function value which, with a certain percentage, may lead to rejection of the parameter vector. If it is rejected, then the previous parameter vector and hence the lower cost function value are passed to the next iteration. That this is the case here is indicated in the logs with acc: false (which means that the new parameter vector was not accepted).

Interesting, I may have misinterpreted the log! I always thought the output/result of one iteration was printed. I thought it showed the cost of the last mutation, etc.
However, If I understand correctly, it is actually the input to the next iteration which gets logged. Which, of course, is the parameter-vector before the rejected one.

[dariogoetz]

Could this be due to the Executor comparing the current cost with the best cost using <= and not <?
In executor.rs:

        // check if parameters are the best so far
        if self.state.get_cost() <= self.state.get_best_cost() {
            let param = self.state.get_param();
            let cost = self.state.get_cost();
            self.state.best_param(param).best_cost(cost);
            self.state.new_best();
        }

[stefan-k]

Thanks for digging into this, I haven't had time yet. This seems very much to be the problem. Even if it isn't the root cause, it should be < instead of <=. I provided the fix in #152 and I will merge it as soon as the CI passes.

[stefan-k]

Fixed in #152. Feel free to reopen if there is more to discuss.