Oh cool, very good to have you over here! Just so I fully understand: If the thread local buffer has filled up and a fresh one is created using an atomic compare-and-swap, what happens to the old one? Will it still be processed? If yes: What happens if the production of messages (into the buffers) is continuously faster than the consumption (out of the buffer)? Is that just ballooning it into memory or is there some back-pressure mechanism?
Yes, the full buffer is shipped to a separate thread for processing.
By default, if the production of tracepoints into buffers is faster than they are processed, memory usage increases over time. There are diagnostics emitted which indicate that this may be happening.
Alternatively, if the user chooses to use "non-dynamic" buffers, each thread is allowed a maximum of 2 buffers: one that it's using to write tracepoints, and one that is being processed. If the current buffer fills while the other buffer is still being processed, tracepoints are dropped and a diagnostic emitted.
I should highlight a major drawback of each thread having its own in-memory buffer. Because different threads fill and ship their buffers at different rates, trace data is written to disk out of order. It is the job of the offline formatter to sort the tracepoints into chronological order.
I am not proposing we use this model for logging in Swift, because I don't think requiring an offline formatter in order to get a chronological log is a viable option.
I really like this concept 
.
If logs are going to be buffered, what happens when application crashes? Are logs going to be missing?
2 Likes
Very good question that we need to consider. Options we have:
- decide against any buffering
- accept that crashes lose the last messages (probably a bad idea)
fork()a process instead of a thread so we can write them even after a crash (not portable to Windows I suspect)- catch the
SIGILLin process and only exit the process when the logger daemon thread caught up and processed everything in the buffer. This works but is relying on Swift implementation details. I suspect @Joe_Groff has an opinion here and probably doesn't think that's good idea ;)
Did I forget anything?
3 Likes
FWIW the IBM JVM installs a sigaction() handler at startup which flushes buffered tracepoints so they are not lost on SIGSEGV etc. I remember someone saying that Swift doesn't play nice with that approach, but I don't remember why.
Yes, that's what I mean with 'catching the SIGILL'. It works fine I've used that but it relies on implementation details on how Swift implements traps. If it were to use kill(getpid(), SIGKILL); pause() in the future this trick wouldn't work.
But we control all the pieces, don't we? ("we" being "the Swift project")
1 Like
Yes and No I guess. No because not all platforms probably surface a trap using a signal that you can catch in user space. Yes because on those platforms the runtime could offer a hook 
. But this is really something for the compiler folk to weigh in. CC @Joe_Groff/@John_McCall
1 Like
We need to be careful about installing signal handlers for the specific requirements of one library because it can interfere with other legitimate reasons that the application might want to install signal handlers. Swift generally tries to not "take over" the process.
If platforms don't provide any other way to perform emergency process cleanup, then maybe we do need to make our own system. It should be a cohesive and well-designed system in that case, though, so that e.g. other systems that need to take over the signal handler themselves can still trigger our cleanups.
4 Likes
The topic of emergency cleanup also came up in this thread about the commonly-requested ability to soft-land when subprocesses crash so they don't immediately take down an entire supervising process. That would also require a way for us to install some kind of handling logic without interfering with other signal handlers the process may have set up independently of Swift (and as @johannesweiss noted, it'd require us to standardize what trap Swift code emits to take down a process in a semi-recoverable way). It would be nice if we could guarantee that at least some level of log messages get flushed even when the process crashes, since log messages are often intended to diagnose crash conditions.
3 Likes
This is not dissimilar to how logging works in a Cloud Foundry environment. Applications hosted in such an environment have light-weight logging methods that simply write to an application container's sysout, syserr, and /dev/log. From there, a daemon called the "Metron Agent" gathers logs from these sources, converts them into a events (encoded using GBP), and sends the events to a server for distribution to Firehose end-points.
In my experience, this works great for the application. However, environments hosting applications generating great volumes of logs need to throw serious resources to support the Firehose.
I know of no log aggregator (e.g., Splunk, ELK) that can consume the Firehose protocol directly. Hence, "nozzles" are necessary to filter and transform log events into RFC-5424 compliant syslog messages, which consumer more resources.
However, the Cloud Foundry Firehose does convey events other than log messages, such as metrics, HTTP start-stop times, heartbeats and more. AppDynamics is one company I know of that consumes metrics directly from the Firehose for Enterprise scale monitoring.
1 Like
I think Python does a great job with its logging module. It allows you to:
- Use the global logger or create custom local ones.
- Filter the emitted messages by multiple criteria, including the origin module.
- Attach multiple handlers (or customize the default ones) to each logger and configure them to only process some filtered messages.
Having similar features in a new Swift Logger would be very handy and powerful.
Thanks @John_McCall and @Joe_Groff for pitching in, this is very relevant information. Should we kick off a separate thread on how we could flush log buffers in case of a crash? Doing that we can also chat about 'soft-landing sub-processes that crash' and maybe we find a good way that works for both systems.
To make more immediate progress on logging I feel we should continue to talk about the API first. I think that how the underlying logging system works won't surface in the actual logging API so we can do both in parallel and start with a very basic logging mechanism for example something that just writes to stdout and blocks. What we do however still need to decide is how we reach the logger: explicitly through dependency injection (what I called 'local logger') or implicitly through a global (what I called 'global logger').
Paging @IanPartridge do you think it makes sense to separate the discussions on how the logging system works from the API?
Wrt how to reach the logger, I think having global functions that "do the right thing" without the user having to pass around a logger (for the common cases) would be very valuable.
If I'm building some new component, and the "proper" way of logging is just as easy as calling print is, I'll use the proper way for sure. But if I need to figure out some way to inject a logger into the new component or do some other setup, I'm probably going to fall back to using print at least some of the time, if I'm honest with myself.
I thing the Rust log crate would be a nice model to follow/build upon.
It's built on one premise that I think is a good one: In the default case, only binaries should control where and how logs end up. Libraries are encouraged to use the log macros that log into a global logger instance, but are discouraged from setting or touching that global logger in some other way. In fact, the global logger can only be set once. The default global logger when nothing is set is a noop-implementation.
This does not stop libraries from passing around their own logger instance to do specialized logging to some file or service or something, but makes sure that the path of least resistance (just writing debug!("something")) doesn't mean clients of libraries have to deal with stuff in stdout/err they don't want.
The Log trait is also very small, and doesn't include anything relating to nesting etc. That is left to the individual loggers to design an API for, which keeps the log crate very small and focused, just providing the logging macros, the Log trait, and a way to set the global logger.
Then there are some other niceties:
Every log has a target (module path by default), that the global logger can use to filter things (think different log levels for different modules, we could probably use #file until a proper module system comes along).
They optimize performance when logging is disabled by asking the logger beforehand whether a log statement with a given target and log level would even be logged. If it wouldn't, the message is never constructed. We might not need this and just use an auto-closure instead, but I'm not sure how expensive those are to construct.
(whoops, wall of text 
I'll see if I have the time to hack together a quick Swift-clone of the log crate later today, to see how well it would translate)
4 Likes
One way to solve the local/global "reaching the logger" question is to provide an "execution context" i.e. implicit parameters. Silently passing extra arguments to all function calls is likely to be prohibitive from a performance standpoint, so an acceptable implementation would likely use something like thread local storage and end up requiring somewhat sophisticated machinery to make sure the "context" is what you expect it to be. Even if implemented, I can see such a feature being abused and decreasing the legibility of Swift code.
That said, Swift already supports some semantics which can also be abused to great effect (like custom operators) and while there are examples of projects doing so, the wider community seems to avoid it.
Yes I think this is a good idea.
Our focus in the work group should be on finding ways we can improve the server-side ecosystem today. I don't think that solutions which require potentially complex compiler changes, changes to the stdlib (which would have to go through the Swift Evolution process) etc. should be our focus at the moment.
A common logging abstraction which blocks while writing to stdout would still be an improvement on the current situation.
To go back to your distinction between "global" and "local" loggers, my personal view is that a solution that requires passing a logging existential around everywhere as a parameter to every function is not likely to see widespread adoption, simply because of how ugly it makes the code. People won't bother, they will think "oh I'll never want to log from this tiny function, I won't bother passing in the logger, just to keep it simple". And then in the future you find that of course you do want to log from there and now you have a refactoring exercise on your hands...
If it could be stashed in a struct/class and accessed via self.logger.log() then maybe that would see more usage, but there is a lot to be said for the simplicity of offering a global Log.info("hello world").
6 Likes
This is a little off-topic, but it might be worth considering:
Logging is a different form of gathering analytics; generally the places where you log stuff are also the places where you end up wanting to gather analytics. What if the logging API were built in such a way as to support gathering analytics?
4 Likes
That would be extremely interesting to see, thanks for offering.
1 Like