High database usage by get_auth_chain_ids_chains after no particular event

[n-peugnet]

Description

The CPU usage of my server started to increase after no particular action on my end. After digging a little, I did find that the get_auth_chain_ids_chains transaction started to take a lot more time that previously.

Synapse exporter:

Postgres exporter:

Steps to reproduce

• Run synapse for a long time 😅

Homeserver

club1.fr

Synapse Version

1.103.0

Installation Method

Debian packages from packages.matrix.org

Database

PostgreSQL single server, restored from a backup

Workers

Single process

Platform

• Debian 11 Bullseye
• Linux club1.fr 5.10.0-31-amd64 #1 SMP Debian 5.10.221-1 (2024-07-14) x86_64 GNU/Linux
• No VM, no Containers, Bare metal

Configuration

Definitely some unusual config:

# Message retention policy at the server level.
#
# Room admins and mods can define a retention period for their rooms using the
# 'm.room.retention' state event, and server admins can cap this period by setting
# the 'allowed_lifetime_min' and 'allowed_lifetime_max' config options.
#
# If this feature is enabled, Synapse will regularly look for and purge events
# which are older than the room's maximum retention period. Synapse will also
# filter events received over federation so that events that should have been
# purged are ignored and not stored again.
#
retention:
  # The message retention policies feature is disabled by default. Uncomment the
  # following line to enable it.
  #
  enabled: true

  # Default retention policy. If set, Synapse will apply it to rooms that lack the
  # 'm.room.retention' state event. Currently, the value of 'min_lifetime' doesn't
  # matter much because Synapse doesn't take it into account yet.
  #
  default_policy:
    min_lifetime: 1d
    max_lifetime: 3y

media_retention:
  local_media_lifetime: 2y
  remote_media_lifetime: 90d

# When this option is enabled, the room "complexity" will be checked before a user
# joins a new remote room. If it is above the complexity limit, the server will
# disallow joining, or will instantly leave.
limit_remote_rooms:
  enabled: true
  complexity: 10
  complexity_error: "Désolé, cette room est trop complèxe pour le serveur CLUB1."
  admins_can_join: false

# disable presence completely
presence:
  enabled: false

Relevant log output

https://static.club1.fr/nicolas/random-other/log-synapse-2024-07-19.log

Anything else that would be useful to know?

No response

[n-peugnet]

I enabled DEBUG logging for synapse.storage.SQL, and I can sew quite a few blocks like this one:

