4 DLog is meant to be a performant and system-wide logging solution. This means
5 that it has to do more than just harvest logs which makes it a bit more complex
6 than what would suffice for a single program. Various users of DLog also have
7 their own unique needs and while they are free to fork the code, we try to
8 accomodate their needs in the central repo for corporate reasons. This document
9 is meant to serve as a basic introduction to DLog and shed some light on some
10 of the more "wtf" of its elements.
16 ─────────────┼────────────────────────────────────────────────────────────────
17 libdlog │ The client-side API, responsible for a priori filtering and
18 │ sending the log to the appropriate backend-dependent log sink.
19 ─────────────┼────────────────────────────────────────────────────────────────
20 dlogutil │ The developer tool for printing logs collected by the framework
21 │ and a handful of other administrative tasks.
22 ─────────────┼────────────────────────────────────────────────────────────────
23 dlog_logger │ Under the pipe backend (see below), this daemon is responsible
24 │ for storing logs received from libdlog. Under all backends, it
25 │ also periodically copies data from log storage to disk files as
26 │ defined in its configuration.
27 ─────────────┼────────────────────────────────────────────────────────────────
28 dlogctl │ A developer tool to control some aspects of DLog at run time.
29 │ In particular it changes a priori filters and disables buffers.
30 ─────────────┼────────────────────────────────────────────────────────────────
31 dlogsend │ A simple command-line utility that sends logs. 'Nuff said.
32 ─────────────┼────────────────────────────────────────────────────────────────
33 libdlogutil │ A developer API to programmatically receive logs.
38 DLog started out as an Android feature and was just a wrapper around /dev/log_*
39 kernel devices. There were 4 of those (to keep platform, radio, app and other
40 logs separate), also introduced just for Android (officially Linux never had
41 this feature). At some point the kernel guys decided to throw those devices out
42 (which finally happened in v5.0 after spending some time in staging and having
43 nobody rework it) and suggested to create a solution in userland instead.
45 This led us to create the pipe backend. Due to strict client requirements about
46 performance, we've shuffled a lot of code around, including moving processing
47 to the server. This was done in hope that the legacy Android devices would end
48 up being dropped in production images, which never happened. In the end, this
49 resulted in two backends with little in common regarding how they handle stuff
50 under the hood, but sharing idiosyncracies (like the 4 buffers).
52 Another backend is the zero-copy backend, developed for stable products, where
53 reading logs only really happens at a service depot if something breaks. This
54 approach emphasises performance of log writing at all costs, sacrificing various
55 needless abstractions (like the 4 buffers) and reading performance. Experimental
56 and fresh, so probably not recommended for general use, yet.
60 │ Android Logger Backend │ Pipe Backend │ Zero-copy Backend
61 ───────────────┼───────────────────────────────┼───────────────────────────────┼───────────────────────────────
62 Log storage │ Four kernel devices, one for │ dlog_logger daemon stores all │ One kernel device representing
63 │ each core buffer. │ core logs in its memory. Size │ a giant chunk of memory, split
64 │ │ of the buffers is controlled │ into smaller blocks that are
65 │ │ through a configuration file. │ leased to programs for direct
66 │ │ They are cyclical as well. │ writing. Size is compile-time
68 ───────────────┼───────────────────────────────┼───────────────────────────────┼───────────────────────────────
69 Mem footprint │ Medium, usually on the order │ Similar to Android Logger, │ Large, on the order of 32 MB.
70 │ of 2 MB. Entirely filled with │ with the size being set at │ Chunks are filled individually
71 │ log entries, so no waste. The │ boot time via text config. │ in parallel so many can be
72 │ size of each buffer is set at │ │ partially empty (overhead due
73 │ kernel module compile time. │ │ to waste). The size is set at
74 │ │ │ kernel module compile time.
75 ───────────────┼───────────────────────────────┼───────────────────────────────┼───────────────────────────────
76 Cycling │ Cyclical, so all logs are in │ Cyclical. │ The whole block is recycled at
77 semantics │ order and removal happens by │ Same as Android Logger. │ once, so it is possible for a
78 │ individual log age. │ │ log to be recycled even if the
79 │ │ │ previous log wasn't. Blocks
80 │ │ │ are recycled in roughly cyclic
82 ───────────────┼───────────────────────────────┼───────────────────────────────┼───────────────────────────────
83 Log interface │ Devices can be opened, read │ For each buffer, the daemon │ Clients can use an ioctl to
84 │ and written to like regular │ exposes twin sockets: one to │ obtain memory chunks which can
85 │ files. │ rule the buffer and one to │ be mmap()'d. Then they write
86 │ │ bind clients to the buffer. │ or read mapped memory directly
87 ───────────────┼───────────────────────────────┼───────────────────────────────┼───────────────────────────────
88 Timestamps │ The device adds a timestamp │ Both REALTIME and MONOTONIC │ Clients procure a timestamp
89 │ when it RECEIVES a log, using │ timestamps are added; both by │ using the MONOTONIC clock.
90 │ the REALTIME clock. │ the library on SENDING a log │ The difference between SENDING
91 │ │ and the daemon on RECEIVING, │ and RECEIVING isn't meaningful
92 │ │ for a total of 4 timestamps. │ in this context, nominally it
93 │ │ │ is a SENDING timestamp though.
94 ───────────────┼───────────────────────────────┼───────────────────────────────┼───────────────────────────────
95 Sorting │ Logs are implicitly sorted by │ Logs are sorted in the daemon │ Logs are sorted by dlogutil.
96 │ the order they arrived in the │ according to one of the four │ The memory chunks are assigned
97 │ buffer. dlogutil then simply │ timestamps, as specified in │ in an arbitrary fashion, but
98 │ merges the buffers since they │ the config. dlogutil allows │ since the size is known before
99 │ are already sorted. │ to specify a different one, │ the action, a bucket sort can
100 │ │ in which case it sorts again, │ be used.
101 │ │ else merging already-sorted. │
102 ───────────────┼───────────────────────────────┼───────────────────────────────┼───────────────────────────────
103 Monitoring │ Possible and cheap, │ Possible and reasonably cheap │ Possible, but requires fairly
104 live logs │ with no loss of logs. │ with no loss of logs. │ expensive polling of the whole
105 │ │ │ memory area. Risks some logs
106 │ │ │ slipping between the cracks.
107 ───────────────┼───────────────────────────────┼───────────────────────────────┼───────────────────────────────
108 QoS │ Available. │ Available. │ Not available since it requires
109 │ │ │ major overheads and the problem
110 │ │ │ it solves (overhead of logs) is
111 │ │ │ already mitigated with zero-copy
112 ───────────────┼───────────────────────────────┼───────────────────────────────┼───────────────────────────────
113 Performance │ High, direct communication │ Medium, but still the best │ Extreme for writing.
114 │ with the kernel. │ available in the userspace. │ Mediocre for reading.
115 ───────────────┼───────────────────────────────┼───────────────────────────────┼───────────────────────────────
116 Availability │ Only with kernel support. │ Practically every *nix. │ Only with kernel support.
117 ───────────────┼───────────────────────────────┼───────────────────────────────┼───────────────────────────────
118 Reliability │ High, the kernel ensures that │ Medium, the daemon can die │ Remains to be seen, but there
119 │ nothing goes wrong. │ and pipes can get clogged. │ are sacrifices in the name of
120 │ │ │ performance so it's unlikely
121 │ │ │ to be very robust and it has
122 │ │ │ not yet seen much live testing
123 ───────────────┼───────────────────────────────┼───────────────────────────────┼───────────────────────────────
124 Maintenance │ Hard, involves tinkering with │ Easy, everything is in the │ Hard, Adeptus Mechanicus tier.
125 │ kernel code and the internal │ userspace and the internal │
126 │ format is fairly rigid. │ format is forward-compatible. │
128 Backend support on the platform is autodetected by looking if the relevant
129 devices are present, but it can be specified explicitly via config if need be.
131 The autodetection is not only for simplicity; in Tizen IoT images, the kernel
132 and modules are different for each target, but the root filesystem is shared.
133 The DLog config is part of the root filesystem, and so is shared between all the
134 targets. This means that we can't supply a static config because it would be
135 used on targets with varying support for kernel-based backends.
137 dlog_logger interface
138 ---------------------
140 As mentioned in the table above, when the pipe backend is being used, DLog's
141 daemon, dlog_logger, uses two sockets per each buffer in order to interact with
142 other processes. One of them, the control socket, is used to perform
143 administrative tasks, such as clearing the buffer, fetching usage and capacity,
144 but also fetching the actual logs (for returning them by (lib)dlogutil). In
145 order to do so, the client just writes a simple control message. The other
146 socket is used to write logs -- in order to do so, the process which wants to
147 log writes a control message, and in response receives a pipe connected to the
148 daemon (hence the name: pipe backend) to which it can finally write the logs.
149 The reason for such a convoluted process is that pipes are more performant than
150 sockets. Therefore, in a long running process (which is the case that we
151 optimize for), it is better to suffer from some overhead during connection,
152 than to use sockets which are simpler, but would result in higher overhead for
155 We use two sockets instead of one, because they require different permissions;
156 almost everything on Tizen can log, but we only want administrators to perform
157 administrative tasks. Additionally, we eschew DBus in favor of a simple custom
158 solution, because DLog is supposed to be a very low level, low dependency,
159 highest possible performance solution.
161 When the Android Logger or the zero-copy backend is being used, applications can
162 interact with devices directly. Therefore, the sockets aren't used and aren't
163 created. In some cases, this might mean that the daemon is not needed at all; in
164 this case it will detect it and quit automatically. However, there are other
165 features that require the daemon. These include log persistence, KMSG and Syslog
166 support and QoS. These features are explained below, and when they are enabled,
167 the daemon won't quit even if a kernel-based backend is being used.
172 At some point the idea to make DLog the logging overmind of the system was
173 floated around: to make it responsible (at least to an extent) for the various
174 other places that collect logs. Ultimately, nothing came out of it (syslog is
175 handled by systemd journal), but the code remains and complicates things; see
176 below. However, we're reluctant to simplify because unified logging could be
177 genuinely good to have and we anticipate that we're going to get asked to get
178 back to this at some point in the foreseeable future. Those two buffers are
179 handled using the pipe backend even if the logger backend is being used (and
180 sockets are created for them).
182 Timestamps and sorting
183 ----------------------
185 The original kernel devices just slapped a timestamp when they got a log and
186 called it a day. The pipe-backend daemon initially replicated this, but at some
187 point people noticed that if the system is very busy, the timestamp they gather
188 locally and the one added by the daemon can differ a bit and requested that we
189 use an "accurate" timestamp, i.e. add it library-side. With multiple programs,
190 it is possible for the daemon to receive logs in a different order than their
191 timestamps were added, which then led to complaints about logs being printed
192 seemingly out of order, confusing developers. Sorting was added, which stumbled
193 upon a bunch of issues like "what if somebody changes the clock, especially
194 backwards" or "what if a client forked the kernel to change device clock type
195 to be fundamentally incomparable". Ultimately we had to collect all possible
196 timestamps since they could potentially have to be compared against each other
197 (see below: KMSG, Syslog and Android devices all use different timestamps, only
198 pipe-based logs are flexible).
200 Here's what timestamp types are available from different log sources:
202 - KMSG gets a sent-monotonic timestamp when log is sent, and the daemon adds
203 both receive timestamps.
204 - syslog gets a sent-realtime timestamp when log is sent, and the daemon adds
205 both receive timestamps.
206 - When Android Logger backend is enabled, all its buffers have only the
207 sent-realtime timestamp available.
208 - When zero-copy backend is enabled, all its buffers have only the
209 sent-monotonic timestamp available.
210 - When pipe backend is enabled, all its buffers have all four timestamps
211 available. Note that if the stdout redirector is used, receive timestamps
212 refer to the moment when the last character (newline or a zero byte) is
213 received. Also, in the case of the stdout redirector, sent timestamps are
214 just copies of the receive timestamps and can be wildly inaccurate -- the
215 only reason we add them is that they are available in the normal logs and we
216 want to be able to depend on their existence.
218 Having four different timestamps inflicts quad damage upon our ability to
219 compare such logs to each other. We are forced to copy both KMSG and Syslog
220 logs into the daemon just so that they have some sort of receive timestamp.
222 It would be great to simplify this but I expect it would take some sneaky
223 gaslighting to implement without anybody raising a big fuss about it and it
224 would still have to involve explaining to random people why their timestamp
227 Filtering and limiting
228 ----------------------
230 A posteriori filtering, as done by dlogutil and dlog_logger file logging, is
231 fairly obvious: people are usually only interested in a subset of logs. This
232 filtering can be done by a handful of parameters such as pid, tag, and priority.
234 A priori filtering is done by the library. It is done to reduce responsibility
235 a client program has over the amount of logs it produces. Everybody wants to
236 produce as many logs as possible, but if everybody does that then the system can
237 grind to a halt (at least on Tizen, where everything is too broken to go without
238 logs so people throw absolutely disgusting amounts of them and the hardware is
239 not stellar either so struggles a lot). Nipping as many logs in the bud as we
240 can means that everybody can spam as many logs as they want relatively cheaply,
241 since they all get thrown directly in the trash anyway (there's a metaphor for
242 something here). This type of filtering can be done either based on a static
243 config loaded just once at startup, or a mode enabled where the config can be
244 changed dynamically at runtime. This incurs a runtime cost for logging as we
245 could not do it "properly" based on events without changing the API, so it can
246 be disabled if not wanted. Dynamic filtering is controlled through dlogctl.
248 Unlike a posteriori filtering, a priori filtering doesn't have to mean dropping
249 affected logs completely. Instead of denying the log completely in
250 configuration, the user can limit logs of each tag to a number per minute. This
251 is, however, a limit per process; for example if we limit the tag GENERIC_TAG to
252 10 tags per minute, and we have 10 processes spamming with this tag, we will get
253 100 logs every minute. This is not an intentional limitation, but it's hard to
254 think of a better solution in the library, and implementing it server side would
255 require either forking the kernel module (which is not something we are going to
256 do), or dropping the Android Logger backend.
258 A priori filtering can also be done by the pid, and again the user can either
259 deny the log completely or set a limit per time unit. However, currently,
260 a single filter can't use both pid and other (tag/priority) settings.
265 This is a simple mechanism for controlling the total amount of logs in the
266 system. From the user perspective, it amounts to choosing the total amount of
267 logs, and afterwards, logs will be dropped in order to stay under the limit.
270 As usual, it's not so simple from the technical standpoint. The main issue is,
271 again, the Android Logger backend, which means that logging programs talk
272 directly to the kernel and not to any userspace service. Our solution is
273 located in the dlog_logger server, but works in a way that doesn't require a
274 connection to DLog clients. Specifically, the daemon counts the logs, and when
275 the limit is surpassed, it makes a list of logging processes, and then makes an
276 attempt (using one of the heuristics) to give each one a limit per time period.
277 This limit is sent to the clients using the dynamic filtering (see above).
279 The above is not even implemented for the zero-copy backend, though the same
280 set of limitations would apply since it's a kernel module. On the other hand it
281 would ruin performance due to the overhead of syscalls, plus there's no need to
282 limit logs if they are fast enough not to hog the entire CPU) so we probably are
283 going to leave it unsupported.
285 All of this means that QoS limit is not a hard limit, but rather a suggestion
286 that the logger tries its best to follow; however, it will be broken from time
287 to time, and as often there will be less logs kept than possible. A better
288 solution would, again, either be in kernel space or be pipe backend only.
293 This is a work in progress library to receive logs from a working system. It
294 is meant to be used in, for example, log analysis daemons. A developer wanting
295 to use this library has to first use the configuration function, and then they
296 can use the connect function and then get the logs one by one (with a possible
299 The library uses much of the code that used to be in dlogutil, and dlogutil
300 has been rewritten to use the library. This means that libdlogutil should work
301 exactly the same way as dlogutil, but with a different log sink -- to the
302 program and not to the user. Since developers are often familiar with the
303 command line utility, they should have a decent idea about what the various
304 API functions do, and they've got dlogutil itself as the ultimate reference.
306 Beware! The API is, so far, internal. This means that while we will try not
307 to introduce breaking changes, we are not bound not to do so and anybody
308 using the library is doing it on their own responsibility.
313 The unit tests are located in the src/tests directory. Each file is its own
314 binary and is built against the DLog source code directly (as you can see in
315 Makefile.am). We do not use any test framework; instead, we fail by assert.h
316 assertions or returning a failure exit code manually. These tests are run
317 automatically during compilation. Sometimes, we'd like to check for the nitty
318 gritty syscall things; we use the linker wrapping mechanism for that, which
319 allows to replace an existing function with a new one (which could call the
320 existing function in its body). The flag is set in Makefile.am, and using this
321 in .c test files is rather intuitive (see existing files for comparision). Note
322 however, that this mechanism is incredibly fragile (for example: what if the
323 compiler inlines the function?), so don't be surprised if it decides to break
324 randomly. Also note that some of these tests don't make much sense (and actually
325 were added mostly for coverage/KPI reasons), in that they don't really check the
326 result of the function, but rather the concrete implementation (usually this
327 means the order of syscalls/glibc functions). This means that you sadly
328 shouldn't be surprised when let's say changing malloc to calloc, or some similar
329 totally correct thing, breaks the tests.
331 The integration tests are located in the tests directory. The main test file is
332 dlog_test.in, which is a big POSIX shell script that runs all tests in order. It
333 mostly runs the executables exported by the main packages, like dlogutil and
334 dlogsend, but it also uses some purpose-built tools that are also located in the
335 tests directory, which however only use the DLog public API. These tests are
336 located in a separate package, dlog-tests, and can be run manually; for details,
337 see the message during the instalation of this package. They are also highly
338 stateful, and for now they don't really care about fully cleaning their own
339 state to a degree higher than required for them to work. These tests also don't
340 count into coverage statistics (for technical reasons). You can also find some
341 benchmarks in this directory, but they have been mostly written ad hoc, and are
342 not really supposed to be run right now.
344 The TL;DR on how to test DLog 100% is as follows:
345 1. Compile the package. If the unit tests fail, you will get a log file in the
346 build directory in the GBS root. If they succeed, you won't get a log file,
348 2. Install all the packages, including dlog-tests. Make sure to reboot your
349 target afterwards (you will get a message about this while installing the
351 3. Run `dlog_test pipe` and `dlog_test logger`. There are other options (see the
352 script for details) but it is enough to do this.
353 4. Uninstall test package, reboot afterwards. You can test DLog manually now if
354 you feel like so. See if the target boots, call dlogutil to see if there are
357 As you might have seen, both unit and integration tests could use some love.
358 Unfortunately, we have never really had any time to do any improvement here
359 (except of course writing new tests, which we do try to do, especially if there
360 is a regression). We'd like to avoid adding dependencies just for tests, but it
361 would be great to improve these one day. In the meantime, both unit and
362 integration tests can catch (and have caught in the past) some real bugs.
projects / platform / core / system / dlog.git / blob