search

toddsundsted / ktistec

Single user ActivityPub (https://www.w3.org/TR/activitypub/) server.
GNU Affero General Public License v3.0
350 stars 21 forks source link

Pagination has become slow #96

Open winks opened 2 months ago

winks commented 2 months ago

Hey, I'm still(?) running 2.0.0-8 and recently I've noticed that pagination has become massively slow, going to https://sup.f5n.org/?page=2 from https://sup.f5n.org/?page=2 is easily 5-6s at times. Now that I properly tested it and not relied on my pinned tab loading whenever.. I think the same is true for the logged in start page.

CPU seems to be spiking a bit, the sqlite has grown to around 750MB since I deployed it but I suppose that shouldn't be it, as pagination just works?

Any clues how to debug or investigate that? The server is just a dual core VPS but the load is generally below one and everything else is running without noticeable performance issues.

Happy to try a new version if that makes sense but as I (at some point in the past) mentioned building is not even possible on this VPS, but I can use a bigger machine.

toddsundsted commented 2 months ago

@winks the issue is probably the query planner not making good use of indexes. take a look at https://github.com/toddsundsted/ktistec/issues/75. myself and others have had success running analyze on the database. (be sure to make a backup though)

winks commented 2 months ago

Thanks, my indices look just like the pasted example and I tried running analyze and also the PRAGMA optimize. I want to say it has gotten better, but it's still 20-25s, so maybe down 40-50% but still unbearably slow.

toddsundsted commented 2 months ago

my other suggestion is to upgrade if you can. i've also made changes to the queries (see 0d9002cb) that give the query planner hints about the most effective indices to use.

winks commented 2 months ago

Ok, that worked, thanks a lot.

I've had some problems with the build in the last year so I hadn't tried to upgrade in quite a bit, but the Dockerfile from the main branch worked perfectly just now. (Had to fiddle with the shards command, etc.pp, but doesn't matter now that it worked)

winks commented 2 months ago

Just updated to 2.0.0-11 and it's still not better but I finally see the same query being slow and logged.

Did multiple ANALYZE and I think I have all the migrations been run, and I checked the index names, so nothing obvious there, but I'm doublechecking that as it seems just so obviously slow.

Here's a full log (just redacted the URLs):

(oh, and running these interactively via sqlite3 during the application running gives results instantly, not after 3-10s)

2024-05-03 21:18:26 UTC 200 GET /actors/wink?page=2 59041.48ms
2024-05-03T21:17:29.628297Z NOTICE - database: Slow query [  2371.202ms] -- SELECT count(*) FROM relationships AS n LEFT JOIN activities AS a ON a.iri = n.to_iri LEFT JOIN actors AS c ON c.iri = a.actor_iri LEFT JOIN objects AS o ON o.iri =
 a.object_iri LEFT JOIN objects AS e ON e.iri = n.to_iri LEFT JOIN actors AS t ON t.iri = e.attributed_to_iri WHERE +n.from_iri = ? AND n.type IN ("Relationship::Content::Notification::Announce","Relationship::Content::Notification::Follow"
,"Relationship::Content::Notification::Like","Relationship::Content::Notification::Mention","Relationship::Content::Notification::Reply","Relationship::Content::Notification::Follow::Hashtag","Relationship::Content::Notification::Follow::Me
ntion","Relationship::Content::Notification::Follow::Thread","Relationship::Content::Notification")  AND "c".deleted_at IS NULL AND "c".blocked_at IS NULL   AND "o".deleted_at IS NULL AND "o".blocked_at IS NULL   AND "a".undone_at IS NULL
 AND "e".deleted_at IS NULL AND "e".blocked_at IS NULL   AND "t".deleted_at IS NULL AND "t".blocked_at IS NULL   AND n.created_at > ? -- args: ["https://sup.f5n.org/actors/wink", 2024-04-05 18:31:14.0 UTC]
2024-05-03T21:17:29.628319Z NOTICE - database: [{0, "SCAN n"}, {0, "SEARCH a USING INDEX idx_activities_iri (iri=?) LEFT-JOIN"}, {0, "SEARCH c USING INDEX idx_actors_iri (iri=?) LEFT-JOIN"}, {0, "SEARCH o USING INDEX idx_objects_iri (iri=?)
 LEFT-JOIN"}, {0, "SEARCH e USING INDEX idx_objects_iri (iri=?) LEFT-JOIN"}, {0, "SEARCH t USING INDEX idx_actors_iri (iri=?) LEFT-JOIN"}]
2024-05-03T21:17:35.591775Z NOTICE - database: Slow query [  5947.780ms] -- 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: ["https://hachyderm.io/users/..."]
2024-05-03T21:17:35.591806Z NOTICE - database: [{0, "MATERIALIZE replies_to"}, {3, "SETUP"}, {8, "SCAN CONSTANT ROW"}, {3, "RECURSIVE STEP"}, {24, "SCAN t"}, {24, "BLOOM FILTER ON o (in_reply_to_iri=?)"}, {24, "SEARCH o USING INDEX idx_obje
cts_in_reply_to_iri (in_reply_to_iri=?)"}, {24, "BLOOM FILTER ON a (iri=?)"}, {24, "SEARCH a USING INDEX idx_actors_iri (iri=?)"}, {0, "SCAN r"}, {0, "SEARCH o USING COVERING INDEX idx_objects_iri (iri=?)"}]
2024-05-03T21:17:42.237027Z NOTICE - database: Slow query [  6640.286ms] -- 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: ["https://tech.lgbt/users/..."]
2024-05-03T21:17:42.237052Z NOTICE - database: [{0, "MATERIALIZE replies_to"}, {3, "SETUP"}, {8, "SCAN CONSTANT ROW"}, {3, "RECURSIVE STEP"}, {24, "SCAN t"}, {24, "BLOOM FILTER ON o (in_reply_to_iri=?)"}, {24, "SEARCH o USING INDEX idx_obje
cts_in_reply_to_iri (in_reply_to_iri=?)"}, {24, "BLOOM FILTER ON a (iri=?)"}, {24, "SEARCH a USING INDEX idx_actors_iri (iri=?)"}, {0, "SCAN r"}, {0, "SEARCH o USING COVERING INDEX idx_objects_iri (iri=?)"}]
2024-05-03T21:17:44.542182Z NOTICE - database: Slow query [  2291.769ms] -- 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: ["https://hachyderm.io/users/..."]
2024-05-03T21:17:44.542207Z NOTICE - database: [{0, "MATERIALIZE replies_to"}, {3, "SETUP"}, {8, "SCAN CONSTANT ROW"}, {3, "RECURSIVE STEP"}, {24, "SCAN t"}, {24, "BLOOM FILTER ON o (in_reply_to_iri=?)"}, {24, "SEARCH o USING INDEX idx_obje
cts_in_reply_to_iri (in_reply_to_iri=?)"}, {24, "BLOOM FILTER ON a (iri=?)"}, {24, "SEARCH a USING INDEX idx_actors_iri (iri=?)"}, {0, "SCAN r"}, {0, "SEARCH o USING COVERING INDEX idx_objects_iri (iri=?)"}]
2024-05-03T21:17:50.090811Z NOTICE - database: Slow query [  5544.679ms] -- 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: ["https://mastodon.social/users/..."]
2024-05-03T21:17:50.090840Z NOTICE - database: [{0, "MATERIALIZE replies_to"}, {3, "SETUP"}, {8, "SCAN CONSTANT ROW"}, {3, "RECURSIVE STEP"}, {24, "SCAN t"}, {24, "BLOOM FILTER ON o (in_reply_to_iri=?)"}, {24, "SEARCH o USING INDEX idx_obje
cts_in_reply_to_iri (in_reply_to_iri=?)"}, {24, "BLOOM FILTER ON a (iri=?)"}, {24, "SEARCH a USING INDEX idx_actors_iri (iri=?)"}, {0, "SCAN r"}, {0, "SEARCH o USING COVERING INDEX idx_objects_iri (iri=?)"}]
2024-05-03T21:18:01.105278Z NOTICE - database: Slow query [ 11006.859ms] -- 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: ["https://mastodon.social/users/..."]
2024-05-03T21:18:01.105308Z NOTICE - database: [{0, "MATERIALIZE replies_to"}, {3, "SETUP"}, {8, "SCAN CONSTANT ROW"}, {3, "RECURSIVE STEP"}, {24, "SCAN t"}, {24, "BLOOM FILTER ON o (in_reply_to_iri=?)"}, {24, "SEARCH o USING INDEX idx_obje
cts_in_reply_to_iri (in_reply_to_iri=?)"}, {24, "BLOOM FILTER ON a (iri=?)"}, {24, "SEARCH a USING INDEX idx_actors_iri (iri=?)"}, {0, "SCAN r"}, {0, "SEARCH o USING COVERING INDEX idx_objects_iri (iri=?)"}]
2024-05-03T21:18:06.890487Z NOTICE - database: Slow query [  5772.134ms] -- 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: ["https://octodon.social/users/..."]
2024-05-03T21:18:06.890520Z NOTICE - database: [{0, "MATERIALIZE replies_to"}, {3, "SETUP"}, {8, "SCAN CONSTANT ROW"}, {3, "RECURSIVE STEP"}, {24, "SCAN t"}, {24, "BLOOM FILTER ON o (in_reply_to_iri=?)"}, {24, "SEARCH o USING INDEX idx_obje
cts_in_reply_to_iri (in_reply_to_iri=?)"}, {24, "BLOOM FILTER ON a (iri=?)"}, {24, "SEARCH a USING INDEX idx_actors_iri (iri=?)"}, {0, "SCAN r"}, {0, "SEARCH o USING COVERING INDEX idx_objects_iri (iri=?)"}]
2024-05-03T21:18:10.420468Z NOTICE - database: Slow query [  3523.573ms] -- 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: ["https://..."]
2024-05-03T21:18:10.420513Z NOTICE - database: [{0, "MATERIALIZE replies_to"}, {3, "SETUP"}, {8, "SCAN CONSTANT ROW"}, {3, "RECURSIVE STEP"}, {24, "SCAN t"}, {24, "BLOOM FILTER ON o (in_reply_to_iri=?)"}, {24, "SEARCH o USING INDEX idx_obje
cts_in_reply_to_iri (in_reply_to_iri=?)"}, {24, "BLOOM FILTER ON a (iri=?)"}, {24, "SEARCH a USING INDEX idx_actors_iri (iri=?)"}, {0, "SCAN r"}, {0, "SEARCH o USING COVERING INDEX idx_objects_iri (iri=?)"}]
2024-05-03T21:18:10.531843Z NOTICE - database: Slow query [   104.589ms] -- 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: ["https://..."]
2024-05-03T21:18:10.531866Z NOTICE - database: [{0, "MATERIALIZE replies_to"}, {3, "SETUP"}, {8, "SCAN CONSTANT ROW"}, {3, "RECURSIVE STEP"}, {24, "SCAN t"}, {24, "BLOOM FILTER ON o (in_reply_to_iri=?)"}, {24, "SEARCH o USING INDEX idx_obje
cts_in_reply_to_iri (in_reply_to_iri=?)"}, {24, "BLOOM FILTER ON a (iri=?)"}, {24, "SEARCH a USING INDEX idx_actors_iri (iri=?)"}, {0, "SCAN r"}, {0, "SEARCH o USING COVERING INDEX idx_objects_iri (iri=?)"}]
2024-05-03T21:18:16.267701Z NOTICE - database: Slow query [  5731.985ms] -- 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: ["https://mastodon.social/users
/..."]
2024-05-03T21:18:16.267742Z NOTICE - database: [{0, "MATERIALIZE replies_to"}, {3, "SETUP"}, {8, "SCAN CONSTANT ROW"}, {3, "RECURSIVE STEP"}, {24, "SCAN t"}, {24, "BLOOM FILTER ON o (in_reply_to_iri=?)"}, {24, "SEARCH o USING INDEX idx_obje
cts_in_reply_to_iri (in_reply_to_iri=?)"}, {24, "BLOOM FILTER ON a (iri=?)"}, {24, "SEARCH a USING INDEX idx_actors_iri (iri=?)"}, {0, "SCAN r"}, {0, "SEARCH o USING COVERING INDEX idx_objects_iri (iri=?)"}]
2024-05-03T21:18:26.282374Z NOTICE - database: Slow query [ 10000.087ms] -- 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: ["https://..."]
2024-05-03T21:18:26.282408Z NOTICE - database: [{0, "MATERIALIZE replies_to"}, {3, "SETUP"}, {8, "SCAN CONSTANT ROW"}, {3, "RECURSIVE STEP"}, {24, "SCAN t"}, {24, "BLOOM FILTER ON o (in_reply_to_iri=?)"}, {24, "SEARCH o USING INDEX idx_obje
cts_in_reply_to_iri (in_reply_to_iri=?)"}, {24, "BLOOM FILTER ON a (iri=?)"}, {24, "SEARCH a USING INDEX idx_actors_iri (iri=?)"}, {0, "SCAN r"}, {0, "SEARCH o USING COVERING INDEX idx_objects_iri (iri=?)"}]

this is a breakdown of the database (824 MB):

sqlite> select count(*) from accounts;
1
sqlite> select count(*) from coll
COLLATE      collections
sqlite> select count(*) from collections ;
6580
sqlite> select count(*) from migrations ;
44
sqlite> select count(*) from points ;
43778
sqlite> select count(*) from tag_statistics ;
15110
sqlite> select count(*) from activities ;
345914
sqlite> select count(*) from filter_terms ;
0
sqlite> select count(*) from objects;
159266
sqlite> select count(*) from relationships ;
329689
sqlite> select count(*) from tags;
182767
sqlite> select count(*) from actors;
157868
sqlite> select count(*) from last_times ;
1
sqlite> select count(*) from options ;
4
sqlite> select count(*) from sessions;
4471
sqlite> select count(*) from tasks;
17066
toddsundsted commented 2 months ago

Thank you for providing the logs with the query plan output! The issue is the use of bloom filter (99% certain). 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 to confirm this.

There are a few alternatives. One is to change the version of SQLite you build and run against. The other is to implement "a fix" that disables bloom filters.

But first, can you confirm your SQLite version?

toddsundsted commented 2 months ago

If you're feeling adventurous, here's the patch that turns off the use of Bloom filters. It probably won't apply cleanly against v2.0.0-8 but it should not require too much hand modification.

diff --git a/src/framework/ext/sqlite3.cr b/src/framework/ext/sqlite3.cr
index f0101bdf..2e544dd0 100644
--- a/src/framework/ext/sqlite3.cr
+++ b/src/framework/ext/sqlite3.cr
@@ -52,11 +52,13 @@ lib LibSQLite3
   fun result_text = sqlite3_result_text(SQLite3Context, UInt8*, Int32, Void*) : Nil
   fun version_number = sqlite3_libversion_number() : Int32
   fun version = sqlite3_libversion() : UInt8*
+  fun test_control = sqlite3_test_control(Int32, ...) : Int32
 end

 module Ktistec
   module SQLite3
     SQLITE_CONFIG_MEMSTATUS = 9_i32
+    SQLITE_TESTCTRL_OPTIMIZATIONS = 15_i32

     if (code = LibSQLite3.config(SQLITE_CONFIG_MEMSTATUS, 1_i32)) != LibSQLite3::Code::OKAY
       Log.warn { "#{code}: couldn't set SQLITE_CONFIG_MEMSTATUS: this is not fatal" }
@@ -87,6 +89,10 @@ module Ktistec

     Ktistec.database.setup_connection do |connection|
       LibSQLite3.create_function(connection, "strip", 1, UTF8 | DETERMINISTIC | DIRECTONLY, nil, ->strip_fn, nil, nil)
+
+      # Disable bloom filters.
+      LibSQLite3.test_control(Ktistec::SQLite3::SQLITE_TESTCTRL_OPTIMIZATIONS, connection, 0x080000_i32)
+
     end

     LibSQLite3.version.tap do |version|
winks commented 2 months ago

There are a few versions of SQLite with a bug that affects Ktistec.

Oh wow, I'd totally overlooked this in the README, sorry. This is from my container:

SQLite3 version 3.40.1

But now for the weird part. I built this last night with the Dockerfile from the main branch:

 $ docker run --rm -it crystallang/crystal:latest-alpine
[...]
/ # apk add sqlite-static
(1/1) Installing sqlite-static (3.40.1-r1)

So how did you build it that you didn't have the problem? (I am pretty sure I built the version before that with the 1.7.3 crystal base image, but that also gives me 3.40.1-r1 when I upgrade it now although it is based on Alpine 3.16...

Or did sqlite create the filters back then with a bad version? That sounds a bit unlikely...

winks commented 2 months ago

Yeah that solved it.

Instead of patching the code I fiddled with the build image, here's the diff:

diff --git Dockerfile Dockerfile
index 70b25a4c..c672fd66 100644
--- Dockerfile
+++ Dockerfile
@@ -1,9 +1,11 @@
 FROM crystallang/crystal:latest-alpine AS builder
-RUN apk update && apk upgrade && apk add sqlite-static
+RUN apk update && apk upgrade && apk add npm && apk add sqlite-static --repository=https://dl-cdn.alpinelinux.org/alpine/edge/main
 WORKDIR /build/
 ARG version
-RUN git clone --branch ${version:-v2.0.0-10} --depth 1 https://github.com/toddsundsted/ktistec .
+RUN git clone --branch main --depth 1 https://github.com/toddsundsted/ktistec .
 RUN shards update && shards install --production
+RUN npm install
+RUN npm run build
 RUN crystal build src/ktistec/server.cr --static --no-debug --release

 FROM alpine:latest AS server

pagination now takes 1.4 - 2.8s with SQLite3 version 3.45.3

toddsundsted commented 2 months ago

pagination now takes 1.4 - 2.8s

1.4 seconds would still be a slow query, even for pagination. i run a pretty low power cloud VM and no page takes longer than 100msec to load, even far back in history. how long does it take to just load the main page?

winks commented 2 months ago

Main page at /, logged in - 2583ms according to the log, 4.07s according to Firefox / Network tab

First pagination - 2515ms, and 4.31s with Firefox.

I know that's still kinda slow but it's no comparison.

Putting in the 2 queries below:

2024-05-05 11:31:29 UTC 200 GET /actors/wink 2583.09ms
2024-05-05T11:31:29.417052Z NOTICE - database: Slow query [  2503.607ms] -- SELECT count(*) FROM relationships AS n LEFT JOIN activities AS a ON a.iri = n.to_iri LEFT JOIN actors AS c ON c.iri = a.actor_iri LEFT JOIN objects AS o ON o.iri = a.object_iri LEFT JOIN objects AS e ON e.iri = n.to_iri LEFT JOIN actors AS t ON t.iri = e.attributed_to_iri WHERE +n.from_iri = ? AND n.type IN ("Relationship::Content::Notification::Announce","Relationship::Content::Notification::Follow","Relationship::Content::Notification::Like","Relationship::Content::Notification::Mention","Relationship::Content::Notification::Reply","Relationship::Content::Notification::Follow::Hashtag","Relationship::Content::Notification::Follow::Mention","Relationship::Content::Notification::Follow::Thread","Relationship::Content::Notification")  AND "c".deleted_at IS NULL AND "c".blocked_at IS NULL   AND "o".deleted_at IS NULL AND "o".blocked_at IS NULL   AND "a".undone_at IS NULL   AND "e".deleted_at IS NULL AND "e".blocked_at IS NULL   AND "t".deleted_at IS NULL AND "t".blocked_at IS NULL   AND n.created_at > ? -- args: ["https://sup.f5n.org/actors/wink", 2024-04-05 18:31:14.0 UTC]
2024-05-05T11:31:29.417075Z NOTICE - database: [{0, "SCAN n"}, {0, "SEARCH a USING INDEX idx_activities_iri (iri=?) LEFT-JOIN"}, {0, "SEARCH c USING INDEX idx_actors_iri (iri=?) LEFT-JOIN"}, {0, "SEARCH o USING INDEX idx_objects_iri (iri=?) LEFT-JOIN"}, {0, "SEARCH e USING INDEX idx_objects_iri (iri=?) LEFT-JOIN"}, {0, "SEARCH t USING INDEX idx_actors_iri (iri=?) LEFT-JOIN"}]
2024-05-05 11:32:33 UTC 200 GET /actors/wink?page=2 2515.25ms
2024-05-05T11:32:33.902353Z NOTICE - database: Slow query [  2459.967ms] -- SELECT count(*) FROM relationships AS n LEFT JOIN activities AS a ON a.iri = n.to_iri LEFT JOIN actors AS c ON c.iri = a.actor_iri LEFT JOIN objects AS o ON o.iri = a.object_iri LEFT JOIN objects AS e ON e.iri = n.to_iri LEFT JOIN actors AS t ON t.iri = e.attributed_to_iri WHERE +n.from_iri = ? AND n.type IN ("Relationship::Content::Notification::Announce","Relationship::Content::Notification::Follow","Relationship::Content::Notification::Like","Relationship::Content::Notification::Mention","Relationship::Content::Notification::Reply","Relationship::Content::Notification::Follow::Hashtag","Relationship::Content::Notification::Follow::Mention","Relationship::Content::Notification::Follow::Thread","Relationship::Content::Notification")  AND "c".deleted_at IS NULL AND "c".blocked_at IS NULL   AND "o".deleted_at IS NULL AND "o".blocked_at IS NULL   AND "a".undone_at IS NULL   AND "e".deleted_at IS NULL AND "e".blocked_at IS NULL   AND "t".deleted_at IS NULL AND "t".blocked_at IS NULL   AND n.created_at > ? -- args: ["https://sup.f5n.org/actors/wink", 2024-04-05 18:31:14.0 UTC]
2024-05-05T11:32:33.902377Z NOTICE - database: [{0, "SCAN n"}, {0, "SEARCH a USING INDEX idx_activities_iri (iri=?) LEFT-JOIN"}, {0, "SEARCH c USING INDEX idx_actors_iri (iri=?) LEFT-JOIN"}, {0, "SEARCH o USING INDEX idx_objects_iri (iri=?) LEFT-JOIN"}, {0, "SEARCH e USING INDEX idx_objects_iri (iri=?) LEFT-JOIN"}, {0, "SEARCH t USING INDEX idx_actors_iri (iri=?) LEFT-JOIN"}]

The VM isn't particularly great either but it's idling at load 0.0x to 0.2 and not spiking when I click the pagination. There's a ton of other stuff running though, at normal speed.

toddsundsted commented 2 months ago

those queries are not using the indexes they should be using.

for comparison (running the same versions of both server and database), i get:

2024-05-05T11:54:01.733186Z NOTICE - database: Slow query [    65.569ms] -- SELECT count(*) FROM relationships AS n LEFT JOIN activities AS a ON a.iri = n.to_iri LEFT JOIN actors AS c ON c.iri = a.actor_iri LEFT JOIN objects AS o ON o.iri = a.object_iri LEFT JOIN objects AS e ON e.iri = n.to_iri LEFT JOIN actors AS t ON t.iri = e.attributed_to_iri WHERE +n.from_iri = ? AND n.type IN ("Relationship::Content::Notification::Announce","Relationship::Content::Notification::Follow","Relationship::Content::Notification::Like","Relationship::Content::Notification::Mention","Relationship::Content::Notification::Reply","Relationship::Content::Notification::Follow::Hashtag","Relationship::Content::Notification::Follow::Mention","Relationship::Content::Notification::Follow::Thread","Relationship::Content::Notification")  AND "c".deleted_at IS NULL AND "c".blocked_at IS NULL   AND "o".deleted_at IS NULL AND "o".blocked_at IS NULL   AND "a".undone_at IS NULL   AND "e".deleted_at IS NULL AND "e".blocked_at IS NULL   AND "t".deleted_at IS NULL AND "t".blocked_at IS NULL   AND n.created_at > ? -- args: ["https://epiktistes.com/actors/toddsundsted", 2024-05-01 19:58:06.809000000 UTC]
2024-05-05T11:54:01.733334Z NOTICE - database: [{0, "SEARCH n USING INDEX idx_relationships_type (type=?)"}, {0, "SEARCH a USING INDEX idx_activities_iri (iri=?) LEFT-JOIN"}, {0, "SEARCH c USING INDEX idx_actors_iri (iri=?) LEFT-JOIN"}, {0, "SEARCH o USING INDEX idx_objects_iri (iri=?) LEFT-JOIN"}, {0, "SEARCH e USING INDEX idx_objects_iri (iri=?) LEFT-JOIN"}, {0, "SEARCH t USING INDEX idx_actors_iri (iri=?) LEFT-JOIN"}]
winks commented 2 months ago

I just did a .schema dump of my Sqlite DB and a new one I spun up with 2.0.0-11.

All indices are there, all create table statements are the same, the only differences are indentation and sometimes the quoting, which is odd but should not matter.

Example:

-    "deleted_at" datetime
-  , blocked_at datetime, name text, thread text COLLATE NOCASE);
+    "deleted_at" datetime,
+    "blocked_at" datetime,
+    "name" text,
+    "thread" text COLLATE NOCASE
+  );
toddsundsted commented 2 months ago

the query plan for your instance isn't using "idx_relationships_type" at all, which is the best index for this query since the count we want is roughly the number of relationships of that type.

can you confirm that "idx_relationships_type" exists, and if it exists run "ANALYZE idx_relationships_type;" with the sqlite command line utility (to see if that nudges the query planner to pick up the index).

winks commented 2 months ago 
sqlite> explain query plan select count(*) from relationships ;
QUERY PLAN
`--SCAN TABLE relationships USING COVERING INDEX idx_relationships_type
Run Time: real 0.000 user 0.000024 sys 0.000045

sqlite> analyze idx_relationships_type;
Run Time: real 0.121 user 0.037912 sys 0.021163

sqlite> explain query plan SELECT count(*) FROM relationships AS n LEFT JOIN activities AS a ON a.iri = n.to_iri LEFT JOIN actors AS c ON c.iri = a.actor_iri LEFT JOIN objects AS o ON o.iri = a.object_iri LEFT JOIN objects AS e ON e.iri = n.to_iri LEFT JOIN actors AS t ON t.iri = e.attributed_to_iri WHERE n.from_iri = "https://sup.f5n.org/actors/wink" AND n.type IN ("Relationship::Content::Notification::Announce","Relationship::Content::Notification::Follow","Relationship::Content::Notification::Like","Relationship::Content::Notification::Mention","Relationship::Content::Notification::Reply","Relationship::Content::Notification::Follow::Hashtag","Relationship::Content::Notification::Follow::Mention","Relationship::Content::Notification::Follow::Thread","Relationship::Content::Notification")  AND "c".deleted_at IS NULL AND "c".blocked_at IS NULL   AND "o".deleted_at IS NULL AND "o".blocked_at IS NULL   AND "a".undone_at IS NULL   AND "e".deleted_at IS NULL AND "e".blocked_at IS NULL   AND "t".deleted_at IS NULL AND "t".blocked_at IS NULL and n.created_at > "2024-04-05";
QUERY PLAN
|--SCAN TABLE relationships AS n
|--SEARCH TABLE activities AS a USING INDEX idx_activities_iri (iri=?)
|--SEARCH TABLE actors AS c USING INDEX idx_actors_iri (iri=?)
|--SEARCH TABLE objects AS o USING INDEX idx_objects_iri (iri=?)
|--SEARCH TABLE objects AS e USING INDEX idx_objects_iri (iri=?)
`--SEARCH TABLE actors AS t USING INDEX idx_actors_iri (iri=?)
Run Time: real 0.000 user 0.000079 sys 0.000145

it's really weird

winks commented 2 months ago

TIL about https://sqlite.org/lang_reindex.html - it's 150-200ms now

toddsundsted commented 2 months ago

reindex fixed the query?

winks commented 2 months ago

Yep, thanks for the pointers.

2024-05-05 14:29:31 UTC 200 GET /actors/wink 134.3ms
2024-05-05 14:29:59 UTC 200 GET /actors/wink?page=2 128.95ms
2024-05-05 14:30:02 UTC 200 GET /actors/wink?page=3 140.08ms

Still not completely sure why in the CLI it still says SCAN TABLE relationships AS n when it's clearly fast... but maybe that is the version 3.31.1 here.