350 lines
20 KiB
HTML
350 lines
20 KiB
HTML
<!DOCTYPE html>
|
||
<html lang="en-US">
|
||
|
||
<head>
|
||
<meta charset='utf-8'>
|
||
<meta http-equiv="X-UA-Compatible" content="IE=edge">
|
||
<meta name="viewport" content="width=device-width,maximum-scale=2">
|
||
<link rel="stylesheet" type="text/css" media="screen" href="/assets/css/style.css?v=05a341d6ecac876cf57ea6591a288d09b2d6d356">
|
||
|
||
<!-- Begin Jekyll SEO tag v2.8.0 -->
|
||
<title>40 Ms Bug | Vorner’s random stuff</title>
|
||
<meta name="generator" content="Jekyll v3.9.3" />
|
||
<meta property="og:title" content="40 Ms Bug" />
|
||
<meta property="og:locale" content="en_US" />
|
||
<meta name="description" content="40 millisecond bug" />
|
||
<meta property="og:description" content="40 millisecond bug" />
|
||
<link rel="canonical" href="https://vorner.github.io/2020/11/06/40-ms-bug.html" />
|
||
<meta property="og:url" content="https://vorner.github.io/2020/11/06/40-ms-bug.html" />
|
||
<meta property="og:site_name" content="Vorner’s random stuff" />
|
||
<meta property="og:type" content="article" />
|
||
<meta property="article:published_time" content="2020-11-06T00:00:00+00:00" />
|
||
<meta name="twitter:card" content="summary" />
|
||
<meta property="twitter:title" content="40 Ms Bug" />
|
||
<script type="application/ld+json">
|
||
{"@context":"https://schema.org","@type":"BlogPosting","dateModified":"2020-11-06T00:00:00+00:00","datePublished":"2020-11-06T00:00:00+00:00","description":"40 millisecond bug","headline":"40 Ms Bug","mainEntityOfPage":{"@type":"WebPage","@id":"https://vorner.github.io/2020/11/06/40-ms-bug.html"},"url":"https://vorner.github.io/2020/11/06/40-ms-bug.html"}</script>
|
||
<!-- End Jekyll SEO tag -->
|
||
|
||
<!-- start custom head snippets, customize with your own _includes/head-custom.html file -->
|
||
|
||
<!-- Setup Google Analytics -->
|
||
|
||
|
||
|
||
<!-- You can set your favicon here -->
|
||
<!-- link rel="shortcut icon" type="image/x-icon" href="/favicon.ico" -->
|
||
|
||
<!-- end custom head snippets -->
|
||
|
||
</head>
|
||
|
||
<body>
|
||
|
||
<!-- HEADER -->
|
||
<div id="header_wrap" class="outer">
|
||
<header class="inner">
|
||
|
||
|
||
<h1 id="project_title">Vorner's random stuff</h1>
|
||
<h2 id="project_tagline"></h2>
|
||
|
||
|
||
</header>
|
||
</div>
|
||
|
||
<!-- MAIN CONTENT -->
|
||
<div id="main_content_wrap" class="outer">
|
||
<section id="main_content" class="inner">
|
||
<h1 id="40-millisecond-bug">40 millisecond bug</h1>
|
||
|
||
<p>This is a small story about tracking down a production bug in a Rust
|
||
application. I don’t know if there’s any take away from this one for the reader,
|
||
but it felt interesting so I’m sharing it.</p>
|
||
|
||
<h2 id="a-bit-of-backstory">A bit of backstory</h2>
|
||
|
||
<p>In Avast, we have a Rust application called <a href="/2019/05/19/rust-in-avast.html">urlite</a>. It serves as a backend to
|
||
some other applications, provides them a HTTP API. It’s in Rust because it is
|
||
latency critical. Latencies of most requests are under a millisecond.</p>
|
||
|
||
<p>It was written with <a href="https://docs.rs/tokio/0.1.*"><code class="language-plaintext highlighter-rouge">tokio-0.1</code></a> and <a href="https://docs.rs/hyper/0.12.*"><code class="language-plaintext highlighter-rouge">hyper-0.12</code></a> to deal with the HTTP. We
|
||
were quite late to update to newer versions, in part because it worked fine and
|
||
the amount of <code class="language-plaintext highlighter-rouge">async</code> code was single quite short function, so we didn’t have
|
||
much motivation. And in part because we use the <a href="https://crates.io/crates/spirit"><code class="language-plaintext highlighter-rouge">spirit</code></a> libraries for
|
||
configuration. It’s a library to take configuration and set up the internal
|
||
state of the program for it ‒ configuration contains the ports to listen to,
|
||
etc, and it manages spawning the HTTP server objects inside the program and can
|
||
even migrate from one set of ports to other at runtime.</p>
|
||
|
||
<p>But migrating <a href="https://crates.io/crates/spirit"><code class="language-plaintext highlighter-rouge">spirit</code></a> to newer <code class="language-plaintext highlighter-rouge">tokio</code> and <code class="language-plaintext highlighter-rouge">hyper</code> was a big task (because
|
||
the API surface is quite large, the library does a bit unusual things compared
|
||
to all the usual applications and the change between old and new <code class="language-plaintext highlighter-rouge">tokio</code> was
|
||
quite large).</p>
|
||
|
||
<p>Anyway, eventually I got permission to work on the migration of <a href="https://crates.io/crates/spirit"><code class="language-plaintext highlighter-rouge">spirit</code></a> as
|
||
part of my job. It took about a week to migrate both <a href="https://crates.io/crates/spirit"><code class="language-plaintext highlighter-rouge">spirit</code></a> and <a href="/2019/05/19/rust-in-avast.html">urlite</a>. It
|
||
went through review, went through the automatic tests and we put it to the
|
||
staging environment for a while, watching the logs and graphs. Everything seemed
|
||
fine, so after few days of everything looking fine, we pushed the button and put
|
||
it to production.</p>
|
||
|
||
<h2 id="the-increased-latencies">The increased latencies</h2>
|
||
|
||
<p>As it goes in these kinds of stories, by now you’re expecting to see what went
|
||
wrong.</p>
|
||
|
||
<p>The thing is, our own metrics and graphs were fine. But the latency on the
|
||
downstream service querying us increased by 40ms. The deployment got reverted,
|
||
and we started to dig into where these latencies come from.</p>
|
||
|
||
<h2 id="it-was-acting-really-weird">It was acting really weird</h2>
|
||
|
||
<p>There were several very suspicious things about that.</p>
|
||
|
||
<ul>
|
||
<li>Our own „internal“ latencies stayed the same. Our CPU usage also stayed the
|
||
same.</li>
|
||
<li>The latency graph on the downstream side was flat 40ms <em>constant</em>.</li>
|
||
</ul>
|
||
|
||
<p>Now, if we introduced some performance regression in the query handling, we
|
||
would expect our CPU consumption to rise. We would also expect the latency graph
|
||
to be a bit spiky, not completely flat 40ms constant. It almost looked like
|
||
there was a 40ms <code class="language-plaintext highlighter-rouge">sleep</code> somewhere. But why would anyone put a 40ms sleep
|
||
anywhere?</p>
|
||
|
||
<p>I’ve looked through documentation and didn’t see anything obvious. I’ve tried
|
||
searching both our code and code of the dependencies for <code class="language-plaintext highlighter-rouge">40</code>, asked on Slack if
|
||
that <code class="language-plaintext highlighter-rouge">40ms</code> value was familiar to anyone. Nothing.</p>
|
||
|
||
<p>The working theory we started with was that there could be some kind of back-off
|
||
sleep on some kind of failure. Maybe <code class="language-plaintext highlighter-rouge">hyper</code> would be closing inactive
|
||
connections in the new version, forcing the application to reconnect (the graph
|
||
was for 99th percentile, so if we happened to close each 100th connection and
|
||
reconnection took this long…) and maybe try IPv6 first and we would be listening
|
||
on IPv4 only or… (in other words, we didn’t have a clear clue).</p>
|
||
|
||
<h2 id="the-benchmarks">The benchmarks</h2>
|
||
|
||
<p>My colleague started to investigate in a more thorough way than just throwing
|
||
ideas around on Slack. He run a <code class="language-plaintext highlighter-rouge">wrk</code> benchmark against the service. On his
|
||
machine, the latencies were fine. So he commandeered one of the stage nodes to
|
||
play with it and run the benchmark there. And every request had 40ms latency on
|
||
that machine. The previous version of <code class="language-plaintext highlighter-rouge">urlite</code> was fine, with under one
|
||
millisecond.</p>
|
||
|
||
<p><em>Something</em> was probably sleeping somewhere on the production servers, but not
|
||
on the development machine. There probably was some difference in the OS
|
||
settings, but definitely difference in the kernel version. The servers are
|
||
running some well-tried Linux distribution, so they have a lot older version,
|
||
while a developer is likely to run something much more on the edge.</p>
|
||
|
||
<h2 id="configuration-options">Configuration options</h2>
|
||
|
||
<p>The selling point of <a href="https://crates.io/crates/spirit"><code class="language-plaintext highlighter-rouge">spirit</code></a> is that most of the thing one can set in the
|
||
builders of various libraries and types now can be just put into a config file
|
||
without any recompilation. If we did configuration by hand, we would expose only
|
||
the things we thought would be useful, but with spirit, there’s everything. So,
|
||
naturally, tweaking some of the config knobs was the next step (because it was
|
||
easy to do).</p>
|
||
|
||
<p>It was discovered that turning the <code class="language-plaintext highlighter-rouge">http1-writev</code> option <em>off</em>, which
|
||
corresponds to
|
||
<a href="https://docs.rs/hyper/0.13.8/hyper/server/struct.Builder.html#method.http1_writev">this method</a>
|
||
in <code class="language-plaintext highlighter-rouge">hyper</code>, made the latencies go away.</p>
|
||
|
||
<p>We now had a solution, but I wasn’t happy about not understanding <em>why</em> that
|
||
helped, so I went to dig the rabbit hole and find the root cause. Turns out
|
||
there were several little things in just the constellation to make the problem
|
||
manifest.</p>
|
||
|
||
<h2 id="overriding-the-defaults-of-http1_writev">Overriding the defaults of <code class="language-plaintext highlighter-rouge">http1_writev</code></h2>
|
||
|
||
<p>The method controls the strategy in which way data are pushed into the socket.
|
||
With vectored writes enabled, it sends two separate buffers (one with headers,
|
||
the other with the body if it’s small enough) through a single <a href="https://linux.die.net/man/2/writev"><code class="language-plaintext highlighter-rouge">writev</code></a>
|
||
syscall. If they are disabled, <code class="language-plaintext highlighter-rouge">hyper</code> copies all the bytes into a single
|
||
buffer and sends that as a whole.</p>
|
||
|
||
<p>It turns out that the method takes a <code class="language-plaintext highlighter-rouge">bool</code>, but there are actually 3 states.
|
||
The third (auto) is signalled by <em>not</em> calling the method and <code class="language-plaintext highlighter-rouge">spirit-hyper</code> was
|
||
calling it always, with the default to turn the <a href="https://linux.die.net/man/2/writev"><code class="language-plaintext highlighter-rouge">writev</code></a> on. I don’t know if
|
||
leaving it on auto would make the bug go away, but I’ve fixed the problem in the
|
||
library anyway.</p>
|
||
|
||
<h2 id="splitting-vectored-writes">Splitting vectored writes</h2>
|
||
|
||
<p>Spirit wants to support a bit of configuration on top of what the underlying
|
||
libraries provide on their own. One of such things is limiting the number of
|
||
concurrently accepted connections on a single listening socket. Users don’t have
|
||
to take advantage of that (the types for the configuration can be composed
|
||
together to either contain that bit or not and the administrator may leave the
|
||
values for the limits unset in the configuration and then they won’t be
|
||
enforced).</p>
|
||
|
||
<p>Anyway, in case the support for the limits is opted in through using the type
|
||
with the configuration fields, the connections themselves are wrapped in a
|
||
<a href="https://docs.rs/spirit-tokio/0.7.*/spirit_tokio/net/limits/struct.Tracked.html"><code class="language-plaintext highlighter-rouge">Tracked</code></a>
|
||
type. The type tries to be mostly transparent for use and can be used inside
|
||
<code class="language-plaintext highlighter-rouge">hyper</code> (which is what the default configuration type alias in <code class="language-plaintext highlighter-rouge">spirit-hyper</code>
|
||
does), but tracks how many connections there are, to not accept more if it runs
|
||
out of the limit.</p>
|
||
|
||
<p>When implementing the bunch of traits for the wrapper, I’ve overlooked the
|
||
<a href="https://docs.rs/tokio/0.2.*/tokio/io/trait.AsyncWrite.html#method.poll_write_buf"><code class="language-plaintext highlighter-rouge">AsyncWrite::poll_write_buff</code></a>.
|
||
It is a provided method, which means it has a default implementation. It is the
|
||
one that abstracts the OS-level <code class="language-plaintext highlighter-rouge">writev</code>, it can write multiple buffers (the
|
||
<a href="https://docs.rs/bytes/0.5.*/bytes/buf/trait.Buf.html"><code class="language-plaintext highlighter-rouge">Buf</code></a> represents a
|
||
segmented buffer).</p>
|
||
|
||
<p>The default implementation simply delegates to multiple calls to the ordinary
|
||
write. Therefore, this omission combined with the default of enabling vectored
|
||
writes results in calling into the kernel twice, each time with a small buffer,
|
||
instead of once with two small buffers or once with a big buffer.</p>
|
||
|
||
<p>That was definitely something to get fixed, because if nothing else, syscalls
|
||
are expensive and calling more of them is not great. But I’ve finally felt like
|
||
I’m on the right path, because:</p>
|
||
|
||
<h2 id="nagles-algorithm">Nagle’s algorithm</h2>
|
||
|
||
<p>You probably know that TCP stream is built from packets going there and back.
|
||
Optimizing how to split the stream into the packets and when to send them is a
|
||
hard problem and the research in that area is still ongoing, because there are
|
||
many conflicting requirements. One wants to deliver the data with low latency,
|
||
utilize the whole bandwidth, but not overflow the capacity of the link (in which
|
||
case the latencies would go up or packets would get lost and would have to be
|
||
retransmitted), leave some bandwidth to other connections, etc.</p>
|
||
|
||
<p>The <a href="https://en.wikipedia.org/wiki/Nagle%27s_algorithm">Nagle’s algorithm</a> is
|
||
one of the older tricks up in TCP’s sleeve. The network doesn’t like small
|
||
packets. It is better to send as large packets as the link allows, because each
|
||
packet has certain overhead ‒ the headers that take some space, but also routers
|
||
spend computation power mostly based on number of packets and less on their
|
||
size. If you start sending a lot of tiny packets, the performance will suffer.
|
||
While the links are limited by the number of bytes that can pass through them,
|
||
routers are more limited by the number of packets. If a router declares to be
|
||
able to handle a gigabit connection, it actually means a gigabit <em>if you use
|
||
full-sized packets</em>, but will get to few megabits if you split the data into
|
||
tiny packets.</p>
|
||
|
||
<p>So it would be better to wait until the send buffer contains a packetfull of
|
||
data before sending anything. But we can’t do that, because we don’t <em>know</em>
|
||
there’ll ever be a full packet of data, or generating more data might wait for
|
||
the other side to answer. We would never send anything and wait forever and the
|
||
Internet would not work.</p>
|
||
|
||
<p>Instead, the algorithm is willing to send <em>one</em> undersized packet and then it
|
||
waits for an <code class="language-plaintext highlighter-rouge">ACK</code> from the other side until sending another undersized one. If
|
||
it gets a packetfull of data to send in the meantime, that’s great and it sends
|
||
it (it won’t get better by waiting longer), but it won’t ever have two
|
||
undersized ones somewhere in flight, therefore won’t kill the network’s
|
||
performance by them.</p>
|
||
|
||
<p>This works, it’ll make progress eventually because once the <code class="language-plaintext highlighter-rouge">ACK</code> comes and
|
||
all the data that accumulated until then is sent.</p>
|
||
|
||
<p>But it also slows things down. Like in our case. What happens if we do it using
|
||
single syscall, the whole HTTP response forms a single undersized packet (we
|
||
have really small answers) and gets sent, no matter if it’s submitted to the
|
||
kernel by one big or two small buffers.</p>
|
||
|
||
<p>On the other hand, if we split the submission into two syscalls, this is what
|
||
happens:</p>
|
||
|
||
<ul>
|
||
<li>We write the first part (headers). The kernel sends them out as an undersized
|
||
packet.</li>
|
||
<li>We write the second part (the body). But the kernel shelves them into the send
|
||
buffer and waits for sending them until it sees the <code class="language-plaintext highlighter-rouge">ACK</code>, because there’s one
|
||
undersized packet somewhere in flight already. Here is our sleep.</li>
|
||
</ul>
|
||
|
||
<p>This theory got confirmed by toggling the <code class="language-plaintext highlighter-rouge">tcp-nodelay</code> option on (and leaving
|
||
<code class="language-plaintext highlighter-rouge">writev</code> on too, without the fix in the library applied), which also solved our
|
||
problem. This option turns the Nagle’s algorithm off and just sends all data out
|
||
as soon as possible (considering other things like buffers in the network card,
|
||
TCP windows, congestion algorithms…).</p>
|
||
|
||
<h2 id="ok-but-why-40ms">Ok, but why 40ms?</h2>
|
||
|
||
<p>But wait, the other service lives on the same machine. It really can’t take that
|
||
long for the packet to pass through the loopback interface and an <code class="language-plaintext highlighter-rouge">ACK</code> to
|
||
return back. Hell, it should not take 40ms if it was a different datacenter on
|
||
the same continent. Not speaking about this taking <em>exactly</em> 40ms. Even if we
|
||
had really <em>long</em> loopback, it would not turn out to be 40ms exactly each time.</p>
|
||
|
||
<p>So there must be something more happening.</p>
|
||
|
||
<p>And indeed, there is. It’s called <em>delayed ACKs</em> and it’s also an optimisation
|
||
of TCP. One that got introduced about the same time as Nagle’s algorithm, but
|
||
without knowing about each other or considering how they would interact.</p>
|
||
|
||
<p>You see, one doesn’t want to send small packets (deja-vu?). A packet carrying
|
||
only an <code class="language-plaintext highlighter-rouge">ACK</code> and no data is certainly small and we don’t want to send it if we
|
||
can help that.</p>
|
||
|
||
<p>As an <code class="language-plaintext highlighter-rouge">ACK</code> can be used to acknowledge multiple received packets at once and it
|
||
can piggy-back on a packet with actual data in it, the receiver wants to wait a
|
||
little bit. The idea is, when data is received, it often provokes the
|
||
application to respond to it with some other data so we wait for that to happen,
|
||
then send the data with the <code class="language-plaintext highlighter-rouge">ACK</code>. If not, we at last wait for a <em>second</em>
|
||
packet, to acknowledge two at once. Only if we don’t get any response data nor
|
||
more incoming packets we decide to send that <code class="language-plaintext highlighter-rouge">ACK</code> eventually. After all, the
|
||
sender doesn’t really need that <code class="language-plaintext highlighter-rouge">ACK</code> fast, does it, because if it would have
|
||
more data to send, it would send at least the whole TCP window, which is several
|
||
packets long.</p>
|
||
|
||
<p>Except that the other side might be waiting for it to send more data because of
|
||
the Nagle’s algorithm. That sucks.</p>
|
||
|
||
<p>And indeed, a little bit of searching through the Internet actually finds a
|
||
<a href="https://lwn.net/Articles/502585/">kernel patch</a> talking about delayed ACKs and
|
||
the value of 40ms. Bingo, this can’t be coincidence.</p>
|
||
|
||
<p>I have reasons to believe this interaction got somehow solved in newer kernels
|
||
(I don’t know how, but apparently, it no longer happens on our development
|
||
machines). And that 40ms timeout is something the client side chooses.</p>
|
||
|
||
<h2 id="conclusion">Conclusion</h2>
|
||
|
||
<p>Well, sometimes the situation happens to be a really complex mess that results
|
||
in some weird interaction (and make a good material for a blog post). The above
|
||
combination of the TCP <em>optimisations</em> is described on the Internet, but I’d say
|
||
it’s not widely known one. That getting triggered through defaulting to a less
|
||
optimal but generally <em>good enough</em> implementation is even bigger chance. And
|
||
that such a small detail can make your optimized service 40 times slower.</p>
|
||
|
||
<p>Nevertheless, our takeaway, apart from fixing the discovered issues is:</p>
|
||
|
||
<ul>
|
||
<li>We started to watch not only our own graphs, but graphs of other services
|
||
around and have alerts for them. Our own graphs just can’t contain delays
|
||
introduced by packets sleeping somewhere in the kernel.</li>
|
||
<li>We now run with <code class="language-plaintext highlighter-rouge">tcp-nodelay</code> enabled. Even when the bug is now fixed, the
|
||
interaction is still technically possible to hit in case the client uses
|
||
pipelining ‒ the client could send two HTTP requests in a row without waiting
|
||
for the first response in between, possibly in the same TCP packet. Then we
|
||
would have written the first response and hit the problem after writing the
|
||
second one.</li>
|
||
</ul>
|
||
|
||
<p>Obviously, Rust doesn’t catch all the bugs, this one have slipped through the
|
||
compiler 😈. And while we have discovered the cause reasonably fast, it also
|
||
required a bit of luck (the toggling of the <code class="language-plaintext highlighter-rouge">writev</code> option was just random
|
||
playing around, not really something we had reasons to believe would help).</p>
|
||
|
||
|
||
</section>
|
||
</div>
|
||
|
||
<!-- FOOTER -->
|
||
<div id="footer_wrap" class="outer">
|
||
<footer class="inner">
|
||
|
||
<p>Published with <a href="https://pages.github.com">GitHub Pages</a></p>
|
||
</footer>
|
||
</div>
|
||
</body>
|
||
</html>
|