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.

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.

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.

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.

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.

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().

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.

Another API change:  LogEntry must have a Thread reference, either in addition to or in replacement of the Tid reference it has currently.

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)?

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.