2024-07-22 21:47:14,401 - synapse.storage.SQL - 493 - DEBUG - GET-3728057 - [SQL time] {get_auth_chain_ids_chains-c52929} 6.112671 sec
2024-07-22 21:47:14,420 - synapse.storage.SQL - 467 - DEBUG - GET-3728057 - [SQL] {get_auth_chain_ids_chains-c52929} WITH RECURSIVE links(chain_id) AS ( SELECT DISTINCT origin_chain_id FROM event_auth_chain_links WHERE origin_chain_id = ANY(?) UNION SELECT target_chain_id FROM event_auth_chain_links INNER JOIN links ON (chain_id = origin_chain_id) ) SELECT origin_chain_id, origin_sequence_number, target_chain_id, target_sequence_number FROM links INNER JOIN event_auth_chain_links ON (chain_id = origin_chain_id)
2024-07-22 21:47:14,421 - synapse.storage.SQL - 472 - DEBUG - GET-3728057 - [SQL values] {get_auth_chain_ids_chains-c52929} [[1733489, 448752, 1733506, 448754, 1602442, 1733521, 1602450, 1733538, 1602478, 454457, 448763, 454458, 448771, 1733609, 1733613, 448784, 1471551, 448794, 1602642, 448802, 1602710, 448812, 1602732, 1602750, 1733899, 1733903, 1602838, 1733921, 1602890, 448847, 448849, 448852, 448856, 1734028, 448861, 448864, 1734088, 1734090, 1734117, 1734171, 1734196, 448892, 1734206, 1734208, 1734209, 1603139, 1603142, 1734218, 1734224, 1603159, 1603169, 1603170, 1734291, 1603236, 1603266, 1734340, 448920, 1603271, 685786, 1734363, 1341158, 448931, 1341182, 1603335, 1734438, 1734446, 685879, 1341242, 1341244, 448944, 685889, 1734473, 448947, 1734479, 1603412, 1341269, 685909, 685920, 685921, 685923, 1603441, 448955, 685942, 685950, 685965, 1734545, 685986, 685988, 1734575, 686000, 686002, 686004, 1341378, 686022, 1603537, 1734638, 1734642, 448982, 1603596, 1734674, 1341467, 1603615, 1603623, 1603625, 448991, 1734700, 448994, 1341503, 1341504, 1603678, 1734763, 1734765, 449007, 1734784, 1603728, 449013, 449018, 1734837, 1341623, 1603777, 1734870, 1734878, 1341673, 1734893, 1734903, 1734906, 449033, 1603839, 1734915, 449036, 1734928, 1734930, 449038, 1603874, 1341753, 1341763, 1341767, 1603914, 1341775, 1734998, 1360858, 1341794, 1341800, 449057, 1735048, 1735052, 1735068, 1735069, 1604001, 1735077, 1735085, 1604044, 1604061, 1604078, 1341947, 1604113, 1735190, 1735211, 1604164, 449103, 1735268, 1735280, 1735293, 1342079, 1604230, 449112, 1735334, 449119, 1735369, 1735375, 1735377, 449128, 1735394, 1604328, 449131, 1342195, 1735418, 1604361, 1735444, 1735453, 1735480, 1735484, 1360953, 1735502, 1735516, 1735533, 1735534, 1106879, 1604485, 1604487, 1735559, 1735585, 1735594, 449171, 1735606, 1604542, 1342400, 1342405, 1604553, 1342412, 1604567, 1735646, 1735653, 1604583, 449183, 1342455, 1735687, 1342472, 1735711, 449195, 1342557, 1735784, 1361016, 1080445, 1735808, 454547, 1735824, 449216, 449217, 1735841, 1735843, 1604779, 1080498, 1735862, 1735867, 1342659, 1735876, 449227, 1735889, 1604819, 1735893, 1080548, 1735919, 1735933, 1604874, 1735951, 1735954, 1736001, 1736007, 1736010, 1736013, 1736032, 1736053, 1604989, 687504, 687511, 1605032, 1605038, 1605059, 687567, 1342937, 1361088, 687616, 1605134, 687631, 449293, 1605147, 1343025, 1605179, 1605183, 687685, 687694, 687711, 687726, 449310, 1605245, 687745, 1605261, 449318, 1343140, 1626844, 687792, 1343165, 1343176, 1361133, 687826, 1343188, 449336, 1605396, 1605404, 1605426, 1605428, 1343285, 687929, 1605438, 1343313, 1605459, 1605460, 687967, 687976, 687984, 449367, 1343379, 1343426, 1605598, 454583, 449399, 1474621, 1361209, 449411, 1605767, 1343662, 449425, 1605814, 1343702, 1343719, 1605902, 1343783, 1605941, 1343800, 1361264, 1343877, 449470, 449483, 1606133, 1343990, 1344038, 1606212, 449509, 1344114, 1606262, 1344120, 1606286, 1344156, 1344163, 449526, 1606320, 449534, 1606360, 1344239, 1606425, 1606438, 1344294, 1344300, 1606446, 1606455, 1100845, 449556, 449561, 1606534, 1344410, 1344415, 1344456, 449583, 1606613, 449586, 1361393, 1344520, 449595, 449596, 1344532, 1606679, 449599, 449603, 449605, 1606756, 1606759, 1344616, 1606770, 1344673, 1344686, 449628, 1344694, 1606849, 1606876, 1344761, 1606912, 449649, 1606938, 1606939, 1606943, 1606953, 1344814, 1606964, 1231202, 1344855, 449667, 1607033, 1607036, 449672, 1607056, 1607060, 449674, 1607067, 1213854, 1344940, 449679, 1213967, 449698, 1345056, 1345094, 1345105, 1345114, 449718, 1345143, 970756, 1345174, 1345182, 1361533, 454650, 1083080, 454653, 1345281, 449747, 1345300, 1345388, 1345392, 449769, 449789, 690171, 690174, 690176, 970829, 1345583, 690284, 690377, 690407, 454674, 690467, 449877, 1345963, 449882, 1345967, 1346004, 1346022, 1346030, 449895, 1346050, 1346079, 449905, 1346102, 1346124, 1346129, 1346131, 1346134, 454688, 1739369, 1346161, 1739393, 1346185, 1739410, 1346197, 449929, 455646, 1346223, 449939, 1346276, 454695, 1739565, 1739582, 1739599, 1739633, 1739642, 1739647, 1739661, 691090, 1346458, 1739684, 691108, 1215442, 1215443, 1215444, 1215445, 1739734, 1215447, 1215448, 1215446, 691180, 1608696, 691204, 971035, 1739794, 1608739, 1608745, 1739820, 450012, 691263, 1346629, 1346644, 1739860, 691285, 1215580, 1215585, 1215587, 691307, 1215597, 1739895, 1739896, 1608823, 450027, 691341, 1608865, 691375, 691390, 450041, 1740000, 1740003, 1346794, 1346803, 1608953, 1740047, 1740064, 1608999, 1740076, 450061, 1346876, 1478006, 450081, 454721, 1609152, 450090, 1347019, 1347041, 450099, 1347069, 1347087, 1609256, 1347132, 1609276, 1609282, 1216075, 450122, 450123, 691842, 691862, 1216154, 691869, 1347231, 691882, 1609390, 1085105, 1216236, 1609456, 1347327, 1609471, 1347347, 1347350, 1085230, 1622486, 1347393, 1609560, 1085297, 1347465, 1609616, 1609624, 1609627, 1347486, 1347489, 1216443, 1347517, 1347528, 1347546, 450202, 450206, 1347633, 1347661, 450222, 1347690, 450228, 1231783, 450239, 1347811, 450250, 450254, 1216770, 1347843, 1347885, 1347904, 1347913, 1347937, 450275, 450276, 1347968, 450280, 1347986, 1347987, 1348027, 1348042, 450314, 450315, 1348195, 450331, 1348237, 1217191, 1348287, 1348293, 1348295, 450348, 450354, 1757304, 1348357, 1362166, 1348449, 1217416, 450393, 454784, 450403, 1348600, 1217553, 450411, 1348664, 1348673, 971452, 450425, 1348698, 1217631, 1348718, 450458, 454796, 971497, 1348956, 450478, 1348966, 450480, 1217934, 1232037, 450493, 1349067, 450516, 450518, 450526, 1218150, 450548, 450549, 1218301, 1218302, 450560, 450567, 454818, 450571, 1218377, 450584, 450589, 1349543, 450593, 1218500, 450601, 1349593, 450609, 1349656, 1349660, 1218596, 1349691, 450623, 1232171, 1349717, 1349753, 454835, 1349855, 454838, 450677, 450678, 455676, 1350019, 1218955, 1350041, 1350096, 1219037, 1219049, 1350121, 1350180, 1350190, 1350196, 1350203, 1350222, 450730, 563814, 1350251, 1350279, 1219213, 563871, 563894, 1350337, 450751, 563922, 1350355, 563931, 563939, 563948, 563983, 563989, 1350430, 564008, 564012, 564066, 454861, 450784, 450785, 564078, 564092, 1350528, 1350529, 564101, 564104, 1350544, 1623115, 1350559, 1219494, 1219519, 564163, 564176, 564182, 564189, 564194, 564201, 564206, 564209, 455681, 564219, 1350656, 564231, 564253, 1350689, 1219640, 1219652, 564294, 564314, 1350751, 564322, 564329, 1219695, 564341, 1219703, 454872, 564393, 564414, 1350852, 564433, 1350875, 1219818, 1350894, 564464, 564478, 564479, 1219853, 564494, 450869, 1350942, 1613103, 450875, 564548, 564553, 1350989, 564558, 564576, 1351014, 564583, 450890, 564606, 564619, 450895, 564652, 454885, 1613254, 450905, 1351113, 450912, 1613297, 1613299, 1220096, 454888, 564762, 1351209, 1613372, 564812, 1220196, 1613423, 1220230, 1613469, 564917, 564930, 1232505, 564949, 1613526, 450960, 564962, 1351407, 1220343, 564988, 1613583, 565023, 565031, 1351466, 565034, 450976, 565042, 1351476, 1351493, 565070, 565081, 565085, 1220449, 454902, 1613692, 1613703, 1220508, 454905, 1613751, 1351638, 1613788, 1623332, 1351703, 1613862, 451026, 1351730, 451032, 1613920, 1351808, 1613984, 1613989, 565449, 565451, 1614042, 1351901, 1614045, 565473, 454917, 1614080, 1614081, 1614095, 565523, 565543, 565555, 1614134, 565570, 1220934, 565589, 451091, 565631, 565643, 565649, 1614238, 565680, 1614257, 451105, 451110, 455693, 1221081, 454928, 1221128, 565769, 565778, 451125, 565793, 565825, 565835, 565837, 565848, 1614428, 451138, 1614444, 451141, 565876, 565883, 1745538, 1614472, 451148, 565913, 1745564, 1745582, 1745619, 1221349, 1614569, 1623489, 1221393, 1614618, 1614649, 1614650, 1352514, 451191, 1745786, 1352590, 1745820, 451202, 1614760, 451204, 1221549, 1352627, 1745845, 1352633, 1614781, 1745853, 1614794, 1745871, 1614800, 1352664, 1614821, 1745912, 451220, 1745941, 1221696, 1352771, 1745997, 1221710, 1221733, 1352841, 1352844, 1746075, 1746076, 1221792, 1352889, 454956, 1746139, 1746140, 451265, 1746172, 451276, 1353000, 1221947, 1353033, 1232834, 1221969, 451291, 1222015, 1746314, 1353129, 1353142, 1353145, 451311, 1746391, 451317, 451323, 1746436, 451325, 1353227, 1746469, 1746476, 1353270, 1746494, 451338, 1757501, 1222266, 454974, 1353347, 1353362, 1746581, 1353369, 1746587, 451364, 1746643, 1353443, 1746668, 1353477, 1746714, 1222440, 451383, 1222447, 1353533, 1746755, 454983, 1353574, 960359, 451395, 1746795, 1353586, 1353601, 1353602, 451402, 451403, 960430, 451414, 1746897, 451417, 960474, 960480, 451419, 1746915, 451421, 1222651, 960511, 960544, 1747045, 451446, 451448, 451450, 1747080, 451453, 451455, 1222847, 454997, 451466, 1747167, 1747195, 451475, 451479, 1747217, 1747226, 451482, 1747232, 1623809, 1747263, 1747274, 1223002, 1747299, 1747319, 1747322, 451503, 451505, 451506, 1354147]]

