Materialize: perf: loss of interactivity

[rjnn]

Description updated on October 26, 2020 by @benesch.

The term "loss of interactivity" refers to any time where simple queries do not return quickly. Selecting all records from a simple table in Materialize should take only a few milliseconds. If a simple query takes longer than a few milliseconds to return, it is likely that Materialize has lost interactivity.

Empirically, Materialize loses interactivity when a dataflow operator takes up too much CPU time without yielding. Timely is cooperative scheduled, so one badly-behaved operator can prevent any other operator from running. In particular, no peeks (i.e., SELECT queries) can be retired while a badly-behaved operator is hogging the CPU.

Note that timing SELECT 1 does not effectively surface interactivity problems. SELECT 1 is so simple—specifically, it optimizes to a constant—that it is handled entirely at the coordinator, and the coordinator usually remains responsive even when the dataflow layer is not.

The best way to measure loss of interactivity is to create a very simple table with very little data

CREATE TABLE t (a INT);
INSERT INTO t VALUES (1);

and then measure how long it takes to retrieve all data from that table:

SELECT * FROM t;

If you don't have a table t handy, you can use one of the small tables in mz_catalog instead, like mz_sources. Queries on the catalog are not special, and are treated just like queries on user tables; the data in the catalog tables just so happens to be updated by Materialize itself, rather than by Kafka.

The hallmark of loss of interactivity is that a query that _should_ be fast is not fast. Some queries are slow; if a slow query is slow, that does not imply a loss of interactivity.

When you encounter loss of interactivity, the hard part is identifying the cause. Sometimes it's as easy as "the second-to-last thing you ran." If you just created a complicated view, and things were working fine before you created that view, the view is probably the culprit. Sometimes it's not so clear. In either case, run the "Materialize becomes unresponsive for seconds at a time!" queries in the diagnostic queries doc, which surfaces operators that are taking up a lot of CPU time.

Since we don't presently intend to switch Timely to use a preemptive scheduler, the only way forward is via a big game of whack a mole. Whenever we find an operator that uses too much CPU at a time, we need to fix it so it yields more regularly. To do that, we need your help filing reports about things that cause loss of interactivity!

When you file a bug about loss of interactivity:

• Include the query or queries that you think caused the loss of interactivity.
• Include the query that made you notice the loss of interactivity. (This is the query that should be fast but is not.)
• Include the scheduling histogram output from the diagnostic query mentioned above.
• Link the issue below.

Known loss of interactivity issues:

