Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Managing strings is very slow in a large component #6207

Closed
1 task done
burner1024 opened this issue Jun 19, 2021 · 28 comments
Closed
1 task done

Managing strings is very slow in a large component #6207

burner1024 opened this issue Jun 19, 2021 · 28 comments
Assignees
Labels
bug Something is broken.
Milestone

Comments

@burner1024
Copy link
Contributor

burner1024 commented Jun 19, 2021

Describe the issue
Using new "Manage strings" permission, I delete strings from components. Small ones work reasonably well, large ones take unreasonably long time.

uwsgi stderr | [2021-06-19 16:48:23,012: INFO/2462] fallout/fixt/es: processing po/spanish.po, content changed
...
uwsgi stderr | [2021-06-19 16:51:57,101: INFO/2462] fallout/fixt/es: updating completed

Adding is even worse... uwsgi is crunching something for 15 minutes already and no result.
My POs are a few MBs.

I already tried
Nothing comes to mind, really.
I searched for a large component with "manage strings" enabled on Hosted to compare and see if it's the same, but didn't find any.

  • I've read and searched the docs and did not find the answer there.
    If you didn’t try already, try to search there what you wrote above.

To Reproduce the issue
Delete/add a string from/to a large PO component.

Expected behavior
String deleted/added quickly.

Server configuration and status
Using Docker 4.7-1 with pretty much default config.

$ docker-compose exec --user weblate weblate weblate list_versions
 * Weblate: 4.7
 * Django: 3.2.4
 * siphashc: 2.1
 * translate-toolkit: 3.3.6
 * lxml: 4.6.3
 * Pillow: 8.2.0
 * bleach: 3.3.0
 * python-dateutil: 2.8.1
 * social-auth-core: 4.1.0
 * social-auth-app-django: 4.0.0
 * django-crispy-forms: 1.12.0
 * oauthlib: 3.1.1
 * django-compressor: 2.4.1
 * djangorestframework: 3.12.4
 * django-filter: 2.4.0
 * django-appconf: 1.0.4
 * user-agents: 2.2.0
 * filelock: 3.0.12
 * setuptools: 40.8.0
 * jellyfish: 0.8.2
 * openpyxl: 3.0.7
 * celery: 5.1.0
 * kombu: 5.1.0
 * translation-finder: 2.9
 * weblate-language-data: 2021.5
 * html2text: 2020.1.16
 * pycairo: 1.16.2
 * pygobject: 3.30.4
 * diff-match-patch: 20200713
 * requests: 2.25.1
 * django-redis: 5.0.0
 * hiredis: 2.0.0
 * sentry_sdk: 1.1.0
 * Cython: 0.29.23
 * misaka: 2.1.1
 * GitPython: 3.1.14
 * borgbackup: 1.1.16
 * pyparsing: 2.4.7
 * pyahocorasick: 1.4.2
 * python-redis-lock: 3.7.0
 * Python: 3.7.3
 * Git: 2.20.1
 * psycopg2: 2.9
 * psycopg2-binary: 2.8.6
 * phply: 1.2.5
 * chardet: 4.0.0
 * ruamel.yaml: 0.17.9
 * tesserocr: 2.5.1
 * akismet: 1.1
 * boto3: 1.17.96
 * zeep: 4.0.0
 * aeidon: 1.9
 * iniparse: 0.5
 * mysqlclient: 2.0.3
 * Mercurial: 5.8
 * git-svn: 2.20.1
 * git-review: 2.1.0
 * Redis server: 6.2.4
 * PostgreSQL server: 13.3
 * Database backends: django.db.backends.postgresql
 * Cache backends: default:RedisCache, avatar:FileBasedCache
 * Email setup: django.core.mail.backends.smtp.EmailBackend: 127.0.0.1
 * OS encoding: filesystem=utf-8, default=utf-8
 * Celery: redis://cache:6379/1, redis://cache:6379/1, regular
 * Platform: Linux 5.8.0-55-generic (x86_64)

Weblate deploy checks

SystemCheckError: System check identified some issues:

CRITICALS:
?: (weblate.E003) Cannot send e-mail ([Errno 111] Connection refused), please check EMAIL_* settings.
	HINT: https://docs.weblate.org/en/weblate-4.7/admin/install.html#out-mail
?: (weblate.E027) The path /app/data/secret is owned by a different user, check your DATA_DIR settings.
	HINT: https://docs.weblate.org/en/weblate-4.7/admin/install.html#file-permissions

WARNINGS:
?: (security.W004) You have not set a value for the SECURE_HSTS_SECONDS setting. If your entire site is served only over SSL, you may want to consider setting a value and enabling HTTP Strict Transport Security. Be sure to read the documentation first; enabling HSTS carelessly can cause serious, irreversible problems.
?: (security.W008) Your SECURE_SSL_REDIRECT setting is not set to True. Unless your site should be available over both SSL and non-SSL connections, you may want to either set this setting True or configure a load balancer or reverse-proxy server to redirect all connections to HTTPS.
?: (security.W012) SESSION_COOKIE_SECURE is not set to True. Using a secure-only session cookie makes it more difficult for network traffic sniffers to hijack user sessions.
?: (security.W018) You should not have DEBUG set to True in deployment.

INFOS:
?: (weblate.I021) Error collection is not set up, it is highly recommended for production use
	HINT: https://docs.weblate.org/en/weblate-4.7/admin/install.html#collecting-errors
?: (weblate.I028) Backups are not configured, it is highly recommended for production use
	HINT: https://docs.weblate.org/en/weblate-4.7/admin/backup.html

System check identified 8 issues (1 silenced)
nijel added a commit that referenced this issue Jun 21, 2021
That is too expensive for the few attributes we need.

Issue #6207
@nijel
Copy link
Member

nijel commented Jun 21, 2021

We have already some improvements ready for 4.7.1 which should improve the situation. In our tests it reduced the processing time to 60-70%, but it depends on many aspects.

@burner1024
Copy link
Contributor Author

burner1024 commented Jun 21, 2021

I tried bleeding just now:

(small component)
weblate_1   | uwsgi stderr | [2021-06-21 13:30:36,719: INFO/387] fallout/fo2tweaks/es: processing data/text/po/spanish.po, content changed
weblate_1   | uwsgi stderr | [2021-06-21 13:30:37,304: INFO/387] fallout/fo2tweaks/es: updating completed

(large component)
uwsgi stderr | [2021-06-21 13:34:46,663: INFO/374] fallout/fixt/es: processing po/spanish.po, content changed
...
uwsgi stderr | [2021-06-21 13:40:43,086: INFO/374] fallout/fixt/es: updating completed

Browser is blocked for all the processing time, so... 5 or 3 or even 1 minute is effectively the same - not usable.

It seems to spend most of the time in SQL, I sampled some queries:

SELECT "trans_variant"."id", "trans_variant"."component_id", "trans_variant"."variant_regex", "trans_variant"."key" FROM "trans_variant" INNER JOIN "trans_variant_defining_units" ON ("trans_variant"."id" = "trans_variant_defining_units"."variant_id") WHERE "trans_variant_defining_units"."unit_id" = 1432484
UPDATE "trans_unit" SET "translation_id" = 64, "id_hash" = 1475286454103327925, "location" = 'data/text/english/dialog/palguard.msg:103, data/text/english/dialog/pcargrd.msg:103', "context" = '', "note" = '', "flags" = '', "source" = 'What a nice day. I hope we don''t have any attacks today.', "previous_source" = '', "target" = 'Hace un día precioso. Espero que hoy no nos ataquen.', "state" = 20, "original_state" = 20, "details" = '{}', "position" = 14051, "num_words" = 12, "priority" = 100, "pending" = false, "timestamp" = '2017-08-28T21:30:59+00:00'::timestamptz, "extra_flags" = '', "explanation" = '', "variant_id" = NULL, "source_unit_id" = 1427001 WHERE "trans_unit"."id" = 469669
UPDATE "trans_unit" SET "translation_id" = 64, "id_hash" =  -5770396855701994789, "location" = 'data/text/english/game/combatai.msg:7013', "context" = '', "note" = '', "flags" = '', "source" = 'Let''s flatline you!', "previous_source" = '', "target" = '¡Vamos a ponerte a raya!', "state" = 20, "original_state" = 20, "details" = '{}', "position" = 21114, "num_words" = 3, "priority" = 100, "pending" = false, "timestamp" = '2017-08-28T21:32:51+00:00'::timestamptz, "extra_flags" = '', "explanation" = '', "variant_id" = NULL, "source_unit_id" = 1433689 WHERE "trans_unit"."id" = 476732
SELECT "trans_unit"."id", "trans_unit"."translation_id", "trans_unit"."id_hash", "trans_unit"."location", "trans_unit"."context", "trans_unit"."note", "trans_unit"."flags", "trans_unit"."source", "trans_unit"."previous_source", "trans_unit"."target", "trans_unit"."state", "trans_unit"."original_state", "trans_unit"."details", "trans_unit"."position", "trans_unit"."num_words", "trans_unit"."priority", "trans_unit"."pending", "trans_unit"."timestamp", "trans_unit"."extra_flags", "trans_unit"."explanation", "trans_unit"."variant_id", "trans_unit"."source_unit_id" FROM "trans_unit" WHERE "trans_unit"."id" = 1435741 LIMIT 21
UPDATE "trans_unit" SET "location" = 'dialog/dcjoey.msg:241', "note" = '', "flags" = '', "position" = 5429 WHERE "trans_unit"."id" = 1367982
SELECT "trans_variant"."id", "trans_variant"."component_id", "trans_variant"."variant_regex", "trans_variant"."key" FROM "trans_variant" INNER JOIN "trans_variant_defining_units" ON ("trans_variant"."id" = "trans_variant_defining_units"."variant_id") WHERE "trans_variant_defining_units"."unit_id" = 1374356

Could it be that after a string is added or deleted, Weblate goes on to recalculate unit ids, and whatever is based on it, and does that one by one?

@nijel
Copy link
Member

nijel commented Jun 21, 2021

Bleeding probably still doesn't have the changes, tomorrow one should have them

@burner1024
Copy link
Contributor Author

Built one myself, tried it:

uwsgi stderr | [2021-06-21 15:05:03,964: INFO/404] fallout/fixt/es: processing po/spanish.po, content changed
uwsgi stderr | [2021-06-21 15:08:28,525: INFO/404] fallout/fixt/es: updating completed

@nijel
Copy link
Member

nijel commented Jun 21, 2021

I doubt it's actually bleeding. If you just build https://github.com/WeblateOrg/docker/ you will get what is published as edge. To actually get bleeding version, you should adjust the Docker file by https://github.com/WeblateOrg/docker/blob/main/.github/bin/bleeding

@burner1024
Copy link
Contributor Author

burner1024 commented Jun 21, 2021

yes, I did use bleeding script

@burner1024
Copy link
Contributor Author

Added dogslow:

