Mass re-indexation can miss (a lot of) content

I should test it out, will do that now

I'm a little confused as how an orderBy would help here.

I tried to replicate this but I was not able to get the missing nodes logic.

Could you get us a to z guide on how to replicate?

Also, in any case, a sort on the changed date would be welcome, just to get the oldest ones first.

Well, it does make sense. I'm going to commit this

Removing the sort in the count query, no need there

needs backport to 6.x-3.x

While this will help reduce the amount of content that might be missed, it can still miss content that is updated at the exactly the same time.

For example, lets take this database and assume that we index three documents at a time:

id | timestamp
11 | 100 (in first batch)
12 | 100 (in first batch)
13 | 250 (in first batch)
14 | 250
15 | 250
16 | 250
17 | 250
18 | 250
19 | 100
20 | 100

after first batch
$last_changed = 100
$last_entity_id = 13

You can create something like this by creating ten entities at the same time (timestamp 100), running cron once (which indexes documents 11-13) and then updating six documents (13-18, new timestamp 250). Note that these operations all happened at exactly the same second, which might be due to a busy site or a batch import.

You now have a Solr index that includes the latest version of 11-12, an outdated version of 13 and no version of 14-20. Ideally we should be indexing 14-20 first, followed by 13. This patch gets most of the way there, although it will index 13 earlier than is ideal.

id | timestamp
19 | 100 (in second batch)
20 | 100 (in second batch)
13 | 250 (in second batch)
14 | 250
15 | 250
16 | 250
17 | 250
18 | 250

after second batch
$last_changed = 250
$last_entity_id = 20

The bigger problem is that after the second batch, both $last_changed and $last_entity_id are set to values that will miss content.

$last_changed will be set to 250, so will miss any content that was updated at exactly the same time as the last indexed item (13).

14-18 are now scheduled to be indexed after 19 and 20, so will be missed by the $last_entity_id check, and were also updated at the same time as 13 so will be missed by the $last_changed check.

I can't see any way of keeping track of what has and hasn't been indexed using only the $last_changed and $last_entity_id variables - there will always be ways that entities can end up hidden behind other entities.

I see two potential solutions:
1) Add a 'last_indexed' column to the table. We then choose entities to index where last_indexed is null or last_indexed < last_updated (and choose last_indexed is null entities first). This means changing a database row for every entity we index, which could have performance problems.
2) Replace the table with an "entities to index" queue table with an auto incrementing id. This id can then be tracked as a Drupal variable and the indexed entities periodically deleted from the table. This avoids regular database writes, but the queue id could easily overflow as 32 bit integer.

After some conversation in IRC we found out that this is indeed a potential problem. I'd like to see if we can add the milliseconds to the table as an update to the module. Or even a contrib module perhaps? I'm not sure how easy that would be given that the timestamp is an integer. Perhaps we could add a new column to the index that saves the milliseconds and you have a third sort on that number?

Or... We change the timestamp to a float, and have the regular unix timestamp + the milliseconds behind the comma...

Ignoring timestamps that are exactly the same for now, I think the more complex problem can be summed up as us trying to maintain two queues (based on last updated and entity id) with a single table, and either queue might contain items from the other queue. If the first queue picks up an item that is also in the second queue, then everything behind the item in the second queue gets discarded.

There are two potential solutions to this problem:
1) Separate out the two queues. I think you might be able to do this by simply adding an entity_id check to the first OR. So:
db_or()->condition('aie.changed', $last_changed, '>')
->condition(db_and()
->condition('aie.changed', $last_changed, '<=')
->condition('aie.entity_id', $last_entity_id, '>')
)

Becomes:
// Entities that we have already indexed but have since been updated
db_or()->condition(db_and()
->condition('aie.changed', $last_changed, '>')
->condition('aie.entity_id', $last_entity_id, '<='))
// Entities that we have never indexed
->condition(db_and()
->condition('aie.changed', $last_changed, '<=')
->condition('aie.entity_id', $last_entity_id, '>')
)

I'm wary of this solution though, as I can easily imagine there being another scenario where the indexing remains incorrect.

