Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

panic when transactional workload is mixed with concurrent DDL: cannot fail to peek: CollectionMissing or Dataflow requested as_of not >= since #19743

Closed
philip-stoev opened this issue Jun 6, 2023 · 25 comments · Fixed by #20267
Assignees
Labels
A-ADAPTER Topics related to the ADAPTER layer C-bug Category: something is broken

Comments

@philip-stoev
Copy link
Contributor

What version of Materialize are you using?

v0.58.0-dev (e015c3e)

What is the issue?

When running a concurrent workload that mixes transactional statements, SELECTs and DDLs, the coordinator will panic either like this:

thread 'coordinator' panicked at 'cannot fail to peek: CollectionMissing(User(139))', /var/lib/buildkite-agent/builds/buildkite-buil
ders-d43b1b5-i-02d3dc3c9ce9a81d6-1/materialize/tests/src/adapter/src/util.rs:273:23
stack backtrace:
   0: rust_begin_unwind
             at ./rustc/9eb3afe9ebe9c7d2b84b71002d44f4a0edac95e0/library/std/src/panicking.rs:575:5
   1: core::panicking::panic_fmt
             at ./rustc/9eb3afe9ebe9c7d2b84b71002d44f4a0edac95e0/library/core/src/panicking.rs:64:14
   2: <core::result::Result<(), mz_compute_client::controller::error::PeekError> as mz_adapter::util::ResultExt<()>>::unwrap_or_term
inate
             at ./var/lib/buildkite-agent/builds/buildkite-builders-d43b1b5-i-02d3dc3c9ce9a81d6-1/materialize/tests/src/adapter/src/