Could this be a symptom of GHSA-3h7q-rfh9-xm4v ?

EDIT: it does not seem so, I just updated to v1.111 and the issue persists.

[n-peugnet]

It started to become worse tonight:

[n-peugnet]

As it seems the problem came from intensive recursive SQL queries, I tried to issue a reindex (verbose) database synapse; (07/23 13h) after the Synapse upgrade to v1.111, to make sure the indices were as optimized as possible, but it did not solve anything. Quite the opposite:

The get_auth_chain_difference_chains increase is probably due to the Synapse upgrade from v1.103 to v1.111, as it happened the 22 at 22:12:08.
EDIT: I just saw that this particular issue is tracked in #17129

[n-peugnet]

As my best clue was the logs shown in #17470 (comment), I decided to find what rooms were affected. So I used the following query where 444066 can be replaced by any of the value returned by the long query :

SELECT room_id
FROM event_auth_chains AS chains
INNER JOIN events ON (chains.event_id = events.event_id)
WHERE chain_id = 444066;

In my case, I had multiple long queries all linking to !lAoVmVifHHtoeOAmHO:grapheneos.org, so I decided to delete is using the admin API. And it seems everything went back to normal.

EDIT: hmm... not really, there are a lot of other rooms that show this behaviour
EDIT2: after deleting the few rooms that showed up in long queries it seems the situation is now under control, but I am still waiting for a large room to be purged.

[parisni]

same behavior on my side. Running v1.106.0