September 10, 2014 Re: Voting: std.logger | ||||
---|---|---|---|---|
| ||||
Posted in reply to Dicebot | On 09/10/2014 06:54 PM, Dicebot wrote: > On Wednesday, 10 September 2014 at 16:34:06 UTC, Andrei Alexandrescu wrote: >> One possibility is to have the first function be a one-liner that >> forwards to another. That way there will be less code bloating. >> >> void fun(uint l = __LINE__, A...)(A... as) { >> funImpl(l, as); >> } >> >> private void funImpl(A...)(uint line, A...) { >> ... bulk of the code goes here ... >> } > > Those are already small functions AFAIK (I was speaking about symbol > bloat, not code bloat). It does not help with compilation issue though - > each logging call creates a totally new template instance which means > allocating new object for DMD internal representation and running > semantic phase for it. And mature applications can have thousands of > logging calls. I have yet to run tests to see actual impact but it > concerns me from the pure DMD internals point of view. Another possibility would be to fix this bug, but the mechanism isn't particularly elegant nor efficient: https://issues.dlang.org/show_bug.cgi?id=13455 :o) |
September 11, 2014 Re: Voting: std.logger | ||||
---|---|---|---|---|
| ||||
Posted in reply to Timon Gehr | On 9/10/14, 11:46 AM, Timon Gehr wrote:
> Oops! Touché! Thanks. While the code indeed works, there actually _is_
> an issue here. :o)
Please bugzillize. Thanks! -- Andrei
|
September 16, 2014 Re: Voting: std.logger | ||||
---|---|---|---|---|
| ||||
Posted in reply to Dicebot | On Wednesday, 10 September 2014 at 16:54:14 UTC, Dicebot wrote: so the current version has one template args log functions that take __LINE__ and friends as normal parameter. I think that was the last complaint, please correct me if I'm wrong. So next round? |
September 19, 2014 Re: Voting: std.logger | ||||
---|---|---|---|---|
| ||||
Posted in reply to Robert burner Schadek | Am Tue, 16 Sep 2014 21:22:36 +0000 schrieb "Robert burner Schadek" <rburners@gmail.com>: > On Wednesday, 10 September 2014 at 16:54:14 UTC, Dicebot wrote: > > so the current version has one template args log functions that take __LINE__ and friends as normal parameter. > > I think that was the last complaint, please correct me if I'm wrong. WAT? > So next round? Hell no! Am Mon, 15 Sep 2014 22:33:45 +0000 schrieb "Robert burner Schadek" <rburners@gmail.com>: > again, the idea of std.logger is not to give you everything, because nobody knows what that even is, the idea is to make it possible to do everything and have it understandable later and use transparently I understand that part Robert, and already made use of that flexibility. But you use this to play down any concerns about the thread safety of the infrastructure you wrote and finally get std.logger accepted and merged. > the threading behavior has been clarified in the api docs. You can't just clarify it in the docs. It requires actual code to work both ways. > the (a)synchronicity guarantees is part of the concrete Logger impl. the Logger api does not force synchronize or asynchronize behavior, it allows both to be implemented by every subclass of Logger. All access to global state has to be synchronized before we can safely do so, and std.logger doesn't even attempt to in its current state! Some examples: SITUATION: isLoggingEnabled(LogLevel ll, LogLevel loggerLL, LogLevel globalLL, lazy bool condition) { … return ll >= globalLL && ll >= loggerLL && globalLL != LogLevel.off && loggerLL != LogLevel.off && condition } @property LogLevel globalLogLevel() @trusted @nogc { return globalLogLevelImpl(); } private ref LogLevel globalLogLevelImpl() @trusted @nogc { static __gshared LogLevel ll = LogLevel.all; return ll; } is called like this: isLoggingEnabled(stdlog.logLevel, stdlog.logLevel, globalLogLevel, condition); Inside `isLoggingEnabled`, we can expect condition to be evaluated in the context of the calling thread, but the three log level variables passed in create a race condition. Imagine another thread sets `stdlog.logLevel` from warning to error during a logging call. Inside `isLoggingEnabled` you'd now get: return LogLevel.warning >= globalLL && LogLevel.warning >= LogLevel.error && globalLL != LogLevel.off && loggerLL != LogLevel.off && condition This will unconditionally return false of course. The `stdlog` is now at log level warning AND error at the same time. WAT? EFFECT: Every blue moon a log message will be swallowed by std.logger. SITUATION: private Mutex __stdloggermutex; static this() { __stdloggermutex = new Mutex; } @property ref Logger stdlog() @trusted { static __gshared bool once; static __gshared Logger logger; static __gshared ubyte[__traits(classInstanceSize, FileLogger)] buffer; __stdloggermutex.lock(); scope(exit) __stdloggermutex.unlock(); if (!once) { once = true; logger = emplace!FileLogger(buffer, stderr, globalLogLevel()); } return logger; } Every thread will now create its own thread local mutex to protect access to global state. EFFECT: ** This protects exactly nothing. ** Write instead: __gshared private Mutex __stdloggermutex; shared static this() { __stdloggermutex = new Mutex; } If you need help with multi-threading please ask either here or on IRC. I have found that we have some people in the community that can explain even the fine details of atomic fences. SITUATION: We set the global log level through `globalLogLevel`: @property void globalLogLevel(LogLevel ll) @trusted { if (stdlog !is null) { stdlog.logLevel = ll; } globalLogLevelImpl = ll; } What you tried here, was to set the global log level in case we don't have `stdlog` initialized already, because during its creation it will pick up the global log level. Now `globalLogLevelImpl = ll;` will never be executed, because inside the `stdlog` property function, it is initialized and thus `stdlog !is null` will always be true. Unless the user sets `stdlog` to null, which I assume is invalid, since it creates fuzzy semantics: The first time `stdlog` is encountered to be null it is set to a FileLogger, any other time it stays null. EFFECT: There is no synchronization around the access to the stdlog. D as far as I know doesn't require that machine word reads/writes are atomic, so in theory you could get a `stdlog` where one half is an old value and the other a new one. That won't happen on ARM and x86, but I thought I'd mention. Much more importantly though another thread could change `stdlog` between `stdlog !is null` and `stdlog.logLevel = ll;`. Assuming you want to protect all of the global state with `__stdloggermutex`: @property void globalLogLevel(LogLevel ll) @trusted { synchronized(__stdloggermutex) { // TODO: stdlog will always initialize itself. // So remove the check? if (stdlog !is null) { stdlog.logLevel = ll; } globalLogLevelImpl = ll; } } SITUATION: There are 12(!) log methods in the Logger class that call `beginLogMsg` and `finishLogMsg`, which are not thread-safe. We could either override all 12 log methods, which have a complex signature and a lot of boiler plate code or just those two plus `logMsgPart`. The implementations would look very similar if all they want to be is thread safe: protected void beginLogMsg(string file, int line, string funcName, string prettyFuncName, string moduleName, LogLevel logLevel, Tid threadId, SysTime timestamp, Logger logger) @trusted { // Don't lock anything if we statically disabled logs static if (isLoggingActive()) { // no 2nd thread may begin logging this.mutex.lock(); // something may go wrong in super's method scope (failure) this.mutex.unlock(); super.beginLogMsg(file, line, funcName, prettyFuncName, moduleName, logLevel, threadId, timestamp, logger); } } protected void logMsgPart(const(char)[] msg) { // don't mess with the mutex outside of enabled logging static if (isLoggingActive()) { // something may go wrong in super's method scope (failure) this.mutex.unlock(); super.logMsgPart(msg); } } protected void finishLogMsg() { // don't mess with the mutex outside of enabled logging static if (isLoggingActive()) { // in any case unlock the mutex afterwards scope (exit) this.mutex.unlock(); super.finishLogMsg() } } EFFECT: The above is a minimum requirement to make Logger thread safe and I think it is easy to forget a static-if or the conditions under which to unlock the mutex. It would be nicer if std.logger was already thread safe to begin with, because it is today common to deal with more than one thread. Also the implementation above has two issues: 1) It cannot be used as a base class, because as an implementation detail it already encapsulates the use of `Appender` which will use the GC. 2) I think it is bad to split up locking and unlocking a mutex over the course of three methods if it is avoidable. So my conclusion is to be able to have a reusable thread safe Logger, which doesn't depend on the GC, it is necessary to pull the thread safety code one level up into the 12 log methods. HINT: Since the 3 methods are protected, it might be an idea to also move the static-if outside of them, so they wont get compiled in at all when logging is statically disabled. That's sort of DRY and will force any call to them to also be statically checked for `static if (isLoggingEnabled())`.) HINT: Maybe the abstract base class should not contain `protected Appender!string msgAppender;` ? SITUATION: abstract class Logger { … void delegate() fatalHandler; } EFFECT: Since a delegate consists of two pointers, it will always be set in two memory operations, no matter the architecture. If it is called in one thread while being set in another, it can have a context that doesn't match the function pointer. E.g. you might be calling car.explode(); instead of string.explode(); This is not guaranteed to be a complete list of the issues, but you get the idea. Even if the likelihood of some things I mentioned that could happen is small, they are still errors in the design. And since I am very pedantic about thread safety and want to see these addressed. The other thing is that since you didn't put thought into how std.logger will work in a multi-threaded environment, it is likely the API doesn't make it particularly easy to build on. (See above for suggestions to move thread safety up one level). Also I'm still missing a statement on recursion. How does std.logger deal with e.g. error/warning/... recursively calling itself? P.S.: This was my most thorough review of any Phobos code yet. I guess that means that I'm actually interested in it and feel that it is sorely missing! So thank you for designing this. It is a nice and simple single-threaded standard logging framework aside from the threading issues. -- Marco |
September 19, 2014 Re: Voting: std.logger | ||||
---|---|---|---|---|
| ||||
Posted in reply to Marco Leise | On Friday, 19 September 2014 at 05:25:18 UTC, Marco Leise wrote:
>
> WAT?
>
>> So next round?
>
> Hell no!
>
before every voting there is a review and I guess you started that.
I will address the thread-safety sufficiently in the next incarnation.
Thank you for taking the time
|
September 19, 2014 Re: Voting: std.logger | ||||
---|---|---|---|---|
| ||||
Posted in reply to Robert burner Schadek | On Tuesday, 16 September 2014 at 21:22:37 UTC, Robert burner Schadek wrote:
> On Wednesday, 10 September 2014 at 16:54:14 UTC, Dicebot wrote:
>
> so the current version has one template args log functions that take __LINE__ and friends as normal parameter.
>
> I think that was the last complaint, please correct me if I'm wrong.
>
> So next round?
Once you feel that thread safety concerns are addressed please write me an e-mail. I am currently on vacation with irregular internet access so may miss regular NG post.
|
September 19, 2014 Re: Voting: std.logger | ||||
---|---|---|---|---|
| ||||
Posted in reply to Robert burner Schadek | Am Fri, 19 Sep 2014 09:26:59 +0000 schrieb "Robert burner Schadek" <rburners@gmail.com>: > On Friday, 19 September 2014 at 05:25:18 UTC, Marco Leise wrote: > > > > WAT? > > > >> So next round? > > > > Hell no! > > > > before every voting there is a review and I guess you started that. :) > I will address the thread-safety sufficiently in the next incarnation. Ok, thank you. If you get stuck or need a another review, just drop me a mail. 4 eyes see more than 2. I'd even do the changes I had in mind myself and create a pull request if you don't mind. By the way, does anyone else use std.experimental.logger yet? Dicebot? > Thank you for taking the time You're welcome. I'm really looking forward to this project. This is the kind of component that makes libraries mix and match and helps D grow. -- Marco |
September 19, 2014 Re: Voting: std.logger | ||||
---|---|---|---|---|
| ||||
Posted in reply to Robert burner Schadek | On 9/19/14, 2:26 AM, Robert burner Schadek wrote:
> On Friday, 19 September 2014 at 05:25:18 UTC, Marco Leise wrote:
>>
>> WAT?
>>
>>> So next round?
>>
>> Hell no!
>>
>
> before every voting there is a review and I guess you started that.
>
>
> I will address the thread-safety sufficiently in the next incarnation.
>
> Thank you for taking the time
Nice, thanks! -- Andrei
|
September 19, 2014 Re: Voting: std.logger | ||||
---|---|---|---|---|
| ||||
Posted in reply to Marco Leise | On Friday, 19 September 2014 at 11:48:28 UTC, Marco Leise wrote: > Ok, thank you. If you get stuck or need a another review, just > drop me a mail. 4 eyes see more than 2. I'd even do the > changes I had in mind myself and create a pull request if you > don't mind. PRs are most welcome > >> Thank you for taking the time > > You're welcome. I'm really looking forward to this project. > This is the kind of component that makes libraries mix and > match and helps D grow. |
September 20, 2014 Re: Voting: std.logger | ||||
---|---|---|---|---|
| ||||
Posted in reply to Robert burner Schadek | Am Fri, 19 Sep 2014 15:12:34 +0000 schrieb "Robert burner Schadek" <rburners@gmail.com>: > PRs are most welcome Ok, I'm working on it. From the looks of it I will iterate a bit on the code and create one massive pull request with a lot of smaller commits to make it comprehensible. -- Marco |
Copyright © 1999-2021 by the D Language Foundation