Docs: search returns no results after there are recent doc changes (but comes back later)

[sarahboyce]

See: https://forum.djangoproject.com/t/docs-seem-to-go-missing-for-a-given-version-when-there-are-docs-changes/35861

We get periodic reports about the docs search stopping working:

• https://code.djangoproject.com/ticket/35861
• https://code.djangoproject.com/ticket/35710
• https://code.djangoproject.com/ticket/35860

[bmispelon]

Here is how the update_docs management command is run on the server (with CRON):
15 * * * * /bin/bash -c "source /home/www/www/venv/bin/activate && django-admin update_docs --settings=djangoproject.settings.prod --verbosity=2 --update-index --purge-cache | ts '[\%Y-\%m-\%d \%H:\%M:\%S]' >> /home/www/www/logs/cron_update_docs.log"

[sarahboyce]

Are there logs on how long this takes to run?
To me that looks like it refreshes everything every 15 minutes, rather than reacting to when there are docs changes (and then only updating those docs)

[bmispelon]

Are there logs on how long this takes to run? To me that looks like it refreshes everything every 15 minutes, rather than reacting to when there are docs changes (and then only updating those docs)

There are logs, let me see if I can get some numbers from them.

As far as I know, the CRON entry I posted above is the only way the docs get built. There's no push, it's all pull, and it happens every hour at 15 past (not every 15min).

[nessita]

Here is how the update_docs management command is run on the server (with CRON): 15 * * * * /bin/bash -c "source /home/www/www/venv/bin/activate && django-admin update_docs --settings=djangoproject.settings.prod --verbosity=2 --update-index --purge-cache | ts '[\%Y-\%m-\%d \%H:\%M:\%S]' >> /home/www/www/logs/cron_update_docs.log"

@pauloxnet Does the above ring any bell for you?

[bmispelon]

Here is the log I have for today: https://gist.github.com/bmispelon/b2a714f02daa300fa1e2dfef78ad7ebd (there's a lot of noise that seems to be caused by incomplete translated docs).

Note that this was before #1692 was deployed.

[sarahboyce]

I was searching around the 15 minutes past mark and for a few minutes after - and that was fine
So I think having docs changes are related.
I wonder if the translation strings being updated is playing a part here

[sarahboyce]

Actually I think this line is suspicious

djangoproject.com/docs/management/commands/update_index.py

Line 16 in 777ec4f

Document.objects.search_reset()

We seem to update everything anyway so I'm not sure why we need to first null out the search index

[pauloxnet]

Here is how the update_docs management command is run on the server (with CRON): 15 * * * * /bin/bash -c "source /home/www/www/venv/bin/activate && django-admin update_docs --settings=djangoproject.settings.prod --verbosity=2 --update-index --purge-cache | ts '[\%Y-\%m-\%d \%H:\%M:\%S]' >> /home/www/www/logs/cron_update_docs.log"

@pauloxnet Does the above ring any bell for you?

The command run from cron seems correct to me, it's the same one I've run several times locally without any problems.

As I just ran it again now on my laptop to check the timing:

$ time python -m manage update_docs --settings=djangoproject.settings.prod --verbosity=2 --update-index --force

...

Indexed 1529 documents in 2.7s.

real	3m56,187s
user	17m51,930s
sys	0m40,349s

Re-indexing takes less than 3 seconds, but I only have 3 release in 3 languages ​​locally, and I imagine my laptop has more processing power and memory than the server,

To understand the cause of the recurring problems with search on the site, we should understand what happens on the server when it regenerates the documentation for all versions of Django and with the various languages ​​supported.

[pauloxnet]

Actually I think this line is suspicious

djangoproject.com/docs/management/commands/update_index.py

Line 16 in 777ec4f

Document.objects.search_reset()

We seem to update everything anyway so I'm not sure why we need to first null out the search index

If you see some line before, there's a transaction.atomic:

djangoproject.com/docs/management/commands/update_index.py

Line 8 in 777ec4f

@transaction.atomic

Since indexing happens in a transaction, search queries continue to work correctly, while the command deletes and recreates all the vectors on which they are performed.