root@a4e772dbdd31:/# cat /tmp/dog/slow_request_m0remabc.log 
Undead request intercepted at: 21-06-2021 15:51:38 UTC

POST http://localhost:8080/unit/237033/delete/
Hostname:   a4e772dbdd31
Thread ID:  140409198516096
Process ID: 391
Started:    21-06-2021 15:51:13 UTC

  File "/usr/local/lib/python3.7/dist-packages/django/core/handlers/wsgi.py", line 133, in __call__
    response = self.get_response(request)
  File "/usr/local/lib/python3.7/dist-packages/django/core/handlers/base.py", line 130, in get_response
    response = self._middleware_chain(request)
  File "/usr/local/lib/python3.7/dist-packages/django/core/handlers/exception.py", line 47, in inner
    response = get_response(request)
  File "/home/weblate/.local/lib/python3.7/site-packages/dogslow/__init__.py", line 313, in __call__
    response = self.get_response(request)
  File "/usr/local/lib/python3.7/dist-packages/django/core/handlers/exception.py", line 47, in inner
    response = get_response(request)
  File "/usr/local/lib/python3.7/dist-packages/weblate/middleware.py", line 87, in __call__
    response = self.get_response(request)
  File "/usr/local/lib/python3.7/dist-packages/django/core/handlers/exception.py", line 47, in inner
    response = get_response(request)
  File "/usr/local/lib/python3.7/dist-packages/weblate/middleware.py", line 72, in __call__
    return self.get_response(request)
  File "/usr/local/lib/python3.7/dist-packages/django/core/handlers/exception.py", line 47, in inner
    response = get_response(request)
  File "/usr/local/lib/python3.7/dist-packages/django/utils/deprecation.py", line 117, in __call__
    response = response or self.get_response(request)
  File "/usr/local/lib/python3.7/dist-packages/django/core/handlers/exception.py", line 47, in inner
    response = get_response(request)
  File "/usr/local/lib/python3.7/dist-packages/django/utils/deprecation.py", line 117, in __call__
    response = response or self.get_response(request)
  File "/usr/local/lib/python3.7/dist-packages/django/core/handlers/exception.py", line 47, in inner
    response = get_response(request)
  File "/usr/local/lib/python3.7/dist-packages/django/utils/deprecation.py", line 117, in __call__
    response = response or self.get_response(request)
  File "/usr/local/lib/python3.7/dist-packages/django/core/handlers/exception.py", line 47, in inner
    response = get_response(request)
  File "/usr/local/lib/python3.7/dist-packages/weblate/accounts/middleware.py", line 74, in __call__
    response = self.get_response(request)
  File "/usr/local/lib/python3.7/dist-packages/django/core/handlers/exception.py", line 47, in inner
    response = get_response(request)
  File "/usr/local/lib/python3.7/dist-packages/django/utils/deprecation.py", line 117, in __call__
    response = response or self.get_response(request)
  File "/usr/local/lib/python3.7/dist-packages/django/core/handlers/exception.py", line 47, in inner
    response = get_response(request)
  File "/usr/local/lib/python3.7/dist-packages/django/utils/deprecation.py", line 117, in __call__
    response = response or self.get_response(request)
  File "/usr/local/lib/python3.7/dist-packages/django/core/handlers/exception.py", line 47, in inner
    response = get_response(request)
  File "/usr/local/lib/python3.7/dist-packages/django/utils/deprecation.py", line 117, in __call__
    response = response or self.get_response(request)
  File "/usr/local/lib/python3.7/dist-packages/django/core/handlers/exception.py", line 47, in inner
    response = get_response(request)
  File "/usr/local/lib/python3.7/dist-packages/weblate/accounts/middleware.py", line 156, in __call__
    return self.get_response(request)
  File "/usr/local/lib/python3.7/dist-packages/django/core/handlers/exception.py", line 47, in inner
    response = get_response(request)
  File "/usr/local/lib/python3.7/dist-packages/weblate/api/middleware.py", line 26, in __call__
    response = self.get_response(request)
  File "/usr/local/lib/python3.7/dist-packages/django/core/handlers/exception.py", line 47, in inner
    response = get_response(request)
  File "/usr/local/lib/python3.7/dist-packages/weblate/middleware.py", line 200, in __call__
    response = self.get_response(request)
  File "/usr/local/lib/python3.7/dist-packages/django/core/handlers/exception.py", line 47, in inner
    response = get_response(request)
  File "/usr/local/lib/python3.7/dist-packages/django/core/handlers/base.py", line 181, in _get_response
    response = wrapped_callback(request, *callback_args, **callback_kwargs)
  File "/usr/local/lib/python3.7/dist-packages/django/contrib/auth/decorators.py", line 21, in _wrapped_view
    return view_func(request, *args, **kwargs)
  File "/usr/local/lib/python3.7/dist-packages/django/views/decorators/http.py", line 40, in inner
    return func(request, *args, **kwargs)
  File "/usr/local/lib/python3.7/dist-packages/weblate/trans/views/edit.py", line 938, in delete_unit
    unit.translation.delete_unit(request, unit)
  File "/usr/lib/python3.7/contextlib.py", line 74, in inner
    return func(*args, **kwds)
  File "/usr/local/lib/python3.7/dist-packages/weblate/trans/models/translation.py", line 1323, in delete_unit
    self.handle_store_change(request, user, previous_revision)
  File "/usr/local/lib/python3.7/dist-packages/weblate/trans/models/translation.py", line 1179, in handle_store_change
    self.check_sync(request=request, change=change)
  File "/usr/local/lib/python3.7/dist-packages/weblate/trans/models/translation.py", line 382, in check_sync
    for unit in self.unit_set.prefetch_bulk().select_for_update()
  File "/usr/local/lib/python3.7/dist-packages/django/db/models/query.py", line 280, in __iter__
    self._fetch_all()
  File "/usr/local/lib/python3.7/dist-packages/django/db/models/query.py", line 1326, in _fetch_all
    self._prefetch_related_objects()
  File "/usr/local/lib/python3.7/dist-packages/django/db/models/query.py", line 813, in _prefetch_related_objects
    prefetch_related_objects(self._result_cache, *self._prefetch_related_lookups)
  File "/usr/local/lib/python3.7/dist-packages/django/db/models/query.py", line 1734, in prefetch_related_objects
    level,
  File "/usr/local/lib/python3.7/dist-packages/django/db/models/query.py", line 1876, in prefetch_one_level
    rel_attr_val = rel_obj_attr(rel_obj)
  File "/usr/local/lib/python3.7/dist-packages/django/db/models/fields/related.py", line 650, in get_foreign_related_value
    return self.get_instance_value_for_fields(instance, self.foreign_related_fields)
  File "/usr/local/lib/python3.7/dist-packages/django/db/models/fields/related.py", line 656, in get_instance_value_for_fields
    for field in fields:

This report does not contain the local stack variables.
To enable this (very verbose) information, add this to your Django settings:
  DOGSLOW_STACK_VARS = True

@nijel
Copy link
Member

nijel commented Jun 21, 2021

This looks pretty much as expected - Weblate rescans the file after removing the string and this select is the most expensive part of the update.

@burner1024
Copy link
Contributor Author

burner1024 commented Jun 22, 2021

So... are you saying that this performance is expected? Or you can't reproduce it?

I enabled query logging for postgres, apparently deleting a string results in ~50000 SELECT + 50000 UPDATE queries.

$ #before
$ docker logs wl_database_1 2>&1 | grep "LOG:  statement" | awk '{print $7}' | sort | uniq -c
      5 
    863 BEGIN
    614 CLOSE
    862 COMMIT
    614 DECLARE
     13 DELETE
   1226 FETCH
    861 INSERT
   2306 SELECT
      3 UPDATE
$ #after
$ docker logs wl_database_1 2>&1 | grep "LOG:  statement" | awk '{print $7}' | sort | uniq -c
      5 
    863 BEGIN
    614 CLOSE
    862 COMMIT
    614 DECLARE
     33 DELETE
   1226 FETCH
    863 INSERT
      1 ROLLBACK
  51667 SELECT
      1 SHOW
  49324 UPDATE

@nijel
Copy link
Member

nijel commented Jun 22, 2021

All strings present in the file after the deleted one will be updated, so the number of updates is expected. It's this query:

UPDATE "trans_unit" SET "location" = 'dialog/dcjoey.msg:241', "note" = '', "flags" = '', "position" = 5429 WHERE "trans_unit"."id" = 1367982

There should not be that many of select queries though. Maybe it's the variants causing this as this query should be prefetched at once and not executed for every unit:

SELECT "trans_variant"."id", "trans_variant"."component_id", "trans_variant"."variant_regex", "trans_variant"."key" FROM "trans_variant" INNER JOIN "trans_variant_defining_units" ON ("trans_variant"."id" = "trans_variant_defining_units"."variant_id") WHERE "trans_variant_defining_units"."unit_id" = 1374356

nijel added a commit that referenced this issue Jun 22, 2021
This saves additional query per created unit as the can not be variants
for unit which has been just created.

Issue #6207
@burner1024
Copy link
Contributor Author

burner1024 commented Jun 22, 2021

So, it's like I thought. But, adding a variant does not result in "processing po, content changed", so maybe deleting also needn't?

I did some more tests:

  • small component (15 strings)
    • deleting first one results in ~40 SELECT, 30 UPDATE
    • deleting last one: ~90 SELECT, 3 UPDATE
  • large component (25k strings)
    • deleting last one: ~25 seconds, ~120 SELECT, 6 UPDATE
    • deleting first one: ~4 minutes, 50k SELECT, 50k UPDATE

So, reads and writes are likely doubled somewhere. But even if that is fixed, working with large components is impossible. I guess deletion should be offloaded? In fact, in PO terms strings probably should not be deleted from the file, simply marked as "obsolete".
Still, 4 minutes is a lot even for a background process. For an instance with, say, 100 translations, it's not hard to imagine that for example, 10 strings per hour get deleted. If each one takes a few minutes, they are likely to block each other and/or compound db load exponentially (not to mention disrupting translator's workflow).

Although in fact, I'm more interested in adding than deleting. The problem is that while adding to small POs also works fine, with large ones I have even less luck: didn't have the patience to get at least one variant added. It's just loading forever.
Here's a relevant dogslow (at 60 seconds):

Undead request intercepted at: 22-06-2021 10:40:45 UTC

