startup slowness (related to DB size?)

Question

startup slowness (related to DB size?)

felixkrohn opened this issue a year ago · 17 comments

Hi,
I'm (very passively) using ktistec since somewhen late last year.
I noticed some time ago that ktistec stopped responding when I went further back in my activity stream, usually around page 11. Today I noticed that it wouldn't respond anymore at page 9, so I decided to restart the container.

I't been starting up for about 1h now, the process taking 99% of a CPU core, and the UI still not responding - neither locally (curl on 127.0.0.1) nor (of course) through the reverse proxy ("Error while Peeking first byte: read tcp: i/o timeout" says traefik), with the tcp session to ktistec timing out without any data.

The sqlite DB has grown to 510M size, might that be a reason? If yes, is there a way to keep the relevant data (subscriptions, user data, ...) and drop everything else for a clean new start?

Logs from before my restart are lost, however in the current log stream I see loads of this:

Exception: Error while writing data to the client (HTTP::Server::ClientError)
from ???
from ???
from ???
from ???
from ???
from ???
from ???
from ???
from ???
from ???
from ???
from ???
Caused by: Error writing to socket: Broken pipe (IO::Error)
from ???
from ???
from ???
from ???
from ???
from ???
from ???
from ???
from ???
from ???
from ???
from ???
from ???

Is there any way to debug further?
Do you maybe plan on releasing ready-to-use docker images in order to exclude an issue in individual builds?

Answer 1 · 2023-07-22T15:39:28.000Z

Paging hasn’t been a problem for me—I just verified to be sure. How much memory have you allocated to the container. The database size shouldn’t matter—SQLite is good at paging in what it needs, though it becomes a problem for backups and is imo crufty. What is logged immediately after the server starts?

Answer 2 · 2023-07-22T15:49:02.000Z

There's no set limit... and while is used around 470M before restart, it's now at almost 10G....

The first log lines look like this:

[development] Ktistec is ready to lead at http://0.0.0.0:8085
2023-07-22T13:16:54.349200Z INFO - OpenSSL::SSL::Error: SSL_connect: I/O error: https://bildung.social/users/YYY/inbox
2023-07-22T13:17:12.120430Z INFO - {"@context" => "https://www.w3.org/ns/activitystreams", "id" => "https://domain1.tld/users/XXX/followers", "type" => "OrderedCollection", "totalItems" => 735, "first" => "https://domain1.tld/users/XXX/followers?page=1"}
2023-07-22T13:17:12.387493Z INFO - {"@context" => "https://www.w3.org/ns/activitystreams", "id" => "https://domain1.tld/users/XXX/followers", "type" => "OrderedCollection", "totalItems" => 735, "first" => "https://domain1.tld/users/XXX/followers?page=1"}
2023-07-22T13:17:12.390705Z INFO - {"@context" => "https://www.w3.org/ns/activitystreams", "id" => "https://domain1.tld/users/XXX/followers", "type" => "OrderedCollection", "totalItems" => 735, "first" => "https://domain1.tld/users/XXX/followers?page=1"}
2023-07-22T13:17:12.413059Z INFO - {"@context" => "https://www.w3.org/ns/activitystreams", "id" => "https://domain1.tld/users/XXX/followers", "type" => "OrderedCollection", "totalItems" => 735, "first" => "https://domain1.tld/users/XXX/followers?page=1"}
2023-07-22T13:17:12.436870Z INFO - {"@context" => "https://www.w3.org/ns/activitystreams", "id" => "https://domain1.tld/users/XXX/followers", "type" => "OrderedCollection", "totalItems" => 735, "first" => "https://domain1.tld/users/XXX/followers?page=1"}
2023-07-22T13:17:12.472166Z INFO - {"@context" => "https://www.w3.org/ns/activitystreams", "id" => "https://domain1.tld/users/XXX/followers", "type" => "OrderedCollection", "totalItems" => 735, "first" => "https://domain1.tld/users/XXX/followers?page=1"}
2023-07-22T13:17:12.607536Z INFO - {"@context" => "https://www.w3.org/ns/activitystreams", "id" => "https://domain1.tld/users/XXX/followers", "type" => "OrderedCollection", "totalItems" => 735, "first" => "https://domain1.tld/users/XXX/followers?page=1"}
2023-07-22T13:17:12.763777Z INFO - {"@context" => "https://www.w3.org/ns/activitystreams", "id" => "https://domain1.tld/users/XXX/followers", "type" => "OrderedCollection", "totalItems" => 735, "first" => "https://domain1.tld/users/XXX/followers?page=1"}
2023-07-22T13:17:12.856096Z INFO - {"@context" => "https://www.w3.org/ns/activitystreams", "id" => "https://domain1.tld/users/XXX/followers", "type" => "OrderedCollection", "totalItems" => 735, "first" => "https://domain1.tld/users/XXX/followers?page=1"}
2023-07-22T13:17:13.023471Z INFO - {"@context" => "https://www.w3.org/ns/activitystreams", "id" => "https://social.linux.pizza/users/ZZZ/followers", "type" => "OrderedCollection", "totalItems" => 428, "first" => "https://social.linux.pizza/users/ZZZ/followers?page=1"}
2023-07-22T13:17:13.026786Z INFO - {"@context" => "https://www.w3.org/ns/activitystreams", "id" => "https://domain1.tld/users/XXX/followers", "type" => "OrderedCollection", "totalItems" => 735, "first" => "https://domain1.tld/users/XXX/followers?page=1"}
2023-07-22T13:17:13.028937Z INFO - {"@context" => "https://www.w3.org/ns/activitystreams", "id" => "https://domain1.tld/users/XXX/followers", "type" => "OrderedCollection", "totalItems" => 735, "first" => "https://domain1.tld/users/XXX/followers?page=1"}
2023-07-22T13:17:13.136447Z INFO - {"@context" => "https://www.w3.org/ns/activitystreams", "id" => "https://mastodon.gamedev.place/users/WWW/followers", "type" => "OrderedCollection", "totalItems" => 16215, "first" => "https://mastodon.gamedev.place/users/WWW/followers?page=1"}
2023-07-22T13:17:13.203296Z INFO - {"@context" => "https://www.w3.org/ns/activitystreams", "id" => "https://social.linux.pizza/users/ZZZ/followers", "type" => "OrderedCollection", "totalItems" => 428, "first" => "https://social.linux.pizza/users/ZZZ/followers?page=1"}
2023-07-22T13:17:13.205987Z INFO - {"@context" => "https://www.w3.org/ns/activitystreams", "id" => "https://domain1.tld/users/XXX/followers", "type" => "OrderedCollection", "totalItems" => 735, "first" => "https://domain1.tld/users/XXX/followers?page=1"}
2023-07-22T13:17:13.272893Z INFO - {"@context" => "https://www.w3.org/ns/activitystreams", "id" => "https://ard.social/users/tagesschau/followers", "type" => "OrderedCollection", "totalItems" => 30059, "first" => "https://ard.social/users/tagesschau/followers?page=1"}

(some user names anonymized)

Answer 3 · 2023-07-22T15:53:53.000Z

The CPU data shows high load when browsing and restarting, but back to almost idle when not accessing the instance:

Answer 4 · 2023-07-27T16:35:25.000Z

Now I managed to catch an error in the log (I rebuilt the container without the --no-debug flag):

2023-07-27 16:29:58 UTC 200 GET /actors/felix?page=9 66496.78ms
2023-07-27 16:29:58 UTC 404 GET /api/v1/streaming/public/local 5.16ms
2023-07-27 16:29:58 UTC 400 POST /actors/felix/inbox 52.08ms
2023-07-27 16:29:58 UTC 400 POST /actors/felix/inbox 117.04ms
Exception: Error while writing data to the client (HTTP::Server::ClientError)
from /usr/share/crystal/src/http/server/response.cr:206:9 in 'unbuffered_write'
from /usr/share/crystal/src/string.cr:5004:3 in '->'
from /build/lib/kemal/src/kemal/route.cr:12:9 in '->'
from /usr/share/crystal/src/primitives.cr:266:3 in 'call'
from /build/lib/kemal/src/kemal/exception_handler.cr:8:7 in 'call'
from /usr/share/crystal/src/http/server/handler.cr:28:7 in 'call'
from /usr/share/crystal/src/http/server/handler.cr:28:7 in 'call_next'
from /build/lib/kemal/src/kemal/init_handler.cr:12:7 in 'process'
from /usr/share/crystal/src/http/server.cr:500:5 in '->'
from /usr/share/crystal/src/primitives.cr:266:3 in 'run'
from ???
Caused by: Error writing to socket: Broken pipe (IO::Error)
from /usr/share/crystal/src/io/evented.cr:156:7 in 'unbuffered_write'
from /usr/share/crystal/src/http/server/response.cr:220:11 in 'unbuffered_write'
from /usr/share/crystal/src/string.cr:5004:3 in '->'
from /build/lib/kemal/src/kemal/route.cr:12:9 in '->'
from /usr/share/crystal/src/primitives.cr:266:3 in 'call'
from /build/lib/kemal/src/kemal/exception_handler.cr:8:7 in 'call'
from /usr/share/crystal/src/http/server/handler.cr:28:7 in 'call'
from /usr/share/crystal/src/http/server/handler.cr:28:7 in 'call_next'
from /build/lib/kemal/src/kemal/init_handler.cr:12:7 in 'process'
from /usr/share/crystal/src/http/server.cr:500:5 in '->'
from /usr/share/crystal/src/primitives.cr:266:3 in 'run'
from ???