• [ ] dropping indexes (#4620)

Frequently asked questions

Shouldn't catalog queries still be fast, even if Materialize loses interactivity?
No. The data in the catalog lives in the dataflow plane, just like user data. The same infrastructure to query user data is used to query catalog data. (This greatly simplifies the architecture, and makes it possible to join user data with catalog data.) When you lose interactivity, you lose the ability to get answers to any non-constant queries, regardless of whether those queries access catalog data or user data.

We could special case catalog data, but that would be misdirected effort. Users are as likely to be impacted by their SELECT * FROM very_small_table suddenly taking several seconds (or minutes!) to respond as they are to be impacted by SHOW VIEWS getting slow. Better to invest energy in fixing the root issue, so that all queries get fast.

I pressed Ctrl-C. Why is my query still using resources?
That's tracked by #2392. Pressing Ctrl-C does not actually interrupt the computation. It just gives you your shell back. Whatever you ran will still be running in the background.

When to close this issue

Experience suggests there are dozens more loss-of-interactivity issues waiting to be discovered. Don't close this issue just because there are no presently outstanding loss-of-interactivity issues.

We can close this issue if either:

• We solve this issue architecturally; e.g. by learning to preempt operators
• We have several production deployments running for many months in which no loss of interactivity is observed, even under heavy load.

[benesch]

I'm hopeful that this will be fixed by the second commit from #1574. I think your connection might have been falling out of sync due to a bug in our TAIL code. Will try to repro tomorrow.

[rjnn]

Doesn't seem fixed.

This is on materialize SHA b339fbcef (i.e. before the fix):

arjun=> select * from raw;
^CCancel request sent
Time: 11664.129 ms (00:11.664)
arjun=> 

I then reran it on the latest master (SHA ea98e467f):

arjun=> select * from raw;
^CCancel request sent
^CCancel request sent
^CCancel request sent
Time: 21358.906 ms (00:21.359)
arjun=>

[benesch]

Oh, ok, I think I see the issue. Here's an easy way to create an awful query:

create materialized view v as values (1), (2), (3);
select * from v, v, v, v, v, v, v, v, v, v, v, v;

That last query should take a second or so to run. If you hit C-c quickly, you will in fact see cancellation occur.

If we ramp up the difficulty of the query to

select * from v, v, v, v, v, v, v, v, v, v, v, v, v, v, v, v, v, v, v, v, v, v;

it may take a long time before the cancellation occurs, if ever. This is because cancellation can't interrupt a running worker.step() call, because timely is cooperatively scheduled. I've verified (via a println) that cancellation occurs the moment we go around the loop again—i.e., the moment Timely decides to gives us control back.

cc @frankmcsherry maybe there is some way to limit the maximum amount of work Timely will do on a single call to step? Empirically I'm seeing it take >60s here.

There is another related problem which is that even after the user is given their prompt back the queries continue to execute, eating up CPU and memory. That too is hard to solve, as interrupting running dataflows is even scarier than asking worker.step to come back to us sooner—and the latter is required for the former anyway.

[benesch]

Maybe one of our operators needs a fuel tank?

[benesch]

Anyway, I'm kicking this out of the 0.1 milestone and into the 0.2 milestone, since there's no way we're going to be able to improve the situation in the next few days.

[frankmcsherry]

cc @frankmcsherry maybe there is some way to limit the maximum amount of work Timely will do on a single call to step? Empirically I'm seeing it take >60s here.

We should check out what is running for so long! The join operators are fuel limited, and should yield after producing 1M tuples. The reduce operators are not currently but could become so. There are some other operators (arrange, at least) whose position is "if you got X records at me, I will do X amount of work".

But, timely scheduling is def a thing that should be easy to open up. The next step is probably to sort out if it is timely that needs to yield, or a timely operator. I'd guess the latter (timely can't interrupt an operator, other than by squeezing its input pipe) and we can start looking through these and robustifying them.

[frankmcsherry]

Hrm. you know what it could be: some operators, possibly join, check their fuel after each key. All the cross joins wouldn't give it a chance to take a break. I'll investigate that!

[benesch]

I’ll bet there are multiple issues! Arjun’s initial discovery of this issue
was with a query that might not have had cross joins. (Hard to tell from
the snippet.) But the salient point is that the interactivity of
cancellation depends on the overall interactivity of the timely
computation, which is relatively unrelated to the particular query you are
trying to cancel.

On Thu, Jan 30, 2020 at 6:36 PM Frank McSherry [e-mail]
wrote:

Hrm. you know what it could be: some operators, possibly join, check their
fuel after each key. All the cross joins wouldn't give it a chance to take
a break. I'll investigate that!

—
You are receiving this because you were assigned.

Reply to this email directly, view it on GitHub
https://github.com/MaterializeInc/materialize/issues/1537?email_source=notifications&email_token=AAGXSIHNVGW5TDWACNKNNB3RANP57A5CNFSM4KGT6DH2YY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOEKM6UNA#issuecomment-580512308,
or unsubscribe
https://github.com/notifications/unsubscribe-auth/AAGXSIF2EBYR6GMAAMLPQHTRANP57ANCNFSM4KGT6DHQ
.

[frankmcsherry]

Why doesn't the coordinator just return a cancellation? Why block on the workers?

[benesch]

Well one day we will want to actively interrupt dataflows on the workers, so we need to send them a message anyway. And it seemed cleaner for information to always flow in the same loop (client -> coord -> worker -> coord -> client) rather than having short-circuiting.

Having the coordinator just return a cancellation wouldn't really make the situation much better here. You'd get your prompt back immediately, but then if you go to issue another peek, you'd promptly get stuck in exactly the same spot, because the worker isn't processing peeks if it's not processing cancellations.

[rjnn]

For what it's worth, the original query was just a view that had about 200 JSON -> and ->> operators to recordify a fat JSON blob over a source that had a few gigabytes of data.

[benesch]

Well, that sure smells like the culprit to me. Our Map operator suffers from the same performance issue we just fixed for UnaryFlatMap. Paging @frankmcsherry.

[frankmcsherry]