POST http://localhost:8080/new-unit/fallout/fixt/ru/
Hostname:   234c659c9c07
Thread ID:  140054938601344
Process ID: 404
Started:    22-06-2021 10:39:45 UTC

  File "/usr/local/lib/python3.7/dist-packages/django/core/handlers/wsgi.py", line 133, in __call__
    response = self.get_response(request)
  File "/usr/local/lib/python3.7/dist-packages/django/core/handlers/base.py", line 130, in get_response
    response = self._middleware_chain(request)
  File "/usr/local/lib/python3.7/dist-packages/django/core/handlers/exception.py", line 47, in inner
    response = get_response(request)
  File "/usr/local/lib/python3.7/dist-packages/dogslow/__init__.py", line 313, in __call__
    response = self.get_response(request)
  File "/usr/local/lib/python3.7/dist-packages/django/core/handlers/exception.py", line 47, in inner
    response = get_response(request)
  File "/usr/local/lib/python3.7/dist-packages/weblate/middleware.py", line 87, in __call__
    response = self.get_response(request)
  File "/usr/local/lib/python3.7/dist-packages/django/core/handlers/exception.py", line 47, in inner
    response = get_response(request)
  File "/usr/local/lib/python3.7/dist-packages/weblate/middleware.py", line 72, in __call__
    return self.get_response(request)
  File "/usr/local/lib/python3.7/dist-packages/django/core/handlers/exception.py", line 47, in inner
    response = get_response(request)
  File "/usr/local/lib/python3.7/dist-packages/django/utils/deprecation.py", line 117, in __call__
    response = response or self.get_response(request)
  File "/usr/local/lib/python3.7/dist-packages/django/core/handlers/exception.py", line 47, in inner
    response = get_response(request)
  File "/usr/local/lib/python3.7/dist-packages/django/utils/deprecation.py", line 117, in __call__
    response = response or self.get_response(request)
  File "/usr/local/lib/python3.7/dist-packages/django/core/handlers/exception.py", line 47, in inner
    response = get_response(request)
  File "/usr/local/lib/python3.7/dist-packages/django/utils/deprecation.py", line 117, in __call__
    response = response or self.get_response(request)
  File "/usr/local/lib/python3.7/dist-packages/django/core/handlers/exception.py", line 47, in inner
    response = get_response(request)
  File "/usr/local/lib/python3.7/dist-packages/weblate/accounts/middleware.py", line 74, in __call__
    response = self.get_response(request)
  File "/usr/local/lib/python3.7/dist-packages/django/core/handlers/exception.py", line 47, in inner
    response = get_response(request)
  File "/usr/local/lib/python3.7/dist-packages/django/utils/deprecation.py", line 117, in __call__
    response = response or self.get_response(request)
  File "/usr/local/lib/python3.7/dist-packages/django/core/handlers/exception.py", line 47, in inner
    response = get_response(request)
  File "/usr/local/lib/python3.7/dist-packages/django/utils/deprecation.py", line 117, in __call__
    response = response or self.get_response(request)
  File "/usr/local/lib/python3.7/dist-packages/django/core/handlers/exception.py", line 47, in inner
    response = get_response(request)
  File "/usr/local/lib/python3.7/dist-packages/django/utils/deprecation.py", line 117, in __call__
    response = response or self.get_response(request)
  File "/usr/local/lib/python3.7/dist-packages/django/core/handlers/exception.py", line 47, in inner
    response = get_response(request)
  File "/usr/local/lib/python3.7/dist-packages/weblate/accounts/middleware.py", line 156, in __call__
    return self.get_response(request)
  File "/usr/local/lib/python3.7/dist-packages/django/core/handlers/exception.py", line 47, in inner
    response = get_response(request)
  File "/usr/local/lib/python3.7/dist-packages/weblate/api/middleware.py", line 26, in __call__
    response = self.get_response(request)
  File "/usr/local/lib/python3.7/dist-packages/django/core/handlers/exception.py", line 47, in inner
    response = get_response(request)
  File "/usr/local/lib/python3.7/dist-packages/weblate/middleware.py", line 200, in __call__
    response = self.get_response(request)
  File "/usr/local/lib/python3.7/dist-packages/django/core/handlers/exception.py", line 47, in inner
    response = get_response(request)
  File "/usr/local/lib/python3.7/dist-packages/django/core/handlers/base.py", line 181, in _get_response
    response = wrapped_callback(request, *callback_args, **callback_kwargs)
  File "/usr/local/lib/python3.7/dist-packages/django/views/decorators/http.py", line 40, in inner
    return func(request, *args, **kwargs)
  File "/usr/local/lib/python3.7/dist-packages/django/contrib/auth/decorators.py", line 21, in _wrapped_view
    return view_func(request, *args, **kwargs)
  File "/usr/local/lib/python3.7/dist-packages/weblate/trans/views/edit.py", line 919, in new_unit
    if not form.is_valid():
  File "/usr/local/lib/python3.7/dist-packages/django/forms/forms.py", line 175, in is_valid
    return self.is_bound and not self.errors
  File "/usr/local/lib/python3.7/dist-packages/django/forms/forms.py", line 170, in errors
    self.full_clean()
  File "/usr/local/lib/python3.7/dist-packages/django/forms/forms.py", line 373, in full_clean
    self._clean_form()
  File "/usr/local/lib/python3.7/dist-packages/django/forms/forms.py", line 400, in _clean_form
    cleaned_data = self.clean()
  File "/usr/local/lib/python3.7/dist-packages/weblate/trans/forms.py", line 1995, in clean
    self.translation.validate_new_unit_data(**data)
  File "/usr/local/lib/python3.7/dist-packages/weblate/trans/models/translation.py", line 1406, in validate_new_unit_data
    current.source != store.content_units[pos].source
  File "/usr/local/lib/python3.7/dist-packages/weblate/formats/base.py", line 347, in content_units
    return [unit for unit in self.all_units if unit.has_content()]
  File "/usr/local/lib/python3.7/dist-packages/weblate/formats/base.py", line 347, in <listcomp>
    return [unit for unit in self.all_units if unit.has_content()]
  File "/usr/local/lib/python3.7/dist-packages/weblate/formats/ttkit.py", line 134, in has_content
    and not self.mainunit.isobsolete()
  File "/usr/local/lib/python3.7/dist-packages/translate/storage/pypo.py", line 568, in isblank
    return False
  File "/usr/local/lib/python3.7/dist-packages/translate/storage/pypo.py", line 458, in _msgidlen
    return len(unquotefrompo(self.msgid))
  File "/usr/local/lib/python3.7/dist-packages/translate/storage/pypo.py", line 652, in hasplural
    def hasplural(self):

This report does not contain the local stack variables.
To enable this (very verbose) information, add this to your Django settings:
  DOGSLOW_STACK_VARS = True

I see only one SQL query in PG activity, but it's in idle state for 10 minutes already:

 weblate | 2021-06-22 10:39:47.499332+00 | SELECT "addons_addon"."id", "addons_addon"."component_id", "addons_addon"."name", "addons_addon"."configuration", "addons_addon"."state", "addons_addon"."project_scope", "addons_addon"."repo_scope" FROM "addons_addon" INNER JOIN "trans_component" ON ("addons_addon"."component_id" = "trans_component"."id") WHERE (("addons_addon"."component_id" = 16 AND NOT "addons_addon"."project_scope") OR ("trans_component"."project_id" = 13 AND "addons_addon"."project_scope") OR ("trans_component"."linked_component_id" = 16 AND "addons_addon"."repo_scope") OR ("addons_addon"."component_id" IS NULL AND "addons_addon"."repo_scope"))

nijel added a commit that referenced this issue Jun 22, 2021
This avoids updating every unit separately in most cases.

Issue #6207
nijel added a commit that referenced this issue Jun 22, 2021
This makes it super slow for big translations and brings very little
value. Such cases should be catched in the testsuite and not at runtime.

Issue #6207
@nijel
Copy link
Member

nijel commented Jun 22, 2021

So, reads and writes are likely doubled somewhere.

There is always the source string which needs to be updated as well...

large component (25k strings)

* deleting last one: ~25 seconds, ~120 SELECT, 6 UPDATE

* deleting first one: ~4 minutes, 50k SELECT, 50k UPDATE

I've made updating of the units positions in a single query in 4976d8b, that should make the removal same speed regardless the actual location of the string in the file.

Although in fact, I'm more interested in adding than deleting.

That should be way faster with 277150d.

@nijel nijel self-assigned this Jun 22, 2021
@nijel nijel added the bug Something is broken. label Jun 22, 2021
@nijel nijel added this to the 4.7.1 milestone Jun 22, 2021
@burner1024
Copy link
Contributor Author

burner1024 commented Jun 22, 2021

I built 277150d

  • Deleting first string: ~100 SELECT, still 50k UPDATE. PO is still reprocessed, browser blocked for processing ~2 minutes.
  • Adding a variant: uwsgi stderr | [pid: 607|app: 0|req: 16/40] 172.18.0.1 () {64 vars in 1314 bytes} [Tue Jun 22 12:46:47 2021] POST /new-unit/fallout/fixt/ru/ => generated 0 bytes in 6596 msecs (HTTP/1.1 302) 8 headers in 405 bytes (2 switches on core 0). 6.5 seconds is already usable, though I imagine still not comfortable for translators.
    Edit: tried adding a few more, it fluctuates up to 10 seconds.

@nijel
Copy link
Member

nijel commented Jun 22, 2021

Is the deleting slow when executed after adding a variant or even without that (for example after another deleting or after importing the translation)? Looking at the code, adding a variant might mess up this...

@nijel
Copy link
Member

nijel commented Jun 22, 2021

Also make sure there are no pending changes prior doing removal, otherwise you are measuring commit + delete.

nijel added a commit that referenced this issue Jun 22, 2021
Assume the underlying code is reliable and skip the validation at
runtime.

Issue #6207
nijel added a commit that referenced this issue Jun 22, 2021
It will be added to the end in most cases.

Issue #6207
@burner1024
Copy link
Contributor Author

burner1024 commented Jun 22, 2021

I tried deleting first, it was before adding (cold start).
With 9a19b7d

  • deleting: 1 minute, 25k UPDATE now:
uwsgi stderr | [2021-06-22 13:55:37,478: INFO/405] fallout/fixt: skipped push: push on commit disabled
uwsgi stderr | [2021-06-22 13:55:41,587: INFO/405] fallout/fixt/ru: processing po/russian.po, content changed
uwsgi stderr | [2021-06-22 13:56:50,282: INFO/405] fallout/fixt/ru: updating completed
  • adding variant (also made sure to commit previously): still 6-10 seconds.
    It seems that adding one variant somehow triggers an update for all of them 1 by 1, and does so 3 times?