2023-07-27T16:31:18.702407Z ERROR - http.server: Unhandled exception on HTTP::Handler
Closed stream (IO::Error)
from /usr/share/crystal/src/io.cr:118:5 in 'write'
from /usr/share/crystal/src/string.cr:5004:3 in 'call'
from /usr/share/crystal/src/http/server/handler.cr:28:7 in 'call'
from /usr/share/crystal/src/http/server/handler.cr:28:7 in 'call_next'
from /build/lib/kemal/src/kemal/init_handler.cr:12:7 in 'process'
from /usr/share/crystal/src/http/server.cr:500:5 in '->'
from /usr/share/crystal/src/primitives.cr:266:3 in 'run'
from ???

2023-07-27 16:31:18 UTC 404 GET /api/v1/streaming/public/local 5.08ms

Can I do more to help debug?

Answer 5 · 2023-07-27T16:59:42.000Z

regarding the pagination issue, I noticed the following:

2023-07-27 16:40:43 UTC 200 GET /actors/felix?page=2 17442.73ms
2023-07-27 16:41:45 UTC 200 GET /actors/felix?page=3 24561.63ms
2023-07-27 16:42:28 UTC 200 GET /actors/felix?page=4 31238.28ms
2023-07-27 16:43:13 UTC 200 GET /actors/felix?page=5 38625.38ms
2023-07-27 16:43:52 UTC 200 GET /actors/felix?page=5 38580.68ms
2023-07-27 16:44:37 UTC 200 GET /actors/felix?page=6 45340.8ms
2023-07-27 16:45:23 UTC 200 GET /actors/felix?page=6 45350.78ms
2023-07-27 16:46:16 UTC 200 GET /actors/felix?page=6 45606.9ms
2023-07-27 16:47:16 UTC 200 GET /actors/felix?page=7 52458.16ms
2023-07-27 16:48:23 UTC 200 GET /actors/felix?page=8 59604.79ms
2023-07-27 16:49:36 UTC 200 GET /actors/felix?page=9 67029.18ms

The higher the page number, the longer it takes ktistec to compute a result. When the answer time exceeds 60s, ktistec still assumes a success (code 200), but the page doesn't get delivered to the browser, who continues waiting after the log line appears, before erroring out about 30s later.

The traefik (reverse proxy in front) logs show this:

2023/07/07 17:42:34 transport.go:2262: Unsolicited response received on idle HTTP channel starting with "63e4\r\n \n \n \n <style type="text/css">\n body { text-align:center;font-family:helvetica,arial;font-size:22px;\n color:#888;margin:20px}\n img { max-width: 579px; width: 100%; }\n #c {margin:0 auto;width:500px;text-align:left}\n </style>\n \n \n
Kemal doesn't know this way.
\n [...]

I'll check if tuning traefik's timeout values helps at least delivering Kemal's error page.

Answer 6 · 2023-08-01T15:38:35.000Z

@felixkrohn those steadily increasing queries times for older content look at lot like an index is missing on the database. how comfortable would you be opening up the database from the command line and dumping out some information about your schema.

Answer 7 · 2023-08-06T16:49:54.000Z

@toddsundsted quite comfortable, what info would you need? (might answer with delay due to vacations)

Answer 8 · 2023-08-07T12:28:22.000Z

there are a few key tables that i'd like to check have the correct indexes. launch the sqlite3 shell on your database (sqlite3 ktistec.db) and then dump the schema for objects, actors and relationships (.schema objects etc.). i noticed a comment in the code about the query planner in some versions of sqlite not making optimal query plans. it would help to know what version of ktistec and sqlite you are running (the latter is dumped to the log when ktistec starts). we might have to get sqlite reanalyze the tables.