2) Switch to using $last_changed only. This is much simpler logic, and only has two small disadvantages that I can see:
a) if you edit an unindexed entity then it will be put to the back of the indexing queue. This is only a problem when you've got a lot waiting to be indexed - if that is the case I'd be more concerned about speeding up indexing.
b) it is an api change (if not the function calls, then at least the values that come back). This could actually be seen as an advantage, as any custom code that relies on the current behavior is likely to be broken too.

If we switch to using $last_changed only, then we need a way of differentiating items that have exactly the same timestamp. Increasing to microtime precision would help there, but it would still be possible for two entities to have exactly the same time, either due to very fast updates or, more likely, deliberately setting "changed" on a block of entities that you want to reindex using a single SQL query. Something that is guaranteed to be unique between two entities with the same changed timestamp is the entity_id, so I propose repurposing $last_entity_id as a tiebreaker for multiple entities that have the same changed timestamp.

db_or()
// Entities that have been changed more recently than the most up to date indexed entity
->condition('aie.changed', $last_changed, '>')
// Tie breaker for entities that was changed at exactly the same time as the last indexed entity
->condition(db_and()
->condition('aie.changed', $last_changed, '=')
->condition('aie.entity_id', $last_entity_id, '>'))
)
// It is important that everything is indexed by changed date then entity id
// for the conditions above to work correctly
->orderBy('aie.changed', 'ASC')
->orderBy('aie.entity_id', 'ASC');;

This should implement the change described in #11 option 2

Fix typo in function name. Hopefully that was causing the other failures too, as otherwise I'm not sure how to debug those.

Forgot to make $bundles available in my shared function.

I've decided to get it again inside the function, as I think the code that returns early in the functions if there are no bundles is premature optimisation and would be better removed (although I've left it for now to avoid complicating the patch).

The patch on #16 has worked in my testing

I didn't realise apachesolr_index_send_to_solr() returned true when there was nothing to index, which resulted in last_index_position being cleared.

This version only updates progress if something has been indexed, and logs an error if either of the varialbes are missing.

OK, that patch got stuck if an entire batch of documents were inspected and excluded by apachesolr_{entity_type_}exclude, as it would treat them as if there had been an error with the solr server.

This version skips the call to apachesolr_set_last_index_position (and other code) based on whether the module has any documents to index.

We have been using this in production for about 10 days now and it seems to be working well

I've come across the same problem, and pinned it pretty much down to exactly what goes wrong and an easy way of replicating the problem.

Symptom:

If there are more *updated* items in the apache solr indexing queue (sharing the same timetamp) than will be indexed by one cron run, the "index all queued content" option will only index the number of items that will be indexed by one cron run.

How to reproduce:

- You have indexed 100 documents from Drupal.
- Your Apachesolr settings say you should index 50 items per cron run.
- Force an update of the apache solr index by setting the apachesolr_index_entities_node.changed column beyond the last update for 90 of your already indexed items.
- The Apachesolr status page will now say 90 items remain for indexing.
- If you attempt to "index all queued content", only 50 items are actually sent to Solr.
- The other 40 items will never be reindexed.

Why does this happen?

The update algorithm for selecting items only uses last entity_id or last changed date (apachesolr_index_get_entities_to_index). After the equivalent of one cron run, the last changed date is changed to the date of the last indexed item (apachesolr_index_entities). If several entries share the same timestamp (not at all unthinkable in big custom bulk operations) you risk not getting your data indexed and you have no error messages to tell the story.

Proposted solution

I propose adding a dirty-bit column to the apachesolr_index_entities_node table, named "pending". If set to 1, update, if set to 0, leave alone. The function apachesolr_index_entities could then run a bulk db_update on all rows that were successfully indexed, setting the dirty bit to 0.

You lose efficiency with the db_update, but gain efficiency in the function that selects items to reindex.

I have myself implemented a custom solution (1 changed and 3 added lines of code) that doesn't demand changes in the database structure or API. It's much less efficient than the proposed solution and not worthy of publication unless explicitly asked for. Simply put, the hack subtracts 1ms from the last changed timestamp for every indexed document, updates the apache_solr_index_entities_node table for each indexed document, and sets that timestamp as the "last index update" timestamp. Because of the subtracted millisecond, all documents sharing timestamp with the recently indexed documents will still be indexed on next run, and the already indexed documen'ts won't be indexed again. Hacky, dirty, slow - but it works for us until there is a permanent solution.

Remi

@remimikalsen, does the patch posted above fix your problem?