2021-06-22 14:11:17.734 UTC [292] LOG:  statement: DECLARE "_django_curs_140702676903808_sync_27" NO SCROLL CURSOR WITHOUT HOLD FOR SELECT "trans_variant"."id", "trans_variant"."component_id", "trans_variant"."variant_regex", "trans_variant"."key" FROM "trans_variant" WHERE "trans_variant"."component_id" = 16
2021-06-22 14:11:17.735 UTC [292] LOG:  statement: FETCH FORWARD 2000 FROM "_django_curs_140702676903808_sync_27"
2021-06-22 14:11:17.738 UTC [292] LOG:  statement: UPDATE "trans_unit" SET "variant_id" = 3 WHERE "trans_unit"."id" IN (SELECT U0."id" FROM "trans_unit" U0 INNER JOIN "trans_translation" U1 ON (U0."translation_id" = U1."id") WHERE (U0."source" = 'RemindBoy message: Water supplies exhausted. Vault 13 is dead.' AND U1."component_id" = 16 AND U0."variant_id" IS NULL))
2021-06-22 14:11:18.261 UTC [292] LOG:  statement: UPDATE "trans_unit" SET "variant_id" = 3 WHERE "trans_unit"."id" IN (SELECT V0."id" FROM "trans_unit" V0 INNER JOIN "trans_translation" V1 ON (V0."translation_id" = V1."id") WHERE (V0."id_hash" IN (SELECT U0."id_hash" FROM "trans_unit" U0 INNER JOIN "trans_variant_defining_units" U1 ON (U0."id" = U1."unit_id") WHERE U1."variant_id" = 3) AND V1."component_id" = 16 AND V0."variant_id" IS NULL))
2021-06-22 14:11:18.265 UTC [292] LOG:  statement: UPDATE "trans_unit" SET "variant_id" = 4 WHERE "trans_unit"."id" IN (SELECT U0."id" FROM "trans_unit" U0 INNER JOIN "trans_translation" U1 ON (U0."translation_id" = U1."id") WHERE (U0."source" = 'RemindBoy message: Water supplies nearly gone in Vault 13.  Situation critical.' AND U1."component_id" = 16 AND U0."variant_id" IS NULL))
2021-06-22 14:11:18.714 UTC [292] LOG:  statement: UPDATE "trans_unit" SET "variant_id" = 4 WHERE "trans_unit"."id" IN (SELECT V0."id" FROM "trans_unit" V0 INNER JOIN "trans_translation" V1 ON (V0."translation_id" = V1."id") WHERE (V0."id_hash" IN (SELECT U0."id_hash" FROM "trans_unit" U0 INNER JOIN "trans_variant_defining_units" U1 ON (U0."id" = U1."unit_id") WHERE U1."variant_id" = 4) AND V1."component_id" = 16 AND V0."variant_id" IS NULL))
2021-06-22 14:11:18.719 UTC [292] LOG:  statement: UPDATE "trans_unit" SET "variant_id" = 5 WHERE "trans_unit"."id" IN (SELECT U0."id" FROM "trans_unit" U0 INNER JOIN "trans_translation" U1 ON (U0."translation_id" = U1."id") WHERE (U0."source" = 'zzz123' AND U1."component_id" = 16 AND U0."variant_id" IS NULL))
2021-06-22 14:11:19.184 UTC [292] LOG:  statement: UPDATE "trans_unit" SET "variant_id" = 5 WHERE "trans_unit"."id" IN (SELECT V0."id" FROM "trans_unit" V0 INNER JOIN "trans_translation" V1 ON (V0."translation_id" = V1."id") WHERE (V0."id_hash" IN (SELECT U0."id_hash" FROM "trans_unit" U0 INNER JOIN "trans_variant_defining_units" U1 ON (U0."id" = U1."unit_id") WHERE U1."variant_id" = 5) AND V1."component_id" = 16 AND V0."variant_id" IS NULL))
2021-06-22 14:11:19.189 UTC [292] LOG:  statement: UPDATE "trans_unit" SET "variant_id" = 6 WHERE "trans_unit"."id" IN (SELECT U0."id" FROM "trans_unit" U0 INNER JOIN "trans_translation" U1 ON (U0."translation_id" = U1."id") WHERE (U0."source" = 'The Romans waged war to gather slaves and wealth.' AND U1."component_id" = 16 AND U0."variant_id" IS NULL))
2021-06-22 14:11:19.636 UTC [292] LOG:  statement: UPDATE "trans_unit" SET "variant_id" = 6 WHERE "trans_unit"."id" IN (SELECT V0."id" FROM "trans_unit" V0 INNER JOIN "trans_translation" V1 ON (V0."translation_id" = V1."id") WHERE (V0."id_hash" IN (SELECT U0."id_hash" FROM "trans_unit" U0 INNER JOIN "trans_variant_defining_units" U1 ON (U0."id" = U1."unit_id") WHERE U1."variant_id" = 6) AND V1."component_id" = 16 AND V0."variant_id" IS NULL))
2021-06-22 14:11:19.640 UTC [292] LOG:  statement: UPDATE "trans_unit" SET "variant_id" = 7 WHERE "trans_unit"."id" IN (SELECT U0."id" FROM "trans_unit" U0 INNER JOIN "trans_translation" U1 ON (U0."translation_id" = U1."id") WHERE (U0."source" = 'asdq1' AND U1."component_id" = 16 AND U0."variant_id" IS NULL))
2021-06-22 14:11:20.110 UTC [292] LOG:  statement: UPDATE "trans_unit" SET "variant_id" = 7 WHERE "trans_unit"."id" IN (SELECT V0."id" FROM "trans_unit" V0 INNER JOIN "trans_translation" V1 ON (V0."translation_id" = V1."id") WHERE (V0."id_hash" IN (SELECT U0."id_hash" FROM "trans_unit" U0 INNER JOIN "trans_variant_defining_units" U1 ON (U0."id" = U1."unit_id") WHERE U1."variant_id" = 7) AND V1."component_id" = 16 AND V0."variant_id" IS NULL))
2021-06-22 14:11:20.114 UTC [292] LOG:  statement: UPDATE "trans_unit" SET "variant_id" = 8 WHERE "trans_unit"."id" IN (SELECT U0."id" FROM "trans_unit" U0 INNER JOIN "trans_translation" U1 ON (U0."translation_id" = U1."id") WHERE (U0."source" = 'qwez' AND U1."component_id" = 16 AND U0."variant_id" IS NULL))
2021-06-22 14:11:20.570 UTC [292] LOG:  statement: UPDATE "trans_unit" SET "variant_id" = 8 WHERE "trans_unit"."id" IN (SELECT V0."id" FROM "trans_unit" V0 INNER JOIN "trans_translation" V1 ON (V0."translation_id" = V1."id") WHERE (V0."id_hash" IN (SELECT U0."id_hash" FROM "trans_unit" U0 INNER JOIN "trans_variant_defining_units" U1 ON (U0."id" = U1."unit_id") WHERE U1."variant_id" = 8) AND V1."component_id" = 16 AND V0."variant_id" IS NULL))
2021-06-22 14:11:20.574 UTC [292] LOG:  statement: UPDATE "trans_unit" SET "variant_id" = 9 WHERE "trans_unit"."id" IN (SELECT U0."id" FROM "trans_unit" U0 INNER JOIN "trans_translation" U1 ON (U0."translation_id" = U1."id") WHERE (U0."source" = 'Spain built an empire from its lust for gold and territory.' AND U1."component_id" = 16 AND U0."variant_id" IS NULL))
2021-06-22 14:11:21.030 UTC [292] LOG:  statement: UPDATE "trans_unit" SET "variant_id" = 9 WHERE "trans_unit"."id" IN (SELECT V0."id" FROM "trans_unit" V0 INNER JOIN "trans_translation" V1 ON (V0."translation_id" = V1."id") WHERE (V0."id_hash" IN (SELECT U0."id_hash" FROM "trans_unit" U0 INNER JOIN "trans_variant_defining_units" U1 ON (U0."id" = U1."unit_id") WHERE U1."variant_id" = 9) AND V1."component_id" = 16 AND V0."variant_id" IS NULL))
2021-06-22 14:11:21.034 UTC [292] LOG:  statement: UPDATE "trans_unit" SET "variant_id" = 10 WHERE "trans_unit"."id" IN (SELECT U0."id" FROM "trans_unit" U0 INNER JOIN "trans_translation" U1 ON (U0."translation_id" = U1."id") WHERE (U0."source" = 'Hitler shaped a battered Germany into an economic superpower.' AND U1."component_id" = 16 AND U0."variant_id" IS NULL))
2021-06-22 14:11:21.476 UTC [292] LOG:  statement: UPDATE "trans_unit" SET "variant_id" = 10 WHERE "trans_unit"."id" IN (SELECT V0."id" FROM "trans_unit" V0 INNER JOIN "trans_translation" V1 ON (V0."translation_id" = V1."id") WHERE (V0."id_hash" IN (SELECT U0."id_hash" FROM "trans_unit" U0 INNER JOIN "trans_variant_defining_units" U1 ON (U0."id" = U1."unit_id") WHERE U1."variant_id" = 10) AND V1."component_id" = 16 AND V0."variant_id" IS NULL))
2021-06-22 14:11:21.480 UTC [292] LOG:  statement: UPDATE "trans_unit" SET "variant_id" = 11 WHERE "trans_unit"."id" IN (SELECT U0."id" FROM "trans_unit" U0 INNER JOIN "trans_translation" U1 ON (U0."translation_id" = U1."id") WHERE (U0."source" = 'assssss' AND U1."component_id" = 16 AND U0."variant_id" IS NULL))
2021-06-22 14:11:21.924 UTC [292] LOG:  statement: UPDATE "trans_unit" SET "variant_id" = 11 WHERE "trans_unit"."id" IN (SELECT V0."id" FROM "trans_unit" V0 INNER JOIN "trans_translation" V1 ON (V0."translation_id" = V1."id") WHERE (V0."id_hash" IN (SELECT U0."id_hash" FROM "trans_unit" U0 INNER JOIN "trans_variant_defining_units" U1 ON (U0."id" = U1."unit_id") WHERE U1."variant_id" = 11) AND V1."component_id" = 16 AND V0."variant_id" IS NULL))
2021-06-22 14:11:21.925 UTC [292] LOG:  statement: FETCH FORWARD 2000 FROM "_django_curs_140702676903808_sync_27"
2021-06-22 14:11:21.926 UTC [292] LOG:  statement: CLOSE "_django_curs_140702676903808_sync_27"
2021-06-22 14:11:21.927 UTC [292] LOG:  statement: SELECT "lang_language"."id", "lang_language"."code", "lang_language"."name", "lang_language"."direction" FROM "lang_language" WHERE "lang_language"."id" = 75 LIMIT 21
2021-06-22 14:11:21.928 UTC [292] LOG:  statement: INSERT INTO "trans_change" ("unit_id", "language_id", "project_id", "component_id", "translation_id", "comment_id", "suggestion_id", "announcement_id", "screenshot_id", "alert_id", "user_id", "author_id", "timestamp", "action", "target", "old", "details") VALUES (1465742, 75, 13, 16, 117, NULL, NULL, NULL, NULL, NULL, 2, 2, '2021-06-22T14:11:21.928432+00:00'::timestamptz, 31, 'ffffff', '', '{}') RETURNING "trans_change"."id"
2021-06-22 14:11:21.929 UTC [292] LOG:  statement: RELEASE SAVEPOINT "s140702676903808_x13"
2021-06-22 14:11:21.961 UTC [292] LOG:  statement: SELECT COUNT("__col1"), SUM("__col2"), SUM(LENGTH("__col3")), SUM(CASE WHEN "__col4" = 10 THEN 1 ELSE 0 END), SUM(CASE WHEN "__col4" = 10 THEN "__col2" ELSE 0 END), SUM(CASE WHEN "__col4" = 10 THEN LENGTH("__col3") ELSE 0 END), SUM(CASE WHEN "__col4" = 100 THEN 1 ELSE 0 END), SUM(CASE WHEN "__col4" = 100 THEN "__col2" ELSE 0 END), SUM(CASE WHEN "__col4" = 100 THEN LENGTH("__col3") ELSE 0 END), SUM(CASE WHEN "__col4" >= 20 THEN 1 ELSE 0 END), SUM(CASE WHEN "__col4" >= 20 THEN "__col2" ELSE 0 END), SUM(CASE WHEN "__col4" >= 20 THEN LENGTH("__col3") ELSE 0 END), SUM(CASE WHEN "__col4" < 20 THEN 1 ELSE 0 END), SUM(CASE WHEN "__col4" < 20 THEN "__col2" ELSE 0 END), SUM(CASE WHEN "__col4" < 20 THEN LENGTH("__col3") ELSE 0 END), SUM(CASE WHEN "__col4" = 0 THEN 1 ELSE 0 END), SUM(CASE WHEN "__col4" = 0 THEN "__col2" ELSE 0 END), SUM(CASE WHEN "__col4" = 0 THEN LENGTH("__col3") ELSE 0 END), SUM(CASE WHEN "__col4" = 30 THEN 1 ELSE 0 END), SUM(CASE WHEN "__col4" = 30 THEN "__col2" ELSE 0 END), SUM(CASE WHEN "__col4" = 30 THEN LENGTH("__col3") ELSE 0 END), SUM(CASE WHEN "__col5" IS NULL THEN 1 ELSE 0 END), SUM(CASE WHEN "__col5" IS NULL THEN "__col2" ELSE 0 END), SUM(CASE WHEN "__col5" IS NULL THEN LENGTH("__col3") ELSE 0 END), SUM(CASE WHEN "active_checks_count" > 0 THEN 1 ELSE 0 END), SUM(CASE WHEN "active_checks_count" > 0 THEN "__col2" ELSE 0 END), SUM(CASE WHEN "active_checks_count" > 0 THEN LENGTH("__col3") ELSE 0 END), SUM(CASE WHEN ("active_checks_count" > 0 AND "__col4" = 20) THEN 1 ELSE 0 END), SUM(CASE WHEN ("active_checks_count" > 0 AND "__col4" = 20) THEN "__col2" ELSE 0 END), SUM(CASE WHEN ("active_checks_count" > 0 AND "__col4" = 20) THEN LENGTH("__col3") ELSE 0 END), SUM(CASE WHEN "dismissed_checks_count" > 0 THEN 1 ELSE 0 END), SUM(CASE WHEN "dismissed_checks_count" > 0 THEN "__col2" ELSE 0 END), SUM(CASE WHEN "dismissed_checks_count" > 0 THEN LENGTH("__col3") ELSE 0 END), SUM(CASE WHEN "suggestion_count" > 0 THEN 1 ELSE 0 END), SUM(CASE WHEN "suggestion_count" > 0 THEN "__col2" ELSE 0 END), SUM(CASE WHEN "suggestion_count" > 0 THEN LENGTH("__col3") ELSE 0 END), SUM(CASE WHEN ("__col4" < 20 AND "suggestion_count" = 0) THEN 1 ELSE 0 END), SUM(CASE WHEN ("__col4" < 20 AND "suggestion_count" = 0) THEN "__col2" ELSE 0 END), SUM(CASE WHEN ("__col4" < 20 AND "suggestion_count" = 0) THEN LENGTH("__col3") ELSE 0 END), SUM(CASE WHEN ("__col4" >= 30 AND "suggestion_count" > 0) THEN 1 ELSE 0 END), SUM(CASE WHEN ("__col4" >= 30 AND "suggestion_count" > 0) THEN "__col2" ELSE 0 END), SUM(CASE WHEN ("__col4" >= 30 AND "suggestion_count" > 0) THEN LENGTH("__col3") ELSE 0 END), SUM(CASE WHEN "comment_count" > 0 THEN 1 ELSE 0 END), SUM(CASE WHEN "comment_count" > 0 THEN "__col2" ELSE 0 END), SUM(CASE WHEN "comment_count" > 0 THEN LENGTH("__col3") ELSE 0 END) FROM (SELECT COUNT("checks_check"."id") FILTER (WHERE NOT "checks_check"."dismissed") AS "active_checks_count", COUNT("checks_check"."id") FILTER (WHERE "checks_check"."dismissed") AS "dismissed_checks_count", COUNT("trans_suggestion"."id") AS "suggestion_count", COUNT("trans_comment"."id") FILTER (WHERE NOT "trans_comment"."resolved") AS "comment_count", "trans_unit"."id" AS "__col1", "trans_unit"."num_words" AS "__col2", "trans_unit"."source" AS "__col3", "trans_unit"."state" AS "__col4", "trans_unit_labels"."label_id" AS "__col5" FROM "trans_unit" LEFT OUTER JOIN "checks_check" ON ("trans_unit"."id" = "checks_check"."unit_id") LEFT OUTER JOIN "trans_suggestion" ON ("trans_unit"."id" = "trans_suggestion"."unit_id") LEFT OUTER JOIN "trans_comment" ON ("trans_unit"."id" = "trans_comment"."unit_id") LEFT OUTER JOIN "trans_unit" T6 ON ("trans_unit"."source_unit_id" = T6."id") LEFT OUTER JOIN "trans_unit_labels" ON (T6."id" = "trans_unit_labels"."unit_id") WHERE "trans_unit"."translation_id" = 30 GROUP BY "trans_unit"."id", "trans_unit_labels"."label_id") subquery
2021-06-22 14:11:22.197 UTC [292] LOG:  statement: SELECT "trans_change"."id", "trans_change"."unit_id", "trans_change"."language_id", "trans_change"."project_id", "trans_change"."component_id", "trans_change"."translation_id", "trans_change"."comment_id", "trans_change"."suggestion_id", "trans_change"."announcement_id", "trans_change"."screenshot_id", "trans_change"."alert_id", "trans_change"."user_id", "trans_change"."author_id", "trans_change"."timestamp", "trans_change"."action", "trans_change"."target", "trans_change"."old", "trans_change"."details" FROM "trans_change" WHERE "trans_change"."id" = 483197 LIMIT 21
2021-06-22 14:11:22.198 UTC [292] LOG:  statement: SAVEPOINT "s140702676903808_x15"
2021-06-22 14:11:22.199 UTC [292] LOG:  statement: INSERT INTO "trans_unit" ("translation_id", "id_hash", "location", "context", "note", "flags", "source", "previous_source", "target", "state", "original_state", "details", "position", "num_words", "priority", "pending", "timestamp", "extra_flags", "explanation", "variant_id", "source_unit_id") VALUES (30,  -4615925357981967800, '', 'fffffff', '', '', 'ffffff', '', 'ffffff', 20, 0, '{"add_unit": true}', 24670, 1, 100, true, '2021-06-22T14:11:22.199581+00:00'::timestamptz, '', '', NULL, 1465742) RETURNING "trans_unit"."id"
2021-06-22 14:11:22.201 UTC [292] LOG:  statement: SELECT "checks_check"."id", "checks_check"."unit_id", "checks_check"."check", "checks_check"."dismissed" FROM "checks_check" WHERE "checks_check"."unit_id" = 1465743
2021-06-22 14:11:22.207 UTC [292] LOG:  statement: SELECT "trans_unit"."id", "trans_unit"."translation_id", "trans_unit"."id_hash", "trans_unit"."location", "trans_unit"."context", "trans_unit"."note", "trans_unit"."flags", "trans_unit"."source", "trans_unit"."previous_source", "trans_unit"."target", "trans_unit"."state", "trans_unit"."original_state", "trans_unit"."details", "trans_unit"."position", "trans_unit"."num_words", "trans_unit"."priority", "trans_unit"."pending", "trans_unit"."timestamp", "trans_unit"."extra_flags", "trans_unit"."explanation", "trans_unit"."variant_id", "trans_unit"."source_unit_id" FROM "trans_unit" INNER JOIN "trans_translation" ON ("trans_unit"."translation_id" = "trans_translation"."id") INNER JOIN "trans_component" ON ("trans_translation"."component_id" = "trans_component"."id") WHERE ("trans_unit"."context" = 'fffffff' AND "trans_unit"."source" = 'ffffff' AND "trans_component"."project_id" = 13 AND "trans_component"."source_language_id" = 75 AND "trans_translation"."language_id" = 97 AND NOT ("trans_unit"."id" = 1465743) AND "trans_component"."allow_translation_propagation" AND "trans_translation"."plural_id" = 199)
2021-06-22 14:11:22.479 UTC [292] LOG:  statement: SELECT "lang_language"."id", "lang_language"."code", "lang_language"."name", "lang_language"."direction" FROM "lang_language" WHERE "lang_language"."id" = 75 LIMIT 21
2021-06-22 14:11:22.480 UTC [292] LOG:  statement: SELECT "trans_variant"."id", "trans_variant"."component_id", "trans_variant"."variant_regex", "trans_variant"."key" FROM "trans_variant" INNER JOIN "trans_variant_defining_units" ON ("trans_variant"."id" = "trans_variant_defining_units"."variant_id") WHERE "trans_variant_defining_units"."unit_id" = 1465743
2021-06-22 14:11:22.482 UTC [292] LOG:  statement: SELECT "trans_variant"."id", "trans_variant"."component_id", "trans_variant"."variant_regex", "trans_variant"."key" FROM "trans_variant" WHERE ("trans_variant"."component_id" = 16 AND "trans_variant"."key" = 'assssss') LIMIT 21
2021-06-22 14:11:22.484 UTC [292] LOG:  statement: INSERT INTO "trans_variant_defining_units" ("variant_id", "unit_id") VALUES (11, 1465743) ON CONFLICT DO NOTHING
2021-06-22 14:11:22.486 UTC [292] LOG:  statement: SELECT "trans_variant"."id", "trans_variant"."component_id", "trans_variant"."variant_regex", "trans_variant"."key" FROM "trans_variant" WHERE ("trans_variant"."component_id" = 16 AND NOT ("trans_variant"."variant_regex" = ''))
2021-06-22 14:11:22.487 UTC [292] LOG:  statement: DECLARE "_django_curs_140702676903808_sync_28" NO SCROLL CURSOR WITHOUT HOLD FOR SELECT "trans_variant"."id", "trans_variant"."component_id", "trans_variant"."variant_regex", "trans_variant"."key" FROM "trans_variant" WHERE "trans_variant"."component_id" = 16
2021-06-22 14:11:22.488 UTC [292] LOG:  statement: FETCH FORWARD 2000 FROM "_django_curs_140702676903808_sync_28"
2021-06-22 14:11:22.490 UTC [292] LOG:  statement: UPDATE "trans_unit" SET "variant_id" = 3 WHERE "trans_unit"."id" IN (SELECT U0."id" FROM "trans_unit" U0 INNER JOIN "trans_translation" U1 ON (U0."translation_id" = U1."id") WHERE (U0."source" = 'RemindBoy message: Water supplies exhausted. Vault 13 is dead.' AND U1."component_id" = 16 AND U0."variant_id" IS NULL))
2021-06-22 14:11:22.936 UTC [292] LOG:  statement: UPDATE "trans_unit" SET "variant_id" = 3 WHERE "trans_unit"."id" IN (SELECT V0."id" FROM "trans_unit" V0 INNER JOIN "trans_translation" V1 ON (V0."translation_id" = V1."id") WHERE (V0."id_hash" IN (SELECT U0."id_hash" FROM "trans_unit" U0 INNER JOIN "trans_variant_defining_units" U1 ON (U0."id" = U1."unit_id") WHERE U1."variant_id" = 3) AND V1."component_id" = 16 AND V0."variant_id" IS NULL))
2021-06-22 14:11:22.940 UTC [292] LOG:  statement: UPDATE "trans_unit" SET "variant_id" = 4 WHERE "trans_unit"."id" IN (SELECT U0."id" FROM "trans_unit" U0 INNER JOIN "trans_translation" U1 ON (U0."translation_id" = U1."id") WHERE (U0."source" = 'RemindBoy message: Water supplies nearly gone in Vault 13.  Situation critical.' AND U1."component_id" = 16 AND U0."variant_id" IS NULL))
2021-06-22 14:11:23.385 UTC [292] LOG:  statement: UPDATE "trans_unit" SET "variant_id" = 4 WHERE "trans_unit"."id" IN (SELECT V0."id" FROM "trans_unit" V0 INNER JOIN "trans_translation" V1 ON (V0."translation_id" = V1."id") WHERE (V0."id_hash" IN (SELECT U0."id_hash" FROM "trans_unit" U0 INNER JOIN "trans_variant_defining_units" U1 ON (U0."id" = U1."unit_id") WHERE U1."variant_id" = 4) AND V1."component_id" = 16 AND V0."variant_id" IS NULL))
2021-06-22 14:11:23.390 UTC [292] LOG:  statement: UPDATE "trans_unit" SET "variant_id" = 5 WHERE "trans_unit"."id" IN (SELECT U0."id" FROM "trans_unit" U0 INNER JOIN "trans_translation" U1 ON (U0."translation_id" = U1."id") WHERE (U0."source" = 'zzz123' AND U1."component_id" = 16 AND U0."variant_id" IS NULL))
2021-06-22 14:11:23.828 UTC [292] LOG:  statement: UPDATE "trans_unit" SET "variant_id" = 5 WHERE "trans_unit"."id" IN (SELECT V0."id" FROM "trans_unit" V0 INNER JOIN "trans_translation" V1 ON (V0."translation_id" = V1."id") WHERE (V0."id_hash" IN (SELECT U0."id_hash" FROM "trans_unit" U0 INNER JOIN "trans_variant_defining_units" U1 ON (U0."id" = U1."unit_id") WHERE U1."variant_id" = 5) AND V1."component_id" = 16 AND V0."variant_id" IS NULL))
2021-06-22 14:11:23.832 UTC [292] LOG:  statement: UPDATE "trans_unit" SET "variant_id" = 6 WHERE "trans_unit"."id" IN (SELECT U0."id" FROM "trans_unit" U0 INNER JOIN "trans_translation" U1 ON (U0."translation_id" = U1."id") WHERE (U0."source" = 'The Romans waged war to gather slaves and wealth.' AND U1."component_id" = 16 AND U0."variant_id" IS NULL))
2021-06-22 14:11:24.280 UTC [292] LOG:  statement: UPDATE "trans_unit" SET "variant_id" = 6 WHERE "trans_unit"."id" IN (SELECT V0."id" FROM "trans_unit" V0 INNER JOIN "trans_translation" V1 ON (V0."translation_id" = V1."id") WHERE (V0."id_hash" IN (SELECT U0."id_hash" FROM "trans_unit" U0 INNER JOIN "trans_variant_defining_units" U1 ON (U0."id" = U1."unit_id") WHERE U1."variant_id" = 6) AND V1."component_id" = 16 AND V0."variant_id" IS NULL))
2021-06-22 14:11:24.285 UTC [292] LOG:  statement: UPDATE "trans_unit" SET "variant_id" = 7 WHERE "trans_unit"."id" IN (SELECT U0."id" FROM "trans_unit" U0 INNER JOIN "trans_translation" U1 ON (U0."translation_id" = U1."id") WHERE (U0."source" = 'asdq1' AND U1."component_id" = 16 AND U0."variant_id" IS NULL))
2021-06-22 14:11:24.740 UTC [292] LOG:  statement: UPDATE "trans_unit" SET "variant_id" = 7 WHERE "trans_unit"."id" IN (SELECT V0."id" FROM "trans_unit" V0 INNER JOIN "trans_translation" V1 ON (V0."translation_id" = V1."id") WHERE (V0."id_hash" IN (SELECT U0."id_hash" FROM "trans_unit" U0 INNER JOIN "trans_variant_defining_units" U1 ON (U0."id" = U1."unit_id") WHERE U1."variant_id" = 7) AND V1."component_id" = 16 AND V0."variant_id" IS NULL))
2021-06-22 14:11:24.744 UTC [292] LOG:  statement: UPDATE "trans_unit" SET "variant_id" = 8 WHERE "trans_unit"."id" IN (SELECT U0."id" FROM "trans_unit" U0 INNER JOIN "trans_translation" U1 ON (U0."translation_id" = U1."id") WHERE (U0."source" = 'qwez' AND U1."component_id" = 16 AND U0."variant_id" IS NULL))
2021-06-22 14:11:25.185 UTC [292] LOG:  statement: UPDATE "trans_unit" SET "variant_id" = 8 WHERE "trans_unit"."id" IN (SELECT V0."id" FROM "trans_unit" V0 INNER JOIN "trans_translation" V1 ON (V0."translation_id" = V1."id") WHERE (V0."id_hash" IN (SELECT U0."id_hash" FROM "trans_unit" U0 INNER JOIN "trans_variant_defining_units" U1 ON (U0."id" = U1."unit_id") WHERE U1."variant_id" = 8) AND V1."component_id" = 16 AND V0."variant_id" IS NULL))
2021-06-22 14:11:25.190 UTC [292] LOG:  statement: UPDATE "trans_unit" SET "variant_id" = 9 WHERE "trans_unit"."id" IN (SELECT U0."id" FROM "trans_unit" U0 INNER JOIN "trans_translation" U1 ON (U0."translation_id" = U1."id") WHERE (U0."source" = 'Spain built an empire from its lust for gold and territory.' AND U1."component_id" = 16 AND U0."variant_id" IS NULL))
2021-06-22 14:11:25.626 UTC [292] LOG:  statement: UPDATE "trans_unit" SET "variant_id" = 9 WHERE "trans_unit"."id" IN (SELECT V0."id" FROM "trans_unit" V0 INNER JOIN "trans_translation" V1 ON (V0."translation_id" = V1."id") WHERE (V0."id_hash" IN (SELECT U0."id_hash" FROM "trans_unit" U0 INNER JOIN "trans_variant_defining_units" U1 ON (U0."id" = U1."unit_id") WHERE U1."variant_id" = 9) AND V1."component_id" = 16 AND V0."variant_id" IS NULL))
2021-06-22 14:11:25.630 UTC [292] LOG:  statement: UPDATE "trans_unit" SET "variant_id" = 10 WHERE "trans_unit"."id" IN (SELECT U0."id" FROM "trans_unit" U0 INNER JOIN "trans_translation" U1 ON (U0."translation_id" = U1."id") WHERE (U0."source" = 'Hitler shaped a battered Germany into an economic superpower.' AND U1."component_id" = 16 AND U0."variant_id" IS NULL))
2021-06-22 14:11:26.063 UTC [292] LOG:  statement: UPDATE "trans_unit" SET "variant_id" = 10 WHERE "trans_unit"."id" IN (SELECT V0."id" FROM "trans_unit" V0 INNER JOIN "trans_translation" V1 ON (V0."translation_id" = V1."id") WHERE (V0."id_hash" IN (SELECT U0."id_hash" FROM "trans_unit" U0 INNER JOIN "trans_variant_defining_units" U1 ON (U0."id" = U1."unit_id") WHERE U1."variant_id" = 10) AND V1."component_id" = 16 AND V0."variant_id" IS NULL))
2021-06-22 14:11:26.068 UTC [292] LOG:  statement: UPDATE "trans_unit" SET "variant_id" = 11 WHERE "trans_unit"."id" IN (SELECT U0."id" FROM "trans_unit" U0 INNER JOIN "trans_translation" U1 ON (U0."translation_id" = U1."id") WHERE (U0."source" = 'assssss' AND U1."component_id" = 16 AND U0."variant_id" IS NULL))
2021-06-22 14:11:26.520 UTC [292] LOG:  statement: UPDATE "trans_unit" SET "variant_id" = 11 WHERE "trans_unit"."id" IN (SELECT V0."id" FROM "trans_unit" V0 INNER JOIN "trans_translation" V1 ON (V0."translation_id" = V1."id") WHERE (V0."id_hash" IN (SELECT U0."id_hash" FROM "trans_unit" U0 INNER JOIN "trans_variant_defining_units" U1 ON (U0."id" = U1."unit_id") WHERE U1."variant_id" = 11) AND V1."component_id" = 16 AND V0."variant_id" IS NULL))
2021-06-22 14:11:26.522 UTC [292] LOG:  statement: FETCH FORWARD 2000 FROM "_django_curs_140702676903808_sync_28"
2021-06-22 14:11:26.522 UTC [292] LOG:  statement: CLOSE "_django_curs_140702676903808_sync_28"
2021-06-22 14:11:26.524 UTC [292] LOG:  statement: INSERT INTO "trans_change" ("unit_id", "language_id", "project_id", "component_id", "translation_id", "comment_id", "suggestion_id", "announcement_id", "screenshot_id", "alert_id", "user_id", "author_id", "timestamp", "action", "target", "old", "details") VALUES (1465743, 97, 13, 16, 30, NULL, NULL, NULL, NULL, NULL, 2, 2, '2021-06-22T14:11:26.523844+00:00'::timestamptz, 31, 'ffffff', '', '{}') RETURNING "trans_change"."id"
2021-06-22 14:11:26.525 UTC [292] LOG:  statement: RELEASE SAVEPOINT "s140702676903808_x15"
2021-06-22 14:11:26.526 UTC [292] LOG:  statement: SELECT "trans_variant"."id", "trans_variant"."component_id", "trans_variant"."variant_regex", "trans_variant"."key" FROM "trans_variant" WHERE ("trans_variant"."component_id" = 16 AND NOT ("trans_variant"."variant_regex" = ''))
2021-06-22 14:11:26.528 UTC [292] LOG:  statement: DECLARE "_django_curs_140702676903808_sync_29" NO SCROLL CURSOR WITHOUT HOLD FOR SELECT "trans_variant"."id", "trans_variant"."component_id", "trans_variant"."variant_regex", "trans_variant"."key" FROM "trans_variant" WHERE "trans_variant"."component_id" = 16
2021-06-22 14:11:26.528 UTC [292] LOG:  statement: FETCH FORWARD 2000 FROM "_django_curs_140702676903808_sync_29"
2021-06-22 14:11:26.530 UTC [292] LOG:  statement: UPDATE "trans_unit" SET "variant_id" = 3 WHERE "trans_unit"."id" IN (SELECT U0."id" FROM "trans_unit" U0 INNER JOIN "trans_translation" U1 ON (U0."translation_id" = U1."id") WHERE (U0."source" = 'RemindBoy message: Water supplies exhausted. Vault 13 is dead.' AND U1."component_id" = 16 AND U0."variant_id" IS NULL))
2021-06-22 14:11:27.002 UTC [292] LOG:  statement: UPDATE "trans_unit" SET "variant_id" = 3 WHERE "trans_unit"."id" IN (SELECT V0."id" FROM "trans_unit" V0 INNER JOIN "trans_translation" V1 ON (V0."translation_id" = V1."id") WHERE (V0."id_hash" IN (SELECT U0."id_hash" FROM "trans_unit" U0 INNER JOIN "trans_variant_defining_units" U1 ON (U0."id" = U1."unit_id") WHERE U1."variant_id" = 3) AND V1."component_id" = 16 AND V0."variant_id" IS NULL))
2021-06-22 14:11:27.007 UTC [292] LOG:  statement: UPDATE "trans_unit" SET "variant_id" = 4 WHERE "trans_unit"."id" IN (SELECT U0."id" FROM "trans_unit" U0 INNER JOIN "trans_translation" U1 ON (U0."translation_id" = U1."id") WHERE (U0."source" = 'RemindBoy message: Water supplies nearly gone in Vault 13.  Situation critical.' AND U1."component_id" = 16 AND U0."variant_id" IS NULL))
2021-06-22 14:11:27.461 UTC [292] LOG:  statement: UPDATE "trans_unit" SET "variant_id" = 4 WHERE "trans_unit"."id" IN (SELECT V0."id" FROM "trans_unit" V0 INNER JOIN "trans_translation" V1 ON (V0."translation_id" = V1."id") WHERE (V0."id_hash" IN (SELECT U0."id_hash" FROM "trans_unit" U0 INNER JOIN "trans_variant_defining_units" U1 ON (U0."id" = U1."unit_id") WHERE U1."variant_id" = 4) AND V1."component_id" = 16 AND V0."variant_id" IS NULL))
2021-06-22 14:11:27.465 UTC [292] LOG:  statement: UPDATE "trans_unit" SET "variant_id" = 5 WHERE "trans_unit"."id" IN (SELECT U0."id" FROM "trans_unit" U0 INNER JOIN "trans_translation" U1 ON (U0."translation_id" = U1."id") WHERE (U0."source" = 'zzz123' AND U1."component_id" = 16 AND U0."variant_id" IS NULL))
2021-06-22 14:11:27.916 UTC [292] LOG:  statement: UPDATE "trans_unit" SET "variant_id" = 5 WHERE "trans_unit"."id" IN (SELECT V0."id" FROM "trans_unit" V0 INNER JOIN "trans_translation" V1 ON (V0."translation_id" = V1."id") WHERE (V0."id_hash" IN (SELECT U0."id_hash" FROM "trans_unit" U0 INNER JOIN "trans_variant_defining_units" U1 ON (U0."id" = U1."unit_id") WHERE U1."variant_id" = 5) AND V1."component_id" = 16 AND V0."variant_id" IS NULL))
2021-06-22 14:11:27.921 UTC [292] LOG:  statement: UPDATE "trans_unit" SET "variant_id" = 6 WHERE "trans_unit"."id" IN (SELECT U0."id" FROM "trans_unit" U0 INNER JOIN "trans_translation" U1 ON (U0."translation_id" = U1."id") WHERE (U0."source" = 'The Romans waged war to gather slaves and wealth.' AND U1."component_id" = 16 AND U0."variant_id" IS NULL))
2021-06-22 14:11:28.364 UTC [292] LOG:  statement: UPDATE "trans_unit" SET "variant_id" = 6 WHERE "trans_unit"."id" IN (SELECT V0."id" FROM "trans_unit" V0 INNER JOIN "trans_translation" V1 ON (V0."translation_id" = V1."id") WHERE (V0."id_hash" IN (SELECT U0."id_hash" FROM "trans_unit" U0 INNER JOIN "trans_variant_defining_units" U1 ON (U0."id" = U1."unit_id") WHERE U1."variant_id" = 6) AND V1."component_id" = 16 AND V0."variant_id" IS NULL))
2021-06-22 14:11:28.368 UTC [292] LOG:  statement: UPDATE "trans_unit" SET "variant_id" = 7 WHERE "trans_unit"."id" IN (SELECT U0."id" FROM "trans_unit" U0 INNER JOIN "trans_translation" U1 ON (U0."translation_id" = U1."id") WHERE (U0."source" = 'asdq1' AND U1."component_id" = 16 AND U0."variant_id" IS NULL))
2021-06-22 14:11:28.801 UTC [292] LOG:  statement: UPDATE "trans_unit" SET "variant_id" = 7 WHERE "trans_unit"."id" IN (SELECT V0."id" FROM "trans_unit" V0 INNER JOIN "trans_translation" V1 ON (V0."translation_id" = V1."id") WHERE (V0."id_hash" IN (SELECT U0."id_hash" FROM "trans_unit" U0 INNER JOIN "trans_variant_defining_units" U1 ON (U0."id" = U1."unit_id") WHERE U1."variant_id" = 7) AND V1."component_id" = 16 AND V0."variant_id" IS NULL))
2021-06-22 14:11:28.805 UTC [292] LOG:  statement: UPDATE "trans_unit" SET "variant_id" = 8 WHERE "trans_unit"."id" IN (SELECT U0."id" FROM "trans_unit" U0 INNER JOIN "trans_translation" U1 ON (U0."translation_id" = U1."id") WHERE (U0."source" = 'qwez' AND U1."component_id" = 16 AND U0."variant_id" IS NULL))
2021-06-22 14:11:29.253 UTC [292] LOG:  statement: UPDATE "trans_unit" SET "variant_id" = 8 WHERE "trans_unit"."id" IN (SELECT V0."id" FROM "trans_unit" V0 INNER JOIN "trans_translation" V1 ON (V0."translation_id" = V1."id") WHERE (V0."id_hash" IN (SELECT U0."id_hash" FROM "trans_unit" U0 INNER JOIN "trans_variant_defining_units" U1 ON (U0."id" = U1."unit_id") WHERE U1."variant_id" = 8) AND V1."component_id" = 16 AND V0."variant_id" IS NULL))
2021-06-22 14:11:29.258 UTC [292] LOG:  statement: UPDATE "trans_unit" SET "variant_id" = 9 WHERE "trans_unit"."id" IN (SELECT U0."id" FROM "trans_unit" U0 INNER JOIN "trans_translation" U1 ON (U0."translation_id" = U1."id") WHERE (U0."source" = 'Spain built an empire from its lust for gold and territory.' AND U1."component_id" = 16 AND U0."variant_id" IS NULL))
2021-06-22 14:11:29.691 UTC [292] LOG:  statement: UPDATE "trans_unit" SET "variant_id" = 9 WHERE "trans_unit"."id" IN (SELECT V0."id" FROM "trans_unit" V0 INNER JOIN "trans_translation" V1 ON (V0."translation_id" = V1."id") WHERE (V0."id_hash" IN (SELECT U0."id_hash" FROM "trans_unit" U0 INNER JOIN "trans_variant_defining_units" U1 ON (U0."id" = U1."unit_id") WHERE U1."variant_id" = 9) AND V1."component_id" = 16 AND V0."variant_id" IS NULL))
2021-06-22 14:11:29.695 UTC [292] LOG:  statement: UPDATE "trans_unit" SET "variant_id" = 10 WHERE "trans_unit"."id" IN (SELECT U0."id" FROM "trans_unit" U0 INNER JOIN "trans_translation" U1 ON (U0."translation_id" = U1."id") WHERE (U0."source" = 'Hitler shaped a battered Germany into an economic superpower.' AND U1."component_id" = 16 AND U0."variant_id" IS NULL))
2021-06-22 14:11:30.131 UTC [292] LOG:  statement: UPDATE "trans_unit" SET "variant_id" = 10 WHERE "trans_unit"."id" IN (SELECT V0."id" FROM "trans_unit" V0 INNER JOIN "trans_translation" V1 ON (V0."translation_id" = V1."id") WHERE (V0."id_hash" IN (SELECT U0."id_hash" FROM "trans_unit" U0 INNER JOIN "trans_variant_defining_units" U1 ON (U0."id" = U1."unit_id") WHERE U1."variant_id" = 10) AND V1."component_id" = 16 AND V0."variant_id" IS NULL))
2021-06-22 14:11:30.136 UTC [292] LOG:  statement: UPDATE "trans_unit" SET "variant_id" = 11 WHERE "trans_unit"."id" IN (SELECT U0."id" FROM "trans_unit" U0 INNER JOIN "trans_translation" U1 ON (U0."translation_id" = U1."id") WHERE (U0."source" = 'assssss' AND U1."component_id" = 16 AND U0."variant_id" IS NULL))
2021-06-22 14:11:30.576 UTC [292] LOG:  statement: UPDATE "trans_unit" SET "variant_id" = 11 WHERE "trans_unit"."id" IN (SELECT V0."id" FROM "trans_unit" V0 INNER JOIN "trans_translation" V1 ON (V0."translation_id" = V1."id") WHERE (V0."id_hash" IN (SELECT U0."id_hash" FROM "trans_unit" U0 INNER JOIN "trans_variant_defining_units" U1 ON (U0."id" = U1."unit_id") WHERE U1."variant_id" = 11) AND V1."component_id" = 16 AND V0."variant_id" IS NULL))
2021-06-22 14:11:30.578 UTC [292] LOG:  statement: FETCH FORWARD 2000 FROM "_django_curs_140702676903808_sync_29"
...