Answer 9 · 2023-08-27T07:44:43.000Z

Hi Todd,
thanks for your instructions and patience. Here's the sqlite output:

$ sqlite3 ktistec.db
SQLite version 3.34.1 2021-01-20 14:10:07
Enter ".help" for usage hints.
sqlite> .schema objects
CREATE TABLE objects (
"id" integer PRIMARY KEY AUTOINCREMENT,
"created_at" datetime NOT NULL,
"updated_at" datetime NOT NULL,
"type" varchar(63) NOT NULL,
"iri" varchar(255) NOT NULL COLLATE NOCASE,
"visible" boolean,
"published" datetime,
"attributed_to_iri" text COLLATE NOCASE,
"in_reply_to_iri" text COLLATE NOCASE,
"replies" text,
"to" text,
"cc" text,
"summary" text,
"content" text,
"media_type" text,
"source" text,
"attachments" text,
"urls" text,
"deleted_at" datetime
, blocked_at datetime, name text, thread text COLLATE NOCASE);
CREATE INDEX idx_objects_in_reply_to_iri
ON objects (in_reply_to_iri ASC);
CREATE INDEX idx_objects_published
ON objects (published ASC);
CREATE INDEX idx_objects_attributed_to_iri
ON objects (attributed_to_iri ASC);
CREATE UNIQUE INDEX idx_objects_iri
ON objects (iri ASC);
CREATE INDEX idx_objects_thread ON objects (thread ASC);
sqlite> .schema actors
CREATE TABLE actors (
"id" integer PRIMARY KEY AUTOINCREMENT,
"created_at" datetime NOT NULL,
"updated_at" datetime NOT NULL,
"type" varchar(63) NOT NULL,
"iri" varchar(255) NOT NULL COLLATE NOCASE,
"username" varchar(255),
"pem_public_key" text,
"pem_private_key" text,
"inbox" text,
"outbox" text,
"following" text,
"followers" text,
"name" text,
"summary" text,
"icon" text,
"image" text,
"urls" text,
"deleted_at" datetime
, blocked_at datetime, attachments text);
CREATE INDEX idx_actors_username
ON actors (username ASC);
CREATE UNIQUE INDEX idx_actors_iri
ON actors (iri ASC);
sqlite> .schema relationships
CREATE TABLE relationships (
id integer PRIMARY KEY AUTOINCREMENT,
created_at datetime NOT NULL,
updated_at datetime NOT NULL,
type varchar(63) NOT NULL,
from_iri varchar(255) NOT NULL COLLATE NOCASE,
to_iri varchar(255) NOT NULL COLLATE NOCASE,
confirmed boolean,
visible boolean
);
CREATE INDEX idx_relationships_to_iri_type
ON relationships (to_iri ASC, type ASC);
CREATE INDEX idx_relationships_from_iri_created_at_type ON relationships (from_iri ASC, created_at DESC, type ASC);

Answer 10 · 2023-08-29T14:11:10.000Z

@felixkrohn okay, those look fine. the other thing i've noticed is that the query optimizer sometimes needs a hint to get it to optimize sensibly—unfortunately, for me at least, whether it improves things seems to depend on sqlite version, and possibly some other factors. in any case, i'd recommend running the analyze command on the database:

make a backup copy of the database
in the sqlite shell run analyze;
restart

see: https://www.sqlite.org/lang_analyze.html

please make a backup first. i've see this result in worse performance for reasons i've never been able to debug.

reading through the docs, it seems like a good practice is to do small amounts of optimization whenever a database connection is closed. i'm going to play around with that to see if there are any obvious downsides.

Answer 11 · 2023-08-29T14:28:13.000Z

wow, I really didn't believe the analyze command could be this powerful...
You nailed it! I can now browse freely and fluently on my instance... page=1000 loads within seconds, 2000 as well - and my instance doesn't seem to live long enough for it to go much further.

Thanks again Todd!

Answer 12 · 2024-04-01T11:20:39.000Z

The analyze; command increased performance substantially.

There are still a lot of slow queries in the logs, but most of them seem to be related to clean up tasks, which are probably way overdue on my instance.

Answer 13 · 2024-05-03T20:31:26.000Z

Just wanted to add some more information here, as I looked into the logs a bit further. on every timeline load (or any page that shows some posts from anyone), I get following slow-query-warning:

2024-05-03T20:22:17.235426Z   WARN - Slow query [   776.893ms] -- WITH RECURSIVE replies_to(iri) AS ( VALUES(?) UNION SELECT o.iri FROM objects AS o, replies_to AS t JOIN actors AS a ON a.iri = o.attributed_to_iri WHERE o.in_reply_to_iri = t.iri AND o.deleted_at IS NULL AND o.blocked_at IS NULL AND a.deleted_at IS NULL AND a.blocked_at IS NULL ) SELECT count(o.iri) - 1 FROM objects AS o, replies_to AS r WHERE o.iri IN (r.iri) -- args: [" [URL TO SOME POST] "]

Every single one of these queries take between 500ms to 1500ms. So for each page of 10 posts, these queries alone take around 10 seconds for me.

That said, my database is around 3GB in size now, I am not entirely sure how much that might affect performance of these queries. So maybe trimming would be a workaround here as well (?)

Answer 14 · 2024-05-04T01:51:39.000Z

After the slow query log message there are usually several additional log messages with the query plan SQLite used to run the query. Can you provide those? See a potentially similar issue here for an example of what they look like?

Given that it's a recursive query, the problem might be the use of a bloom filter. There are a few versions of SQLite with a bug that affects Ktistec.

https://github.com/toddsundsted/ktistec?tab=readme-ov-file#sqlite3-compatibility

When you restart your server it logs the SQLite version you are using. Can you provide that version along with the query plan to confirm this.

Answer 15 · 2024-05-04T07:33:58.000Z

I am running ktistec via docker from the included dockerfile. Indeed, it uses thr affected sqlite 3.40.1

I'll try to bjndle a different version and give feedback again on the outcome

Answer 16 · 2024-05-04T11:20:11.000Z

Yes, this totally fixed the issue. timeline loading is now almost instant.

I did have to build my own crystal docker image, since the one used by the Dockerfile in ktistec (https://github.com/crystal-lang/distribution-scripts/blob/master/docker/alpine.Dockerfile) is based on alpine-3.17, which has sqlite-3.40.1.

I built my own from an alpine-3.19 image. The Dockerfile could be extended to:

# Crystal-Image
FROM alpine:3.19 as runtime
RUN \
  apk add --update --no-cache --force-overwrite \
    # core dependencies
    gcc gmp-dev libevent-static musl-dev pcre-dev pcre2-dev \
    # stdlib dependencies
    gc-dev libxml2-dev libxml2-static openssl-dev openssl-libs-static tzdata yaml-static zlib-static xz-static \
    # dev tools
    make git wget
RUN wget https://github.com/crystal-lang/crystal/releases/download/1.12.1/crystal-1.12.1-1-linux-x86_64.tar.gz \
  -O /tmp/crystal.tar.gz
RUN \
  tar -xz -C /usr --strip-component=1  -f /tmp/crystal.tar.gz \
    --exclude */lib/crystal/lib \
    --exclude */lib/crystal/*.a \
    --exclude */share/crystal/src/llvm/ext/llvm_ext.o && \
  rm /tmp/crystal.tar.gz
CMD ["/bin/sh"]

FROM runtime as build
RUN \
  apk add --update --no-cache --force-overwrite \
    llvm15-dev llvm15-static g++ libffi-dev
CMD ["/bin/sh"]

FROM build AS builder
RUN apk update && apk upgrade && apk add sqlite-static
WORKDIR /build/
ARG version
RUN git clone --branch ${version:-v2.0.0-11} --depth 1 https://github.com/toddsundsted/ktistec .
RUN shards update && shards install --production
RUN crystal build src/ktistec/server.cr --static --no-debug --release

FROM alpine:latest AS server
RUN apk --no-cache add tzdata
WORKDIR /app
COPY --from=builder /build/etc /app/etc
COPY --from=builder /build/public /app/public
COPY --from=builder /build/server /bin/server
RUN mkdir /db
RUN ln -s /app/public/uploads /uploads
ENV KTISTEC_DB=/db/ktistec.db
CMD ["/bin/server"]
VOLUME /db /uploads
EXPOSE 3000

@toddsundsted in case you are interested, I can push this as a PR?

Answer 17 · 2024-05-04T11:52:38.000Z

As I wrote in #96 - grabbing a newer version of sqlite-static from a newer Alpine release seems to be an easy workaround (not sure I would trust it if it wasn't static...) while this is probably the cleaner approach.

The problem will probably fix itself once the crystal builder image is updated upstream but the question is what's a good solution until then. (also the Dockerfile in main, and thus in the -11 tag, seems to still pull the -10 tag).