Pop() sometimes causes pyo3_runtime.PanicException: overflow when adding durations

[RobinKa]

I just upgraded to egglog 0.6.0 and now I sometimes (often but not for every single call) get this PanicException when I call pop() in my tests. I don't know what the conditions are for it to fail.

               +test *failed* |     @pytest.mark.parametrize("equation", test_equations)
               +test *failed* |     def test_equalities(equation):
               +test *failed* |         ga.egraph.push()
               +test *failed* |     
               +test *failed* |         caught = None
               +test *failed* |     
               +test *failed* |         try:
               +test *failed* |             should_be_equal = True
               +test *failed* |             eq_len = len(equation)
               +test *failed* |             if eq_len == 2:
               +test *failed* |                 lhs, rhs = equation
               +test *failed* |             elif eq_len == 3:
               +test *failed* |                 lhs, rhs, should_be_equal = equation
               +test *failed* |             else:
               +test *failed* |                 raise ValueError("Invalid number of values in equation tuple")
               +test *failed* |     
               +test *failed* |             stop_cond = None
               +test *failed* |             if should_be_equal:
               +test *failed* |                 stop_cond = eq(lhs).to(rhs)
               +test *failed* |     
               +test *failed* |             ga.egraph.register(lhs, rhs)
               +test *failed* |             run_ruleset(ga, options=RunRulesetOptions(limit=100, until=stop_cond))
               +test *failed* |     
               +test *failed* |             # Check if LHS is (not) equal to RHS, don't run any additional steps
               +test *failed* |             check_passes = check_equality(
               +test *failed* |                 ga, lhs, rhs, options=CheckEqualityOptions(limit=0, equal=should_be_equal)
               +test *failed* |             )
               +test *failed* |     
               +test *failed* |             assert check_passes
               +test *failed* |     
               +test *failed* |             # Check against some basic contradictions
               +test *failed* |             ga.egraph.check_fail(eq(E.scalar_literal(0.0)).to(E.scalar_literal(1.0)))
               +test *failed* |             ga.egraph.check_fail(eq(E.scalar_literal(1.0)).to(E.scalar_literal(2.0)))
               +test *failed* |         except Exception as e:
               +test *failed* |             caught = e
               +test *failed* |     
               +test *failed* | >       ga.egraph.pop()

               +test *failed* | tests/test_rules.py:355: 
               +test *failed* | _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
               +test *failed* | /usr/local/lib/python3.8/site-packages/egglog/egraph.py:848: in pop
               +test *failed* |     self._process_commands([bindings.Pop(1)])
               +test *failed* | _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

               +test *failed* | self = EGraph(_flatted_deps=[], _mod_decls=ModuleDeclarations(_decl=Declarations(_functions={'inverse': FunctionDecl(arg_type...f(name='MathExpr', args=())}, _type_ref_to_egg_sort={JustTypeRef(name='MathExpr', args=()): 'MathExpr'})), _token=None)
               +test *failed* | commands = [Pop(1)]

               +test *failed* |     def _process_commands(self, commands: Iterable[bindings._Command]) -> None:
               +test *failed* | >       self._egraph.run_program(*commands)
               +test *failed* | E       pyo3_runtime.PanicException: overflow when adding durations

               +test *failed* | /usr/local/lib/python3.8/site-packages/egglog/egraph.py:690: PanicException
               +test *failed* | ----------------------------- Captured stderr call -----------------------------
               +test *failed* | thread '<unnamed>' panicked at 'overflow when adding durations', library/core/src/time.rs:914:31

Full test logs: https://github.com/RobinKa/egga/actions/runs/6351581741/job/17253022121?pr=1 (PR with the egglog version upgrade: RobinKa/egga#1)

On the CI run it used python-xdist to parallelize the tests but it happens when I run the tests without python-xdist too.

[RobinKa]

Here's RUST_BACKTRACE=full for one of the panics

thread '<unnamed>' panicked at 'overflow when adding durations', library/core/src/time.rs:914:31
stack backtrace:
   0:     0x7f22ff51bb51 - std::backtrace_rs::backtrace::libunwind::trace::h782cc21a5acaf6cb
                               at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/std/src/../../backtrace/src/backtrace/libunwind.rs:93:5
   1:     0x7f22ff51bb51 - std::backtrace_rs::backtrace::trace_unsynchronized::hc579eb24ab204515
                               at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/std/src/../../backtrace/src/backtrace/mod.rs:66:5
   2:     0x7f22ff51bb51 - std::sys_common::backtrace::_print_fmt::h7223525cfdbacda2
                               at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/std/src/sys_common/backtrace.rs:65:5
   3:     0x7f22ff51bb51 - <std::sys_common::backtrace::_print::DisplayBacktrace as core::fmt::Display>::fmt::hbd7d55b7108d2ab8
                               at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/std/src/sys_common/backtrace.rs:44:22
   4:     0x7f22ff53e1ef - core::fmt::rt::Argument::fmt::hb4f4a02b9bd9dd49
                               at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/core/src/fmt/rt.rs:138:9
   5:     0x7f22ff53e1ef - core::fmt::write::h6d54cd7c9e155ec5
                               at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/core/src/fmt/mod.rs:1094:21
   6:     0x7f22ff519ba1 - std::io::Write::write_fmt::h6a453a71c692f63b
                               at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/std/src/io/mod.rs:1713:15
   7:     0x7f22ff51b965 - std::sys_common::backtrace::_print::h1cbaa8b42678f928
                               at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/std/src/sys_common/backtrace.rs:47:5
   8:     0x7f22ff51b965 - std::sys_common::backtrace::print::h4ddf81241a51b337
                               at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/std/src/sys_common/backtrace.rs:34:9
   9:     0x7f22ff51caf7 - std::panicking::default_hook::{{closure}}::hff91f1f484ade5cd
  10:     0x7f22ff51c8e4 - std::panicking::default_hook::h21f14afd59f7aef9
                               at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/std/src/panicking.rs:288:9
  11:     0x7f22ff51cfac - std::panicking::rust_panic_with_hook::h45f66047b14c555c
                               at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/std/src/panicking.rs:705:13
  12:     0x7f22ff51cea7 - std::panicking::begin_panic_handler::{{closure}}::h49d1a88ef0908eb4
                               at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/std/src/panicking.rs:597:13
  13:     0x7f22ff51bf86 - std::sys_common::backtrace::__rust_end_short_backtrace::hccebf9e57f8cc425
                               at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/std/src/sys_common/backtrace.rs:151:18
  14:     0x7f22ff51cbf2 - rust_begin_unwind
                               at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/std/src/panicking.rs:593:5
  15:     0x7f22ff2905f3 - core::panicking::panic_fmt::h54ec9d0e3180a83d
                               at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/core/src/panicking.rs:67:14
  16:     0x7f22ff2905b3 - core::panicking::panic_display::h0e30bc17bca455bf
                               at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/core/src/panicking.rs:150:5
  17:     0x7f22ff2905b3 - core::panicking::panic_str::h3f2c4f87e890c4a7
                               at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/core/src/panicking.rs:134:5
  18:     0x7f22ff2905b3 - core::option::expect_failed::h03fbde71aa9ac6b4
                               at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/core/src/option.rs:1932:5
  19:     0x7f22ff5419e0 - core::option::Option<T>::expect::h5f89a0b060b381f7
                               at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/core/src/option.rs:898:21
  20:     0x7f22ff5419e0 - <core::time::Duration as core::ops::arith::Add>::add::h33fae361e1e7504f
                               at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/core/src/time.rs:914:31
  21:     0x7f22ff5419e0 - <core::time::Duration as core::ops::arith::AddAssign>::add_assign::hf0b4e48d4fab5e6b
                               at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/core/src/time.rs:921:17
  22:     0x7f22ff399742 - egglog::RunReport::union_times::h38ef9263e9e7347a
  23:     0x7f22ff399812 - egglog::RunReport::union::h651a29516887af3d
  24:     0x7f22ff39ab81 - egglog::EGraph::pop::hec17bdef39ad741e
  25:     0x7f22ff3a372a - egglog::EGraph::run_command::h1a909c7d32e16c7c
  26:     0x7f22ff3a70b6 - egglog::EGraph::run_program::h3cdc3518c784f89b
  27:     0x7f22ff339625 - egglog_python::egraph::_::<impl egglog_python::egraph::EGraph>::__pymethod_run_program__::h80b6ddfe2baaf789
  28:     0x7f22ff333de8 - pyo3::impl_::trampoline::trampoline_inner::h9e8542ad2c25f3f4
  29:     0x7f22ff338230 - egglog_python::egraph::_::<impl pyo3::impl_::pyclass::PyMethods<egglog_python::egraph::EGraph> for pyo3::impl_::pyclass::PyClassImplCollector<egglog_python::egraph::EGraph>>::py_methods::ITEMS::trampoline::hcae2aa3360e367f2
  30:           0x53c744 - <unknown>
  31:           0x62feea - PyObject_Call
  32:           0x5b2f48 - _PyEval_EvalFrameDefault
  33:           0x630210 - _PyFunction_Vectorcall
  34:           0x5ad5a7 - _PyEval_EvalFrameDefault
  35:           0x630210 - _PyFunction_Vectorcall
  36:           0x5ad5a7 - _PyEval_EvalFrameDefault
  37:           0x630210 - _PyFunction_Vectorcall
  38:           0x5ae257 - _PyEval_EvalFrameDefault
  39:           0x630210 - _PyFunction_Vectorcall
  40:           0x62fdec - PyObject_Call
  41:           0x5afaa5 - _PyEval_EvalFrameDefault
  42:           0x630210 - _PyFunction_Vectorcall
  43:           0x62feea - PyObject_Call
  44:           0x5afaa5 - _PyEval_EvalFrameDefault
  45:           0x630210 - _PyFunction_Vectorcall
  46:           0x5b1b93 - _PyEval_EvalFrameDefault
  47:           0x54aa3a - <unknown>
  48:           0x5b1b93 - _PyEval_EvalFrameDefault
  49:           0x630210 - _PyFunction_Vectorcall
  50:           0x632d78 - _PyObject_FastCallDictTstate
  51:           0x632e4a - _PyObject_Call_Prepend
  52:           0x6f1d17 - <unknown>
  53:           0x63127c - _PyObject_MakeTpCall
  54:           0x5b2ad3 - _PyEval_EvalFrameDefault
  55:           0x630210 - _PyFunction_Vectorcall
  56:           0x5ad5a7 - _PyEval_EvalFrameDefault
  57:           0x630210 - _PyFunction_Vectorcall
  58:           0x62feea - PyObject_Call
  59:           0x5afaa5 - _PyEval_EvalFrameDefault
  60:           0x630210 - _PyFunction_Vectorcall
  61:           0x5b1b93 - _PyEval_EvalFrameDefault
  62:           0x54aa3a - <unknown>
  63:           0x5b1b93 - _PyEval_EvalFrameDefault
  64:           0x630210 - _PyFunction_Vectorcall
  65:           0x632d78 - _PyObject_FastCallDictTstate
  66:           0x632e4a - _PyObject_Call_Prepend
  67:           0x6f1d17 - <unknown>
  68:           0x62ff2b - PyObject_Call
  69:           0x5afaa5 - _PyEval_EvalFrameDefault
  70:           0x630210 - _PyFunction_Vectorcall
  71:           0x5ad19b - _PyEval_EvalFrameDefault
  72:           0x54aa3a - <unknown>
  73:           0x5ae257 - _PyEval_EvalFrameDefault
  74:           0x630210 - _PyFunction_Vectorcall
  75:           0x62feea - PyObject_Call
  76:           0x5afaa5 - _PyEval_EvalFrameDefault
  77:           0x630210 - _PyFunction_Vectorcall
  78:           0x5ad19b - _PyEval_EvalFrameDefault
  79:           0x630210 - _PyFunction_Vectorcall
  80:           0x5ae257 - _PyEval_EvalFrameDefault
  81:           0x630210 - _PyFunction_Vectorcall
  82:           0x62feea - PyObject_Call
  83:           0x5afaa5 - _PyEval_EvalFrameDefault
  84:           0x630210 - _PyFunction_Vectorcall
  85:           0x5b1b93 - _PyEval_EvalFrameDefault
  86:           0x54aa3a - <unknown>
  87:           0x5b1b93 - _PyEval_EvalFrameDefault
  88:           0x630210 - _PyFunction_Vectorcall
  89:           0x632d78 - _PyObject_FastCallDictTstate
  90:           0x632e4a - _PyObject_Call_Prepend
  91:           0x6f1d17 - <unknown>
  92:           0x63127c - _PyObject_MakeTpCall
  93:           0x5b2ad3 - _PyEval_EvalFrameDefault
  94:           0x630210 - _PyFunction_Vectorcall
  95:           0x62feea - PyObject_Call
  96:           0x5afaa5 - _PyEval_EvalFrameDefault
  97:           0x630210 - _PyFunction_Vectorcall
  98:           0x5b1b93 - _PyEval_EvalFrameDefault
  99:           0x54aa3a - <unknown>
 100:           0x5b1b93 - _PyEval_EvalFrameDefault
 101:           0x630210 - _PyFunction_Vectorcall
 102:           0x632d78 - _PyObject_FastCallDictTstate
 103:           0x632e4a - _PyObject_Call_Prepend
 104:           0x6f1d17 - <unknown>
 105:           0x63127c - _PyObject_MakeTpCall
 106:           0x5b2ad3 - _PyEval_EvalFrameDefault
 107:           0x630210 - _PyFunction_Vectorcall
 108:           0x5ad19b - _PyEval_EvalFrameDefault
 109:           0x630210 - _PyFunction_Vectorcall
 110:           0x5ad19b - _PyEval_EvalFrameDefault
 111:           0x630210 - _PyFunction_Vectorcall
 112:           0x62feea - PyObject_Call
 113:           0x5afaa5 - _PyEval_EvalFrameDefault
 114:           0x630210 - _PyFunction_Vectorcall
 115:           0x5b1b93 - _PyEval_EvalFrameDefault
 116:           0x54aa3a - <unknown>
 117:           0x5b1b93 - _PyEval_EvalFrameDefault
 118:           0x630210 - _PyFunction_Vectorcall
 119:           0x632d78 - _PyObject_FastCallDictTstate
 120:           0x632e4a - _PyObject_Call_Prepend
 121:           0x6f1d17 - <unknown>
 122:           0x63127c - _PyObject_MakeTpCall
 123:           0x5b2ad3 - _PyEval_EvalFrameDefault
 124:           0x630210 - _PyFunction_Vectorcall
 125:           0x5ad19b - _PyEval_EvalFrameDefault
 126:           0x630210 - _PyFunction_Vectorcall
 127:           0x5ad19b - _PyEval_EvalFrameDefault
 128:           0x5ac171 - <unknown>
 129:           0x6e074f - PyEval_EvalCode
 130:           0x6c4b07 - <unknown>
 131:           0x6c4b90 - <unknown>
 132:           0x6c4d06 - <unknown>
 133:           0x6c9b14 - _PyRun_SimpleFileObject
 134:           0x6c9be7 - _PyRun_AnyFileObject
 135:           0x70d24d - Py_RunMain
 136:           0x70d42d - Py_BytesMain
 137:     0x7f2300d79083 - __libc_start_main
                               at /build/glibc-SzIz7B/glibc-2.31/csu/../csu/libc-start.c:308:16
 138:           0x63742e - _start
 139:                0x0 - <unknown>

[saulshanabrook]

Thanks for opening and providing the traceback. It looks like this error is coming from upstream, not due to the Python bindings. I opened egraphs-good/egglog#240 to track it, feel free to add any more details or ways to reproduce there.

[saulshanabrook]

@RobinKa I have published a new version (0.7.0) with the upstream egglog fix included (egraphs-good/egglog#241)

[RobinKa]

Thank you! 🎉