Add setTracefile() method for structured optimization progress loggingAdd settracefile api

[MySweetEden]

Summary

Adds setTracefile() method for structured, machine-readable optimization progress logging.

Closes #1147

Motivation

As discussed in #1147, structured progress logging is useful for:

• Visualization of optimization progress
• Fair comparison of solver runs
• Analysis of primal/dual bound evolution

This provides a simpler alternative to implementing custom event handlers.

Design Decisions

• JSONL format: Allows streaming writes and partial reads even if optimization crashes
• Separate from setLogfile(): Human-readable log and machine-readable trace serve different purposes
• Append mode by default: Multiple optimize() calls can accumulate in one file
• Automatic close: Trace file is managed internally, no explicit close needed
• Field names match SCIP log: primalbound, dualbound, time, nodes for consistency

Changes

• Added setTracefile(path, mode="a") method to Model
• Internal _write_trace_event() for centralized trace writing
• Event handler for BESTSOLFOUND events

Events Recorded

• solution_update: when a new best solution is found
• solve_finish: when optimization terminates

Fields

type, time, primalbound, dualbound, gap, nodes, nsol

Usage

model.setTracefile("trace.jsonl")
model.optimize()

trace.jsonl contains JSONL records

Future Work

• Recipe/tutorial documentation will be added in a follow-up PR if this implementation is accepted

Open Questions

• Should a solve_start event be added to distinguish multiple optimize() calls in append mode?
• Output format: JSONL is chosen for streaming/crash-safety, but CSV/TSV could be discussed

[Joao-Dionisio]

Hey @MySweetEden , thank you for the contribution! However, can you please make it as a recipe, rather than a part of scip.pxi? We reserve the latter for things that are a part of core-SCIP, and we separate the helpers. So, the flow would be something like

from pyscipopt import Model
from pyscipopt.recipes.traceback import attach_traceback_eventhdlr

m = Model()
attach_traceback_eventhdlr(m)

A bit like the primal_dual_evolution recipe.

How do you feel about this approach? Everything could be implemented in Python, as well.

[MySweetEden]

Thank you for the feedback! I tried implementing it as a recipe, similar to primal_dual_evolution.

Summary

During implementation, I discovered a constraint: the final optimization values cannot be reliably recorded with the recipe approach.

Constraint Found

• No event fires at the moment of optimization completion
• eventexitsol / eventexit only fire when freeTransform() is called
• This means final values (primalbound, dualbound, gap) at solve completion are not captured

Impact on Existing Code

The same constraint affects primal_dual_evolution:

!pip install pyscipopt --quiet
from pyscipopt import Model
from pyscipopt.recipes.primal_dual_evolution import attach_primal_dual_evolution_eventhdlr

m = Model()
m.hideOutput()

x = m.addVar('x', vtype='I', lb=0, ub=10)
y = m.addVar('y', vtype='I', lb=0, ub=10)
m.addCons(x + y <= 15)
m.setObjective(x + 2*y, 'maximize')

attach_primal_dual_evolution_eventhdlr(m)
m.optimize()

print('primal_log:', m.data['primal_log'])
print('dual_log:', m.data['dual_log'])
print(f'Final: primalbound={m.getPrimalbound()}, dualbound={m.getDualbound()}, gap={m.getGap()}')

primal_log: [[0.00025299999999999997, -1e+20], [0.000439, 0.0]]
dual_log: [[0.000258, 1e+20]]
Final: primalbound=25.0, dualbound=25.0, gap=0.0

The final primalbound is 25.0, but the last recorded value in primal_log is 0.0.

Possible Directions

A. Accept the limitation in recipes

• Approach: Document that users need to call freeTransform() after optimize() for complete logs
• Pros: Simple, no changes to core code
• Cons:
  • Users may miss final values without reading docs
  • freeTransform() has side effects (loses warm start capability, impacts performance on repeated optimization)

B. Add a hook in PySCIPOpt's optimize()

• Approach: Add callback mechanism after SCIPsolve() in scip.pxi
• Pros: Solves the problem completely
• Cons: Conflicts with the recipe separation approach

C. Propose a new event type to SCIP (Not recommended)

• SCIP may intentionally avoid a unified "solve finished" event due to multiple termination conditions (optimal, time limit, gap limit, etc.)
• Likely difficult to get accepted upstream

Open Questions

• What direction do you think is best, or do you have other ideas?
• primal_dual_evolution has the same limitation — should it be fixed as well?

