W.C.A. Wijngaards via Unbound-users wrote: > On 03/08/15 19:50, Darren Spruell via Unbound-users wrote: > > Unbound's documentation mentions that query logging can have very > > adverse performance on server operation. I was curious if the > > project feels this has been optimized to the degree possible > > already, or if an approach similar to what some other projects take > > may be beneficial; namely something like delegating logging > > responsibilities to a different thread (Suricata IDS engine, I > > think) or even using a separate log output process (Squid [1], > > OpenBSD's PF/pflogd(8) [2]).
Hi, Darren: I looked into how existing DNS servers (BIND, Unbound) implement query logging when I was originally implementing dnstap support in Unbound. There are some brief notes on slides 6 and 7 in this slide deck: http://dnstap.info/slides/dnstap_nanog60.pdf Benchmarks are shown on slides 36 and 37. Query logging just kills the performance of these two servers. BIND and Unbound are very similar in how their query logging is performed, though the actual implementations are very different. It basically comes down to: (1) Formatting the query into a textual log entry, usually using a printf() family function. (2) Using a stdio function or syslog() to export the log entry to a file or socket. (3) Doing this from the worker thread responsible for processing the query. (The basic idea dates all the way back to BIND 4: http://dnstap.info/slides/dnstap.html#(8).) Using printf() family functions in (1) is bad, since format strings have to be parsed for each entry. If your log format is highly customizable or has a lot of fields, etc. you can end up taking a not insubstantial performance hit. This can be optimized a bit with custom formatting code. (2) + (3) is where the big performance hit comes from, since the C library is ultimately hiding mutexes in the internal implementations of typical functions like fprintf() and syslog() used to write the log output. With heavily threaded servers like BIND and Unbound, (3) causes the contention for those mutexes to impact the performance of the server; you may have many worker threads running and serving clients, but they will all be contending for the same FILE* or syslog mutex. (Though, in the syslog case, there's no particularly good reason that all the threads in a process have to contend for access to the same socket to the syslog server, other than because that's how the syslog() implementation provided by the system works.) If you're only interested in acquiring raw query packets, query logging in the DNS server is probably not the best approach; there are a variety of kernel facilities for acquiring that data without affecting the performance of the DNS server too badly, like BPF/AF_PACKET ("pcap"), ulogd, pflogd, etc., depending on kernel. However, there is additional metadata that can be exported via in-server logging that doesn't appear on the wire, stuff like cache status and bailiwick information (the latter is useful for passive DNS). The dnstap implementation in Unbound is actually a combination of three different things: the "dnstap.pb" protobuf schema itself [0], the protobuf-c [1] implementation of Protocol Buffers for binary message serialization, and the fstrm library [2] which provides a dedicated logging thread and AF_UNIX transport. [0] https://github.com/dnstap/dnstap.pb [1] https://github.com/protobuf-c/protobuf-c [2] https://github.com/farsightsec/fstrm So, using binary protobuf messages rather than printf() style formatting addresses (1) above, though protobuf serialization performance can still be a concern. The lock contention in (2) and (3) are addressed by the use of a dedicated logging thread provided by fstrm that provides each worker thread a lockless way to enqueue log messages. However, all of the logging work can't be deferred to the logging thread, so (3) is still a concern. Namely, the creation of the log message itself (and any needed memory allocations, memory copies, etc.) still has to be done by the worker thread. Since the logging thread performs work asynchronously to the worker threads, we can't defer 100% of the work of creating the log message to the point at which the log data is actually written out: needed data fields that would go into the rendered log message may have been free()'d and would no longer be available. This is because Unbound is written in C and doesn't use any sort of refcounting or garbage collection scheme that we could latch onto to avoid the overhead of those memory copies, so we have to do log message rendering in the worker thread. And this applies regardless of whether the log format is text or binary. In practice, though, that residual overhead from needing to render the log message in the worker thread is not that bad, see slide 38 in the slide deck linked above (compare the 'unbound' or 'unbound-dnstap-disabled' plots against the 'unbound-dnstap-discard' plot). > > Alternately, is dnstap [3] the preferred direction for this? > > Depending on the implementation, the difference in complexity > > between a fast, native textual query log on the server vs. a dnstap > > configuration could be a factor. I'm obviously a bit biased, but dnstap does seem to be the direction that in-server DNS logging is heading in, even with the downside of needing an additional tool outside the DNS server to save the data. (Actually, I think Knot DNS allows writing dnstap data directly to a file.) I know of about 4-5 DNS servers that have implemented dnstap or are in the process of implementing it. And, as far as I know, no one is working on optimizing the existing text query logging in the various servers. (This feature seems to have been added only reluctantly to some of them.) Most of the performance issues don't come down to how the log messages are encoded (text versus binary), but how to keep the cost of exporting the log messages (writing to a socket or file) from impacting the worker threads. If you really do need textual query log data, you might look into converting dnstap encoded log messages into the format you need. There is a "dnstap-ldns" [3] utility that shows a good example of producing plain text and YAML from dnstap data. [3] https://github.com/dnstap/dnstap-ldns > Dnstap is implemented, configure --enable-dnstap. > > Make sure to install the dependencies, libfstrm and protobuf-c. In > unbound.conf it looks a bit like this: > > dnstap: > dnstap-enable: yes > dnstap-socket-path: "/tmp/mysock" You also need to enable logging for some message types, e.g.: dnstap: dnstap-enable: yes dnstap-socket-path: "/tmp/mysock" dnstap-log-client-query-messages: yes dnstap-log-client-response-messages: yes -- Robert Edmonds edmo...@debian.org