weblate.discovery.discovery, weblate.gettext.msgmerge very slow

[tomkolp]

Yesterday I added one component in the github repository. The update, which normally takes about an hour, has not finished yet. weblate.discovery.discovery, weblate.gettext.msgmerge for individual components runs every few minutes. Previously, weblate.discovery.discovery, weblate.gettext.msgmerge took a maximum of 20 minutes. Currently, 12 hours have passed.

Subsequent tasks: weblate.discovery.discovery, weblate.gettext.msgmerge appear every minute, two, sometimes several minutes.

A few days ago I updated postgreSQL, I forgot about tuning postgresql.conf. Yesterday's update from the github repo ran with the default configuration. After a few hours, I stopped the containers and restored postgresql.conf to a good configuration. Unfortunately, it didn't speed things up.

5.4-dev — ee0e7f41c50f0b2696eed59a0b594725876c0a41 --

5.4-dev — ee0e7f41c50f0b2696eed59a0b594725876c0a41
@nijel help

[nijel]

Do you see any errors in the logs?

Are add-ons executed repeatedly where they previously were not? It might be a bug in e3ff25a, but I don't see anything wrong there.

[tomkolp]

I don't see anything unusual in the logs. This is a fragment of the logs after clicking "reset" "reset all changes in weblate repository":