[Joao-Dionisio]

Ah, this is another problem, but still good that you caught it! Apparently, DUALBOUNDIMPROVED and BESTSOLFOUND events are not triggered in presolving (@DominikKamp should they not be, at least in SCIP's native presolving?)
If you disable presolving, you'll see:

primal_log: [[0.000242, -1e+20], [0.000412, 0.0], [0.000477, 0.0], [0.000531, 25.0]]
dual_log: [[0.000244, 1e+20], [0.000412, 30.0], [0.00047799999999999996, 30.0], [0.000532, 25.0]]
Final: primalbound=25.0, dualbound=25.0, gap=0.0

[DominikKamp]

Every improvements should trigger an event, so this is a bug somewhere.

[Joao-Dionisio]

@DominikKamp can reproduce in SCIP with
test_presol_events.c.

/**
 * Test to check if BESTSOLFOUND events are triggered during presolving.
 *
 * Bug report: https://github.com/scipopt/PySCIPOpt/pull/1158
 *
 * Expected: Events should be triggered when solutions are found during presolving.
 * Observed: Events are NOT triggered during presolving.
 */

#include <stdio.h>
#include <string.h>
#include <scip/scip.h>
#include <scip/scipdefplugins.h>

/* Event handler data */
struct SCIP_EventhdlrData {
    int bestSolCount;
};

/* Callback when event is executed */
static SCIP_DECL_EVENTEXEC(eventExecTest)
{
    SCIP_EVENTHDLRDATA* eventhdlrdata;
    SCIP_EVENTTYPE eventtype;

    eventhdlrdata = SCIPeventhdlrGetData(eventhdlr);
    eventtype = SCIPeventGetType(event);

    if (eventtype & SCIP_EVENTTYPE_BESTSOLFOUND) {
        eventhdlrdata->bestSolCount++;
        printf("EVENT: BESTSOLFOUND #%d - primalbound=%.2f, time=%.4f\n",
               eventhdlrdata->bestSolCount,
               SCIPgetPrimalbound(scip),
               SCIPgetSolvingTime(scip));
    }

    return SCIP_OKAY;
}

/* Callback when event handler is initialized for solving */
static SCIP_DECL_EVENTINITSOL(eventInitsolTest)
{
    printf("EVENT HANDLER: eventinitsol called\n");
    SCIP_CALL(SCIPcatchEvent(scip, SCIP_EVENTTYPE_BESTSOLFOUND, eventhdlr, NULL, NULL));
    return SCIP_OKAY;
}

/* Callback when event handler exits solving */
static SCIP_DECL_EVENTEXITSOL(eventExitsolTest)
{
    printf("EVENT HANDLER: eventexitsol called\n");
    SCIP_CALL(SCIPdropEvent(scip, SCIP_EVENTTYPE_BESTSOLFOUND, eventhdlr, NULL, -1));
    return SCIP_OKAY;
}

/* Include the event handler */
static SCIP_RETCODE includeEventHandler(SCIP* scip, SCIP_EVENTHDLRDATA* eventhdlrdata)
{
    SCIP_EVENTHDLR* eventhdlr = NULL;

    SCIP_CALL(SCIPincludeEventhdlrBasic(scip, &eventhdlr, "testevent", "test event handler",
                                         eventExecTest, eventhdlrdata));

    SCIP_CALL(SCIPsetEventhdlrInitsol(scip, eventhdlr, eventInitsolTest));
    SCIP_CALL(SCIPsetEventhdlrExitsol(scip, eventhdlr, eventExitsolTest));

    return SCIP_OKAY;
}

/* Create a simple MIP model:
 * max x + 2y
 * s.t. x + y <= 15
 *      0 <= x <= 10 (integer)
 *      0 <= y <= 10 (integer)
 *
 * Optimal: x=5, y=10, obj=25
 */
static SCIP_RETCODE createModel(SCIP* scip)
{
    SCIP_VAR* x;
    SCIP_VAR* y;
    SCIP_CONS* cons;

    SCIP_CALL(SCIPcreateProbBasic(scip, "test_presol_events"));
    SCIP_CALL(SCIPsetObjsense(scip, SCIP_OBJSENSE_MAXIMIZE));

    /* Create variables */
    SCIP_CALL(SCIPcreateVarBasic(scip, &x, "x", 0.0, 10.0, 1.0, SCIP_VARTYPE_INTEGER));
    SCIP_CALL(SCIPcreateVarBasic(scip, &y, "y", 0.0, 10.0, 2.0, SCIP_VARTYPE_INTEGER));

    SCIP_CALL(SCIPaddVar(scip, x));
    SCIP_CALL(SCIPaddVar(scip, y));

    /* Create constraint: x + y <= 15 */
    SCIP_CALL(SCIPcreateConsBasicLinear(scip, &cons, "c1", 0, NULL, NULL, -SCIPinfinity(scip), 15.0));
    SCIP_CALL(SCIPaddCoefLinear(scip, cons, x, 1.0));
    SCIP_CALL(SCIPaddCoefLinear(scip, cons, y, 1.0));
    SCIP_CALL(SCIPaddCons(scip, cons));

    /* Release */
    SCIP_CALL(SCIPreleaseCons(scip, &cons));
    SCIP_CALL(SCIPreleaseVar(scip, &y));
    SCIP_CALL(SCIPreleaseVar(scip, &x));

    return SCIP_OKAY;
}

int main(int argc, char** argv)
{
    SCIP* scip = NULL;
    SCIP_EVENTHDLRDATA eventhdlrdata = {0};
    int disablePresol = 0;

    if (argc > 1 && strcmp(argv[1], "--no-presol") == 0) {
        disablePresol = 1;
    }

    printf("=== Testing SCIP events during presolving ===\n");
    printf("Presolving: %s\n\n", disablePresol ? "DISABLED" : "ENABLED");

    /* Initialize SCIP */
    SCIP_CALL(SCIPcreate(&scip));
    SCIP_CALL(SCIPincludeDefaultPlugins(scip));

    /* Include our event handler */
    SCIP_CALL(includeEventHandler(scip, &eventhdlrdata));

    /* Create model */
    SCIP_CALL(createModel(scip));

    /* Optionally disable presolving */
    if (disablePresol) {
        SCIP_CALL(SCIPsetPresolving(scip, SCIP_PARAMSETTING_OFF, TRUE));
    }

    /* Solve */
    printf("--- Starting solve ---\n");
    SCIP_CALL(SCIPsolve(scip));
    printf("--- Solve finished ---\n\n");

    /* Print results */
    printf("=== Results ===\n");
    printf("Status: %d\n", SCIPgetStatus(scip));
    printf("Final primalbound: %.2f\n", SCIPgetPrimalbound(scip));
    printf("Final dualbound: %.2f\n", SCIPgetDualbound(scip));
    printf("Gap: %.2f%%\n", 100.0 * SCIPgetGap(scip));
    printf("\n");
    printf("BESTSOLFOUND events caught: %d\n", eventhdlrdata.bestSolCount);

    /* Check if final solution was captured */
    if (SCIPgetPrimalbound(scip) == 25.0 && eventhdlrdata.bestSolCount == 0) {
        printf("\n*** BUG: Optimal solution found but no BESTSOLFOUND event was triggered! ***\n");
    }

    /* Free SCIP */
    SCIP_CALL(SCIPfree(&scip));

    return 0;
}

(pyscipopt) ➜  PySCIPOpt git:(pr-1076) ✗ DYLD_LIBRARY_PATH=/usr/local/lib ./test_presol_events
=== Testing SCIP events during presolving ===
Presolving: ENABLED

--- Starting solve ---
feasible solution found by trivial heuristic after 0.0 seconds, objective value 0.000000e+00
presolving:
(round 1, fast)       0 del vars, 0 del conss, 0 add conss, 2 chg bounds, 0 chg sides, 0 chg coeffs, 0 upgd conss, 0 impls, 0 clqs, 0 implints
(round 2, fast)       1 del vars, 1 del conss, 0 add conss, 2 chg bounds, 0 chg sides, 0 chg coeffs, 0 upgd conss, 0 impls, 0 clqs, 0 implints
presolving (3 rounds: 3 fast, 1 medium, 1 exhaustive):
 2 deleted vars, 1 deleted constraints, 0 added constraints, 2 tightened bounds, 0 added holes, 0 changed sides, 0 changed coefficients
 0 implications, 0 cliques, 0 implied integral variables (0 bin, 0 int, 0 cont)
transformed 1/2 original solutions to the transformed problem space
EVENT HANDLER: eventinitsol called
presolving solved problem
Presolving Time: 0.00

SCIP Status        : problem is solved [optimal solution found]
Solving Time (sec) : 0.00
Solving Nodes      : 0
Primal Bound       : +2.50000000000000e+01 (2 solutions)
Dual Bound         : +2.50000000000000e+01
Gap                : 0.00 %
--- Solve finished ---

=== Results ===
Status: 1
Final primalbound: 25.00
Final dualbound: 25.00
Gap: 0.00%

BESTSOLFOUND events caught: 0

*** BUG: Optimal solution found but no BESTSOLFOUND event was triggered! ***
EVENT HANDLER: eventexitsol called
(pyscipopt) ➜  PySCIPOpt git:(pr-1076) ✗ DYLD_LIBRARY_PATH=/usr/local/lib ./test_presol_events --no-presol
=== Testing SCIP events during presolving ===
Presolving: DISABLED

--- Starting solve ---
feasible solution found by trivial heuristic after 0.0 seconds, objective value 0.000000e+00
presolving:
   (0.0s) symmetry computation started: requiring (bin +, int +, cont +), (fixed: bin -, int -, cont -)
   (0.0s) no symmetry present (symcode time: 0.00)
presolving (0 rounds: 0 fast, 0 medium, 0 exhaustive):
 0 deleted vars, 0 deleted constraints, 0 added constraints, 0 tightened bounds, 0 added holes, 0 changed sides, 0 changed coefficients
 0 implications, 0 cliques, 0 implied integral variables (0 bin, 0 int, 0 cont)
presolved problem has 2 variables (0 bin, 2 int, 0 cont) and 1 constraints
      1 constraints of type <linear>
transformed objective value is always integral (scale: 1)
Presolving Time: 0.00
transformed 1/1 original solutions to the transformed problem space
EVENT HANDLER: eventinitsol called

EVENT: BESTSOLFOUND #1 - primalbound=0.00, time=0.0011
 time | node  | left  |LP iter|LP it/n|mem/heur|mdpt |vars |cons |rows |cuts |sepa|confs|strbr|  dualbound   | primalbound  |  gap   | compl. 
i 0.0s|     1 |     0 |     0 |     - |  oneopt|   0 |   2 |   1 |   1 |   0 |  0 |   0 |   0 | 3.000000e+01 | 2.500000e+01 |  20.00%| unknown
  0.0s|     1 |     0 |     0 |     - |   835k |   0 |   2 |   1 |   1 |   0 |  0 |   0 |   0 | 2.500000e+01 | 2.500000e+01 |   0.00%| unknown

SCIP Status        : problem is solved [optimal solution found]
Solving Time (sec) : 0.00
Solving Nodes      : 1
Primal Bound       : +2.50000000000000e+01 (2 solutions)
Dual Bound         : +2.50000000000000e+01
Gap                : 0.00 %
--- Solve finished ---

=== Results ===
Status: 1
Final primalbound: 25.00
Final dualbound: 25.00
Gap: 0.00%

BESTSOLFOUND events caught: 1
EVENT HANDLER: eventexitsol called

[Joao-Dionisio]

So @MySweetEden , the conclusion is that there is no problem with doing it as a recipe, it's the way to go :)

[MySweetEden]

Thank you both @Joao-Dionisio and @DominikKamp for the detailed feedback and for taking the time to review and improve the code!

I agree with the recipe approach. To keep the PR clean:

1. Reset to commit 98b7e01 (Fixes potentially outdated value of getVal Fixes potentially outdated value of getVal #993) — this will remove all my previous commits modifying core files (scip.pxi, scip.pxd, scip.pyi, etc.)
2. Add the recipe implementation on top of that

This way, the PR will contain only the recipe file without any core file modifications.
I'll force-push to update the branch shortly.

[MySweetEden]

Hi! I've updated the PR to implement as a recipe following your suggestion.

Changes:

• Rebased onto 98b7e01 (Fixes potentially outdated value of getVal)
• Added structured_optimization_trace recipe with tests
• Used _TraceEventhdlr (private class name with underscore) to avoid stubtest errors

Note: The existing primal_dual_evolution recipe has the same stubtest issue with GapEventhdlr (currently in stubs/todo). If you'd like, I can create a follow-up PR to rename it to _GapEventhdlr and remove the todo entry, for consistency.

[Joao-Dionisio]

Thank you, @MySweetEden ! I think it's best to keep the recipe public and just update the stubs, but this is something I can do later, so we can merge now :)