nijel added a commit that referenced this issue Jun 23, 2021
Also detect whether it is needed on creating units.

Issue #6207
@nijel
Copy link
Member

nijel commented Jun 23, 2021

deleting: 1 minute, 25k UPDATE now

I can't reproduce this. Can you please share your component configuration (especially file format, new base and monolingual base)? Is this newly imported translation or something migrated from an older Weblate version?

Adding variant should perform better with bc18758.

@burner1024
Copy link
Contributor Author

Still 25k on deleteion with bc18758 . Weblate upgraded from 3.1.1. PO format, bilingual, no base.

Adding triggers only one set of UPDATEs, but still all of them 1 by 1, feels pretty slow:

nginx stdout | 172.18.0.1 - - [23/Jun/2021:10:22:14 +0000] "POST /new-unit/fallout/fixt/ru/ HTTP/1.1" 302 5 "http://localhost:8080/" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/91.0.4472.106 Safari/537.36"
uwsgi stderr | [pid: 718|app: 0|req: 34/77] 172.18.0.1 () {64 vars in 1314 bytes} [Wed Jun 23 10:22:02 2021] POST /new-unit/fallout/fixt/ru/ => generated 0 bytes in 12107 msecs (HTTP/1.1 302) 8 headers in 405 bytes (2 switches on core 0)
uwsgi stderr | [pid: 560|app: 0|req: 35/78] 172.18.0.1 () {58 vars in 1214 bytes} [Wed Jun 23 10:22:14 2021] GET /translate/fallout/fixt/ru/?checksum=ed7c05a381666b3a => generated 72982 bytes in 1965 msecs (HTTP/1.1 200) 7 headers in 337 bytes (1 switches on core 0)
nginx stdout | 172.18.0.1 - - [23/Jun/2021:10:22:16 +0000] "GET /translate/fallout/fixt/ru/?checksum=ed7c05a381666b3a HTTP/1.1" 200 17470 "http://localhost:8080/" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/91.0.4472.106 Safari/537.36"

