Sean, thanks for the quick response: Good to know! Zero(!) during 10min after 16:30 doesn't look good. This means the Ok, makes more sense. MySQL consumer log not only lacks errors, but has records of successful writes to the db at the time of the problems. Also, the processor logs indicate homogeneous throughput of valid events during all times. *However*, the consumer logs indicate the insert timestamp only, not the event timestamp (which goes to the table). So it could be that there's some data loss inside the consumer code (or in zmq?) that wouldn't stop the write flow, but would skip a segment of events. I'll look deeper into this. I'll try to get those. -- can you give me some idea of how long your "at other moments" delay I'll observe the db during the day and give you an estimate. Thanks!

This sounds like the fixes we did last quarter to the batch insertion basically hid the problem instead of making it go away. On Wed, Apr 15, 2015 at 5:58 PM, Marcel Ruiz Forns <mforns(a)wikimedia.org> wrote:

- The UUID values generated for those records I'll try to get them, sure. > > I followed the master-slave replication lag for some hours, and > perceived a > > pattern in the lag: It gets progressively bigger with time, more or less > > with a 10 minute increase per hour, reaching lags of 1 to 2 hours. At > that > > point, the data gap happens and the replication lag goes back to few > minutes > > lag. I could only catch a data gap "live" 2 times, so that's definitely > not > > a conclusive statement. But, there's this hypothesis that the two > problems > > are related. > Just for clarity, may I ask how are you testing this? 1) To identify the data gaps I used: select left(timestamp, 11), count(*) from Edit_11448630 where timestamp >= '20150415000000' and timestamp < '20150416000000' group by 1; Note that the table name and the timestamps can be adapted as necessary. This query returns something like: +---------------------+----------+ | left(timestamp, 11) | count(*) | +---------------------+----------+ | 20150415000 | 9823 | | 20150415001 | 10158 | | 20150415002 | 9473 | | 20150415003 | 9493 | | 20150415004 | 9297 | | 20150415005 | 9390 | | 20150415010 | 9849 | | 20150415011 | 9619 | | 20150415012 | 10038 | | 20150415013 | 9763 | | 20150415014 | 9750 | | 20150415015 | 9633 | | ... | ... | +---------------------+----------+ Which lists the number of events existing for each 10-minute slot. When there's a data gap, the result of the query looks like this: +---------------------+----------+ | left(timestamp, 11) | count(*) | +---------------------+----------+ | ... | ... | | 20150415150 | 21237 | | 20150415151 | 20677 | | 20150415152 | 20541 | | 20150415153 | 19671 | | 20150415154 | 19623 | | 20150415155 | 19281 | | 20150415160 | 19243 | | 20150415161 | 5708 | <= Gap: 16:20h and 16:30h have no data! | 20150415164 | 11590 | | 20150415165 | 18745 | | ... | ... | +---------------------+----------+ 2) To get the master-slave replication lag I used: select timestamp from Edit_11448630 order by 1 desc limit 1; Again, the table name can be substituted. This gives me, supposedly, the timestamp of the last inserted event. Comparing that with the current time, I get the lag. 3) To correlate both, I just happened to be monitoring the progressively increasing replication lag, and after noticing an abrupt recovery of the latter, I checked and found a data gap.

I didn't mean to suggest we saw this error before. I was trying to say that intuitively the error seems very similar. That is, over time, the lag grows and at some point it's so big that we lose a bunch of data all at once. I was just saying that because the first place I'd look is at that change. For example, I'd try replicating by simulating the same traffic and then I'd revert to the original logic before batch inserts and try that. We've all looked at this code but we must be missing something big.

Fair enough, just a thought. On Wednesday, April 15, 2015, Nuria Ruiz &lt;nuria(a)wikimedia.org&gt; wrote:

Sean and list, I think we found the problem: The data loss is happening within EL consumer code. The error was skillfully dodging the logs, sorry for that. The root cause is that the db insertion takes too long to keep up with the rate of incoming events, and the events buffer gets big. When big enough, the program crashes and the buffered data is lost. Thanks Sean for your comments, they helped a lot! Will update the phab task with a detailed explanation and next steps. https://phabricator.wikimedia.org/T96082 Cheers, Marcel