+++ b/apachesolr.index.incundefined
@@ -440,29 +423,7 @@ function apachesolr_index_get_entities_to_index($env_id, $entity_type, $limit) {
+  $query = apachesolr_index_get_entities_to_index_get_query($env_id, $entity_type);

I don't like this function name, can we somehow make this way shorter?
apachesolr_index_get_next_set_query() or so?

Can Defr and Thomas mark this as RTBC once they feel comfortable?

Applying the patch fails on 7.x-1.x-dev and 7.x-1.1. Assuming you mean #19.

patch -p1 < apachesolr-18281014-indexing_order-19.patch
patching file apachesolr.index.inc
Hunk #4 FAILED at 128.
Hunk #5 FAILED at 423.
Hunk #6 succeeded at 443 (offset -2 lines).
2 out of 6 hunks FAILED -- saving rejects to file apachesolr.index.inc.rej

Remi

This patch should apply to 7.x-1.x-dev (#19 had bit rotted) and renames the function to apachesolr_index_get_next_set_query(). I'm happy with this patch, but obviously can't RTBC.

@remimikalsen I did consider fixing this with a dirty-bit, but discarded that option at the time. I can't remember exactly why though (and why I didn't mention it) - possibly there was a scenario where new content got missed because it never had the dirty bit set? Or maybe it just required bigger changes that this patch. Happy to look into that again though if there is a problem with the solution in the attached patch.

+++ b/apachesolr.index.incundefined
@@ -515,6 +469,46 @@ function apachesolr_index_get_entities_to_index($env_id, $entity_type, $limit) {
+      ->condition('aie.changed', $last_index_position['last_changed'], '>')

Maybe to make it a bit more robust than it was before, should we check if the value $last_index_position['last_changed'] was actually set? Same with last_entity_id

+++ b/apachesolr.index.incundefined
@@ -38,6 +38,9 @@ function apachesolr_index_entities($env_id, $limit) {
+    if (!count($rows)) {

Is count quicker than trying to see if $rows is empty?

+++ b/apachesolr.index.incundefined
@@ -47,20 +50,18 @@ function apachesolr_index_entities($env_id, $limit) {
+          'Failure recording indexing progress. Last entitiy id processed: %entity_id with timestamp %last_changed',

Typo

I'm also wondering how we now cope with entities in the index table that have timestamp 0 or empty and have greater entity id's. This means they were never indexed and the query will now also not select them if I reviewed it properly?

Maybe to make it a bit more robust than it was before, should we check if the value $last_index_position['last_changed'] was actually set? Same with last_entity_id

Maybe, but that probably deserves it's own issue to avoid delaying this one. If that happens at the moment then the most likely scenario is it will do a full reindex (because it will set these after the first batch). That's quite a good failure, and I'm not sure what I'd do if these values weren't set.

Is count quicker than trying to see if $rows is empty?

The performance of both is negligible, but using count gives a hint to the reader that $rows is an array.

I'm also wondering how we now cope with entities in the index table that have timestamp 0 or empty and have greater entity id's. This means they were never indexed and the query will now also not select them if I reviewed it properly?

Good spot - I'll add an extra or.

I applied the new patch, but unfortunately it doesn't seem to work as I'd expected.

When I mark N-items for re-indexing it correctly does the re-indexing, but when the re-indexing is done, the N items are still queued for re-indexing.

R

Sounds like your set_last_index wasn't triggered. Can you put the output of apachesolr_get_last_index_position($env_id, $entity_type) here before indexing and after indexing?

+++ b/apachesolr.index.incundefined
@@ -47,20 +50,18 @@ function apachesolr_index_entities($env_id, $limit) {
+        apachesolr_set_last_index_position($env_id, $entity_type, $last_row->changed, $last_row->entity_id);

I'm also dubious about this, do we want to set the last index position if the current value in the variable is higher than the timestamp of the last entity update?

It seems the problem I encountered wasn't in the patch, but in the dev-version of the Apachesolr module. The patch doesn't work on 7.x-1.1. If someone can provide a ported patch I'd be happy to test it.

Could you please move this to #1900036: node reference with multiple values and remove this information here?

After solving the other bug, this patch apparently worked quite well for me :)

I'm also wondering how we now cope with entities in the index table that have timestamp 0 or empty and have greater entity id's. This means they were never indexed and the query will now also not select them if I reviewed it properly?

Changed should never be 0 or empty - it will either be the timestamp that the entity was last updated, or the time when it was last queued for reindexing, whichever is more recent.

#30 I'm also dubious about this, do we want to set the last index position if the current value in the variable is higher than the timestamp of the last entity update?

I'm not sure I understand. $last_row->changed and $last_row->entity_id are effectively a compound key identify the last element indexed, so we'll always need both of them to identify the next element to index.

Other than the typo, I think the patch in #26 is good

#26: apachesolr-18281014-indexing_order-26.patch queued for re-testing.

Re-roll with the typo fixed

This change seems unnecessary:

+    if (!count($rows)) {
+      continue;
+    }

I guess it is. I think I figured either apachesolr_send_to_index would be expensive (but it already optimises for an empty set of documents) or the code would error in some way (it won't).

Any other thoughts?

Edit: #37 is preferred to this page. See #50.

We should have a test case or two to demonstrate the bug's manifestations and insure against regression

From what I can see the patch in #39 doesn't solve the problem. If more nodes (y) have been updated since last run (with the same changed date) than are indexed on cron (x) , only the first x will get indexed, y - x will be ignored. This problem could be solved by setting a dirty-bit in the index-table, or increasing the resolution of the timestamp, not by fiddling with different variations of the currently broken indexing query..

I have another idea. Don't know if it's better/worse than any other proposed solution, but at least I think it would work.

The current indexer table which looks like this:

+-------------+------------------+------+-----+---------+-------+
| Field       | Type             | Null | Key | Default | Extra |
+-------------+------------------+------+-----+---------+-------+
| entity_type | varchar(32)      | NO   | PRI | NULL    |       |
| entity_id   | int(10) unsigned | NO   | PRI | NULL    |       |
| bundle      | varchar(128)     | NO   | MUL | NULL    |       |
| status      | int(11)          | NO   |     | 1       |       |
| changed     | int(11)          | NO   |     | 0       |       |
+-------------+------------------+------+-----+---------+-------+

An alternative design could be:

+-------------+------------------+------+-----+---------+-------+
| Field       | Type             | Null | Key | Default | Extra |
+-------------+------------------+------+-----+---------+-------+
| entity_type | varchar(32)      | NO   | PRI | NULL    |       |
| entity_id   | int(10) unsigned | NO   | PRI | NULL    |       |
| bundle      | varchar(128)     | NO   | MUL | NULL    |       |
| status      | int(11)          | NO   |     | 1       |       |
| revision_id | int(10) unsigned | NO   | PRI | NULL    | auto_increment |
+-------------+------------------+------+-----+---------+-------+

We remove "changed" and instead introduce "revision_id" with auto increment.

Every time an entity is updated/created, an delete/insert query is performed against the indexer table. The idea is to insert/update an incremented revision_id for the entry.

We also maintain a "last_revision_id" per index table.

The query is then very safe and simple, just "SELECT * from indexer_table WHERE revision_id > !last_revision_id ORDER BY revision_id ASC LIMIT X". After we have processed these entities, the last_revision_id can be updated with the value of the last processed entity.

When re-indexing is needed last_revision_id can be set to "0".

Don't know if I'm missing anything, or if this would work?

@gnucifer It should handle that - the logic in #39 is to index everything on last changed, but when multiple nodes have the same last changed date then to index the ones with the lower entity ids first. This means the next batch will index more entities with the same date, but higher entity ids.

Please see #11 for more detailed explanation.

A dirty bit is another option, but seems an unnecessary change unless there are problems with this patch. Increasing the resolution won't fix all cases, as it is possible to mark lots of nodes as updated using a single query, so they'd have identical last updated times, however accurate you make it.

If you're able to write a test case that demonstrates this problem it would really help move the issue along, and either prove or disprove that #39 fixes the bug.

Yes, I think you are correct! Sorry about the bashing. I have tried to imagine a scenario where it would fail, but since the oldest updates are always processed first, it should be impossible to "contaminate" the set by for example introducing a higher last_entity_id.

Updated issue summary.

minor suggestions - it seems this new version dosn't account for !empty($row->status)

Maybe it doesn't need to?

Also, if the function is supposed to be internal and no part of the "api", please name with a leading underscore.

Finally, since indexing is a delicate area, can you think about a test case to add to make sure we don't have regressions in the future?

I need to backport this to 6.x for a client and start testing. What's the procedure to get my patch into the issue queue properly? I see the backport to 6.x tag, but I don't know if it's relevant until this is committed.

If you are ordering by "oldest first" ->orderBy('aie.changed', 'ASC') then some content may take a while get to the head of the queue.
A document will wait in the queue because it was saved, but just as it gets to the head of the queue, it gets saved again it gets put to the back of the queue again, etc.

Perhaps use drupal's queue instead: http://api.drupal.org/api/drupal/modules%21system%21system.queue.inc/gro...

@theapi: Please see #11. It's not ideal, but you shouldn't routinely have a long queue waiting to be indexed, so it shouldn't be a problem in practise. Using system.queue looks interesting, but also looks like more work.

@criznach: Problems should be patched in 7.x-1.x first, then the version will be changed to 6.x-1.x and status patch (requires to be ported).

The main thing that is holding this up is some decent tests, but I've not had a chance to write any yet. I have tried to split out the refactoring part of #39 into https://drupal.org/node/2011492 though - it would be great to have that reviewed and committed, then I'll happily re-roll an easier to read version of #39.

@ianmthomasuk: I have already ported #39 to 6.x because we needed to start working with it. I'm open to tracking your changes while I'm still working on this project. Note that the refactoring caused a small problem, because in 6.x we can't easily add the ->count operation since we're building the query as a string. The easiest solutions seem to be: wrap the returned string query in a subselect (performance issue?), or add a count mode parameter to the helper method.

Also, I need to look into one issue where hook_nodeapi claims to update 8406 nodes via node reference, but the Solr status page says there are only 8340 queued to index. My facet also shows 8340. I've eliminated revisions as the cause... I need to play with some queries...

I'll check out https://drupal.org/node/2011492

#38
+ if (!count($rows)) {
+ continue;
+ }

This seems needed to prevent watchdog entries ("Failure recording indexing progress") for entity types that have nothing to be indexed.

Some related info was posted here #1777830: Indexing node with same changed date

This is just a rerolled patch - going to work on a test case to prove it also

Finally found a way to test this bug. Let's see what our testbot says.

@@ -473,6 +473,85 @@ class DrupalSolrNodeTestCase extends DrupalWebTestCase {
+    // Create 20 nodes (10 times 2)

This is wrong, should be 10 nodes, 2 times 5. we don't need more to re-create the problem

code style:

 REQUEST_TIME+1

Also, we should set a static timestamp for the nodes that are saved to insure that all all saved with the same value - otherwise the test could easily save some across 2 seconds.

In addition, a code comment explaining the motivation for the test and what regression it's looking for is pretty important.

Committed to 7.x-1.x, needs backport

Update proposed solution section to reflect that the dirty-bit option isn't being developed.

requires #2011492: Remove duplicated indexing code to be backported first.

Here's my shot at the D6 backport. This patch incorporates #2011492: Remove duplicated indexing code comment #15, and #57 from this issue queue.

Attaching revised patch. The last one is broken because I was passing arguments to db_query in an array, instead of as comma separated values.

One more time: here's a revised patch, with dpm() removed.

Edit: Sorry, further testing has shown this patch is not in working order yet. I will continue working on it and hopefully post a usable one soon.

@Mark_
Thanks for your work. In order to easier review this patch and to avoid that we introduce new bugs I would prefer to have a separate patch for #2011492: Remove duplicated indexing code first.

I understand. I have submitted a working patch on #2011492: Remove duplicated indexing code.

Thanks to Mark_ #2011492: Remove duplicated indexing code has been committed. Let's go ahead with this one.

Ok, here's my D6 backport for this issue.

I've been using it on a production site for a few days with no problems.

Subscribing. Patch looks good, although I have not been able to test it yet.

This bug came up for me when using built-in drush commands:

drush solr-delete-index node:nodetype
drush solr-index

Attempting to purge and reindex an entire node type pushed us quickly over the thresholds described on this issue - and all entries had the same changed value in the solr queue.

The tests in patch #68 fail.
I fixed some parts of the tests like undefined variables or wrong node types. Now the tests basically work but are still failing on the essential part of testApacheSolrNodeReindex().

Finally I got the d6 tests to pass.