Should be easy to fix. The FlatMapUnary issue was a quadratic -> linear fix, though, and this might be more of a constant factor improvement. Probably the right long-term solution is that each operator of substance can just bolt on any map/filter/project work (per a @jamii proposal).

[frankmcsherry]

We can probably also invest in a FlatMapUnary/Map fusion transformation. We do map fusion, but .. fusing all these things probably helps out a fair bit.

[benesch]

Ok, I propose that we split this into two issues:

• A tracking issue for active cancellation, where we actually interrupt a running dataflow when a cancellation request arrives. This is about saving resources, though, and not about improving interactivity. It's also not likely to get done anytime soon.
• A tracking issue for loss of interactivity. @rjnn next time you see a cancellation request hang, can you fire up another session and do a SELECT * FROM mz_catalog.mz_catalog_names or some other small logging view? I'm willing to bet that your cancellation request will succeed at the same moment as that trivial select. And obviously the real problem here is that no queries of any sort can complete if one Timely operator is hogging the CPU for seconds or minutes at a time. (Note that SELECT 1 is not a sufficient test of interactivity, as that's handled without involving Timely.)

[frankmcsherry]

Ideally, you could do SELECT * FROM mz_catalog.mz_scheduling_histogram WHERE duration_ns > 1000000000 which will report operators that took more than 1s of time in a scheduling activation.

Or

SELECT * FROM mz_catalog.mz_scheduling_histogram ORDER BY duration_ns LIMIT 20

or whatever makes the most sense (each of these seem sane, but could be overwhelming).

[benesch]

Listen to Frank, not me!

[frankmcsherry]

But we should probably go through this to find a standard snippet to post so that folks in the wild with this issue can provide a report back (i.e. something that finds laggards, joins their ids with dataflow_operators to get names, maybe some more stuff).

[ruchirK]

btw this is a reasonably helpful query

select 
    mz_catalog.mz_scheduling_histogram.id, 
    mz_catalog.mz_scheduling_histogram.worker, 
    name, 
    dataflow_id, 
    count, 
    duration_ns / 1000000 as duration_ms 
from 
    mz_catalog.mz_scheduling_histogram, 
    mz_catalog.mz_dataflow_operator_dataflows 
where
    mz_catalog.mz_scheduling_histogram.id = mz_catalog.mz_dataflow_operator_dataflows.id and
    mz_catalog.mz_scheduling_histogram.worker = mz_catalog.mz_dataflow_operator_dataflows.worker
order by 
    duration_ms desc;

sorry about the formatting :P

[benesch]

I've made this issue just about the loss of interactivity, as mentioned in https://github.com/MaterializeInc/materialize/issues/1537#issuecomment-581048341, and filed https://github.com/MaterializeInc/materialize/issues/2392 about active dataflow cancellation.

[rjnn]

I think this issue can be closed out given that it's sufficiently obsolete, and there are other work items being tracked elsewhere that are more specific and recent. My report, at least, is definitely obsolete. With your permission, @benesch.

[benesch]

Sounds good to me!

[benesch]

I'm going to reopen this, because clearly it is still an issue. See #4537 and #4620.

[ruchirK]

@krishmanoh2 and I found that restarting Materialize with MZ_LOG=debug on a single worker can cause loss of interactivity that seemed to self resolve after a few minutes. This is likely because the librdkafka logging is very verbose however it did not show up in the perf top profile so maybe there's more at play. Krishna indicated that he had previously seen Materialize for much longer without self resolving, and I'll post updates here if we end up reproducing that.

[benesch]

Huh, that's super surprising. IIUC librdkafka logs from another thread, so I don't see how that would wedge the dataflow workers. (I suppose librdkafka logging could just exhaust the available CPU, but... that would also be really surprising.)

[ruchirK]

it could also be the caused by the larger than normal log volume systemwide I guess?

[krishmanoh2]

Restart specific - this problem could be user perception related to data availability after a restart.

Could we report server status (online/recovering) and index status (maybe rebuilding, available etc) in a mz view so the user knows status of the views? Now when I start up mz, it looks like data is going to be immediately available. It is upto the end user to figure out that indexes are being rebuilt.

With other products, after a restart, when querying data and if not ready, they return an error saying something like "index X is being rebuilt and will be available for querying in Y minutes". In mz, I would assume that a restart will restore data back to point just before restart or best effort before returning results to end-user.

[philip-stoev]

5704 is an example of a loss of interactivity, with a SQL-only test case