As I wrote in the comment above it takes less than 3 seconds on my laptop, so I've simulated a longer run locally, putting a time.sleep(60) in the command, and I confirm that search never stopped working during the index regeneration.

[sarahboyce]

I wonder if the GinIndex needs tuning 🤔
Perhaps we should experiment with setting the gin_pending_list_limit
I also noticed that we limit updating the cache to only the docs versions that changed, perhaps we should that also when updating the search?

[pauloxnet]

I wonder if the GinIndex needs tuning 🤔
Perhaps we should experiment with setting the gin_pending_list_limit

What makes you think this? Have you read the GIN index update timeframe? I would be interested in having these timeframes so I can give you my opinion. If not, before making changes and seeing what happens, I would try to read the database timeframes.

In the meantime I added the time spent by PG updating the search vectors in the logs in #1695

I also noticed that we limit updating the cache to only the docs versions that changed, perhaps we should that also when updating the search?

I've never looked into the cache part. I think it might be worth looking into to see how it behaves and what the update times are, but someone with permissions to the service should try to read this information.

[sarahboyce]

What makes you think this? Have you read the GIN index update timeframe?

I was reading this article on GIN Indexes this morning. I'm just trying to give ideas of things we can look into 🙂
I agree we should know more before we change things 👍

[pauloxnet]

Here is the log I have for today:
...
Note that this was before #1692 was deployed.

Can you share the log now that we have merged #1692 and #1695 ?

Can you export from the server and add in the code and additional fixtures file with all releases and languages, in addition to doc_releases.json? It will be very useful to emulate locally what happens on the server when the Cron runs?

[bmispelon]

I just noticed that search was not working this morning for me on 5.1 and dev. I observed this at ~10am and the update_docs logs on the server show no rebuild activity since several days.

I first tried to just purge the cache with purge_cache --doc-versions=dev to see if that would fix it, but that didn't seem to help

Then I tried rebuilding the index with update_index. That took about a minute (didn't measure exactly and forgot to turn on verbosity). Initially that didn't seem to help, but a few minutes later the search was working again.

[bmispelon]

Here is the log I have for today:
...
Note that this was before #1692 was deployed.

Can you share the log now that we have merged #1692 and #1695 ?

Can you export from the server and add in the code and additional fixtures file with all releases and languages, in addition to doc_releases.json? It will be very useful to emulate locally what happens on the server when the Cron runs?

Here is the log for 2024-10-27 as well as a dumpdata fixture for the whole release app (they're both compressed with gzip):

cron_update_docs_20241027.log.gz
releases_20241027.json.gz

[pauloxnet]

Here is the log I have for today:
...
Note that this was before #1692 was deployed.

Can you share the log now that we have merged #1692 and #1695 ?
Can you export from the server and add in the code and additional fixtures file with all releases and languages, in addition to doc_releases.json? It will be very useful to emulate locally what happens on the server when the Cron runs?

Here is the log for 2024-10-27 ...

I can't find any occurrence of "Indexed" in the log file, it seems that the update_index as not being executed.

as well as a dumpdata fixture for the whole release app (they're both compressed with gzip)

In order to try locally to execute the same flow of update docs and index, I need also the fixtures for all "docs.documentrelease".

[pauloxnet]

Then I tried rebuilding the index with update_index. That took about a minute (didn't measure exactly and forgot to turn on verbosity). Initially that didn't seem to help, but a few minutes later the search was working again.

Do you think that the search started working again thanks to the execution of the update_index command?

If so, two considerations come to mind:

1. it seems that when the documentation update is performed, the indexes are not updated, because otherwise the data in the vector's column would still be there, and the search would consequently work, or, even stranger, there is something that deletes the data in the search vectors column
2. it seems that there is some slowdown on the database because at the end of the query execution the search should start working immediately (we should understand how to analyze what happens on the db)

[bmispelon]

Sorry, I didn't think about the DocumentRelease objects. Here they are:

docs_documentreleases_20241027.json.gz

I think the reason you don't see indexed in the logs is simply because there hasn't been a documentation update since Friday (25th): https://github.com/django/django/commits/main/docs. You have to push some more docs commits and then we'll be able to see the effect! 😅

[sarahboyce]

(just pushed a docs change 👍)