Re: Weird bug in std.logger? Possible memory corruption
On 1/11/23 18:26, Christian Köstlin wrote: It's really weird: https://run.dlang.io/is/fIBR2n I think I might have found out the issue. It's indeed related to the lazy parameter and reentrance. The usual logger functions consist of three parts: a header, the message, and the "finalizer". [1]. Internally this is implemented using a string appender [2, 3]. However, this string appender is a member of the class, and this is the source of the bug, because it's shared among all the calls to the logger. It's usually protected by a mutex, so different threads don't mess with each other, but it didn't take reentrancy into account. And so the call to the logging function within `foo` takes place once the appender is already populated, so this is what happens: 1. Header of first call to `log` (`info`, in this case, but it's irrelevant). 2. Body of first invocation -> Call to `foo()` -> Second call to `log`. 3. The buffer is cleared: The first header is discarded (and previous body, if there were any). 4. The second invocation proceeds normally, and the control returns to the first invocation 5. Now the buffer contains the full content of the previous call, and the return of `foo` is added. This is exactly what we see. If we do an assignment **before**, then the call is no longer reentrant and everything happens as expected. So I'd still call it a bug, but at least there seems to be no memory corruption. Also, it doesn't have an easy way to fix it without changing the interface (and potentially affecting already existing custom implementations). In my view, `writeLogMsg` should create a brand new appender (not a member of the class) that would be passed as a parameter to `beginLogMsg`, `logMsgPart` and `finishLogMsg()`. Anyway, I think the mystery is more or less solved. [1]: https://dlang.org/phobos/std_logger_core.html#.Logger [2]: https://github.com/dlang/phobos/blob/master/std/logger/core.d#L1401 [3]: https://github.com/dlang/phobos/blob/master/std/logger/core.d#L619-L641
Re: Weird bug in std.logger? Possible memory corruption
On Wednesday, 1 November 2023 at 17:26:42 UTC, Christian Köstlin wrote: ... It's really weird: https://run.dlang.io/is/fIBR2n Interesting because I wrote a similar test as you did. And that increment (Or lack of) called my attention, If I can I'll try and take a look at that (std.logger) info() Implementation later after work. Matheus.
Re: Weird bug in std.logger? Possible memory corruption
On Wednesday, 1 November 2023 at 14:15:55 UTC, matheus wrote:
On Tuesday, 31 October 2023 at 21:19:34 UTC, Arafel wrote:
...
Assigning the value to a variable works as expected:
```d
import std.logger : info;
void main() {
auto s = foo();
info(s);
}
auto foo() {
info("In foo");
return "Hello, world.";
}
```
...
Unless you do:
string s;
info(s=foo());
I think this is a bug, or at least very weird behavior.
Matheus.
It's really weird: https://run.dlang.io/is/fIBR2n
Re: Weird bug in std.logger? Possible memory corruption
On Tuesday, 31 October 2023 at 21:19:34 UTC, Arafel wrote:
...
Assigning the value to a variable works as expected:
```d
import std.logger : info;
void main() {
auto s = foo();
info(s);
}
auto foo() {
info("In foo");
return "Hello, world.";
}
```
...
Unless you do:
string s;
info(s=foo());
I think this is a bug, or at least very weird behavior.
Matheus.
Re: Weird bug in std.logger? Possible memory corruption
I can only imagine that it's related to the logging functions taking lazy arguments, although I cannot see why it would be a problem in a simple case like this. I've been thinking a bit more about it, and it must be indeed because of the lazy argument. `foo()` is an argument to `info`, but it also uses the logger. However, because it's a lazy argument, it's not called from `main`, but from `info` itself. I strongly suspect that the problem is that it's not reentrant. I'm not clear what it's supposed to happen, but assuming this case won't be supported, it should at least be documented. Should I open a bug about it?
Weird bug in std.logger? Possible memory corruption
Hi,
Today I have just found a weird bug in std.logger. Consider:
```d
import std.logger : info;
void main() {
info(foo());
}
auto foo() {
info("In foo");
return "Hello, world.";
}
```
The output is:
```
2023-10-31T20:41:05.274 [info] onlineapp.d:8:foo In foo
2023-10-31T20:41:05.274 [info] onlineapp.d:8:foo In fooHello, world.
```
The second line is obviously wrong, as it repeats the first line as its
header. That's why I suspect memory corruption.
Assigning the value to a variable works as expected:
```d
import std.logger : info;
void main() {
auto s = foo();
info(s);
}
auto foo() {
info("In foo");
return "Hello, world.";
}
```
gets the proper output:
```
2023-10-31T21:09:46.529 [info] onlineapp.d:9:foo In foo
2023-10-31T21:09:46.529 [info] onlineapp.d:5:main Hello, world.
```
I can only imagine that it's related to the logging functions taking
lazy arguments, although I cannot see why it would be a problem in a
simple case like this.
Re: std.logger issue
On Thursday, 26 January 2023 at 20:08:51 UTC, Krzysztof Jajeśnica wrote: On Thursday, 26 January 2023 at 17:17:28 UTC, o3o wrote: how can I enable `trace` level? Set `sharedLog.logLevel` instead of `globalLogLevel`. ```d // Note: the cast is needed because sharedLog is shared (cast()sharedLog).logLevel = LogLevel.all; ``` Explanation: logging functions (`trace`, `log`, etc.) called without a logger perform the logging using a global logger called `sharedLog`. `sharedLog` uses `LogLevel.info` by default, which is why your trace messages were not showing. Thank you very much Krzysztof, it works.
Re: std.logger issue
On 1/26/23 12:08, Krzysztof Jajeśnica wrote:
> On Thursday, 26 January 2023 at 17:17:28 UTC, o3o wrote:
>> how can I enable `trace` level?
>
> Set `sharedLog.logLevel` instead of `globalLogLevel`.
Good catch. I had tried the following without success:
stdThreadLocalLog.logLevel = LogLevel.all;
> // Note: the cast is needed because sharedLog is shared
> (cast()sharedLog).logLevel = LogLevel.all;
I did not think casting that way would be the right thing to do.
Although I've never used std.logger, and without remembering who
implemented it (sincere aplogies), given how simple the use cases of
logging are, I found its implementation very complicated. For example,
the following function is one I stumbled upon while debugging the OP's
issue:
bool isLoggingEnabled()(LogLevel ll, LogLevel loggerLL,
LogLevel globalLL, lazy bool condition = true) @safe
{
return ll >= globalLL
&& ll >= loggerLL
&& ll != LogLevel.off
&& globalLL != LogLevel.off
&& loggerLL != LogLevel.off
&& condition;
}
I don't think it is possible to entagle usage issues with functions with
that semantic complexity.
Ali
Re: std.logger issue
On Thursday, 26 January 2023 at 17:17:28 UTC, o3o wrote: how can I enable `trace` level? Set `sharedLog.logLevel` instead of `globalLogLevel`. ```d // Note: the cast is needed because sharedLog is shared (cast()sharedLog).logLevel = LogLevel.all; ``` Explanation: logging functions (`trace`, `log`, etc.) called without a logger perform the logging using a global logger called `sharedLog`. `sharedLog` uses `LogLevel.info` by default, which is why your trace messages were not showing.
std.logger issue
```
// rdmd --main -unitest app.d
import std.stdio;
import std.logger;
unittest {
globalLogLevel = LogLevel.all;
infof("g: %s", globalLogLevel);
trace("trace"); // NO output!
info("info");
warning("warn");
error("error");
}
```
output is:
```
2023-01-26T18:16:13.546 [info] log.d:6:main g: all
2023-01-26T18:16:13.546 [info] log.d:8:main info
2023-01-26T18:16:13.546 [warning] log.d:9:main warn
2023-01-26T18:16:13.546 [error] log.d:10:main error
```
how can I enable `trace` level?
Thank
[Issue 23323] std.logger (previously experimental) needs better documentation
https://issues.dlang.org/show_bug.cgi?id=23323 Iain Buclaw changed: What|Removed |Added Priority|P1 |P4 --
[Issue 23323] New: std.logger (previously experimental) needs better documentation
https://issues.dlang.org/show_bug.cgi?id=23323
Issue ID: 23323
Summary: std.logger (previously experimental) needs better
documentation
Product: D
Version: D2
Hardware: All
OS: All
Status: NEW
Severity: enhancement
Priority: P1
Component: phobos
Assignee: nob...@puremagic.com
Reporter: andrej.mitrov...@gmail.com
It took me quite a bit of time to realize why by default `log(string)` will do
nothing at all. In fact I think the default is very counter-intuitive.
Here's an example:
-
import std.experimental.logger;
void main (){
log("Hello?");
logf(LogLevel.info, "%s", "test 1");
logf(LogLevel.error, "%s", "test 2");
log(LogLevel.info, "test 3");
}
-
The first line will not be emitted to stdout or stderr, or anywhere for that
matter. The user is supposed to explicitly set the logging level. But it's not
even obvious for which logger they're supposed to do that.
The actual solution is:
-
import std.experimental.logger;
void main (){
stdThreadLocalLog().logLevel = LogLevel.info;
log("Now this works");
}
-
I lost a fair bit of time digging through phobos sources to understand what's
going on. I think we should at least document that you have to do this to get
any kind of output to stdout/stderr when calling 'log()'.
--
Re: OT: std.logger was Re: std.experimental Timeline
Sorry for late reponse, I don't read NG that often now. On Monday, 4 January 2016 at 17:06:16 UTC, Robert burner Schadek wrote: I actually have a patch in the pipeline for this,. That patch require to change the protection for beginLogMsg, logMsgPart, finishLogMsg from protected to public and bye bye cast. logMsgPart already takes a const(char)[]. I actually thought the protection was public to begin with. Very good, this will get rid of one of API problems I was going to mention :) Yes the cast is ugly, but then I'm writing dynamic content into stack arrays. It is not just ugly, it is undefined behavior by D specification. You are casting to immutable data that will inevitably going to change. Most likely it will work on all existing compilers but such code won't pass any decent code review. With protection changes it becomes possible to avoid LogEntry though so this becomes sort of fixed. However .. BTW, the default implementation is a direct result of the "by default multi-threading safe" requirement brought up multiple times during reviews. .. this remains a concern. I know that with some tweaks and lot of custom overriding I can build logging system that works with reusable buffers. However, it would be incompatible with any 3d party logger which is defined in terms of `LogEntry` and that kills the main benefit of having standard API in the first place. I'd like (if it is even possible) to have a fast thread-safe no-allocation logger with thread-local proxies as a default one available because it is both very common demand from a logging system and will influence how derived 3d-party loggers will be designed. But that can be a more problematic task because `const(char)[]` is not implicitly shared and we don't have any good guidelines for sharing mutable data in Phobos :) Right now I have no idea what should be done - it is simply a problem that is likely to result in at least some API changes and a good example why just being in std.experimental for a long period doesn't safeguard against finding unexpected API issues (I have only realized the issue several weeks ago, despite being the review manager of original proposal and reading it in great details). Anyway, if people have issues with std.(experimental.)logger, please write to the forum, bugzilla, github, or directly to me. As I have mentioned in the e-mail, I will do so as soon as I will have any half-decent proposal and will be able to help :)
Re: OT: std.logger was Re: std.experimental Timeline
On Tuesday, 5 January 2016 at 16:34:27 UTC, Dicebot wrote: BTW, the default implementation is a direct result of the "by default multi-threading safe" requirement brought up multiple times during reviews. .. this remains a concern. I know that with some tweaks and lot of custom overriding I can build logging system that works with reusable buffers. However, it would be incompatible with any 3d party logger which is defined in terms of `LogEntry` and that kills the main benefit of having standard API in the first place. I'd like (if it is even possible) to have a fast thread-safe no-allocation logger with thread-local proxies as a default one available because it is both very common demand from a logging system and will influence how derived 3d-party loggers will be designed. If you could write this up as a callgraph with some (ascii) art showing thread boundaries, you would help me a lot understanding your requirement. But that can be a more problematic task because `const(char)[]` original proposal and reading it in great details). Anyway, if people have issues with std.(experimental.)logger, please write to the forum, bugzilla, github, or directly to me. As I have mentioned in the e-mail, I will do so as soon as I will have any half-decent proposal and will be able to help :) You don't need to do my work, it is nice of you to do that, but all I need is a problem description I can work with.
Re: OT: std.logger was Re: std.experimental Timeline
On Monday, 4 January 2016 at 09:24:44 UTC, Robert burner Schadek wrote: On Sunday, 3 January 2016 at 21:37:28 UTC, Dicebot wrote: Haven't found any issues with std.allocator so far but std.logger definitely is not Phobos ready per my requirements. I have been recently re-evaluating it as possible replacement for old Tango logger we use and found that in several places it forces unnecessary GC allocations and/or immutability (i.e. https://github.com/D-Programming-Language/phobos/blob/master/std/experimental/logger/core.d#L742 requires that log message must be formatted into immutable string before it can be passed to another logger). This is a deal breaker that can possibly require major API change to fix. I do not follow. 1. Tango passes a const(char)[] around [1]. What is the difference? 2. Have you looked at the doc and the impl. of FileLogger? They both show an easy how to implement a Logger without the GC. With that it is also trivial to make a MultiLogger that does not allocate. BTW, the default implementation is a direct result of the "by default multi-threading safe" requirement brought up multiple times during reviews. [1] https://github.com/SiegeLord/Tango-D2/blob/d2port/tango/util/log/Log.d#L1297 If I understand correctly (based on previous statements by Dicebot), the problem is that at Sociomantic, they reuse buffers heavily. So, they basically don't use string much of anywhere and instead use some combination of char[] and const(char)[] (so that the array elements can be given new values without reallocating), and std.experimental.logger - like a lot of typical D code - uses string, which means that when they log a message with std.experimental.logger, their buffer has to be copied into a string, which means that an allocation occurs, which in their environment is unacceptable. So, to work for them, they would need std.experimental.logger to accept something like const(char)[] or an arbitrary ranges of characters and to not allocate inside of any of its logging functions. Any requirement to convert to string (be it by the user of the logger or inside of the logger itself) doesn't work with their requirements. I'm not particularly familiar with std.experimental.logger as it stands, by I would guess that to fit Sociomantic's requirements, it would need to either manage to log without actually constructing any array of characters (e.g. by printing each of its elements in turn without actually putting them together first), or it would need to reuse a buffer every time it created the line to log (which would incur the cost of copying the characters but wouldn't normally have to allocate). But I don't know how well that fits in with the logger being hierarchical via classes (which solves other design requirements) or how close the current implementation is to that. Certainly, being forced to use classes does prevent the logger from using some of the typical techniques that we use (particularly with regards to ranges). So, the logger definitely presents some challenges that most other Phobos code doesn't have to deal with. :| Though obviously, you'd be more aware of that than anyone. :) - Jonathan M Davis
OT: std.logger was Re: std.experimental Timeline
On Sunday, 3 January 2016 at 21:37:28 UTC, Dicebot wrote: Haven't found any issues with std.allocator so far but std.logger definitely is not Phobos ready per my requirements. I have been recently re-evaluating it as possible replacement for old Tango logger we use and found that in several places it forces unnecessary GC allocations and/or immutability (i.e. https://github.com/D-Programming-Language/phobos/blob/master/std/experimental/logger/core.d#L742 requires that log message must be formatted into immutable string before it can be passed to another logger). This is a deal breaker that can possibly require major API change to fix. I do not follow. 1. Tango passes a const(char)[] around [1]. What is the difference? 2. Have you looked at the doc and the impl. of FileLogger? They both show an easy how to implement a Logger without the GC. With that it is also trivial to make a MultiLogger that does not allocate. BTW, the default implementation is a direct result of the "by default multi-threading safe" requirement brought up multiple times during reviews. [1] https://github.com/SiegeLord/Tango-D2/blob/d2port/tango/util/log/Log.d#L1297
Re: OT: std.logger was Re: std.experimental Timeline
On Monday, 4 January 2016 at 10:58:09 UTC, Jonathan M Davis wrote: If I understand correctly (based on previous statements by Dicebot), the problem is that at Sociomantic, they reuse buffers heavily. So, they basically don't use string much of anywhere and instead use some combination of char[] and const(char)[] (so that the array elements can be given new values without reallocating), and std.experimental.logger - like a lot of typical D code - uses string, which means that when they log a message with std.experimental.logger, their buffer has to be copied into a string, which means that an allocation occurs, which in their environment is unacceptable. FileLogger is a Logger that can be used after only one allocation. new FileLogger; Everything else (logging, ...) does not require a single allocation. If you look at the documentation above [1] you will understand why. Building a MultiLogger (Logger of Loggers) that forwards the calls to the log functions to the contained Loggers without allocation is also trivial. Logging into a passed in buffer is also trivial (as long as you buffer is big enough for the data to log, but that is design problem). So, to work for them, they would need std.experimental.logger to accept something like const(char)[] or an arbitrary ranges of characters and to not allocate inside of any of its logging functions. Any requirement to convert to string (be it by the user of the logger or inside of the logger itself) doesn't work with their requirements. as said above, no Logger has to allocate for logging, and no string has to be created. An allocation schema was selected however, to make multi threading work by default. Creating a user specific Logger that fits the Logger interface and that uses a static buffer to write the data to is properly less than 20 lines of code. I'm not particularly familiar with std.experimental.logger as it stands, by I would guess that to fit Sociomantic's requirements, it would need to either manage to log without actually constructing any array of characters (e.g. by printing each of its elements in turn without actually putting them together first), or it would need to reuse a buffer every time it created the line to log (which would incur the cost of copying the characters but wouldn't normally have to allocate). But I don't know how well that fits in with the logger being hierarchical via classes (which solves other design requirements) or how close the current implementation is to that. Certainly, being forced to use classes does prevent the logger from using some of the typical techniques that we use (particularly with regards to ranges). So, the logger definitely presents some challenges that most other Phobos code doesn't have to deal with. :| Though obviously, you'd be more aware of that than anyone. :) - Jonathan M Davis If you guess of their requirements is correct, std.experimental.logger fulfills the requirements. [1] https://github.com/D-Programming-language/phobos/blob/master/std/experimental/logger/core.d#L812
Re: OT: std.logger was Re: std.experimental Timeline
As talk is cheap, here is the code: http://dpaste.dzfl.pl/ba4df05339f6 not 20 lines but for 99 lines you get two Loggers and some tests.
Re: OT: std.logger was Re: std.experimental Timeline
Yes the cast is ugly, but then I'm writing dynamic content into stack arrays. I actually have a patch in the pipeline for this,. That patch require to change the protection for beginLogMsg, logMsgPart, finishLogMsg from protected to public and bye bye cast. logMsgPart already takes a const(char)[]. I actually thought the protection was public to begin with. Anyway, if people have issues with std.(experimental.)logger, please write to the forum, bugzilla, github, or directly to me.
Re: OT: std.logger was Re: std.experimental Timeline
On Monday, 4 January 2016 at 13:48:16 UTC, Robert burner Schadek wrote: On Monday, 4 January 2016 at 10:58:09 UTC, Jonathan M Davis wrote: So, to work for them, they would need std.experimental.logger to accept something like const(char)[] or an arbitrary ranges of characters and to not allocate inside of any of its logging functions. Any requirement to convert to string (be it by the user of the logger or inside of the logger itself) doesn't work with their requirements. as said above, no Logger has to allocate for logging, and no string has to be created. An allocation schema was selected however, to make multi threading work by default. Creating a user specific Logger that fits the Logger interface and that uses a static buffer to write the data to is properly less than 20 lines of code. Well, looking at your implementation in your other post, you're able to make it work by casting to string when it's not actually a string. So, you're circumventing the type system to make it work. Depending on what the base class does with the resulting string, it may work, but there's no guarantee that it will, especially if you end up deriving your logger class from a 3rd party one. For this code to be safe, msg in LogEntry really needs to be const(char)[] and not string. I'm not particularly familiar with std.experimental.logger as it stands, by I would guess that to fit Sociomantic's requirements, it would need to either manage to log without actually constructing any array of characters (e.g. by printing each of its elements in turn without actually putting them together first), or it would need to reuse a buffer every time it created the line to log (which would incur the cost of copying the characters but wouldn't normally have to allocate). But I don't know how well that fits in with the logger being hierarchical via classes (which solves other design requirements) or how close the current implementation is to that. Certainly, being forced to use classes does prevent the logger from using some of the typical techniques that we use (particularly with regards to ranges). So, the logger definitely presents some challenges that most other Phobos code doesn't have to deal with. :| Though obviously, you'd be more aware of that than anyone. :) - Jonathan M Davis If you guess of their requirements is correct, std.experimental.logger fulfills the requirements. Only by doing a risky cast that happens to work in a reduced example but does not work in the general case. Now, the changes required to avoid the cast should be minimal and straightforward, but as long as a cast to string is required in order to avoid allocating a string, the logger doesn't safely support avoiding allocations. My guess is that it didn't even occur to Dicebot to make the cast, but I doubt that he would be happy with that solution anyway, particularly given the recent PR and related discussion on adding message to Throwable (which returns const(char)[]): https://github.com/D-Programming-Language/druntime/pull/1445 Regardless, Dicebot will obviously have to talk with you about their requirements and why he thinks that std.logger doesn't fit them. - Jonathan M Davis
Re: std.logger sharedLog usage
On Monday, 30 March 2015 at 04:05:12 UTC, lobo wrote: Thank you, lobo. next version will have equal default LogLevel for all Logger. https://github.com/D-Programming-Language/phobos/pull/3124
Re: std.logger sharedLog usage
On Sunday, 29 March 2015 at 12:37:23 UTC, Robert burner Schadek
wrote:
On Sunday, 29 March 2015 at 01:36:24 UTC, lobo wrote:
Hi,
I'm trying to use std.experimental.logger and I'd like the
logf(), tracef() style functions to log to a file and stdout.
(note: I can use sharedLog.logf(), sharedLog.tracef(), but I
prefer just logf())
So I did this:
shared static this() {
auto ml = new MultiLogger();
ml.insertLogger(stdout, new FileLogger(std.stdio.stdout));
ml.insertLogger(applog, new FileLogger(applog.txt));
sharedLog = ml;
logf(This is a test); // Doesn't work
}
Which doesn't work, so I'm wondering if it's possible to do
what I want.
thanks,
lobo
just add the line stdThreadLocalLog.logLevel = LogLevel.info
before logf and it should work. The default LogLevel of the
MultiLogger and FileLogger is high than the default LogLevel of
stdThreadLocalLog. (I will fix that)
Thank you, lobo.
Re: std.logger sharedLog usage
On Sunday, 29 March 2015 at 01:36:24 UTC, lobo wrote:
Hi,
I'm trying to use std.experimental.logger and I'd like the
logf(), tracef() style functions to log to a file and stdout.
(note: I can use sharedLog.logf(), sharedLog.tracef(), but I
prefer just logf())
So I did this:
shared static this() {
auto ml = new MultiLogger();
ml.insertLogger(stdout, new FileLogger(std.stdio.stdout));
ml.insertLogger(applog, new FileLogger(applog.txt));
sharedLog = ml;
logf(This is a test); // Doesn't work
}
Which doesn't work, so I'm wondering if it's possible to do
what I want.
thanks,
lobo
just add the line stdThreadLocalLog.logLevel = LogLevel.info
before logf and it should work. The default LogLevel of the
MultiLogger and FileLogger is high than the default LogLevel of
stdThreadLocalLog. (I will fix that)
std.logger sharedLog usage
Hi,
I'm trying to use std.experimental.logger and I'd like the
logf(), tracef() style functions to log to a file and stdout.
(note: I can use sharedLog.logf(), sharedLog.tracef(), but I
prefer just logf())
So I did this:
shared static this() {
auto ml = new MultiLogger();
ml.insertLogger(stdout, new FileLogger(std.stdio.stdout));
ml.insertLogger(applog, new FileLogger(applog.txt));
sharedLog = ml;
logf(This is a test); // Doesn't work
}
Which doesn't work, so I'm wondering if it's possible to do what
I want.
thanks,
lobo
Re: std.logger sharedLog usage
On Sunday, 29 March 2015 at 01:36:24 UTC, lobo wrote:
Hi,
I'm trying to use std.experimental.logger and I'd like the
logf(), tracef() style functions to log to a file and stdout.
(note: I can use sharedLog.logf(), sharedLog.tracef(), but I
prefer just logf())
So I did this:
shared static this() {
auto ml = new MultiLogger();
ml.insertLogger(stdout, new FileLogger(std.stdio.stdout));
ml.insertLogger(applog, new FileLogger(applog.txt));
sharedLog = ml;
logf(This is a test); // Doesn't work
}
Which doesn't work, so I'm wondering if it's possible to do
what I want.
thanks,
lobo
Hmm, I should read code before posting. logf() etc. are using
stdThreadLocalLog so this does what I want:
shared static this() {
auto ml = new MultiLogger();
ml.insertLogger(stdout, new FileLogger(std.stdio.stdout));
ml.insertLogger(applog, new FileLogger(applog.txt));
stdThreadLocalLog = ml;
logf(This is a test); // works :)
}
Minor nitpick: This isn't clear in the docs of std.logger.
Throughout sharedLog is referred to as the default logger, not
stdThreadLocalLog.
Other than that I'm finding std.logger is really easy to use,
nice work Phobosians!
bye,
lobo
Re: Voting: std.logger
On Friday, 8 August 2014 at 09:16:11 UTC, Robert burner Schadek wrote: could you elaborate please? Currently I use the version statements in two template functions. I'm not sure why one would brand this negatively as a leak into the library. For example we don't reinstatiate templates if they are instantiated in an imported module. But that module might have been compiled with different settings. Thank you for taking the time, but I found several conceptional problems with that POC. The worst being that if I make the LogLevel inside the TestLogger anything other than a enum it fails, as it is used in the template constraint. That would mean the LogLevel is fixed at CT. Well if your test logger only knows it's log level at runtime, then you obviously can do the comparison only at runtime. You can solve this by checking whether minLogLevel is a compile time constant in the log constraints adding another overload for runtime configurable log levels.
Re: Voting: std.logger
Moved to: https://github.com/burner/phobos/pull/2 I did some simple benchmark, logging Hello world 1_000_000 times with the default logger. (DMD with release settings). Comparing the version before the thread-safety changes with the one afterwards. The timings are: 6.67s and 6.66s - so it is -0.15% slower now. :p Yes, I'm just trying to confuse you. Within margin of error the performance stays the same. The default logger is using lockingTextWriter() for optimum performance. I compared it with a logger I wrote a while ago and which I ported to std.experimental.logger.core.Logger, but extends it by honoring the system locale for terminal output: Assuming LC_ALL=de_DE.iso88591 it * formats the message using Phobos' formattedWrite(...) * converts UTF-8 to UTF-16 * passes it to ICU for normalization (to combine accents) * transcodes the NFC UTF-16 with ICU to system local * uses POSIX write() to dump it to the terminal With all the overhead it still takes only 2.26s for the same 1_000_000 messages. If I use a UTF-8 terminal and skip string conversion it will be 2.03s. So on the one hand it means string transcoding accounts for ~10% and on the other that there is 228% overhead with the default logger. :) Some of which might be low hanging fruit. But that should not be part of this review (which is about API). It was just an observation I wanted to share. -- Marco
Re: Voting: std.logger
Am Fri, 19 Sep 2014 15:12:34 + schrieb Robert burner Schadek rburn...@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
Re: Voting: std.logger
On Friday, 19 September 2014 at 11:48:28 UTC, Marco Leise wrote: By the way, does anyone else use std.experimental.logger yet? Dicebot? No, I provide purely management service here, aggregating reviews/opinions of other community members.
Re: Voting: std.logger
Seeing how MultiLogger passes on the payload to its child
loggers by ref, I tried to make it const, so that no Logger
implementation can correct any of the values and spoil it
for the others in the list.
Then I noticed, that isn't possible because the payloads
contain indirections and one logger takes payloads apart into
separate variables (FileLogger) while others build payloads
from separate variables. Catch 22. You cannot have:
protected void beginLogMsg(string file, int line, string funcName,
string prettyFuncName, string moduleName, LogLevel logLevel,
Tid threadId, SysTime timestamp, Logger logger)
@trusted
{
static if (isLoggingActive)
{
header = LogEntry(file, line, funcName, prettyFuncName,
moduleName, logLevel, threadId, timestamp, null, logger);
}
}
and
override void writeLogMsg(const ref LogEntry payload)
{
this.beginLogMsg(payload.file, payload.line, payload.funcName,
payload.prettyFuncName, payload.moduleName, payload.logLevel,
payload.threadId, payload.timestamp, payload.logger);
…
}
.
Also I wonder if Tid is the correct information to pass in.
It is actually just an MBox from std.concurrency. The real
thread handle is the Thread, which also contains its name,
which might be more useful for logging. What do you think?
--
Marco
Re: Voting: std.logger
On Saturday, 20 September 2014 at 10:24:30 UTC, Marco Leise wrote: Also I wonder if Tid is the correct information to pass in. It is actually just an MBox from std.concurrency. The real thread handle is the Thread, which also contains its name, which might be more useful for logging. What do you think? See also https://github.com/D-Programming-Language/phobos/pull/2482 For std.log I think Tid more useful because it clearly denotes execution context while thread ID is more of an implementation detail (considering message-passing is promoted as a standard D thing)
Re: Voting: std.logger
Ok, then here are my thread-safety changes for std.logger: https://github.com/burner/logger/pull/19 -- Marco
Re: Voting: std.logger
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
Re: Voting: std.logger
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.
Re: Voting: std.logger
Am Fri, 19 Sep 2014 09:26:59 + schrieb Robert burner Schadek rburn...@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
Re: Voting: std.logger
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
Re: Voting: std.logger
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.
Re: Voting: std.logger
Am Tue, 16 Sep 2014 21:22:36 +
schrieb Robert burner Schadek rburn...@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 +
schrieb Robert burner Schadek rburn...@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
Re: Voting: std.logger
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?
Re: Voting: std.logger
On 9/9/14, 12:38 PM, Robert burner Schadek wrote: On Saturday, 30 August 2014 at 02:18:30 UTC, Dicebot wrote: ... have noticed that all logging functions have file/line/function data as template parameters. This will create insane symbol bloat. While I can understand desire to use some nicer variadic argument API providing at least one log function that it simplistic but moves all compile-time data to run-time default argument is absolutely necessary for me to consider this viable. I do not consider that a problem. The benefit is much higher than the cost of the bigger binary. This has already been a long conversation on some previous thread. There may be a miscommunication here. In short: void fun(int x, string f = __FILE__)(double y); can be replaced with: void fun(int x)(double y, string f = __FILE__); Both work and the second produces fewer instantiations. Andrei
Re: Voting: std.logger
On Wednesday, 10 September 2014 at 07:41:49 UTC, Andrei Alexandrescu wrote: There may be a miscommunication here. In short: void fun(int x, string f = __FILE__)(double y); can be replaced with: void fun(int x)(double y, string f = __FILE__); Both work and the second produces fewer instantiations. Andrei But void fun(int l = __LINE__, A...)(A...); cannot be replaced by void fun(A...)(A..., int l = __LINE__); anyway thanks for reading and for trying to help
Re: Voting: std.logger
On Wednesday, 10 September 2014 at 08:47:47 UTC, Robert burner Schadek wrote: But void fun(int l = __LINE__, A...)(A...); cannot be replaced by void fun(A...)(A..., int l = __LINE__); anyway thanks for reading and for trying to help And this is why I am asking for separate `logRaw` overload that takes pre-formatted string, for those who care.
Re: Voting: std.logger
On 10/09/14 10:47, Robert burner Schadek wrote: But void fun(int l = __LINE__, A...)(A...); cannot be replaced by void fun(A...)(A..., int l = __LINE__); Could we modify the compiler to allow that? Just for the special identifiers __LINE__, __FILE__ and similar. It wouldn't be possible to specify a value for that parameter then. -- /Jacob Carlborg
Re: Voting: std.logger
On Wednesday, 10 September 2014 at 11:39:52 UTC, Jacob Carlborg wrote: On 10/09/14 10:47, Robert burner Schadek wrote: But void fun(int l = __LINE__, A...)(A...); cannot be replaced by void fun(A...)(A..., int l = __LINE__); Could we modify the compiler to allow that? Just for the special identifiers __LINE__, __FILE__ and similar. It wouldn't be possible to specify a value for that parameter then. IMO that is overkill, adding another another method that only takes one string as parameter is fine here
Re: Voting: std.logger
On Wednesday, 10 September 2014 at 11:39:52 UTC, Jacob Carlborg wrote: On 10/09/14 10:47, Robert burner Schadek wrote: But void fun(int l = __LINE__, A...)(A...); cannot be replaced by void fun(A...)(A..., int l = __LINE__); Could we modify the compiler to allow that? Just for the special identifiers __LINE__, __FILE__ and similar. It wouldn't be possible to specify a value for that parameter then. This is much desired compiler enhancement in my opinion (this template instance bloat is really bad as it impacts not only symbol bloat but also compile times) but trying to get something that works right here and now.
Re: Voting: std.logger
On Wednesday, 10 September 2014 at 12:14:09 UTC, Dicebot wrote: This is much desired compiler enhancement in my opinion (this template instance bloat is really bad as it impacts not only symbol bloat but also compile times) but trying to get something that works right here and now. killing this special overload, once the compiler does this, should be completely transparent
Re: Voting: std.logger
Jacob Carlborg wrote in message news:lupda8$nl1$1...@digitalmars.com... Could we modify the compiler to allow that? Just for the special identifiers __LINE__, __FILE__ and similar. It wouldn't be possible to specify a value for that parameter then. IIRC Andrei has a bugzilla open for this.
Re: Voting: std.logger
On 09/10/2014 03:22 PM, Daniel Murphy wrote:
Jacob Carlborg wrote in message news:lupda8$nl1$1...@digitalmars.com...
Could we modify the compiler to allow that? Just for the special
identifiers __LINE__, __FILE__ and similar. It wouldn't be possible to
specify a value for that parameter then.
IIRC Andrei has a bugzilla open for this.
Why? I cannot remember a compiler version where the following did not work:
import std.stdio;
void fun(A...)(A args, int l = __LINE__){ writeln(args, ,l); }
void main(){ fun(1,2,3); }
I.e. there is absolutely no issue here.
Re: Voting: std.logger
On Wednesday, 10 September 2014 at 15:41:49 UTC, Timon Gehr wrote:
Why? I cannot remember a compiler version where the following
did not work:
import std.stdio;
void fun(A...)(A args, int l = __LINE__){ writeln(args, ,l); }
void main(){ fun(1,2,3); }
I.e. there is absolutely no issue here.
For every instantiation of of fun there will be a new symbol even
when A are the same, because of __LINE__. For Dicebot that is a
nogo
Re: Voting: std.logger
On Wednesday, 10 September 2014 at 15:41:49 UTC, Timon Gehr wrote:
Why? I cannot remember a compiler version where the following
did not work:
import std.stdio;
void fun(A...)(A args, int l = __LINE__){ writeln(args, ,l); }
void main(){ fun(1,2,3); }
I.e. there is absolutely no issue here.
For every instantiation of of fun there will be a new symbol even
when A are the same, because of __LINE__. For Dicebot that is a
nogo
Re: Voting: std.logger
Timon Gehr wrote in message news:luprft$29v6$1...@digitalmars.com...
Why? I cannot remember a compiler version where the following did not
work:
import std.stdio;
void fun(A...)(A args, int l = __LINE__){ writeln(args, ,l); }
void main(){ fun(1,2,3); }
I.e. there is absolutely no issue here.
Hmm, do it does. Maybe I was thinking of this:
https://issues.dlang.org/show_bug.cgi?id=2599
Re: Voting: std.logger
Robert burner Schadek wrote in message
news:wsanssfvnomcwtnqy...@forum.dlang.org...
import std.stdio;
void fun(A...)(A args, int l = __LINE__){ writeln(args, ,l); }
void main(){ fun(1,2,3); }
For every instantiation of of fun there will be a new symbol even when A
are the same, because of __LINE__. For Dicebot that is a nogo
Not in that example there won't.
Re: Voting: std.logger
On 9/10/14, 1:47 AM, Robert burner Schadek wrote:
On Wednesday, 10 September 2014 at 07:41:49 UTC, Andrei Alexandrescu wrote:
There may be a miscommunication here. In short:
void fun(int x, string f = __FILE__)(double y);
can be replaced with:
void fun(int x)(double y, string f = __FILE__);
Both work and the second produces fewer instantiations.
Andrei
But
void fun(int l = __LINE__, A...)(A...); cannot be replaced by
void fun(A...)(A..., int l = __LINE__);
anyway thanks for reading and for trying to help
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 ...
}
Andrei
Re: Voting: std.logger
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.
Re: Voting: std.logger
On Wednesday, 10 September 2014 at 15:41:49 UTC, Timon Gehr wrote:
On 09/10/2014 03:22 PM, Daniel Murphy wrote:
Jacob Carlborg wrote in message
news:lupda8$nl1$1...@digitalmars.com...
Could we modify the compiler to allow that? Just for the
special
identifiers __LINE__, __FILE__ and similar. It wouldn't be
possible to
specify a value for that parameter then.
IIRC Andrei has a bugzilla open for this.
Why? I cannot remember a compiler version where the following
did not work:
import std.stdio;
void fun(A...)(A args, int l = __LINE__){ writeln(args, ,l); }
void main(){ fun(1,2,3); }
I.e. there is absolutely no issue here.
This is new to me - I can definitely remember trying it and
failing ~ 1-2 years ago.
Re: Voting: std.logger
Am 10.09.2014 17:41, schrieb Timon Gehr:
On 09/10/2014 03:22 PM, Daniel Murphy wrote:
Jacob Carlborg wrote in message news:lupda8$nl1$1...@digitalmars.com...
Could we modify the compiler to allow that? Just for the special
identifiers __LINE__, __FILE__ and similar. It wouldn't be possible to
specify a value for that parameter then.
IIRC Andrei has a bugzilla open for this.
Why? I cannot remember a compiler version where the following did not work:
import std.stdio;
void fun(A...)(A args, int l = __LINE__){ writeln(args, ,l); }
void main(){ fun(1,2,3); }
I.e. there is absolutely no issue here.
Except that it unfortunately doesn't do what is intended:
import std.stdio;
void fun(A...)(A args, int l = __LINE__){ writeln(args, ,l); }
void main(){ fun(10,11); }
output:
10 11
expected:
1011 3
Re: Voting: std.logger
On 09/10/2014 08:18 PM, Sönke Ludwig wrote:
Am 10.09.2014 17:41, schrieb Timon Gehr:
On 09/10/2014 03:22 PM, Daniel Murphy wrote:
Jacob Carlborg wrote in message news:lupda8$nl1$1...@digitalmars.com...
Could we modify the compiler to allow that? Just for the special
identifiers __LINE__, __FILE__ and similar. It wouldn't be possible to
specify a value for that parameter then.
IIRC Andrei has a bugzilla open for this.
Why? I cannot remember a compiler version where the following did not
work:
import std.stdio;
void fun(A...)(A args, int l = __LINE__){ writeln(args, ,l); }
void main(){ fun(1,2,3); }
I.e. there is absolutely no issue here.
Except that it unfortunately doesn't do what is intended:
import std.stdio;
void fun(A...)(A args, int l = __LINE__){ writeln(args, ,l); }
void main(){ fun(10,11); }
output:
10 11
expected:
1011 3
Oops! Touché! Thanks. While the code indeed works, there actually _is_
an issue here. :o)
(It is even more embarrassing seeing that I have actually built my own
implementation of IFTI and it actually matches DMD's behaviour in this
case.)
Re: Voting: std.logger
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)
Re: Voting: std.logger
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
Re: Voting: std.logger
On Monday, 8 September 2014 at 22:54:36 UTC, Dicebot wrote: nogc is not possible because of custom toString that won't fix, but for default types it is nogc. It should be possible to provide custom implementation that throws ad Error for those cases (and thus fits the requirements) and `toString` has sink-based overload. Are there any reason why it doesn't help? catching an Exception from formattedWrite just to throw an Error and thus allowing nothrow is just silly IMO. sink-based overloads are nice but we don't write the toString methods of the user and so can not be sure that they are nogc.
Re: Voting: std.logger
On Saturday, 30 August 2014 at 02:18:30 UTC, Dicebot wrote: I have likely missed several points but overall it seem pretty clear to me that all requests / concerns have not been addressed and this proposal is not yet ready for another round of review. I made the stdlog creating thread-safe and on stack. I think that was the last point that was mentioned. Also x-post from GitHub PR of my personal nitpick: ... have noticed that all logging functions have file/line/function data as template parameters. This will create insane symbol bloat. While I can understand desire to use some nicer variadic argument API providing at least one log function that it simplistic but moves all compile-time data to run-time default argument is absolutely necessary for me to consider this viable. I do not consider that a problem. The benefit is much higher than the cost of the bigger binary. This has already been a long conversation on some previous thread.
Re: Voting: std.logger
On Saturday, 6 September 2014 at 19:41:54 UTC, Kevin Lamonte wrote: On Wednesday, 3 September 2014 at 13:13:31 UTC, Ola Fosheim Grøstad wrote: Since we are talking about performance, I did some tests and found to my surprise that ~95% of the time consumed in a log call is Clock.currTime's call to clock_gettime(). I submitted a report for it (https://issues.dlang.org/show_bug.cgi?id=13433), but it also brings up how to expose it in the std.logger API. that is with all likelihood a syscall, so there goes your performance The API automatically grabs thisTid and Clock.currTime during construction of the LogEntry (plus it should also grab Thread.getThis and Fiber.getThis). Should this behavior be modifiable by clients, by subclasses, or neither? If so, how? yes, I will move some of it into beginLogMsg
Re: Voting: std.logger
On Tuesday, 9 September 2014 at 19:38:16 UTC, Robert burner Schadek wrote: Also x-post from GitHub PR of my personal nitpick: ... have noticed that all logging functions have file/line/function data as template parameters. This will create insane symbol bloat. While I can understand desire to use some nicer variadic argument API providing at least one log function that it simplistic but moves all compile-time data to run-time default argument is absolutely necessary for me to consider this viable. I do not consider that a problem. The benefit is much higher than the cost of the bigger binary. This has already been a long conversation on some previous thread. This unfortunately makes it almost unusable in absence of --gc-sections supporting compiler for lower level domains. Probably I am missing some data though, can you link the discussion thread? This PR dicussion is so long now that it hangs my browser when uncollapsing threads :(
Re: Voting: std.logger
On Saturday, 30 August 2014 at 02:11:49 UTC, Dicebot wrote: On Tuesday, 26 August 2014 at 21:04:28 UTC, Robert burner Schadek wrote: Jakob Ovrum The *API* must support minimal dynamic memory allocation for the normal execution path. However, theoretical *implementation* changes that reduce memory allocation are not a deal-breaker. This seems to be addressed but though it is desired to verify it via @nogc unittest block which uses stub no-op logger (to verify that nothing in between allocates). One place were GC allocations is unavoidable is core.d:1628 - it will always create FileLogger first and allow assigning custom one later. Is there any way to circumvent it? API must specify a strong stance on threading, whatever the form it takes Does not seem to be addressed at all. At least I see no mentions of it in core.d documentation and logger instance itself is plain __gshared thing. $ grep -R -n shared std/experimental/logger/ std/experimental/logger/core.d:1625:static __gshared Logger logger; std/experimental/logger/core.d:1635:static __gshared LogLevel ll = LogLevel.all; Does not seem enough for sure. I working on this This one might seem unnecessarily strict, but I think the fact that Logger is a class and not an interface smells of poor design. I might still be convinced that having it as a class is justified, but my current stance is that it must be an interface. Neither does seem to be addressed nor I can find any comment on why it is not going to be addressed. Every Logger has to have a LogLevel, interfaces won't work there Francesco Cattoglio As far as I undestood, there's no way right now to do logging without using the GC. And that means it is currently impossible to log inside destructor calls. That is a blocker in my book. First part partially addressed - missing @nogc @nothrow logger implementation out of the box. Considering this request does not go very well with current language implementation it may be ignored for now but official stance about it must be clearly documented. at least for logf nothrow will not work because of a wrong formatting string or args. log can not be nothrow because custom toString for structs and class are allowed. nogc is not possible because of custom toString that won't fix, but for default types it is nogc. Byron Heads Logger should include a shared Logger, or include it in the interface for outside libraries to handle the implementation. There will be libraries that thread internally and will need to support shared logging. Is not addressed. See Jakob Ovrun
Re: Voting: std.logger
On Saturday, 30 August 2014 at 02:16:55 UTC, Dicebot wrote: == Martin Nowak == Support duck-typing for the log functions. Logger should be a concept and log functions should be free-standing UFCS functions that take any `isLogger!T`. To support a global `defaultLog` variable, you could add a Logger interface and a loggerObject shim. See http://dlang.org/phobos/std_range.html#inputRangeObject for this a pattern. Neither seem to be addressed nor countered. Overly complicated IMO
Re: Voting: std.logger
Am Mon, 08 Sep 2014 11:17:48 + schrieb Robert burner Schadek rburn...@gmail.com: On Saturday, 30 August 2014 at 02:16:55 UTC, Dicebot wrote: == Martin Nowak == Support duck-typing for the log functions. Logger should be a concept and log functions should be free-standing UFCS functions that take any `isLogger!T`. To support a global `defaultLog` variable, you could add a Logger interface and a loggerObject shim. See http://dlang.org/phobos/std_range.html#inputRangeObject for this a pattern. Neither seem to be addressed nor countered. Overly complicated IMO This may sound surprising, but I believe if we want to make Phobos consistent and give no incentive to roll your own stuff, we should do this for a lot of APIs. Without going into depth (but we could) there are good reasons to use classes and there are good reasons to use duck typing structs. Another API where this mixed scheme would apply are streams. By using function templates with `if (isLogger!T)` and an abstract class Logger, it will only get instantiated once for all derived classes reducing template bloat, while allowing custom instantiations for logger structs to avoid virtual function calls or GC issues. So I agree with Martin. It is a great way to bring the two camps together without major casualties. -- Marco
Re: Voting: std.logger
Am Mon, 08 Sep 2014 11:06:42 + schrieb Robert burner Schadek rburn...@gmail.com: Francesco Cattoglio As far as I undestood, there's no way right now to do logging without using the GC. And that means it is currently impossible to log inside destructor calls. That is a blocker in my book. First part partially addressed - missing @nogc @nothrow logger implementation out of the box. […] at least for logf nothrow will not work because of a wrong formatting string or args. log can not be nothrow because custom toString for structs and class are allowed. nogc is not possible because of custom toString that won't fix, but for default types it is nogc. It is fairly obvious that the next GC implementation needs to allow allocations during a sweep. Maybe we should just assume that it already works ? -- Marco
Re: Voting: std.logger
On Monday, 8 September 2014 at 12:36:29 UTC, Marco Leise wrote: This may sound surprising, but I believe if we want to make Phobos consistent and give no incentive to roll your own stuff, we should do this for a lot of APIs. Without going into depth (but we could) there are good reasons to use classes and there are good reasons to use duck typing structs. Another API where this mixed scheme would apply are streams. By using function templates with `if (isLogger!T)` and an abstract class Logger, it will only get instantiated once for all derived classes reducing template bloat, while allowing custom instantiations for logger structs to avoid virtual function calls or GC issues. So I agree with Martin. It is a great way to bring the two camps together without major casualties. I think the template bloat argument is invalid as __LINE__ and friends are passed as template arguments to allow write and writef type logging. Anyway I will try to make them free standing
Re: Voting: std.logger
On Monday, 8 September 2014 at 13:20:27 UTC, Robert burner
Schadek wrote:
On Monday, 8 September 2014 at 12:36:29 UTC, Marco Leise wrote:
I think the template bloat argument is invalid as __LINE__ and
friends are passed as template arguments to allow write and
writef type logging.
Anyway I will try to make them free standing
The biggest problem I have currently with this that you, or at
least I, can not override the free standing function.
void log(L)(ref L logger) if(isLogger!L) { ... } will match always
and if I create void log(L)(ref L logger) if(isMySpecialLogger!L)
{ ... }
both match and thats a nogo
Re: Voting: std.logger
Am Mon, 08 Sep 2014 13:37:02 +
schrieb Robert burner Schadek rburn...@gmail.com:
On Monday, 8 September 2014 at 13:20:27 UTC, Robert burner
Schadek wrote:
On Monday, 8 September 2014 at 12:36:29 UTC, Marco Leise wrote:
I think the template bloat argument is invalid as __LINE__ and
friends are passed as template arguments to allow write and
writef type logging.
You are right, this benefit of classes doesn't apply here.
Anyway I will try to make them free standing
The biggest problem I have currently with this that you, or at
least I, can not override the free standing function.
void log(L)(ref L logger) if(isLogger!L) { ... } will match always
and if I create void log(L)(ref L logger) if(isMySpecialLogger!L)
{ ... }
both match and thats a nogo
Ok, no matter what the outcome is, I'll see if I can write a
simple file logger that I can use in RAII struct dtors (where
neither allocations nor throwing seem to be an issue) and that
has a fallback to writing to stderr. I wrote earlier that I
would want a fallback logger if writing via the network fails
or the disk is full, but maybe this logic can be implemented
inside a logger implementation. I haven't actually tried your
API yet!
--
Marco
Re: Voting: std.logger
On Monday, 8 September 2014 at 14:49:06 UTC, Marco Leise wrote: Ok, no matter what the outcome is, I'll see if I can write a simple file logger that I can use in RAII struct dtors (where neither allocations nor throwing seem to be an issue) and that has a fallback to writing to stderr. I wrote earlier that I would want a fallback logger if writing via the network fails or the disk is full, but maybe this logic can be implemented inside a logger implementation. I haven't actually tried your API yet! That should be a no-brainer just have a look at FileLogger and start from there
Re: Voting: std.logger
On Wednesday, 3 September 2014 at 03:05:42 UTC, Kevin Lamonte
wrote:
On Tuesday, 2 September 2014 at 14:53:17 UTC, Dicebot wrote:
This is exactly what I call theoretical speculations. Please
provide specific list like this:
1) some method signature needs to be changed
I propose the following API changes (+ changes on default
implementation):
protected LogEntry beginLogMsg(string file, int line,
string funcName,
string prettyFuncName, string moduleName, LogLevel
logLevel,
Tid threadId, SysTime timestamp, Logger logger)
@trusted
{
static if (isLoggingActive())
{
return LogEntry(file, line, funcName,
prettyFuncName,
moduleName, logLevel, threadId, timestamp,
null, logger);
}
}
/** Logs a part of the log message. */
protected void logMsgPart(MsgRange msgAppender,
const(char)[] msg)
{
static if (isLoggingActive())
{
msgAppender.put(msg);
}
}
/** Signals that the message has been written and no more
calls to
$(D logMsgPart) follow. */
protected void finishLogMsg(ref LogEntry entry, MsgRange
msgAppender)
{
static if (isLoggingActive())
{
entry.msg = msgAppender.data;
this.writeLogMsg(entry);
}
}
...with the corresponding changes to logImpl/logImplf to create
msgAppender as a local function variable, and the elimination
of header and msgAppender as Logger class variables.
The benefit to this change is that Logger (including stdlog)
becomes thread-safe, as well as any subclass of Logger that
only implements writeLogMsg().
The only problem with that change is that it will always require
a buffer. FileLogger currently doesn't require a buffer and is
already thread-safe.
stdlog will not be thread-safe by default by this change only
syncing the writeLogMsg function will.
Re: Voting: std.logger
On Monday, 8 September 2014 at 11:06:44 UTC, Robert burner Schadek wrote: First part partially addressed - missing @nogc @nothrow logger implementation out of the box. Considering this request does not go very well with current language implementation it may be ignored for now but official stance about it must be clearly documented. at least for logf nothrow will not work because of a wrong formatting string or args. log can not be nothrow because custom toString for structs and class are allowed. nogc is not possible because of custom toString that won't fix, but for default types it is nogc. It should be possible to provide custom implementation that throws ad Error for those cases (and thus fits the requirements) and `toString` has sink-based overload. Are there any reason why it doesn't help?
Re: Voting: std.logger
On Wednesday, 3 September 2014 at 13:13:31 UTC, Ola Fosheim Grøstad wrote: If you accept slightly out of sync logging then you can have thread local buffers and on x86 use the command RDTSC which gives you a (good enough) timer value so you can merge the buffers from threads later. It takes roughly 20-30 cycles which I presume is better than CAS instructions, or you can just write directly to a global counter without CAS and accept that it jitters? Since we are talking about performance, I did some tests and found to my surprise that ~95% of the time consumed in a log call is Clock.currTime's call to clock_gettime(). I submitted a report for it (https://issues.dlang.org/show_bug.cgi?id=13433), but it also brings up how to expose it in the std.logger API. The API automatically grabs thisTid and Clock.currTime during construction of the LogEntry (plus it should also grab Thread.getThis and Fiber.getThis). Should this behavior be modifiable by clients, by subclasses, or neither? If so, how?
Re: Voting: std.logger
On Saturday, 6 September 2014 at 19:41:54 UTC, Kevin Lamonte wrote: The API automatically grabs thisTid and Clock.currTime during construction of the LogEntry (plus it should also grab Thread.getThis and Fiber.getThis). Should this behavior be modifiable by clients, by subclasses, or neither? If so, how? I think maybe we should start with creating a high performance inlined (for ldc/gdc) in-memory multi-threaded binary reference logger and then extend the interface in ways that does not make it noticeably slower using the reference logger as the baseline. (Noticeably 100%?) When logging to an external logging service you might want the logging service do the time-keeping so you don't get merged logs from multiple servers that are out of sync. In that case collecting absolute time locally is kinda pointless (although you might want to submit serial numbers and relative time between logging events from the same server).
Re: Voting: std.logger
On Tuesday, 2 September 2014 at 15:10:35 UTC, Ola Fosheim Grøstad wrote: On Tuesday, 2 September 2014 at 14:53:17 UTC, Dicebot wrote: If you are going to speak more about abstract performance I am going to simply ignore any of your further posts on topic. I am not abstract. These are very concrete requirements: 1. You have to be able to determine types and formatting at compile time otherwise you cannot do binary logging. 2. You have to be able to determine types and formatting at compile time otherwise you cannot minimize the probability of introducing run-time errors by turning on full logging. Ok, this is much more specific. With a similar concerns in mind I have proposed to add a `log` overload that doesn't have variadic arguments and takes a single pre-formatted string (with file/line/module as default run-time arguments). With a custom formatting function (compile-time or run-time at users choice) it should fit these requirements. Does that sounds feasible to you?
Re: Voting: std.logger
On Friday, 5 September 2014 at 18:24:01 UTC, Dicebot wrote: Ok, this is much more specific. With a similar concerns in mind I have proposed to add a `log` overload that doesn't have variadic arguments and takes a single pre-formatted string (with file/line/module as default run-time arguments). With a custom formatting function (compile-time or run-time at users choice) it should fit these requirements. Does that sounds feasible to you? P.S. Reason why compile-time format checking can't be added to base API is rather simple - it needs to be at least somewhat similar to one of writefln
Re: Voting: std.logger
On Friday, 5 September 2014 at 18:27:12 UTC, Dicebot wrote: P.S. Reason why compile-time format checking can't be added to base API is rather simple - it needs to be at least somewhat similar to one of writefln Hm. My experience with Python for server use tells me that the problem with dynamic languages isn't the primarily the main execution paths, but the exceptional ones. Having to update a server because a request erroneously fails due to a logging statement (or typos in asserts or any other kind of debugging statement) is annoying. Upon further reflection I think it is important to require logging to be a fail-safe transparent operation (conceptually close to an annotation). I don't think monitoring statements should be able to cause runtime errors at all.
Re: Voting: std.logger
On Wednesday, 3 September 2014 at 22:34:30 UTC, Kevin Lamonte wrote: Sounds like a candidate for an attribute, just prefix a function or function call with @trace(level)? I've got a feature request in for just that: https://issues.dlang.org/show_bug.cgi?id=13406 While thinking about it I realize that it's actually very easy to generalize @trace into the equivalent of Common Lisp :before, :after, and :around methods: @scope(scopeFn) . (It would work even better if scope(success) and scope(failure) exposed what they are returning/throwing.) In the meantime Log4D has a (barely tested) mixin. This can already be implemented in a library if mixin of an implementation idiom is used. I think it fits D style better (having attributes modify actual code flow is unprecedented)
Re: Voting: std.logger
On Tuesday, 2 September 2014 at 10:14:27 UTC, Ola Fosheim Grøstad
wrote:
On Tuesday, 2 September 2014 at 06:24:45 UTC, Kevin Lamonte
wrote:
I see a difference between signalling state, tracing execution
and logging state. I guess one roughly can say that:
- signalling is for coordination of subsystems
- logging state is for tracking effects on the database
- tracing is for detecting logic failure after a crash
I've written my own ideas about logging vs tracing over at
https://github.com/klamonte/log4d/docs/philosophy.md . In a
nutshell, logging means the engineered messages targeting
non-developers that are part of the application deliverable and
follow the narrative flow, while tracing is the automated
messages targeting the developers that follow the structural flow.
std.logger provides an acceptable interface for logging and an
absolute minimal interface to tracing, with just the single
LogLevel.trace and trace/tracef functions. Most other systems
provide at least two (debug+trace) or three (fine/finer/finest)
levels between INFO and everything, and some provide
log.entering()/log.exiting() functions that could provide for
what you are describing.
Sounds interesting. I'll have a look at log4d later. But it is
not fully typesafe then? The way I see it you should log a
tuple of values and a reference to a type-safe formatting
expression, but only apply the formatting expression when you
need to so you don't burden the performance thread with
unnecessary work.
Well, sort of. It's not CTFE-like typesafe where the compiler
catches it, but it also isn't possible (AFAIK) to get it wrong
either. PatternLayout's format specifiers don't perform
conversions on client-controlled input, they are straight
substitutions of the LogEntry fields (+ some extras) into the
final emitted string.
It sounds like what you would like is a trace function that
doesn't feature a format string at all, but formatting would
instead be applied at I/O time by a Logger subclass. How about
this?
1. Add a fnArgs field of type Object [] to LogEntry
2, Add something like the following:
void traceFn(int line = __LINE__,
string file = __FILE__, string funcName = __FUNCTION__,
string prettyFuncName = __PRETTY_FUNCTION__,
string moduleName = __MODULE__)(lazy Object [] fnArgs)
@trusted
{
static if (isLoggingActive!LogLevel.trace)
{
if (isLoggingEnabled(LogLevel.trace)
ll = stdlog.logLevel
stdlog.logLevel = globalLogLevel
globalLogLevel != LogLevel.off
stdlog.logLevel != LogLevel.off)
{
auto entry = LogEntry(file, line, funcName,
prettyFuncName,
moduleName, LogLevel.trace, thisTid,
Clock.currTime, null, this, fnArgs);
this.writeLogMsg(entry);
}
}
}
This could also be split into traceFnEnter, traceFnExitSuccess,
and traceFnExitFailure with LogEntry.args set to indicate which
one (, , ! for example) and a mixin provided so that
client code could get it all in a one-liner.
If this would meet your needs, I wouldn't mind it myself. Save
log.trace() for generic messages the developer want to see
between the traceFnEnter/traceFnExitX messages.
Re: Voting: std.logger
Another API change: LogEntry must have a Thread reference, either in addition to or in replacement of the Tid reference it has currently.
Re: Voting: std.logger
On Wednesday, 3 September 2014 at 11:39:59 UTC, Kevin Lamonte wrote: I've written my own ideas about logging vs tracing over at https://github.com/klamonte/log4d/docs/philosophy.md Nice writeup! It is kind of interesting that there are so many different takes on a mundane task such as logging, monitoring, debug-tracing etc. Reminds me of reflections on how many types of NULL you need to cover all the different semantics that NULL can express (was it 5 or 6?). It sounds like what you would like is a trace function that doesn't feature a format string at all, but formatting would instead be applied at I/O time by a Logger subclass. Yes, either that or no formatting at all. If all formatting strings are literals and resolve at compile time then you can extract them from the source and create a big compile time map that convert them into numeric values at compile time and convert the types into numeric values as well. If the API supports full compile time reflection that should be a possibility. High performance logging should just be a series of MOV instructions or SSE equivalents that completes in ~8-40 cycles for a circular buffer with 2^N size. With increasing availability of memory on cloud servers this becomes more and more attractive IMO (you can log a lot in 50MB) It important is that you exploit the fact that the values are already in registers because you usually log values that have recently been computed and that you spend a minimal amount of execution time on registering them, perhaps even writing directly to full memory cache lines to avoid cache pollution (using special SSE commands). If you accept slightly out of sync logging then you can have thread local buffers and on x86 use the command RDTSC which gives you a (good enough) timer value so you can merge the buffers from threads later. It takes roughly 20-30 cycles which I presume is better than CAS instructions, or you can just write directly to a global counter without CAS and accept that it jitters? I personally don't care about enter/exit so much. I care about: 1. tracking the state of the system configuration at the point of failure 2. the paths of execution before the incident 3. the events that led up to it (in order to reproduce the failure). This could also be split into traceFnEnter, traceFnExitSuccess, and traceFnExitFailure with LogEntry.args set to indicate which one (, , ! for example) and a mixin provided so that client code could get it all in a one-liner. Sounds like a candidate for an attribute, just prefix a function or function call with @trace(level)?
Re: Voting: std.logger
On Wednesday, 3 September 2014 at 13:13:31 UTC, Ola Fosheim Grøstad wrote: On Wednesday, 3 September 2014 at 11:39:59 UTC, Kevin Lamonte wrote: This could also be split into traceFnEnter, traceFnExitSuccess, and traceFnExitFailure with LogEntry.args set to indicate which one (, , ! for example) and a mixin provided so that client code could get it all in a one-liner. Sounds like a candidate for an attribute, just prefix a function or function call with @trace(level)? I've got a feature request in for just that: https://issues.dlang.org/show_bug.cgi?id=13406 While thinking about it I realize that it's actually very easy to generalize @trace into the equivalent of Common Lisp :before, :after, and :around methods: @scope(scopeFn) . (It would work even better if scope(success) and scope(failure) exposed what they are returning/throwing.) In the meantime Log4D has a (barely tested) mixin.
Re: Voting: std.logger
On Wednesday, 3 September 2014 at 22:34:30 UTC, Kevin Lamonte wrote: I've got a feature request in for just that: https://issues.dlang.org/show_bug.cgi?id=13406 Interesting! I am not 100% convinced that scope(failure/success) is the way to go since it will cause potentially a lot of extra work when unwinding the stack in case of an exception? Or maybe the stack unwinder could to the tracing directly without using the scope construct. Another option would be to only trace the landing-pad (catch statement) for exceptions, so you would get something like exception X caught in functionname(), but not sure how to do it without loosing information. You might need a counter for each enter/exit or something like that and let the stack-unwinder count down.
Re: Voting: std.logger
On Thursday, 4 September 2014 at 04:53:36 UTC, Ola Fosheim Grøstad wrote: You might need a counter for each enter/exit or something like that and let the stack-unwinder count down. I meant: you might need to increment a stack specific counter, but that does not sound practical. I guess it is better to have a more complex stack unwinder. Co-routines create some problems here. You probably need to trace that they yield.
Re: Voting: std.logger
On Monday, 1 September 2014 at 10:43:34 UTC, Ola Fosheim Grøstad wrote: I guess the most robust solution is to use shared memory and fork, when the child dies you soup up the log and upload it to a logging-server. I'm used to a centralized system taking logs on a continuous basis, with normal, I'm happy messages coming through in a regular interval. When the application dies, it already has had its messages emitted and sucked up by the collection system, and if its heartbeat messages aren't seen then people are prompted to investigate anyway. It's on the main server (e.g. syslog or LogStash) to handle storage space issues like log rotation. I am also interested in lazy formatting, meaning you log a reference to the immutable formatting string and the parameters, but wait with the formatting until the result is needed. log4d does this, it saves the Logger+LogEntry references and only applies PatternLayouts at the end, BUT it does so with the risk that additional fields specified in the conversionPattern might be wrong since they were not generated/evaluated in the context of the original log call. Thread ID (%t) is the main culprit (since it is not in LogEntry, PatternLayout has to get it), but also time between log calls and time since application startup (%r/%R). But it sounds like you want std.logger to not apply formatting even in its infof/errorf/etc functions. That might be a problem for things like the number of rows in a result set, the current time, or the remote system hostname. For example, by the time the logging infrastructure evaluates the number of rows, the result set is long gone and could throw an exception. I would argue that this kind of lazy evaluation would be fine if it was not enabled by default.
Re: Voting: std.logger
On Monday, 1 September 2014 at 18:57:25 UTC, Ola Fosheim Grøstad wrote: On Monday, 1 September 2014 at 16:52:16 UTC, Dicebot wrote: You are totally misunderstanding goals of std.logger - people as _expected_ to roll their own Loggers. std.logger is here only to provide standard API for those to integrate with each other and few trivial common implementation as examples. Rest is dub business. Oh, I understand the intentions perfectly well, but the default should be performant, multithreaded, and cover the most common use scenario. +1 While its useful for the standard library to provide stubs, these mean very little without a default implementation. And the latter shall be quite generic to cover most of the use cases. Rolling one's own loggers shall be done only if the world is not enough.
Re: Voting: std.logger
On Tuesday, 2 September 2014 at 06:53:30 UTC, eles wrote: Oh, I understand the intentions perfectly well, but the default should be performant, multithreaded, and cover the most common use scenario. +1 While its useful for the standard library to provide stubs, these mean very little without a default implementation. And the latter shall be quite generic to cover most of the use cases. Rolling one's own loggers shall be done only if the world is not enough. I disagree and it was declared among goals of this module from the very beginning that it won't go that way, won't even attempt to do it. If you have some good ideas about better default implementation - make pull request after it is merged into std.experimental. Right now it is not in the scope of the review and I will simply ignore all comments that are related purely to implementation. However, if there any API issues that will likely block the implementation you want - those are very important to hear about. This is #1 priority right now.
Re: Voting: std.logger
On Tuesday, 2 September 2014 at 06:24:45 UTC, Kevin Lamonte wrote: I'm used to a centralized system taking logs on a continuous basis, with normal, I'm happy messages coming through in a regular interval. When the application dies, it already has had its messages emitted and sucked up by the collection system, and if its heartbeat messages aren't seen then people are prompted to investigate anyway. It's on the main server (e.g. syslog or LogStash) to handle storage space issues like log rotation. Yes, I think we are discussing many different things at the same time here and it would be a good idea to sort out the different use cases since that affects functionality. I have not thought about heartbeats/keep-alive etc as logging, but it is reasonable to view them as such. I see a difference between signalling state, tracing execution and logging state. I guess one roughly can say that: - signalling is for coordination of subsystems - logging state is for tracking effects on the database - tracing is for detecting logic failure after a crash ? log4d does this, it saves the Logger+LogEntry references and only applies PatternLayouts at the end, BUT it does so with the risk that additional fields specified in the conversionPattern might be wrong since they were not generated/evaluated in the context of the original log call. Thread ID (%t) is the main culprit (since it is not in LogEntry, PatternLayout has to get it), but also time between log calls and time since application startup (%r/%R). Sounds interesting. I'll have a look at log4d later. But it is not fully typesafe then? The way I see it you should log a tuple of values and a reference to a type-safe formatting expression, but only apply the formatting expression when you need to so you don't burden the performance thread with unnecessary work. But it sounds like you want std.logger to not apply formatting even in its infof/errorf/etc functions. That might be a problem for things like the number of rows in a result set, the current time, or the remote system hostname. For example, by the time the logging infrastructure evaluates the number of rows, the result set is long gone and could throw an exception. I think you should log the values as a tuple, but not do the string-conversion, but it is more important for tracing execution than for logging. I guess formatting high level info/error is acceptable, but for tracing I am only interested in very terse value/type info along with an indicator of context. Performance and trouble-free type safe logging is much more important than nice formatting IMO. Traced execution will primarily be used for log analysis after a crash. You can use this on game clients, game servers, web servers etc… E.g.: log configuration + trace last 5 events - crash - compress and upload for analysis.
Re: Voting: std.logger
On Tuesday, 2 September 2014 at 07:10:29 UTC, Dicebot wrote: into std.experimental. Right now it is not in the scope of the review and I will simply ignore all comments that are related purely to implementation. Configuration of logging is part of the API. Conversion of objects to log info affects the API. The API affects performance. You need to design the API with a reference model in mind. Without it the API has no value. That's why you need a reference implementation in order to evaluate the API design. However, if there any API issues that will likely block the implementation you want - those are very important to hear about. This is #1 priority right now. I am concerned about performance, formatting and type safety. You need to: 1. define the use cases you want to cover 2. list the requirements 3. define a model Only then does it make sense to define the API. If D is to have the upper hand as a system level language then the logging must be performant. For performant logging you might not want to do string-formatting at all in the engine you are monitoring.
Re: Voting: std.logger
On Tuesday, 2 September 2014 at 10:25:03 UTC, Ola Fosheim Grøstad wrote: However, if there any API issues that will likely block the implementation you want - those are very important to hear about. This is #1 priority right now. I am concerned about performance, formatting and type safety. You need to: 1. define the use cases you want to cover 2. list the requirements 3. define a model Only then does it make sense to define the API. If D is to have the upper hand as a system level language then the logging must be performant. For performant logging you might not want to do string-formatting at all in the engine you are monitoring. Sorry but it doesn't work that way. If you are concerned about those cases it is you who must do necessary research and provided specific list of requirements / changes. No one else is going to do it. While your raise important concerns it doesn't have any practical application right now and I can't use it in any way as part of review process. We need details (see the responses of other voters). Pure theoretical speculations won't help.
Re: Voting: std.logger
On Tuesday, 2 September 2014 at 13:08:02 UTC, Dicebot wrote: While your raise important concerns it doesn't have any practical application right now and I can't use it in any way as part of review process. We need details (see the responses of other voters). Pure theoretical speculations won't help. Uhm, it isn't theoretical. A low performance string based stdio-logger is not useful in a high performance server where you have short spikes with idle time between the spikes. A coarse grained logger logs state on the application level and I don't need library support for that since it only happens in a handful of locations that I control myself. A fine grained logger logs state on the framework/library level and I don't want to use a logger that spends time on turning ints into strings when it is supposed to be handling requests and sits idle a few milliseconds later. The phobos design lacks a performance oriented focus and si too scripty for a system level langauge. You need benchmarking from the get go. Performance does not happen later as a QoI issue because performance depends on the model the API implies. Fine grained logging must be performant.
Re: Voting: std.logger
On Tuesday, 2 September 2014 at 13:58:24 UTC, Ola Fosheim Grøstad wrote: On Tuesday, 2 September 2014 at 13:08:02 UTC, Dicebot wrote: While your raise important concerns it doesn't have any practical application right now and I can't use it in any way as part of review process. We need details (see the responses of other voters). Pure theoretical speculations won't help. Uhm, it isn't theoretical. A low performance string based stdio-logger is not useful in a high performance server where you have short spikes with idle time between the spikes. A coarse grained logger logs state on the application level and I don't need library support for that since it only happens in a handful of locations that I control myself. A fine grained logger logs state on the framework/library level and I don't want to use a logger that spends time on turning ints into strings when it is supposed to be handling requests and sits idle a few milliseconds later. The phobos design lacks a performance oriented focus and si too scripty for a system level langauge. You need benchmarking from the get go. Performance does not happen later as a QoI issue because performance depends on the model the API implies. Fine grained logging must be performant. This is exactly what I call theoretical speculations. Please provide specific list like this: 1) some method signature needs to be changed 2) design decision that makes GC allocation unavoidable for specific use case 3) example logger implementation that doesn't fit into existing API (show how) If you are going to speak more about abstract performance I am going to simply ignore any of your further posts on topic. Sorry but there is no other way.
Re: Voting: std.logger
On Tuesday, 2 September 2014 at 14:53:17 UTC, Dicebot wrote: If you are going to speak more about abstract performance I am going to simply ignore any of your further posts on topic. I am not abstract. These are very concrete requirements: 1. You have to be able to determine types and formatting at compile time otherwise you cannot do binary logging. 2. You have to be able to determine types and formatting at compile time otherwise you cannot minimize the probability of introducing run-time errors by turning on full logging. This is very important use scenarios: * Performant fine grained logging (as close to zero overhead as you get) in libraries and frameworks is essential for fixing cloud-based servers where you typically cannot use regular strategies. I don't control frameworks, so it is important that they use standard lib logging. * Performant fine grained logging (as close to zero overhead as you get) in client side frameworks is essential for fixing online game clients that runs on heterogenous hardware since you don't get to run a debugger on all configurations. I don't know enough about what the limitations for advanced compile time reflection is, but it has been claimed in this thread that the current design does not make it possible to establish this at compile time. Then I have to conclude that the current design cannot be safe enough or performant enough to be useful in libraries and frameworks and give D an advantage in the server-market... Risks: 1. If D libraries and frameworks starts using and under-performing logger because it is the official D logger library, then you cannot ship products with fine grained logging based on these framworks. This is a lost opportunity. 2. If phobos includes under-performing libraries then you risk having a new split and have two standard libraries and/or two incompatible logging frameworks.
Re: Voting: std.logger
On Tuesday, 2 September 2014 at 14:53:17 UTC, Dicebot wrote:
This is exactly what I call theoretical speculations. Please
provide specific list like this:
1) some method signature needs to be changed
I propose the following API changes (+ changes on default
implementation):
protected LogEntry beginLogMsg(string file, int line, string
funcName,
string prettyFuncName, string moduleName, LogLevel
logLevel,
Tid threadId, SysTime timestamp, Logger logger)
@trusted
{
static if (isLoggingActive())
{
return LogEntry(file, line, funcName, prettyFuncName,
moduleName, logLevel, threadId, timestamp, null,
logger);
}
}
/** Logs a part of the log message. */
protected void logMsgPart(MsgRange msgAppender, const(char)[]
msg)
{
static if (isLoggingActive())
{
msgAppender.put(msg);
}
}
/** Signals that the message has been written and no more
calls to
$(D logMsgPart) follow. */
protected void finishLogMsg(ref LogEntry entry, MsgRange
msgAppender)
{
static if (isLoggingActive())
{
entry.msg = msgAppender.data;
this.writeLogMsg(entry);
}
}
...with the corresponding changes to logImpl/logImplf to create
msgAppender as a local function variable, and the elimination of
header and msgAppender as Logger class variables.
The benefit to this change is that Logger (including stdlog)
becomes thread-safe, as well as any subclass of Logger that only
implements writeLogMsg().
Re: Voting: std.logger
On Monday, 1 September 2014 at 04:32:42 UTC, Kevin Lamonte wrote: Does this logger already exist, could I take a look at it? Not in D AFAIK, circular in-memory logging is a common technique for fixing servers though. If not, if someone writes an appender for writing to the database, you could accomplish this goal with log4d using a buffer appender that triggers on fatal. I guess the most robust solution is to use shared memory and fork, when the child dies you soup up the log and upload it to a logging-server. I am also interested in lazy formatting, meaning you log a reference to the immutable formatting string and the parameters, but wait with the formatting until the result is needed.
Re: Voting: std.logger
On Sunday, 31 August 2014 at 01:09:33 UTC, Ola Fosheim Grøstad wrote: I've got some questions: How does logging interact with pure? You need to be able to log in pure functions. Weakly pure function can take logger as an argument (so I doubt it is useful in practice). Strongly pure functions can't be logged in non-debug statement pretty much by D definition of purity. This may be or may not be an issue but is definitely goes out of the scope of this Phobos proposal. If you have any specific ideas how to address it, please create a separate thread. Does the logger implementation flush() in the case of a crash? (Does it trap all crashes in a way that ensures that logging buffers are written to disk?) Current implementations use basic std.stdio facilities and those flush upon writing a newline symbol - flush happens after each log call. More efficient buffered implementation can be provided later, this shouldn't affect the API. Is logf() needed? Can't you somehow detect that the string is an immutable string literal with string formatting characters? Unreliable, not KISS. I think it is a bad idea.
Re: Voting: std.logger
On Monday, 1 September 2014 at 16:30:46 UTC, Dicebot wrote: purity. This may be or may not be an issue but is definitely goes out of the scope of this Phobos proposal. If you have any […] Current implementations use basic std.stdio facilities and those flush upon writing a newline symbol - flush happens after each log call. More efficient buffered implementation can be provided later, this shouldn't affect the API. […] Unreliable, not KISS. I think it is a bad idea. If the standard library does not provide the following from the get go: 1. general usefulness 2. performance 3. KISS in terms of interface (not in language semantics) then people will be better off rolling their own. Creating a simple logger is not difficult, the challenge is in creating a performant, generally useful one with legible syntax and full CT type safety.
Re: Voting: std.logger
On Monday, 1 September 2014 at 16:52:16 UTC, Dicebot wrote: You are totally misunderstanding goals of std.logger - people as _expected_ to roll their own Loggers. std.logger is here *are expected
Re: Voting: std.logger
On Monday, 1 September 2014 at 16:45:29 UTC, Ola Fosheim Grøstad wrote: If the standard library does not provide the following from the get go: 1. general usefulness 2. performance 3. KISS in terms of interface (not in language semantics) then people will be better off rolling their own. Creating a simple logger is not difficult, the challenge is in creating a performant, generally useful one with legible syntax and full CT type safety. You are totally misunderstanding goals of std.logger - people as _expected_ to roll their own Loggers. std.logger is here only to provide standard API for those to integrate with each other and few trivial common implementation as examples. Rest is dub business. And no, magic identification of format string is neither language KISS nor interface KISS.