@nijel
Copy link
Member

nijel commented Jun 23, 2021

Do you always start from the fresh container? In the past, the position of source strings was not properly tracked, so the first deletion would fill these in and that could explain the number of queries we see. In case you do the removal repeatedly on same database, it should not trigger that much of updates on consequent runs...

@burner1024
Copy link
Contributor Author

burner1024 commented Jun 23, 2021

The same database, only weblate container is re-created.
(PO here if you want to test)

@nijel
Copy link
Member

nijel commented Jun 24, 2021

Do you have configured "Template for new translations"?

@burner1024
Copy link
Contributor Author

burner1024 commented Jun 24, 2021

Yes.

component config

@nijel
Copy link
Member

nijel commented Jun 24, 2021

6474d1b should address the 50k update queries.

@burner1024
Copy link
Contributor Author

It's 25k now, and unfortunately still there for me.

More importantly, adding appears to perform worse and worse with each new variant added:

nginx stdout | 172.18.0.1 - - [24/Jun/2021:13:39:26 +0000] "POST /new-unit/fallout/fixt/ru/ HTTP/1.1" 302 5 "http://localhost:8080/" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/91.0.4472.106 Safari/537.36"
uwsgi stderr | [pid: 408|app: 0|req: 11/35] 172.18.0.1 () {64 vars in 1314 bytes} [Thu Jun 24 13:39:18 2021] POST /new-unit/fallout/fixt/ru/ => generated 0 bytes in 7927 msecs (HTTP/1.1 302) 8 headers in 405 bytes (2 switches on core 0)
uwsgi stderr | [pid: 407|app: 0|req: 5/36] 172.18.0.1 () {58 vars in 1214 bytes} [Thu Jun 24 13:39:26 2021] GET /translate/fallout/fixt/ru/?checksum=8c6367f7b9de0bdc => generated 76585 bytes in 1503 msecs (HTTP/1.1 200) 7 headers in 337 bytes (1 switches on core 0)
nginx stdout | 172.18.0.1 - - [24/Jun/2021:13:39:27 +0000] "GET /translate/fallout/fixt/ru/?checksum=8c6367f7b9de0bdc HTTP/1.1" 200 17345 "http://localhost:8080/" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/91.0.4472.106 Safari/537.36"