weblate-1   | celery-celery stderr | [2024-01-30 08:45:00,012: INFO/MainProcess] Task weblate.addons.tasks.daily_addons[7a62d87b-1473-4746-b138-794dfdc70f66] received
weblate-1   | celery-celery stderr | [2024-01-30 08:45:00,056: DEBUG/10531] eso-spolszczenie/glowne-pliki/zadania/dzienniki/265851556: running daily add-on: weblate.autotranslate.autotranslate
weblate-1   | celery-celery stderr | [2024-01-30 08:45:00,056: DEBUG/ForkPoolWorker-32] eso-spolszczenie/glowne-pliki/zadania/dzienniki/265851556: running daily add-on: weblate.autotranslate.autotranslate
weblate-1   | celery-celery stderr | [2024-01-30 08:45:00,106: DEBUG/10531] eso-spolszczenie/glowne-pliki/zadania/dzienniki/265851556: completed daily add-on: weblate.autotranslate.autotranslate
weblate-1   | celery-celery stderr | [2024-01-30 08:45:00,106: DEBUG/ForkPoolWorker-32] eso-spolszczenie/glowne-pliki/zadania/dzienniki/265851556: completed daily add-on: weblate.autotranslate.autotranslate
weblate-1   | nginx stdout | 85.128.16.28 - - [30/Jan/2024:08:45:01 +0100] "GET /component-list/glowne-pliki HTTP/1.0" 301 0 "-" "-"
weblate-1   | nginx stdout | 85.128.16.28 - - [30/Jan/2024:08:45:01 +0100] "GET /projects/eso-spolszczenie/zadania HTTP/1.0" 301 0 "-" "-"
weblate-1   | nginx stdout | 85.128.16.28 - - [30/Jan/2024:08:45:02 +0100] "GET /projects/eso-spolszczenie/zadania/ HTTP/1.0" 200 87173 "-" "-"
weblate-1   | nginx stdout | 85.128.16.28 - - [30/Jan/2024:08:45:04 +0100] "GET /component-list/glowne-pliki/ HTTP/1.0" 200 1408231 "-" "-"
weblate-1   | nginx stdout | 127.0.0.1 - - [30/Jan/2024:08:45:13 +0100] "GET /healthz/ HTTP/1.1" 200 12 "-" "curl/7.88.1"
weblate-1   | celery-celery stderr | [2024-01-30 08:45:14,593: INFO/MainProcess] Task weblate.utils.tasks.heartbeat[b09a4ccb-8f93-4f42-95dd-78bc689fd2cf] received
weblate-1   | gunicorn stderr | [2024-01-30 08:45:20,875: DEBUG/496] eso-spolszczenie/zadania/chapter-zones/northern-elsweyr/northern-elsweyr-an-animals-grim-abode: completed repository post-update add-on: weblate.discovery.discovery
weblate-1   | gunicorn stderr | [2024-01-30 08:45:20,877: DEBUG/496] eso-spolszczenie/zadania/chapter-zones/northern-elsweyr/northern-elsweyr-an-animals-grim-abode: running repository post-update add-on: weblate.gettext.msgmerge
weblate-1   | gunicorn stderr | [2024-01-30 08:45:20,891: INFO/496] eso-spolszczenie/zadania/chapter-zones/northern-elsweyr/northern-elsweyr-an-animals-grim-abode: weblate.gettext.msgmerge addon skipped, new base was not updated in e9131f1c0902f0c68310586d7db11d151f5cdc62..e9131f1c0902f0c68310586d7db11d151f5cdc62
weblate-1   | gunicorn stderr | [2024-01-30 08:45:20,920: DEBUG/496] eso-spolszczenie/zadania/chapter-zones/northern-elsweyr/northern-elsweyr-an-animals-grim-abode: completed repository post-update add-on: weblate.gettext.msgmerge
weblate-1   | gunicorn stderr | [2024-01-30 08:45:20,934: DEBUG/496] eso-spolszczenie/zadania/story-dlc-zones/wrothgar/wrothgar-flames-of-forge-and-fallen: running repository post-update add-on: weblate.gettext.msgmerge
weblate-1   | gunicorn stderr | [2024-01-30 08:45:20,943: INFO/496] eso-spolszczenie/zadania/story-dlc-zones/wrothgar/wrothgar-flames-of-forge-and-fallen: weblate.gettext.msgmerge addon skipped, new base was not updated in e9131f1c0902f0c68310586d7db11d151f5cdc62..e9131f1c0902f0c68310586d7db11d151f5cdc62
weblate-1   | gunicorn stderr | [2024-01-30 08:45:20,961: DEBUG/496] eso-spolszczenie/zadania/story-dlc-zones/wrothgar/wrothgar-flames-of-forge-and-fallen: completed repository post-update add-on: weblate.gettext.msgmerge
weblate-1   | gunicorn stderr | [2024-01-30 08:45:20,962: DEBUG/496] eso-spolszczenie/zadania/story-dlc-zones/wrothgar/wrothgar-flames-of-forge-and-fallen: running repository post-update add-on: weblate.discovery.discovery
cache-1     | 1:M 30 Jan 2024 07:45:31.003 * 1 changes in 60 seconds. Saving...
cache-1     | 1:M 30 Jan 2024 07:45:31.005 * Background saving started by pid 489
cache-1     | 489:C 30 Jan 2024 07:45:31.674 * DB saved on disk
cache-1     | 489:C 30 Jan 2024 07:45:31.677 * Fork CoW for RDB: current 2 MB, peak 2 MB, average 1 MB
cache-1     | 1:M 30 Jan 2024 07:45:31.710 * Background saving terminated with success
weblate-1   | nginx stdout | 127.0.0.1 - - [30/Jan/2024:08:45:43 +0100] "GET /healthz/ HTTP/1.1" 200 12 "-" "curl/7.88.1"
database-1  | 2024-01-30 07:45:51.534 UTC [22] LOG:  checkpoint complete: wrote 1709 buffers (0.1%); 0 WAL file(s) added, 0 removed, 1 recycled; write=171.306 s, sync=0.009 s, total=171.322 s; sync files=40, longest=0.002 s, average=0.001 s; distance=13922 kB, estimate=33069 kB; lsn=2/2F9EFF58, redo lsn=2/2F9C5780
weblate-1   | nginx stdout | 127.0.0.1 - - [30/Jan/2024:08:46:13 +0100] "GET /healthz/ HTTP/1.1" 200 12 "-" "curl/7.88.1"
weblate-1   | celery-celery stderr | [2024-01-30 08:46:14,597: INFO/MainProcess] Task weblate.utils.tasks.heartbeat[b1d307d9-e840-417b-adc5-e11312575524] received
cache-1     | 1:M 30 Jan 2024 07:46:32.001 * 1 changes in 60 seconds. Saving...
cache-1     | 1:M 30 Jan 2024 07:46:32.004 * Background saving started by pid 490
cache-1     | 490:C 30 Jan 2024 07:46:32.676 * DB saved on disk
cache-1     | 490:C 30 Jan 2024 07:46:32.680 * Fork CoW for RDB: current 2 MB, peak 2 MB, average 1 MB
cache-1     | 1:M 30 Jan 2024 07:46:32.709 * Background saving terminated with success
weblate-1   | gunicorn stderr | [2024-01-30 08:46:37,990: DEBUG/496] eso-spolszczenie/zadania/story-dlc-zones/wrothgar/wrothgar-flames-of-forge-and-fallen: completed repository post-update add-on: weblate.discovery.discovery
weblate-1   | gunicorn stderr | [2024-01-30 08:46:38,011: DEBUG/496] eso-spolszczenie/glowne-pliki/wyszukiwarka-aktywnosci/info-o-nagrodach/264355726: running repository post-update add-on: weblate.discovery.discovery
weblate-1   | nginx stdout | 127.0.0.1 - - [30/Jan/2024:08:46:43 +0100] "GET /healthz/ HTTP/1.1" 200 12 "-" "curl/7.88.1"
weblate-1   | nginx stdout | 127.0.0.1 - - [30/Jan/2024:08:47:13 +0100] "GET /healthz/ HTTP/1.1" 200 12 "-" "curl/7.88.1"
weblate-1   | celery-celery stderr | [2024-01-30 08:47:14,603: INFO/MainProcess] Task weblate.utils.tasks.heartbeat[27a48490-fad6-435c-916b-af61e33b2969] received

You can check the errors in sentry, because I am still sending sentry to your instance.
Unfortunately, everything is blocked, I am not able to merge, rebase, etc.

[nijel]

#10893 should address multiple triggering of the discovery add-on

[tomkolp]

I'll check it as soon as there's a fix.

[tomkolp]

Initially everything works. Can you briefly describe the changes in these additions? In the "base" gui, the progress bar is no longer the sum of all components in the project, but shows the progress for each component separately. The logs also look different.

[nijel]

#10893 only brings back condition removed in
https://github.com/WeblateOrg/weblate/pull/10807/files#diff-815de81bffc610b75def2de884c550297811d0f3b4ec3ceb8538c9d261574aa5L237-L238. I missed that when refactoring the code, so the discover add-on was triggered for all linked components instead of only the main one. Logs for add-ons are consistent across events and a bit more verbose since #10807 to ease debugging.