It s been a couple of weeks since I ve launched
Debian Code Search Instant,
so people have had the chance to use it for a while and that gives me plenty of
data points to look at :-). For every query, I log the search term itself as
well as the duration the query took to execute. That way, I can easily identify
queries that take a long time and see why that is.
There is a class of queries for which Debian Code Search (DCS) doesn t perform
so well, and that s queries that consist of trigrams which are extremely
common. Whenever DCS receives such a query, it needs to search through a lot of
files. Note that it doesn t really matter if there are plenty of results or not
it s the number of files that potentially contain a result which matters.
One such query is arse (we get a lot of curse words). It consists of only two
trigrams ( ars and rse ), which are extremely common in program source code.
As a couple of examples, the terms parse , sparse , charset and coarse
are all matched by that. As an aside, if you really want to search for just
arse , use word boundaries, i.e.
\barse\b , which also makes the query
significantly faster.
Fixing the overloaded frontend
When DCS first received the query, arse would lead to our frontend server
crashing. That was due to (intentionally) unoptimized code we were
aggregating all search results from all 6 source backends in memory, sorted
them, and then wrote them out to disk.
I addressed this in
commit d2922fe92 with the following measures:
-
Instead of keeping the entire result in memory, just write the result to a
temporary file on disk ( unsorted.json ) and store pointers into that file in
memory, i.e. (offset, length) tuples. In order to sort the results, we also
need to store the ranking and the path (to resolve ties and thereby guarantee a
stable result order over multiple search queries). For grouping the results by
source package, we need to keep the package name.
-
If you think about it, you don t need the entire path in order to break a tie
the hash is enough, as it defines an ordering. That ordering may be different,
but any ordering is good enough for the purpose of merely breaking a tie in a
deterministic way. I m using Go s hash/fnv, the only non-cryptographic
(fast!) hash function that is included in Go s standard library.
-
Since this was still leading to Out Of Memory errors, I decided to not store a
copy of the package name in each search result, but rather use a pointer into a
string pool containing all package names. The number of source package names is
relatively small, in the order of 20,000, whereas the number of search results
can be in the millions. Using the stringpool is a clear win the overhead in
the case where #results < #srcpackages is negligible, but as soon as
#results > #srcpackages, you save memory.
With all of that fixed, the query became at all possible, albeit with a runtime
of around 20 minutes.
Double Writing
When running such a long-running query, I noticed that the query ran smooth for
a while, but then it took multiple seconds without any visible progress at the
end of the query before the results appeared. This was due to the frontend
ranking the results and then converting unsorted.json into actual result
pages. Since we provide results ordered by ranking, but also results grouped by
source packages, it was writing every result twice to disk. What s even worse
is that due to re-ordering, every read was essentially random (as opposed to
sequential reads).
What s even worse is that nobody will ever click through all the hundreds of
thousands of result pages, so they are prepared entirely in vain. Therefore,
with
commit
c744b236e I made the frontend generate these result pages on demand. This
cut down the time for the ranking phase at the end of each query from 20-30
seconds (for big queries) to typically less than one second.
Profiling/Monitoring
After adding monitoring to each of the source-backends, I realized that during
these long-running queries, the disk I/O and network I/O was nowhere near my
expectations: each source-backend was sending only a low single-digit number of
megabytes per second back to the frontend (typically somewhere between 1 MB/s
and 3 MB/s). This didn t match up at all with the bandwidth I observed in
earlier performance tests, so I used
wget -O /dev/null to send a
query and discard the result in order to get some theoretical performance
numbers. Suddenly, I was getting more than 10 MB/s worth of results, maxing
out the disks with a read rate of about 200 MB/s.
So where is the bottleneck? I double-checked that neither the CPU on any of our
VMs, nor the network between them was saturated. Note that as of this point,
the CPU of the frontend was at roughly 70% (of one core), which didn t seem a
lot to me. Then, I followed
this excellent tutorial on
profiling Go programs to see where the frontend is spending its time. Turns
out, the biggest consumer of CPU time was the
encoding/json Go package, which
is used for deserializing results received from the backend and serializing
them again before sending them to the client.
Since I was curious about it for a while already, I decided to give
cap n proto a try to replace
JSON as serialization mechanism for communication between the source backends
and the frontend.
Switching
to it (commit 8efd3b41) brought down the CPU load immensely, and made the
query a bit faster. In addition, I killed the next biggest consumer: the
lseek(2) syscall, which we used to call with
SEEK_CUR
and an offset of 0 so that it would tell us the current position. This was
necessary in the first place because we don t know in advance how many bytes
we re going to write when serializing a result to disk. The replacement is a
neat little trick:
type countingWriter int64
func (c *countingWriter) Write(p []byte) (n int, err error)
*c += countingWriter(len(p))
return len(p), nil
// [ ]
// Then, use an io.MultiWriter like this:
var written countingWriter
w := io.MultiWriter(s.tempFiles[backendidx], &written)
result.WriteJSON(w)
With some more profiling, the new bottleneck was suddenly the
read(2) syscall, issued by the cap n proto deserialization,
operating directly on the network connection buffer.
strace
revealed that crunching through the results of one source backend for a long
query,
read(2) was called about 250,000 times. By simply
using
a buffered reader (commit 684467ae), I could reduce that to about 2,000
times.
Another bottleneck was the fact that for every processed result, the frontend
needed to update the query state, which is shared amongst all goroutines (there
is one goroutine for each source backend). All that parallelism isn t very
effective if you need to synchronize the state updates in the end. So with
commit
5d46a572, I refactored the state to be per-backend, so that locking is only
necessary for the first couple of results, and the vast vast majority of
results can be processed entirely without locking.
This brought down the query time from 20 minutes to about 5 minutes, but I
still wasn t happy with the bandwidth: the frontend was doing a bit over
10 MB/s of reads from all source backends combined, whereas with
wget I could get around 40 MB/s with the same query. At this
point, the CPU utilization was around 7% of one core on the frontend, and
profiling didn t immediately reveal an obvious culprit.
After a bit of experimenting (by commenting out code here and there ;-)), I
figured out that the problem was that the frontend was still converting these
results from capnproto buffers to JSON. While that doesn t take a lot of CPU
time, it delays the network stream from the source-backend: once the local and
remote TCP buffers are full, the source-backend will (intentionally!) not
continue with its search, so that it doesn t run out of memory. I m still
convinced that s a good idea, and in fact I was able to solve the problem in an
elegant way: instead of writing JSON to disk and generating result pages on
demand, we now
write
capnproto directly to disk (commit 466b7f3e) and convert it to JSON only
before sending out the result pages. That decreases the overall CPU time since
we only need to convert a small fraction of the results to JSON, but most
importantly, the frontend is now not in the critical path anymore. It can
directly pass the data through, and in fact it uses an
io.TeeReader to do exactly that.
Conclusion
With all of these optimizations, we re now down to about 2.5 minutes for the
search query arse , and the architecture of the system actually got simpler to
reason about.
Most importantly, though, the optimizations don t only play out for a single
query, but for many different queries. I ve deployed the optimized version at
the 15th of December 2014, and you can see that the 99th, 95th and 90th
percentile latency
dropped significantly, i.e. there are a lot fewer spikes than before, and more
queries are processed faster, which is particularly obvious in the third graph
(which is capped at 2 minutes):
Shell script is the lingua franca of Unix, it's available everywhere and often
the only reasonable choice to Get Stuff Done. But it's also clumsy and it's
easy to write unsafe shell scripts, that forget to quote variables, typo
names of functions, etc.
Wouldn't it be nice if we could write code in some better language,
that generated nicely formed shell scripts and avoided such gotchas?
Today, I've built a Haskell monad that can generate shell code.
Here's a fairly involved example. This demonstrates several features,
including the variadic 
the last year hasn't been an easy one for debian. we've seen lots of fights,
unproductive discussions, & in general behaviour which contributed to
what enrico in his brilliant 
Going through some photos, I was able to revisit some of the more memorable moments of my trip to Japan earlier this year.
For example, the time I visited 
A new release of 
I have spent the last days trying to understand the relationship between 
I've owned a 
tl;dr: Providing support for all 3 init systems (sysv-rc, Upstart and systemd) isn t hard, and generating the init scripts / Upstart job / systemd using a template system is a lot easier than I previously thought.
As always, when writing this kind of blog post, I do expect that others will not like what I did. But that s the point: give me your opinion in a constructive way (please be polite even if you don t like what you see I had too many times had to read harsh comments), and I ll implement your ideas if I find it nice.
History of the implementation: how we came to the idea
I had no plan to do this. I don t believe what I wrote can be generalized to all of the Debian archive. It s just that I started doing things, and it made sense when I did it. Let me explain how it happened.
Since it s clear that many, and especially the most advanced one, may have an opinion about which init system they prefer, and because I also support Ubuntu (at least Trusty), I though it was a good idea to support all the main init system: sysv-rc, Upstart and systemd. Though I have counted (for the sake of being exact in this blog) : OpenStack in Debian contains currently 64 init scripts to run daemons in total. That s quite a lot. A way too much to just write them, all by hand. Though that s what I was doing for the last years until this the end of this last summer!
So, doing all by hand, I first started implementing Upstart. Its support was there only when building in Ubuntu (which isn t the correct thing to do, this is now fixed, read further ). Then we thought about adding support for systemd. Gustavo Panizzo, one of the contributors in the OpenStack packages, started implementing it in Keystone (the auth server for OpenStack) for the Juno release which was released this October. He did that last summer, early enough so we didn t expect anyone to use the Juno branch Keystone. After some experiments, we had kind of working. What he did was invoking /etc/init.d/keystone start-systemd , which was still using start-stop-daemon. Yes, that s not perfect, and it s better to use systemd foreground process handling, but at least, we had a unique place where to write the startup scripts, where we check the /etc/default for the logging configuration, configure the log file, and so on.
Then around in october, I took a step backward to see the whole picture with sysv-rc scripts, and saw the mess, with all the tiny, small difference between them. It became clear that I had to do something to make sure they were all the same, with the support for the same things (like which log system to use, where to store the PID, create /var/lib/project, /var/run/project and so on ).
Last, on this month of December, I was able to fix the remaining issues for systemd support, thanks to the awesome contribution of Mikael Cluseau on the Alioth OpenStack packaging list. Now, the systemd unit file is still invoking the init script, but it s not using start-stop-daemon anymore, no PID file involved, and daemons are used as systemd foreground processes. Finally, daemons service files are also activated on installation (they were not previously).
Implementation
So I took the simplistic approach to use always the same template for the sysv-rc switch/case, and the start and stop functions, happening it at the end of all debian/*.init.in scripts. I started to try to reduce the number of variables, and I was surprised of the result: only a very small part of the init scripts need to change from daemon to daemon. For example, for nova-api, here s the init script (LSB header stripped-out):
The abbreviated title above means "Appreciation for Localization" :) I wanted to say a word of thanks for the awesome work done by