Hacker News Board Hacker News, browsed like a classic message board
Live data from Hacker News

NanoLog – a nanosecond scale logging system for C++

github.com

Post reply on HN
Print view View original

11–20 of 67 posts

Re: NanoLog – a nanosecond scale logging system for C++

#11

Post by liuliu »

gmueckl wrote: post #10

I built a similar system with a focus on profiling events with extremely low overhead. When taking an timestamp, the processor cycle count register is read, and pushed into a ring buffer with a tiny descriotion including a static string label. A background thread perodically writes that buffer contents to disk. An offline tool visualizes the recorded events and intervals over time and can do a bit of statistics. This…

We use custom format and an offline process to transform the format into Google Catapult for visualization. Catapult visualization for 30s trace should be pretty reasonable.

Re: NanoLog – a nanosecond scale logging system for C++

#13

Post by holy_city »

muststopmyths wrote: post #3

I spent a lot of time trying to build a fast logging system in my last couple of jobs. The basic lesson (and I'm only talking about C/C++/C# here) is that you will spend most of your time formatting strings if you do your file I/O asynchronously. Since this system has a preprocessor mode, I assume they learnt the same lesson. The bigger lesson is that it really doesn't matter how many millions of logs you can generat…

I've dealt with this problem too, mostly in trying to log/debug real-time media processing where a log trace equivalent would be long chunks of floating point data at multiple trace points in the data flow.

I came to the same conclusion. Raw bandwidth to your logging endpoint is meaningless when you start dealing with big chunks of information, which is common sense I guess. You need a fast way to digest it into whatever format works for the person reading the log later, and it's tough to make it abstract since how data is interpretted can be quite varied even in the same application.

Re: NanoLog – a nanosecond scale logging system for C++

#14

Post by rafa1981 »

bt848 wrote: post #2

Looks interesting but how does one reproduce the comparative benchmarks from the paper? I see the code that benchmarks nanolog but how do I reproduce the baseline for glog?

Author of mini-async-log and its C variant here.

Some time ago I wrote a benchmark for different loggers, but it uses an old version of Nanolog.

https://github.com/RafaGago/logger-bench

Re: NanoLog – a nanosecond scale logging system for C++

#15

Post by MauranKilom »

Iwan-Zotow wrote: post #8
MauranKilom wrote: post #5

The code overall is pretty clever, but at the core of all this they completely ignore strict aliasing to dump stuff into a char* buffer indiscriminately... Look at this function: https://github.com/PlatformLab/NanoLog/blob/master/runtime/N... T argument = *reinterpret_cast (*in); ... uint32_t stringBytes = *reinterpret_cast (*in); A total of 6 reinterpret_casts in that file alone. I didn't see any indication that you…

char* is universal memory format, you could specialize from that into anything you want

That's not how the C++ object model works. Objects in C++ have clearly defined lifetimes. If you reinterpret_cast(someCharBuffer) and then dereference that, you have Undefined Behavior unless an int object is alive at that exact location.

You can do

    int value[2] = {0, 0};
    char* ptr = reinterpret_cast(value) + sizeof(int);
    (*reinterpret_cast(ptr))++;
or (given knowledge about compiler padding):

    struct XY { double x; int y; };
    XY xy = {};
    char* ptr = reinterpret_cast(&xy) + sizeof(double);
    (*reinterpret_cast(ptr))++;
or even (placement new):

    unsigned char* buf = new unsigned char[12];
    buf += 4;
    new (buf) int(0); // Create an int object in the buffer.
    (*reinterpret_cast(buf))++;
    delete[] buf;
But in each case an int object has had its lifetime begin before you can treat the bytes in memory like an int. Everything else is UB.

Re: NanoLog – a nanosecond scale logging system for C++

#16

Post by detaro »

MauranKilom wrote: post #9
Leszek wrote: post #7

Earlier quoted context omitted.

You'd think so, but in fact reinterpret_cast from char* (and unsigned char , and std::byte ) is explicitly allowed by the type aliasing rules.

To the best of my knowledge, casting to char* is totally fine (inspecting an object as bytes) under certain constraints. What is not fine is pretending that an object lives at a position in memory where it does not (i.e. treating bytes of memory as some object through a reinterpret_cast away from char* ). Edit: To clarify, casting away from char* is of course allowed if you cast to whatever object type actually lives…

If I remember correctly, it is fine if there actually was an object of that type (or a "similar" type) in that location. So casting to char* and back is fine, casting to char and then to int-type to inspect multiple bytes is fine as long as alignment plays correctly, ...

It seems like the function only cast to T* if the input pointer hasn't been changed (the paths that do modify it return early), so there's a value there?

Re: NanoLog – a nanosecond scale logging system for C++

#17

Post by bt848 »

rafa1981 wrote: post #14
bt848 wrote: post #2

Looks interesting but how does one reproduce the comparative benchmarks from the paper? I see the code that benchmarks nanolog but how do I reproduce the baseline for glog?

Author of mini-async-log and its C variant here. Some time ago I wrote a benchmark for different loggers, but it uses an old version of Nanolog. https://github.com/RafaGago/logger-bench

Neat. Your code actually contains the issue I was curious about. Why do you log at level ERROR? As I understand it this causes glog to synchronize the output stream after every message.

Re: NanoLog – a nanosecond scale logging system for C++

#18

Post by gpderetta »

detaro wrote: post #16
MauranKilom wrote: post #9

Earlier quoted context omitted.

To the best of my knowledge, casting to char* is totally fine (inspecting an object as bytes) under certain constraints. What is not fine is pretending that an object lives at a position in memory where it does not (i.e. treating bytes of memory as some object through a reinterpret_cast away from char* ). Edit: To clarify, casting away from char* is of course allowed if you cast to whatever object type actually lives…

If I remember correctly, it is fine if there actually was an object of that type (or a "similar" type) in that location. So casting to char* and back is fine, casting to char and then to int-type to inspect multiple bytes is fine as long as alignment plays correctly, ... It seems like the function only cast to T* if the input pointer hasn't been changed (the paths that do modify it return early), so there's a value t…

> casting to char and then to int-type to inspect multiple bytes is fine as long as alignment plays correctly

It is only fine if there were the same exact int types at that address. Remember, UB usually isn't the reinterpret_cast but the dereference.

Re: NanoLog – a nanosecond scale logging system for C++

#19

Post by MauranKilom »

detaro wrote: post #16
MauranKilom wrote: post #9

Earlier quoted context omitted.

To the best of my knowledge, casting to char* is totally fine (inspecting an object as bytes) under certain constraints. What is not fine is pretending that an object lives at a position in memory where it does not (i.e. treating bytes of memory as some object through a reinterpret_cast away from char* ). Edit: To clarify, casting away from char* is of course allowed if you cast to whatever object type actually lives…

If I remember correctly, it is fine if there actually was an object of that type (or a "similar" type) in that location. So casting to char* and back is fine, casting to char and then to int-type to inspect multiple bytes is fine as long as alignment plays correctly, ... It seems like the function only cast to T* if the input pointer hasn't been changed (the paths that do modify it return early), so there's a value t…

> it is fine if there actually was an object of that type (or a "similar" type) in that location.

That is correct. See my other nearby reply.

> So casting to char* and back is fine

Indeed.

> casting to char and then to int-type to inspect multiple bytes is fine as long as alignment plays correctly, ...

Only if the place in memory you are pointing to actually has a live int object. In particular, inspecting the byte representation of an object is fine (including copying the bytes elsewhere, which is why they could just use memcpy instead of reinterpret_cast).

See also http://eel.is/c++draft/basic.types#2 and surroundings.

Re: NanoLog – a nanosecond scale logging system for C++

#20

Post by nemetroid »

From a quick reading of the paper, it sounds like Nanolog is internally translating logging messages into a compacted format, which must be further processed to become human readable. This further processing is not included in the benchmark.

section 4.3, "Decompressor/Aggregator"

> The final component of the NanoLog system is the decompressor/aggregator, which takes as input the compacted log file generated by the runtime and either outputs a human-readable log file or runs aggregations over the compacted log messages. The decompressor reads the dictionary information from the log header, then it processes each of the log messages in turn. For each message, it uses the log id embedded in the file to find the corresponding dictionary entry. It then decompresses the log data as indicated in the dictionary entry and combines that data with static information from the dictionary to generate a human-readable log message. If the decompressor is being used for aggregation, it skips the message formatting step and passes the decompressed log data, along with the dictionary information, to an aggregation function.

section 5.1.2, "Throughput":

> [...] NanoLog performs best when there is little dynamic information in the log message. This is reflected by staticString, a static message, in the throughput benchmark. Here, NanoLog only needs to output about 3-4 bytes per log message due to its compaction and static extraction techniques. Other systems require over an order of magnitude more bytes to represent the messages (41-90 bytes).

> [...] Overall, NanoLog is faster than all other logging systems tested. This is primarily due to NanoLog consistently outputting fewer bytes per message and secondarily because NanoLog defers the formatting and sorting of log messages.

section 5.1.3, "Latency":

> All of the other systems except ETW require the logging thread to either fully or partially materialize the human-readable log message before transferring control to the background thread, resulting in higher invocation latencies. NanoLog on the other hand, performs no formatting and simply pushes all arguments to the staging buffer. This means less computation and fewer bytes copied, resulting in a lower invocation latency.

So NanoLog performs less work and therefore has much higher throughput. This separation of logging and formatting may possibly be a great idea, but it should probably be more prominently mentioned wherever the benchmark table is posted.

Post reply on HN