util.rs:273:23
   3: <mz_adapter::coord::Coordinator>::implement_peek_plan::{closure#0}::{closure#0}
             at ./var/lib/buildkite-agent/builds/buildkite-builders-d43b1b5-i-02d3dc3c9ce9a81d6-1/materialize/tests/src/adapter/src/
coord/peek.rs:446:9
   4: <mz_adapter::coord::Coordinator>::implement_peek_plan::{closure#0}
             at ./var/lib/buildkite-agent/builds/buildkite-builders-d43b1b5-i-02d3dc3c9ce9a81d6-1/materialize/tests/src/adapter/src/
coord/peek.rs:296:5
   5: <mz_adapter::coord::Coordinator>::peek_stage_finish::{closure#0}::{closure#0}
             at ./var/lib/buildkite-agent/builds/buildkite-builders-d43b1b5-i-02d3dc3c9ce9a81d6-1/materialize/tests/src/adapter/src/
coord/sequencer/inner.rs:2361:13
   6: <mz_adapter::coord::Coordinator>::peek_stage_finish::{closure#0}
             at ./var/lib/buildkite-agent/builds/buildkite-builders-d43b1b5-i-02d3dc3c9ce9a81d6-1/materialize/tests/src/adapter/src/
coord/sequencer/inner.rs:2314:5
   7: <mz_adapter::coord::Coordinator>::sequence_peek_stage::{closure#0}
             at ./var/lib/buildkite-agent/builds/buildkite-builders-d43b1b5-i-02d3dc3c9ce9a81d6-1/materialize/tests/src/adapter/src/
coord/sequencer/inner.rs:2067:74
   8: <mz_adapter::coord::Coordinator>::sequence_peek::{closure#0}::{closure#0}
             at ./var/lib/buildkite-agent/builds/buildkite-builders-d43b1b5-i-02d3dc3c9ce9a81d6-1/materialize/tests/src/adapter/src/
coord/sequencer/inner.rs:2026:9
   9: <mz_adapter::coord::Coordinator>::sequence_peek::{closure#0}
             at ./var/lib/buildkite-agent/builds/buildkite-builders-d43b1b5-i-02d3dc3c9ce9a81d6-1/materialize/tests/src/adapter/src/
coord/sequencer/inner.rs:2008:5
  10: <mz_adapter::coord::Coordinator>::sequence_plan::{closure#0}::{closure#0}
             at ./var/lib/buildkite-agent/builds/buildkite-builders-d43b1b5-i-02d3dc3c9ce9a81d6-1/materialize/tests/src/adapter/src/
coord/sequencer.rs:254:70
  11: <mz_adapter::coord::Coordinator>::sequence_plan::{closure#0}
             at ./var/lib/buildkite-agent/builds/buildkite-builders-d43b1b5-i-02d3dc3c9ce9a81d6-1/materialize/tests/src/adapter/src/
coord/sequencer.rs:51:5
  12: <mz_adapter::coord::Coordinator>::handle_execute_inner::{closure#0}::{closure#0}
             at ./var/lib/buildkite-agent/builds/buildkite-builders-d43b1b5-i-02d3dc3c9ce9a81d6-1/materialize/tests/src/adapter/src/
coord/command_handler.rs:553:78
  13: <mz_adapter::coord::Coordinator>::handle_execute_inner::{closure#0}
             at ./var/lib/buildkite-agent/builds/buildkite-builders-d43b1b5-i-02d3dc3c9ce9a81d6-1/materialize/tests/src/adapter/src/
coord/command_handler.rs:353:5
  14: <mz_adapter::coord::Coordinator>::handle_execute::{closure#0}::{closure#0}
             at ./var/lib/buildkite-agent/builds/buildkite-builders-d43b1b5-i-02d3dc3c9ce9a81d6-1/materialize/tests/src/adapter/src/
coord/command_handler.rs:350:61
  15: <mz_adapter::coord::Coordinator>::handle_execute::{closure#0}
             at ./var/lib/buildkite-agent/builds/buildkite-builders-d43b1b5-i-02d3dc3c9ce9a81d6-1/materialize/tests/src/adapter/src/
coord/command_handler.rs:293:5
  16: <tracing::instrument::Instrumented<<mz_adapter::coord::Coordinator>::handle_execute::{closure#0}> as core::future::future::Fut
ure>::poll
             at ./cargo/registry/src/github.com-1ecc6299db9ec823/tracing-0.1.37/src/instrument.rs:272:9
  17: <mz_adapter::coord::Coordinator>::handle_command::{closure#0}
             at ./var/lib/buildkite-agent/builds/buildkite-builders-d43b1b5-i-02d3dc3c9ce9a81d6-1/materialize/tests/src/adapter/src/
coord/command_handler.rs:79:21
  18: <mz_adapter::coord::Coordinator>::message_command::{closure#0}::{closure#0}
             at ./var/lib/buildkite-agent/builds/buildkite-builders-d43b1b5-i-02d3dc3c9ce9a81d6-1/materialize/tests/src/adapter/src/
coord/message_handler.rs:226:33
  19: <mz_adapter::coord::Coordinator>::message_command::{closure#0}
             at ./var/lib/buildkite-agent/builds/buildkite-builders-d43b1b5-i-02d3dc3c9ce9a81d6-1/materialize/tests/src/adapter/src/
coord/message_handler.rs:223:5
  20: <mz_adapter::coord::Coordinator>::handle_message::{closure#0}
             at ./var/lib/buildkite-agent/builds/buildkite-builders-d43b1b5-i-02d3dc3c9ce9a81d6-1/materialize/tests/src/adapter/src/
coord/message_handler.rs:42:63
  21: <mz_adapter::coord::Coordinator>::serve::{closure#0}
             at ./var/lib/buildkite-agent/builds/buildkite-builders-d43b1b5-i-02d3dc3c9ce9a81d6-1/materialize/tests/src/adapter/src/
coord.rs:1393:37
  22: <tokio::runtime::park::CachedParkThread>::block_on::<<mz_adapter::coord::Coordinator>::serve::{closure#0}>::{closure#0}
             at ./cargo/registry/src/github.com-1ecc6299db9ec823/tokio-1.27.0/src/runtime/park.rs:283:63
  23: tokio::runtime::coop::with_budget::<core::task::poll::Poll<()>, <tokio::runtime::park::CachedParkThread>::block_on<<mz_adapter
::coord::Coordinator>::serve::{closure#0}>::{closure#0}>
             at ./cargo/registry/src/github.com-1ecc6299db9ec823/tokio-1.27.0/src/runtime/coop.rs:107:5
  24: tokio::runtime::coop::budget::<core::task::poll::Poll<()>, <tokio::runtime::park::CachedParkThread>::block_on<<mz_adapter::coo
rd::Coordinator>::serve::{closure#0}>::{closure#0}>
             at ./cargo/registry/src/github.com-1ecc6299db9ec823/tokio-1.27.0/src/runtime/coop.rs:73:5
  25: <tokio::runtime::park::CachedParkThread>::block_on::<<mz_adapter::coord::Coordinator>::serve::{closure#0}>
             at ./cargo/registry/src/github.com-1ecc6299db9ec823/tokio-1.27.0/src/runtime/park.rs:283:31
  26: <tokio::runtime::context::BlockingRegionGuard>::block_on::<<mz_adapter::coord::Coordinator>::serve::{closure#0}>
             at ./cargo/registry/src/github.com-1ecc6299db9ec823/tokio-1.27.0/src/runtime/context.rs:315:13
  27: <tokio::runtime::handle::Handle>::block_on::<<mz_adapter::coord::Coordinator>::serve::{closure#0}>
             at ./cargo/registry/src/github.com-1ecc6299db9ec823/tokio-1.27.0/src/runtime/handle.rs:264:9
  28: mz_adapter::coord::serve::{closure#0}::{closure#1}
             at ./var/lib/buildkite-agent/builds/buildkite-builders-d43b1b5-i-02d3dc3c9ce9a81d6-1/materialize/tests/src/adapter/src/
coord.rs:1614:17
note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.

or like this:

thread 'coordinator' panicked at 'Dataflow oneshot-select-t1065 requested as_of (Antichain { elements: [1686041434420] }) not >= since (Antichain { elements: [1686041435099] })', src/adapter/src/coord/dataflows.rs:260:13
stack backtrace:
   0: rust_begin_unwind
             at ./rustc/9eb3afe9ebe9c7d2b84b71002d44f4a0edac95e0/library/std/src/panicking.rs:575:5
   1: core::panicking::panic_fmt
             at ./rustc/9eb3afe9ebe9c7d2b84b71002d44f4a0edac95e0/library/core/src/panicking.rs:64:14
   2: <mz_adapter::coord::Coordinator>::finalize_dataflow
             at ./var/lib/buildkite-agent/builds/buildkite-builders-d43b1b5-i-02d3dc3c9ce9a81d6-1/materialize/tests/src/adapter/src/coord/dataflows.rs:260:13
   3: <mz_adapter::coord::Coordinator>::create_peek_plan::{closure#0}
             at ./var/lib/buildkite-agent/builds/buildkite-builders-d43b1b5-i-02d3dc3c9ce9a81d6-1/materialize/tests/src/adapter/src/coord/peek.rs:279:28
   4: <core::option::Option<mz_adapter::coord::peek::FastPathPlan>>::map_or_else::<core::result::Result<mz_adapter::coord::peek::PeekPlan, mz_adapter::error::AdapterError>, <mz_adapter::coord::Coordinator>::create_peek_plan::{closure#0}, <mz_adapter::coord::Coordinator>::create_peek_plan::{closure#1}>
             at ./rustc/9eb3afe9ebe9c7d2b84b71002d44f4a0edac95e0/library/core/src/option.rs:1064:21
   5: <mz_adapter::coord::Coordinator>::create_peek_plan
             at ./var/lib/buildkite-agent/builds/buildkite-builders-d43b1b5-i-02d3dc3c9ce9a81d6-1/materialize/tests/src/adapter/src/coord/peek.rs:266:25
   6: <mz_adapter::coord::Coordinator>::plan_peek
             at ./var/lib/buildkite-agent/builds/buildkite-builders-d43b1b5-i-02d3dc3c9ce9a81d6-1/materialize/tests/src/adapter/src/coord/sequencer/inner.rs:2494:25
   7: <mz_adapter::coord::Coordinator>::peek_stage_finish::{closure#0}::{closure#0}
             at ./var/lib/buildkite-agent/builds/buildkite-builders-d43b1b5-i-02d3dc3c9ce9a81d6-1/materialize/tests/src/adapter/src/coord/sequencer/inner.rs:2341:25
   8: <mz_adapter::coord::Coordinator>::peek_stage_finish::{closure#0}
             at ./var/lib/buildkite-agent/builds/buildkite-builders-d43b1b5-i-02d3dc3c9ce9a81d6-1/materialize/tests/src/adapter/src/coord/sequencer/inner.rs:2314:5
   9: <mz_adapter::coord::Coordinator>::sequence_peek_stage::{closure#0}
             at ./var/lib/buildkite-agent/builds/buildkite-builders-d43b1b5-i-02d3dc3c9ce9a81d6-1/materialize/tests/src/adapter/src/coord/sequencer/inner.rs:2067:74
  10: <mz_adapter::coord::Coordinator>::sequence_peek::{closure#0}::{closure#0}
             at ./var/lib/buildkite-agent/builds/buildkite-builders-d43b1b5-i-02d3dc3c9ce9a81d6-1/materialize/tests/src/adapter/src/coord/sequencer/inner.rs:2026:9
  11: <mz_adapter::coord::Coordinator>::sequence_peek::{closure#0}
             at ./var/lib/buildkite-agent/builds/buildkite-builders-d43b1b5-i-02d3dc3c9ce9a81d6-1/materialize/tests/src/adapter/src/coord/sequencer/inner.rs:2008:5
  12: <mz_adapter::coord::Coordinator>::sequence_plan::{closure#0}::{closure#0}
             at ./var/lib/buildkite-agent/builds/buildkite-builders-d43b1b5-i-02d3dc3c9ce9a81d6-1/materialize/tests/src/adapter/src/coord/sequencer.rs:254:70
  13: <mz_adapter::coord::Coordinator>::sequence_plan::{closure#0}
             at ./var/lib/buildkite-agent/builds/buildkite-builders-d43b1b5-i-02d3dc3c9ce9a81d6-1/materialize/tests/src/adapter/src/coord/sequencer.rs:51:5
  14: <mz_adapter::coord::Coordinator>::handle_execute_inner::{closure#0}::{closure#0}
             at ./var/lib/buildkite-agent/builds/buildkite-builders-d43b1b5-i-02d3dc3c9ce9a81d6-1/materialize/tests/src/adapter/src/coord/command_handler.rs:553:78
  15: <mz_adapter::coord::Coordinator>::handle_execute_inner::{closure#0}
             at ./var/lib/buildkite-agent/builds/buildkite-builders-d43b1b5-i-02d3dc3c9ce9a81d6-1/materialize/tests/src/adapter/src/coord/command_handler.rs:353:5
  16: <mz_adapter::coord::Coordinator>::handle_execute::{closure#0}::{closure#0}
             at ./var/lib/buildkite-agent/builds/buildkite-builders-d43b1b5-i-02d3dc3c9ce9a81d6-1/materialize/tests/src/adapter/src/coord/command_handler.rs:350:61
  17: <mz_adapter::coord::Coordinator>::handle_execute::{closure#0}
             at ./var/lib/buildkite-agent/builds/buildkite-builders-d43b1b5-i-02d3dc3c9ce9a81d6-1/materialize/tests/src/adapter/src/coord/command_handler.rs:293:5
  18: <tracing::instrument::Instrumented<<mz_adapter::coord::Coordinator>::handle_execute::{closure#0}> as core::future::future::Future>::poll
             at ./cargo/registry/src/github.com-1ecc6299db9ec823/tracing-0.1.37/src/instrument.rs:272:9
  19: <mz_adapter::coord::Coordinator>::handle_command::{closure#0}
             at ./var/lib/buildkite-agent/builds/buildkite-builders-d43b1b5-i-02d3dc3c9ce9a81d6-1/materialize/tests/src/adapter/src/coord/command_handler.rs:79:21
  20: <mz_adapter::coord::Coordinator>::message_command::{closure#0}::{closure#0}
             at ./var/lib/buildkite-agent/builds/buildkite-builders-d43b1b5-i-02d3dc3c9ce9a81d6-1/materialize/tests/src/adapter/src/coord/message_handler.rs:226:33
  21: <mz_adapter::coord::Coordinator>::message_command::{closure#0}
             at ./var/lib/buildkite-agent/builds/buildkite-builders-d43b1b5-i-02d3dc3c9ce9a81d6-1/materialize/tests/src/adapter/src/coord/message_handler.rs:223:5
  22: <mz_adapter::coord::Coordinator>::handle_message::{closure#0}
             at ./var/lib/buildkite-agent/builds/buildkite-builders-d43b1b5-i-02d3dc3c9ce9a81d6-1/materialize/tests/src/adapter/src/coord/message_handler.rs:42:63
  23: <mz_adapter::coord::Coordinator>::serve::{closure#0}
             at ./var/lib/buildkite-agent/builds/buildkite-builders-d43b1b5-i-02d3dc3c9ce9a81d6-1/materialize/tests/src/adapter/src/coord.rs:1393:37
  24: <tokio::runtime::park::CachedParkThread>::block_on::<<mz_adapter::coord::Coordinator>::serve::{closure#0}>::{closure#0}
             at ./cargo/registry/src/github.com-1ecc6299db9ec823/tokio-1.27.0/src/runtime/park.rs:283:63
  25: tokio::runtime::coop::with_budget::<core::task::poll::Poll<()>, <tokio::runtime::park::CachedParkThread>::block_on<<mz_adapter::coord::Coordinator>::serve::{closure#0}>::{closure#0}>
             at ./cargo/registry/src/github.com-1ecc6299db9ec823/tokio-1.27.0/src/runtime/coop.rs:107:5
  26: tokio::runtime::coop::budget::<core::task::poll::Poll<()>, <tokio::runtime::park::CachedParkThread>::block_on<<mz_adapter::coord::Coordinator>::serve::{closure#0}>::{closure#0}>
             at ./cargo/registry/src/github.com-1ecc6299db9ec823/tokio-1.27.0/src/runtime/coop.rs:73:5
  27: <tokio::runtime::park::CachedParkThread>::block_on::<<mz_adapter::coord::Coordinator>::serve::{closure#0}>
             at ./cargo/registry/src/github.com-1ecc6299db9ec823/tokio-1.27.0/src/runtime/park.rs:283:31
  28: <tokio::runtime::context::BlockingRegionGuard>::block_on::<<mz_adapter::coord::Coordinator>::serve::{closure#0}>
             at ./cargo/registry/src/github.com-1ecc6299db9ec823/tokio-1.27.0/src/runtime/context.rs:315:13
  29: <tokio::runtime::handle::Handle>::block_on::<<mz_adapter::coord::Coordinator>::serve::{closure#0}>
             at ./cargo/registry/src/github.com-1ecc6299db9ec823/tokio-1.27.0/src/runtime/handle.rs:264:9
  30: mz_adapter::coord::serve::{closure#0}::{closure#1}
             at ./var/lib/buildkite-agent/builds/buildkite-builders-d43b1b5-i-02d3dc3c9ce9a81d6-1/materialize/tests/src/adapter/src/coord.rs:1614:17
note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.
@philip-stoev philip-stoev added the C-bug Category: something is broken label Jun 6, 2023
@philip-stoev
Copy link
Contributor Author

gh19743.sql.zip

To reproduce, run the attached file in multiple concurrent connections:

cat foo.sql |  psql -h 127.0.0.1 -p 6875 -U materialize &
cat foo.sql |  psql -h 127.0.0.1 -p 6875 -U materialize &
cat foo.sql |  psql -h 127.0.0.1 -p 6875 -U materialize &
cat foo.sql |  psql -h 127.0.0.1 -p 6875 -U materialize &
cat foo.sql |  psql -h 127.0.0.1 -p 6875 -U materialize &
cat foo.sql |  psql -h 127.0.0.1 -p 6875 -U materialize &
cat foo.sql |  psql -h 127.0.0.1 -p 6875 -U materialize &
cat foo.sql |  psql -h 127.0.0.1 -p 6875 -U materialize &
cat foo.sql |  psql -h 127.0.0.1 -p 6875 -U materialize &
cat foo.sql |  psql -h 127.0.0.1 -p 6875 -U materialize &
cat foo.sql |  psql -h 127.0.0.1 -p 6875 -U materialize &
cat foo.sql |  psql -h 127.0.0.1 -p 6875 -U materialize &
cat foo.sql |  psql -h 127.0.0.1 -p 6875 -U materialize &
cat foo.sql |  psql -h 127.0.0.1 -p 6875 -U materialize &
cat foo.sql |  psql -h 127.0.0.1 -p 6875 -U materialize &
cat foo.sql |  psql -h 127.0.0.1 -p 6875 -U materialize &
cat foo.sql |  psql -h 127.0.0.1 -p 6875 -U materialize &
cat foo.sql |  psql -h 127.0.0.1 -p 6875 -U materialize &
cat foo.sql |  psql -h 127.0.0.1 -p 6875 -U materialize &
cat foo.sql |  psql -h 127.0.0.1 -p 6875 -U materialize &

The way the queries was generated was fairly primitive, so the file contains many queries that will error out for various reasons. With a more targeted workload the panics are very likely to happen much faster. Please let me know if a better test case is required.

@philip-stoev philip-stoev added the A-ADAPTER Topics related to the ADAPTER layer label Jun 6, 2023
@philip-stoev philip-stoev changed the title panic when transactional workload is mixed with concurrent DDL panic when transactional workload is mixed with concurrent DDL: cannot fail to peek: CollectionMissing or Dataflow requested as_of not >= since Jun 6, 2023
@maddyblue
Copy link
Contributor

The "Dataflow oneshot-select-t1065 requested as_of (Antichain { elements: [1686041434420] }) not >= since" error is happening because a txn is started, it gets a timestamp, then the second query in the txn runs but the since has advanced beyond the query timestamp. This shouldn't happen due to read holds, so something might be going on there. u208 is a table. Here's the determine_timestamp from a select that's the 2nd select in a txn (no AS OF anywhere). See how the since is greater than the timestamp.

EXXEC: conn=23 stmt=SELECT * FROM [u208 AS materialize.public.obj2]
[src/adapter/src/coord/timestamp_selection.rs:482] &det = TimestampDetermination {
    timestamp_context: TimelineTimestamp(
        EpochMilliseconds,
        1686269985000,
    ),
    since: Antichain {
        elements: [
            1686269986000,
        ],
    },
    upper: Antichain {
        elements: [
            1686269987038,
        ],
    },
    largest_not_in_advance_of_upper: 1686269987037,
    oracle_read_ts: None,
}

@maddyblue
Copy link
Contributor

It is not yet clear if this is related to the other panic, which is caused by an unknown collection id. It is possible they are the same bug! One theory is that a collection is being destroyed and created (the creation happens at the higher since), and so sometimes this manifests as a since problem, sometimes as a unknown id problem depending on where in the race condition it hits.

@sploiselle
Copy link
Contributor

@mjibson can you give me a diff of whatever dbg!'ing you've done on the coordinator side?

@maddyblue
Copy link
Contributor

@sploiselle
Copy link
Contributor

sploiselle commented Jun 12, 2023

Summary:

  1. Connection starts txn
  2. New table gets created
  3. Connection selects from a table whose since is "old"
  4. Some other connection selects from new table, its since is beyond the since of the "old" table.
  5. Connection in txn selects from new table; dies w/ failure

Here are the logs (gh19743.log) and here is the linear narration.

u35 is the "old" table
u85 is the new table
conn=14 is the unfortunate connection.

As the story begins, u35 is at 5397 on conn=14

EXXEC: conn=14 stmt=SELECT * FROM [u35 AS materialize.public.obj2]
[src/adapter/src/coord/timestamp_selection.rs:482] &det = TimestampDetermination {
    timestamp_context: TimelineTimestamp(
        EpochMilliseconds,
        1686526195397,
    ),
    since: Antichain {
        elements: [
            1686526194000,
        ],
    },
    upper: Antichain {
        elements: [
            1686526195398,
        ],
    },
    largest_not_in_advance_of_upper: 1686526195397,
    oracle_read_ts: None,
}
...

u35 advances to 5468 eventually

EXXEC: conn=16 stmt=SELECT * FROM [u35 AS materialize.public.obj2]
[src/adapter/src/coord/timestamp_selection.rs:482] &det = TimestampDetermination {
    timestamp_context: TimelineTimestamp(
        EpochMilliseconds,
        1686526195468,
    ),
    since: Antichain {
        elements: [
            1686526194000,
        ],
    },
    upper: Antichain {
        elements: [
            1686526195469,
        ],
    },
    largest_not_in_advance_of_upper: 1686526195468,
    oracle_read_ts: None,
}
...

conn 14 starts a transaction

EXXEC: conn=14 stmt=START TRANSACTION

u35 is still held at 5468

EXXEC: conn=4 stmt=SELECT * FROM [u35 AS materialize.public.obj2]
[src/adapter/src/coord/timestamp_selection.rs:482] &det = TimestampDetermination {
    timestamp_context: TimelineTimestamp(
        EpochMilliseconds,
        1686526195468,
    ),
    since: Antichain {
        elements: [
            1686526194000,
        ],
    },
    upper: Antichain {
        elements: [
            1686526195469,
        ],
    },
    largest_not_in_advance_of_upper: 1686526195468,
    oracle_read_ts: None,
}
environmentd: 2023-06-11T23:29:57.025826Z  INFO mz_storage_client::controller:
    update_read_capabilities User(35):
        MutableAntichain { updates: ChangeBatch { updates: [(1686526194000, 1), (1686526195000, 1), (1686526195469, 1), (1686526195000, -1), (1686526196000, 1)], clean: 3 }, frontier: [1686526194000], changes: ChangeBatch { updates: [], clean: 0 } }

u85 gets created; this looks like it is after conn14's txn begins.

The closest timestamp I see after conn14's txn begins is:
023-06-11T23:29:57.025826
but u85 looks like it gets created at
2023-06-11T23:29:57.058479Z

CREATTE: id=u85 name=u1.u3.obj3
environmentd: 2023-06-11T23:29:57.058479Z  INFO mz_adapter::catalog: create table materialize.public.obj3 (u85)
environmentd: 2023-06-11T23:29:57.105915Z  INFO mz_storage_client::controller:
    update_read_capabilities User(85):
    MutableAntichain { updates: ChangeBatch { updates: [(0, 1)], clean: 1 }, frontier: [0], changes: ChangeBatch { updates: [], clean: 0 } }

u35 has some old read holds, so its frontier is 1686526194000

environmentd: 2023-06-11T23:29:57.112964Z  INFO mz_storage_client::controller:
    update_read_capabilities User(35):
    MutableAntichain { updates: ChangeBatch { updates: [(1686526194000, 1), (1686526195000, 1), (1686526195469, 1), (1686526195000, -1), (1686526196000, 1)], clean: 3 }, frontier: [1686526194000], changes: ChangeBatch { updates: [], clean: 0 } }

other collections are at 5468 though

environmentd: 2023-06-11T23:29:57.113028Z  INFO mz_storage_client::controller:
    update_read_capabilities User(77)
     MutableAntichain { updates: ChangeBatch { updates: [(1686526195468, 18), (1686526196909, 1)], clean: 2 }, frontier: [1686526195468], changes: ChangeBatch { updates: [], clean: 0 } }

Other txns are choosing 1686526195468 shen selecting from u35

EXXEC: conn=22 stmt=SELECT * FROM [u35 AS materialize.public.obj2]
[src/adapter/src/coord/timestamp_selection.rs:482] &det = TimestampDetermination {
    timestamp_context: TimelineTimestamp(
        EpochMilliseconds,
        1686526195468,
    ),
    since: Antichain {
        elements: [
            1686526194000,
        ],
    },
    upper: Antichain {
        elements: [
            1686526195469,
        ],
    },
    largest_not_in_advance_of_upper: 1686526195468,
    oracle_read_ts: None,
}

conn8 selects from u85, gets a since of 7068

EXXEC: conn=8 stmt=SELECT * FROM [u85 AS materialize.public.obj3]
[src/adapter/src/coord/timestamp_selection.rs:482] &det = TimestampDetermination {
    timestamp_context: TimelineTimestamp(
        EpochMilliseconds,
        1686526197068,
    ),
    since: Antichain {
        elements: [
            1686526197068,
        ],
    },
    upper: Antichain {
        elements: [
            1686526197069,
        ],
    },
    largest_not_in_advance_of_upper: 1686526197068,
    oracle_read_ts: None,
}
[src/adapter/src/coord/dataflows.rs:259] &since = Antichain {
    elements: [
        1686526197068,
    ],
}
[src/adapter/src/coord/dataflows.rs:259] storage_ids = {
    User(
        85,
    ),
}
[src/adapter/src/coord/dataflows.rs:259] compute_ids = {
    User(
        1,
    ): {},
}
environmentd: 2023-06-11T23:29:57.117726Z  INFO mz_storage_client::controller: update_read_capabilities User(85): MutableAntichain { updates: ChangeBatch { updates: [(1686526197068, 1)], clean: 1 }, frontier: [1686526197068], changes: ChangeBatch { updates: [], clean: 0 } }

conn14 selects from u35, setting its time to 5468

EXXEC: conn=14 stmt=SELECT * FROM [u35 AS materialize.public.obj2]
[src/adapter/src/coord/timestamp_selection.rs:482] &det = TimestampDetermination {
    timestamp_context: TimelineTimestamp(
        EpochMilliseconds,
        1686526195468,
    ),
    since: Antichain {
        elements: [
            1686526194000,
        ],
    },
    upper: Antichain {
        elements: [
            1686526195469,
        ],
    },
    largest_not_in_advance_of_upper: 1686526195468,
    oracle_read_ts: None,
}
peeking id u38, get since
got since
environmentd: 2023-06-11T23:29:57.118658Z  INFO mz_storage_client::controller: update_read_capabilities User(35): MutableAntichain { updates: ChangeBatch { updates: [(1686526194000, 1), (1686526195000, 1), (1686526195469, 1), (1686526195000, -1), (1686526196000, 1)], clean: 3 }, frontier: [1686526194000], changes: ChangeBatch { updates: [], clean: 0 } }
environmentd: 2023-06-11T23:29:57.118916Z  INFO mz_storage_client::controller: update_read_capabilities User(35): MutableAntichain { updates: ChangeBatch { updates: [(1686526194000, 1), (1686526195000, 1), (1686526195469, 1), (1686526195000, -1), (1686526196000, 1)], clean: 3 }, frontier: [1686526194000], changes: ChangeBatch { updates: [], clean: 0 } }

conn 20 selects from u85, continues getting 7068

EXXEC: conn=20 stmt=SELECT * FROM [u85 AS materialize.public.obj3]
[src/adapter/src/coord/timestamp_selection.rs:482] &det = TimestampDetermination {
    timestamp_context: TimelineTimestamp(
        EpochMilliseconds,
        1686526197068,
    ),
    since: Antichain {
        elements: [
            1686526197068,
        ],
    },
    upper: Antichain {
        elements: [
            1686526197069,
        ],
    },
    largest_not_in_advance_of_upper: 1686526197068,
    oracle_read_ts: None,
}
[src/adapter/src/coord/dataflows.rs:259] &since = Antichain {
    elements: [
        1686526197068,
    ],
}
[src/adapter/src/coord/dataflows.rs:259] storage_ids = {
    User(
        85,
    ),
}
[src/adapter/src/coord/dataflows.rs:259] compute_ids = {
    User(
        1,
    ): {},
}

conn14 selects from u85––u85's since is 1686526197068, but conn14's txn is fixed to seeing time 5468

EXXEC: conn=14 stmt=SELECT * FROM [u85 AS materialize.public.obj3]
[src/adapter/src/coord/timestamp_selection.rs:482] &det = TimestampDetermination {
    timestamp_context: TimelineTimestamp(
        EpochMilliseconds,
        1686526195468,
    ),
    since: Antichain {
        elements: [
            1686526197068,
        ],
    },
    upper: Antichain {
        elements: [
            1686526197069,
        ],
    },
    largest_not_in_advance_of_upper: 1686526197068,
    oracle_read_ts: None,
}
[src/adapter/src/coord/dataflows.rs:259] &since = Antichain {
    elements: [
        1686526197068,
    ],
}
[src/adapter/src/coord/dataflows.rs:259] storage_ids = {
    User(
        85,
    ),
}
[src/adapter/src/coord/dataflows.rs:259] compute_ids = {
    User(
        1,
    ): {},
}
thread 'coordinator' panicked at 'Dataflow oneshot-select-t4075 requested as_of (Antichain { elements: [1686526195468] }) not >= since (Antichain { elements: [1686526197068] })', src/adapter/src/coord/dataflows.rs:262:13
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace

@philip-stoev
Copy link
Contributor Author

Maybe the transaction should not even be allowed to see tables that were created after it started? Or error our immediately when attempting to SELECT from such a table?

@maddyblue
Copy link
Contributor

Maybe the transaction should not even be allowed to see tables that were created after it started? Or error our immediately when attempting to SELECT from such a table?

Transactions should already be doing this! Will investigate.

@chaas chaas assigned maddyblue and unassigned chaas Jun 14, 2023
@maddyblue
Copy link
Contributor

maddyblue commented Jun 22, 2023

Current story:

  1. Some connection 1 opens a transaction.
  2. Connection 1 runs SELECT * FROM X. A timestamp (let's say at time 10) is generated in the transaction that is valid for all objects (X and Y) in that schema based on the sinces and the global read ts. Read holds are acquired on X and Y at ts=10.
  3. Connection 2 executes CREATE OR REPLACE CREATE MATERIALIZED VIEW on Y.
  4. The compute controller instructs the storage controller to update the read hold for Y to ts=15. <-- This is the bug.
  5. Connection 1 runs SELECT * FROM Y in the txn. Because the transaction already has a timestamp, no sinces need to be consulted, and the query executes at ts=10.
  6. A panic occurs because Y's since is 15, not 10, even though there was a read hold on it.

This is happening in create_dataflows: https://github.com/MaterializeInc/materialize/blob/505338f15ddce774f7a2d83b1ddf6a824cf6a2b6/src/compute-client/src/controller/instance.rs#LL617C1-L617C2
and:

.update_read_capabilities(&mut storage_read_capability_changes);

This seems to be a problem in create_dataflow or else in read holds. I'll continue investigating, but would appreciate any insight.

I tested some theories above about creating indexes or tables while another txn had started then querying them, but we have existing code protecting against that and everything I tried worked as expected (the txn failed with timedomain errors).

@teskje
Copy link
Contributor

teskje commented Jun 22, 2023

I'm missing a lot of context here, but these are my initial thoughts:

  • create_dataflows installs read holds on the dataflow inputs. For each dataflow input, it installs one "global" read hold, and one read hold for each replica in the compute instance. The read holds are all installed at the as_of time of the dataflow, because that is the time from which on the dataflow wants to read from its inputs. So in your example, is the MVs as_of set to 15? If it is not, then this definitely sounds like a bug in create_dataflows. But if the as_of is 15 then everything works as intended.
  • If adapter also installs a read hold for ts=10 on Y, why does it matter if create_dataflows installs read holds for later times? As long as the ts=10 read hold isn't removed, Y's since should not be allowed to advance further than that.

@benesch
Copy link
Member

benesch commented Jun 22, 2023

I'm confused about how the transaction in connection 1 is able to reference the new Y. That new copy of Y should have a new ID that is not in the ID bundle that the connection 1 transaction acquired read holds on, and so the query of Y should fail.

Is it possible that moving work off the main coordinator thread has created a race here? Something like:

Objects X and Y exist in the same schema.

  1. Transaction 1 starts.
  2. Transaction 1 successfully queries object X, establishing read holds on everything in object X's schema.
  3. Transaction 1 successfully plans a query against object Y.
  4. Transaction 1 successfully validates that object Y is in the read set.
  5. Transaction 2 drops object Y.
  6. Transaction 1 panics when it goes to ship the dataflow because object Y has been dropped.

@maddyblue
Copy link
Contributor

Is it possible that moving work off the main coordinator thread has created a race here?

This hasn't happened yet for SELECTs, which still happen in a single coord message.

@maddyblue
Copy link
Contributor

Ugh. I sorted the order of events incorrectly. The CREATE OR REPLACE executed before the transaction started.

@benesch
Copy link
Member

benesch commented Jun 22, 2023

Ah, I see. Just to be absolutely certain I have the order right, can you post a corrected order of events?

@maddyblue
Copy link
Contributor

maddyblue commented Jun 22, 2023


log:240845:68:EXXEC: conn=6 stmt=CREATE MATERIALIZED VIEW obj2 AS SELECT * FROM [u156 AS materialize.public.obj3]
log:240846:1:CREATTE: id=u157 name=u1.u3.obj2
log:241016:8:EXXEC: conn=17 stmt=START TRANSACTION
log:241487:8:EXXEC: conn=17 stmt=SELECT * FROM [u157 AS materialize.public.obj2]
log:242245:1:EXXEC: conn=26 stmt=SELECT * FROM [u157 AS materialize.public.obj2]
log:242288:17:UPDATEREADD: id=u156, frontier=Antichain { elements: [1687390914000] }
log:243056:8:EXXEC: conn=17 stmt=SELECT * FROM [u156 AS materialize.public.obj3]
PANIC because the UPDATEREADD above advanced the since to 14000 of u156, but the open txn is still at 13000:
[src/adapter/src/coord/timestamp_selection.rs:482] &det = TimestampDetermination {
    timestamp_context: TimelineTimestamp(
        EpochMilliseconds,
        1687390913000,
    ),
    since: Antichain {
        elements: [
            1687390914000,
        ],
    },
    upper: Antichain {
        elements: [
            1687390915162,
        ],
    },
    largest_not_in_advance_of_upper: 1687390915161,
    oracle_read_ts: None,
}

the CREATTE line show when we got some create event and the gid and name created. EXXEC shows executed sql statements. UPDATEREADD is printed in the storage controller's update_read_capabilities fn.

@maddyblue
Copy link
Contributor

The EXXEC: conn=26 stmt=SELECT * FROM [u157 AS materialize.public.obj2] line is the query that needs to create a temporary dataflow for its select which is what eventually calls update_read_capabilities that's causing the problem.

@maddyblue
Copy link
Contributor

maddyblue commented Jun 22, 2023

There are no CREATE queries from any connection after the transaction starts.

@maddyblue
Copy link
Contributor

Here's my guess: update_write_frontiers is calling update_read_capabilites incorrectly. It only seems to check the collection's read_policy in some cases. Will keep investigating.

self.update_read_capabilities(&mut read_capability_changes);

@maddyblue
Copy link
Contributor

I'm not able to reproduce this by hand. That combined with the other panic here suggests the read hold stuff is a red herring. I'm still lost!

@sploiselle
Copy link
Contributor

Just jotting this down for my own memory: Matt and I looked at this today and was saw that some sources that should have been considered during timestamp determination were not.

@maddyblue
Copy link
Contributor

Looking into the above question about correctly involving some sources: we just hadn't read everything yet. We were looking at the id bundle for the incoming query, not the id bundle for the timedomain saved in the transaction. The transaction's id bundle is correct, and it does seem to be correctly setting IDs during first statement, then correctly referencing that during later queries in the txn.

@maddyblue
Copy link
Contributor

Think I found it: timestamp determination is done with initial select sources, not full timedomain sources. So subsequent queries in the txn haven't had their sinces considered. This got broken within the last few months. Should have a fix and full explanation out soon.

@maddyblue
Copy link
Contributor

This got broke in #19026

@maddyblue maddyblue added the release-blocker Critical issue that should block *any* release if not fixed label Jun 29, 2023
@maddyblue maddyblue removed the release-blocker Critical issue that should block *any* release if not fixed label Jun 30, 2023
@maddyblue
Copy link
Contributor

Unmarking as a release blocker because the fix will take a bit longer, this doesn't result in catalog corruption, and it occurs only rarely.

chaas added a commit that referenced this issue Aug 2, 2023
… areas (#20406)

As a follow up to
#19743, we want to
be more prescriptive about what types of external contributions we'll
encourage, and more explicit guidelines for picking up an issue.

Surfaces has decided to disallow external contributions to the
coordinator for two reasons:
* The cost of educating and performing extra-thorough reviews is not
worth the benefit-cost/risk tradeoff, given the complexity and
importance of this code
* Major coordinator changes should only be done as part of a more
focused, planned body of work, again given the nuances. One-off changes
picked up at random increase the risk of missed problems.

Questions for reviewer:
* Any other suggestions for both the "areas that are best suited for
external contributions" and "ask first" sections? I picked persist there
arbitrarily, and can remove if folks disagree.

This is one of a series of follow up items from the above issue.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
A-ADAPTER Topics related to the ADAPTER layer C-bug Category: something is broken
Projects
None yet
Development

Successfully merging a pull request may close this issue.

6 participants