In the last ~1 month there have been quite a few ECONNRESET errors from Parsoid in the RESTBase logs, while there had been practically none before:
Since Sep. 14th the rate has significantly decreased, but the errors aren't completely gone yet.
| • GWicke | |
| Sep 20 2015, 11:27 PM |
| F3041193: pasted_file | |
| Dec 2 2015, 4:38 AM |
| F3041189: pasted_file | |
| Dec 2 2015, 4:36 AM |
| F2622357: pasted_file | |
| Sep 20 2015, 11:27 PM |
In the last ~1 month there have been quite a few ECONNRESET errors from Parsoid in the RESTBase logs, while there had been practically none before:
Since Sep. 14th the rate has significantly decreased, but the errors aren't completely gone yet.
The mirror of this on the Parsoid side is the worsening of p99 numbers that I noticed end of August (and load spikes in ganglia, and timeouts in cpu timeouts dashboard) .. initially my theory was that this might be correlated with the upgrade of express from 2.x to 4.x and had asked Arlo to investigate it. But I determined it may not be related.
In the Aug 27 - Sep xx timeframe where you see a lot of econnreset (and where we see a lot of timeouts in the cpu timeouts dashboard), this edit is the reason. Check this Kibana dashboard which I created to verify this. This dashboard is a filtered version of the cpu timeouts dashboard.
Marko, Arlo, and I were chatting on IRC as to why this testwiki page was being retried a lot and whether it was user-driven (in a browser), or if it was a script, or if it was RESTBase job queue retrying this a lot. A couple weeks later (Sep 7, checking my irc logs), it looked a different page that was causing a similar timeout behavior ( https://en.wikipedia.org/wiki/User:Nakon/cascade2?oldid=629929003 ) and I was asking you on IRC about it. The reason I discovered these 2 pages was that both pages caused minor transient load spikes (20% -> 40%).
Anyway, I don't think that something changed on the Parsoid end -- some of these bad parse behavior pages either got created then or got re-rendered (and retried repeatedly from somewhere). So, I think this is still the generic problem with pages. But, if this trend continues, it may not hurt to see if there is something about express 4.x that is exacerbating this behavior.
To me, the new thing was primarily that this wasn't hitting the regular ETIMEDOUT case, but instead just closed the socket. But, it sounds like those pages locked up Parsoid workers hard & then triggered the watchdog timer, which would explain the connection resets.
It's still somewhat odd that this didn't seem to happen before, despite us creating full dumps of all wikis back in Mach / April. It's certainly possible that we didn't hit those user pages earlier as the first dumps focused on ns0, but it still seems a bit odd. Did anything in Parsoid change that would potentially make request processing less async / introduce less yield points?
We know we have cpu and request timeouts on a subset of pages. There are a few outstanding bug reports -- all related to n^2 behavior in DOM passes or really large DOM sizes (T119803: Performance bottleneck in unpackDOMFragments DOM pass, T118467: Introduce <span typeof="mw:Entities"> for long runs of entities, T119883: Investigate inefficiencies in DOM construction and passes for large wikitext pages) besides two that I've already fixed and deployed over the last 6 weeks (n^2 behavior in DSR computation, and another one n^2 behavior in template wrapping).
So, on the Parsoid end, there are ~2400 request timeouts looking at parsoid kibana logs for last month. Looking at the code, after 4 minutes, requests timeout, and we just log a request timeout error but send no response back.
My question is if these econnreset errors are anything different from known parsing timeouts on the parsoid end. What is the error you see on the RESTBase end for these request timeouts? Is there a different error?
The main change is that we are seeing more ECONNRESETs where we would previously see ETIMEDOUTs. This likely means that Parsoid closes the connection before RESTBase times out the connection after two minutes. You mention that this should happen after four minutes, so it might be possible that a) the Parsoid timeout is more trigger-happy than expected, or b) some other issue like OOM is causing the Parsoid process to die.
Looking at the distribution of titles, there seems to be some amount of skew with known candidates (OCG attribution page & User:PiSquared sandbox), but out of about 2400 ECONNRESETs in the last 30 days the top one had only about 30 hits.
We don't have much reliable information on how common this was in the more distant past, as logstash only has 30 days worth of logs. I hadn't seen ECONNRESET feature before I opened this task, despite monitoring the logs quite closely. But, it is absolutely possible that I missed some earlier spikes.
Independent of whether this has gotten more frequent or not, I think it's worth checking why Parsoid workers seem to die so quickly. There might be a way to export the titles causing this from logstash & then repeating those parses in a controlled experiment.