sqllogictests on mac is slow

[chaas]

From @frankmcsherry , who was running sqllogictests for ~10 files on an already-built release.

139.61s user 79.38s system 32% cpu 11:20.45 total
That's eleven minutes to rewrite some EXPLAIN output.
Among the changes that led to this were, I believe, the switch to local CRDB to make things "more like cloud", though as far as I can tell it has made things instead less like cloud, because cloud at least does not take 11 minutes to print out these explain plans.

Also

I'm now rebuilding src/sql which seems to share nothing with a normal MZ build, because I need to refresh one QGM test output.

Which took 7 minutes at 100% CPU.

This slowness in build + execution is affecting all developers and aligns with the goal to make envd startup sub 1s.

[maddyblue]

A command that caused this:

% time bin/sqllogictest --release test/sqllogictest/not-null-propagation.slt test/sqllogictest/tpch.slt test/sqllogictest/window_funcs.slt test/sqllogictest/with_mutually_recursive.slt test/sqllogictest/explain/decorrelated_plan_as_json.slt test/sqllogictest/explain/decorrelated_plan_as_text.slt test/sqllogictest/explain/raw_plan_as_json.slt test/sqllogictest/explain/raw_plan_as_text.slt test/sqllogictest/qgm/qgm-type-inference.slt test/sqllogictest/transform/predicate_pushdown.slt -- --rewrite-results

[chaas]

This pain is also actively being felt by the compute team
Per @antiguru

sqlogictests create a new envd (or something like it) for every statement, which now means that even small files take minutes, where they took seconds in the past.

[maddyblue]

sqlogictests create a new envd for every statement

This either isn't true or is very bad if we are indeed doing that (state is observed across statements), it's a new envd per file though.

[antiguru]

sqlogictests create a new envd for every statement
This either isn't true or is very bad if we are indeed doing that (state is observed across statements), it's a new envd per file though.

Sorry, I should have checked closer, and it's indeed not true that an envd is created for every statement but rather files.

[maddyblue]

FWIW, running the same command pasted above took 38s on my machine on the second try (the first try compiled a bunch of stuff). Did some of that time include compilation?

[frankmcsherry]

Nope. It was the second run for me also.

[maddyblue]

Today's investigation: 8s startup locally, over 6s of that in coord bootstrap. 5s of it is from the catalog entries init, with most of the time spent in #17057.

[maddyblue]

https://gist.github.com/mjibson/bc5a7c17abaf04cb2e3958b12653f71c is a json file of a trace from a CREATE TABLE issued by a sqllogictest statement run on a mac that took 7s to run. It can be uploaded into jaeger for anyone to view. The below screenshot shows that stash and persist operations are just incredibly slow. This is almost certainly either the local cockroach being slow (seems unlikely that it'd be THIS slow), or some translation/network/??? thing the mac is doing to all outgoing network connections, or something like it. I don't have a dev mac so cannot test. Someone who has a mac needs to drive this investigation now.

[danhhz]

300ms+ latencies for those apply_unbatched_cmd_cas calls are crazy and indeed seem to be crdb slowness. the 700ms rollup::set is blob though, which in dev is the local filesystem

[chaas]

A couple notes: 1) this is with running cockroach on Docker 2) I have an M1 mac
Also worth noting when I run bin/environmentd locally, the same CREATE statement takes ~2 seconds, which is slow but not as slow, so it appears to be both

1. some Cockroach slowness
2. something else unique to sqllogictest

For Cockroach slowness we can to put together a "packaged" report of what's wrong to share with them.
For the second issue, we need to do more debugging to get to the root cause.

[maddyblue]

700ms for a local filesystem operation is also way too long. This is for a CREATE TABLE on an empty process. What is taking 700ms to write? More evidence that this is not a cockroach-specific problem.

[teskje]

I don't see large CRDB latencies (using Docker CRDB on an M1 mac), but I do see the file system slowness. For me, the slowest operations happening during CREATE TABLE are batch::write_part operations. I added a couple more spans to see how those split up:

I think the take-away is that disk I/O is just slow. Maybe it could be sped up by using a ramdisk. Or maybe we can find a lightweight S3 mock backend and run our tests against that instead.

[teskje]

Maybe it could be sped up by using a ramdisk. Or maybe we can find a lightweight S3 mock backend and run our tests against that instead.

I did some more testing. Using the file system, my run of the above sqllogictest command takes ~50s.

• Using a ramdisk it takes ~25s.
• Using Minio it takes ~30s.

[tokenrove]

All those filesystem operations look anywhere from 10-40× more expensive than I'd expect them to be -- like rename(2) I'd expect to be no more than about a millisecond. Even the fsyncs I wouldn't expect to be that slow especially in a situation where only a small bit of metadata has changed. Is this overlayfs-on-top-of-ext4-on-top-of-some-VM-layer-on-top-of-HFS+?

[teskje]

Is this overlayfs-on-top-of-ext4-on-top-of-some-VM-layer-on-top-of-HFS+?

That was me running bin/sqllogictest on the host. I don't think that spawns a Docker container behind the scenes.

Note that those fs functions I instrumented were not literally fs operations but async functions performing the same. So there is probably some scheduling overhead involved as well.

[tokenrove]

Is this overlayfs-on-top-of-ext4-on-top-of-some-VM-layer-on-top-of-HFS+?

That was me running bin/sqllogictest on the host. I don't think that spawns a Docker container behind the scenes.

Brutal, so that's just HFS+ or whatever. Apparently sync_all on macOS really does cost 20ms though (it does fcntl F_FULLFSYNC rather than fsync). Maybe we need a reduced-durability-guarantees version of FileBlob for macOS :-)

[maddyblue]

Can we get an in-memory local persist store? That should be the bulk of the remainder after #17326.

[danhhz]

We have one, but it can't be shared across processes. Is that enough?

[maddyblue]

That should work for sqllogictest, which never restarts anything and checks state. Seems like this could be configurable in the process orchestrator via envd config that sqllogictest sets, and maybe we can also allow setting via the envd cli so that we can opt in locally. All mzcompose tests could use the existing disk store as the default.

[maddyblue]

We discovered using the existing mem impl isn't enough, and we'd need to create some shared server which itself uses the mem impl. Someone might type this up someday soon.

[benesch]

Just had a good Slack discussion about how we could instead build some tooling around using a ramfs for the blob store:

I think the way to do this is to teach run.py about some env var like MZ_DEV_RAMFS that specifies the path of a ramfs. When set, it launches environmentd and sqllogictest from within the ramfs, so that all state associated with those processes gets stored in the ramfs. And then we can have a separate set of scripts (or just guidance in the dev guide) about how to create a ramfs in /mnt/tmpfs or something like that.

Getting more clever is likely to be painful though. You need sudo for the mount commands, it’s different on macOS and Linux, etc.

[benesch]

Closing as stale. SLT is still slower than we'd like, but it's totally workable these days, including on my macOS machine.