nginx stdout | 172.18.0.1 - - [24/Jun/2021:13:42:03 +0000] "POST /new-unit/fallout/fixt/ru/ HTTP/1.1" 302 5 "http://localhost:8080/" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/91.0.4472.106 Safari/537.36"
uwsgi stderr | [pid: 408|app: 0|req: 12/43] 172.18.0.1 () {64 vars in 1314 bytes} [Thu Jun 24 13:41:55 2021] POST /new-unit/fallout/fixt/ru/ => generated 0 bytes in 8071 msecs (HTTP/1.1 302) 8 headers in 405 bytes (2 switches on core 0)
uwsgi stderr | [pid: 406|app: 0|req: 3/44] 172.18.0.1 () {58 vars in 1214 bytes} [Thu Jun 24 13:42:03 2021] GET /translate/fallout/fixt/ru/?checksum=86aa3b2ac3297c80 => generated 72428 bytes in 1001 msecs (HTTP/1.1 200) 7 headers in 337 bytes (1 switches on core 0)
nginx stdout | 172.18.0.1 - - [24/Jun/2021:13:42:04 +0000] "GET /translate/fallout/fixt/ru/?checksum=86aa3b2ac3297c80 HTTP/1.1" 200 16620 "http://localhost:8080/" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/91.0.4472.106 Safari/537.36"

