Production postmortemYour math is wrong, recursion doesn’t work this way

time to read 4 min | 641 words

We got a call from a customer, a pretty serious one. RavenDB is used to compute billing charges for customers. The problem was that in one of their instances, the value for a particular customer was wrong. What was worse was that it was wrong on just one instance of the cluster. So the customer would see different values in different locations. We take such things very seriously, so we started an investigation.

Let me walk you through reproducing this issue, we have three collections (Users, Credits and Charges):

image

The user is performing actions in the system, which issue charges. This is balanced by the Credits in the system for the user (payment they made). There is no 1:1 mapping between charges and credits, usually.

Here is an example of the data:

image

And now, let’s look at the index in question:

This is a multi map-reduce index that aggregates data from all three collections. Now, let’s run a query:

image

This is… wrong. The charges & credits should be more or less aligned. What is going on?

RavenDB has a feature called Map Reduce Visualizer, to help work with such scenarios, let’s see what this tells us, shall we?

image

What do we see in this image?

You can see that we have two results for the index. Look at Page #854 (at the top), we have one result with –67,343 and another with +67,329. The second result also does not have an Id property or a Name property.

What is going on?

It is important to understand that the image that we have here represents the physical layout of the data on disk. We run the maps of the documents, and then we run the reduce on each page individually, and sum them up again. This approach allows us to handle even a vast amount of data with ease.

Look at what we have in Page #540. We have two types of documents there, the users/ayende document and the charges documents. Indeed, at the top of Page #540 we can see the result of reducing all the results in the page. The data looks correct.

However…

Look at Page #865, what is going on there? Looks like we have most of the credits there. Most importantly, we don’t have the users/ayende document there. Let’s take a look at the reduce definition we have:

What would happen when we execute it on the results in Page #865? Well, there is no entry with the Name property there. So there is no Name, but there is also no Id. But we project this out to the next stage.

When we are going to reduce the data again among all the entries in Page #854 (the root one), we’ll group by the Id property, but the Id property from the different pages is different. So we get two separate results here.

The issue is that the reduce function isn’t recursive, it assumes that in all invocations, it will have a document with the Name property. That isn’t valid, since RavenDB is free to shuffle the deck in the reduce process. The index should be robust to reducing the data multiple times.

Indeed, that is why we had different outputs on different nodes, since we don’t guarantee that will process results in the same order, only that the output should be identical, if the reduce function is correct. Here is the fixed version:

And the query is now showing the correct results:

image

That is much better Smile

More posts in "Production postmortem" series:

  1. (03 Oct 2022) Do you trust this server?
  2. (15 Sep 2022) The missed indexing reference
  3. (05 Aug 2022) The allocating query
  4. (22 Jul 2022) Efficiency all the way to Out of Memory error
  5. (18 Jul 2022) Broken networks and compressed streams
  6. (13 Jul 2022) Your math is wrong, recursion doesn’t work this way
  7. (12 Jul 2022) The data corruption in the node.js stack
  8. (11 Jul 2022) Out of memory on a clear sky
  9. (29 Apr 2022) Deduplicating replication speed
  10. (25 Apr 2022) The network latency and the I/O spikes
  11. (22 Apr 2022) The encrypted database that was too big to replicate
  12. (20 Apr 2022) Misleading security and other production snafus
  13. (03 Jan 2022) An error on the first act will lead to data corruption on the second act…
  14. (13 Dec 2021) The memory leak that only happened on Linux
  15. (17 Sep 2021) The Guinness record for page faults & high CPU
  16. (07 Jan 2021) The file system limitation
  17. (23 Mar 2020) high CPU when there is little work to be done
  18. (21 Feb 2020) The self signed certificate that couldn’t
  19. (31 Jan 2020) The slow slowdown of large systems
  20. (07 Jun 2019) Printer out of paper and the RavenDB hang
  21. (18 Feb 2019) This data corruption bug requires 3 simultaneous race conditions
  22. (25 Dec 2018) Handled errors and the curse of recursive error handling
  23. (23 Nov 2018) The ARM is killing me
  24. (22 Feb 2018) The unavailable Linux server
  25. (06 Dec 2017) data corruption, a view from INSIDE the sausage
  26. (01 Dec 2017) The random high CPU
  27. (07 Aug 2017) 30% boost with a single line change
  28. (04 Aug 2017) The case of 99.99% percentile
  29. (02 Aug 2017) The lightly loaded trashing server
  30. (23 Aug 2016) The insidious cost of managed memory
  31. (05 Feb 2016) A null reference in our abstraction
  32. (27 Jan 2016) The Razor Suicide
  33. (13 Nov 2015) The case of the “it is slow on that machine (only)”
  34. (21 Oct 2015) The case of the slow index rebuild
  35. (22 Sep 2015) The case of the Unicode Poo
  36. (03 Sep 2015) The industry at large
  37. (01 Sep 2015) The case of the lying configuration file
  38. (31 Aug 2015) The case of the memory eater and high load
  39. (14 Aug 2015) The case of the man in the middle
  40. (05 Aug 2015) Reading the errors
  41. (29 Jul 2015) The evil licensing code
  42. (23 Jul 2015) The case of the native memory leak
  43. (16 Jul 2015) The case of the intransigent new database
  44. (13 Jul 2015) The case of the hung over server
  45. (09 Jul 2015) The case of the infected cluster