uwsgi stderr | [pid: 407|app: 0|req: 6/46] 172.18.0.1 () {64 vars in 1314 bytes} [Thu Jun 24 13:42:25 2021] POST /new-unit/fallout/fixt/ru/ => generated 0 bytes in 8462 msecs (HTTP/1.1 302) 8 headers in 405 bytes (1 switches on core 0)
nginx stdout | 172.18.0.1 - - [24/Jun/2021:13:42:33 +0000] "POST /new-unit/fallout/fixt/ru/ HTTP/1.1" 302 5 "http://localhost:8080/" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/91.0.4472.106 Safari/537.36"
uwsgi stderr | [pid: 555|app: 0|req: 24/47] 172.18.0.1 () {58 vars in 1214 bytes} [Thu Jun 24 13:42:33 2021] GET /translate/fallout/fixt/ru/?checksum=e3e0dc99c1356b16 => generated 72423 bytes in 1202 msecs (HTTP/1.1 200) 7 headers in 337 bytes (2 switches on core 0)
nginx stdout | 172.18.0.1 - - [24/Jun/2021:13:42:34 +0000] "GET /translate/fallout/fixt/ru/?checksum=e3e0dc99c1356b16 HTTP/1.1" 200 16595 "http://localhost:8080/" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/91.0.4472.106 Safari/537.36"

nginx stdout | 172.18.0.1 - - [24/Jun/2021:13:43:12 +0000] "POST /new-unit/fallout/fixt/ru/ HTTP/1.1" 302 5 "http://localhost:8080/" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/91.0.4472.106 Safari/537.36"
uwsgi stderr | [pid: 407|app: 0|req: 7/49] 172.18.0.1 () {64 vars in 1314 bytes} [Thu Jun 24 13:43:04 2021] POST /new-unit/fallout/fixt/ru/ => generated 0 bytes in 8816 msecs (HTTP/1.1 302) 8 headers in 405 bytes (1 switches on core 0)
uwsgi stderr | [pid: 406|app: 0|req: 4/50] 172.18.0.1 () {58 vars in 1214 bytes} [Thu Jun 24 13:43:12 2021] GET /translate/fallout/fixt/ru/?checksum=22468efe09bc1284 => generated 72487 bytes in 970 msecs (HTTP/1.1 200) 7 headers in 337 bytes (1 switches on core 0)
nginx stdout | 172.18.0.1 - - [24/Jun/2021:13:43:13 +0000] "GET /translate/fallout/fixt/ru/?checksum=22468efe09bc1284 HTTP/1.1" 200 16617 "http://localhost:8080/" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/91.0.4472.106 Safari/537.36"

uwsgi stderr | [pid: 408|app: 0|req: 13/52] 172.18.0.1 () {64 vars in 1314 bytes} [Thu Jun 24 13:43:33 2021] POST /new-unit/fallout/fixt/ru/ => generated 0 bytes in 9335 msecs (HTTP/1.1 302) 8 headers in 405 bytes (1 switches on core 0)
nginx stdout | 172.18.0.1 - - [24/Jun/2021:13:43:42 +0000] "POST /new-unit/fallout/fixt/ru/ HTTP/1.1" 302 5 "http://localhost:8080/" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/91.0.4472.106 Safari/537.36"
uwsgi stderr | [pid: 406|app: 0|req: 5/53] 172.18.0.1 () {58 vars in 1214 bytes} [Thu Jun 24 13:43:42 2021] GET /translate/fallout/fixt/ru/?checksum=c06009a25ac88c87 => generated 72480 bytes in 1077 msecs (HTTP/1.1 200) 7 headers in 337 bytes (1 switches on core 0)
nginx stdout | 172.18.0.1 - - [24/Jun/2021:13:43:44 +0000] "GET /translate/fallout/fixt/ru/?checksum=c06009a25ac88c87 HTTP/1.1" 200 16614 "http://localhost:8080/" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/91.0.4472.106 Safari/537.36"

@nijel
Copy link
Member

nijel commented Jun 30, 2021

I did several tests with PO file you've referenced, and I cannot get the 25k queries on removal - it always stays within a sane range around 50.

@nijel nijel modified the milestones: 4.7.1, 4.8 Jun 30, 2021
@burner1024
Copy link
Contributor Author

burner1024 commented Jun 30, 2021

Regardless of the number of queries, what times are you getting?

cdd78b0 results:

  • deleting first string: ~80 seconds, PO reprocessed, 25k UPDATEs
  • deleting last string: ~27 seconds, PO reprocessed, no 25k UPDATEs
  • adding a variant: ~13 seconds

If it takes so long, translators just won't use it. And considering that adding seems to perform worse with each variant... for now there's only 30, but there will be thousands. In order to be usable, both actions would need to take the same time as saving a translation - under 1 sec, max 2.

Edit: and I take back what I said earlier about not worrying about deleting much. Both adding and deleting are important.

@nijel nijel modified the milestones: 4.8, 4.8.1 Aug 21, 2021
@nijel nijel modified the milestones: 4.8.1, 4.9 Sep 10, 2021
@nijel
Copy link
Member

nijel commented Nov 9, 2021

The variants performance should be addressed by a5536ec, 4b84ca0, and ba53c0b.

@nijel nijel closed this as completed Nov 9, 2021
@github-actions
Copy link

github-actions bot commented Nov 9, 2021

Thank you for your report; the issue you have reported has just been fixed.

  • In case you see a problem with the fix, please comment on this issue.
  • In case you see a similar problem, please open a separate issue.
  • If you are happy with the outcome, don’t hesitate to support Weblate by making a donation.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something is broken.
Projects
None yet
Development

No branches or pull requests

2 participants