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

41–50 of 67 posts

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

#41

Post by dclusin »

paulddraper wrote: post #40
Matthias247 wrote: post #33

Earlier quoted context omitted.

> That's why you are supposed to do your formatting in the background thread :). Which then has the drawback that every argument that gets transferred to the background thread must first be heap allocated or static - instead of only the final buffer being that. My gut feeling is that the additional allocation and memory management costs typically outweigh the cost of formatting in the current thread. Even if one pool…

Or you'd copy them. Unless you do something dumb (like copy a vector when you only need to print the size), copying is significantly faster than string formatting.

I think what OP is hinting at here is cache invalidation/eviction caused by the additional thread's processing and memory operations. If your requirements are down to nanosecond granularities then cache misses are probably being measured and noticeable. A third party logging thread doing memory copies and other log processing sounds like a fine way to unintentionally evict a bunch of cache entries. You might be able to mitigate this to some extent with CPU affinities for threads I suppose. Another option would be to move logging to the network and record packets in/out with an out of band monitoring solution.

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

#42

Post by paulddraper »

dclusin wrote: post #41
paulddraper wrote: post #40

Earlier quoted context omitted.

Or you'd copy them. Unless you do something dumb (like copy a vector when you only need to print the size), copying is significantly faster than string formatting.

I think what OP is hinting at here is cache invalidation/eviction caused by the additional thread's processing and memory operations. If your requirements are down to nanosecond granularities then cache misses are probably being measured and noticeable. A third party logging thread doing memory copies and other log processing sounds like a fine way to unintentionally evict a bunch of cache entries. You might be able…

Well yes, using another thread is a only good idea if you have an extra core available.

L1 cache is per-core anyway, and I doubt L2 is going to hurt much.

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

#43

Post by userbinator »

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…

(i.e. treating bytes of memory as some object through a reinterpret_cast away from char ).*

That's how people have used C and C++ for decades in low-level work, and it still works exactly as you'd expect, so stop saying "don't do it" because you're only encouraging the compiler-writer-UB-optimisation-nonsense crowd to make things even worse. It's already bad enough that they think the Holy Standard is the only thing that matters.

I believe Linus has several memorable rants on this topic already.

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

#44

Post by Const-me »

bonzini wrote: post #35
Const-me wrote: post #29

Recently built similar stuff. Even using same __rdtsc() for time. I didn't require any preprocessing. Instead, I require the strings come from readonly section of a module, and logging pointer values. Also logging into circular buffer in shared memory instead of file, as I was only interested in knowing what the app did immediately before a rare crash which takes hours to reproduce.

How do you deal with ASLR (logging from shared libraries or from position-independent executables)?

In that particular case I’ve cheated. I’m writing out of band file which maps pointer addresses into strings. In runtime it’s CAtlMap really fast because the keys are just addresses. I only have ~200 unique messages (ignoring format arguments) so the file is only written for the first few milliseconds. I did that because it was the simplest thing to do. I could use debug symbols + crash dumps, they can resolve these pointers regardless of ASLR, just it was way more complex to implement. BTW, the only reason I was doing that, the main executable is gta5.exe, it’s encrypted, it resists debugging, and I don’t have debug symbols. If it was my own app, I would probably do something much simpler instead.

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

#45

Post by Rapzid »

dclusin wrote: post #41
paulddraper wrote: post #40

Earlier quoted context omitted.

Or you'd copy them. Unless you do something dumb (like copy a vector when you only need to print the size), copying is significantly faster than string formatting.

I think what OP is hinting at here is cache invalidation/eviction caused by the additional thread's processing and memory operations. If your requirements are down to nanosecond granularities then cache misses are probably being measured and noticeable. A third party logging thread doing memory copies and other log processing sounds like a fine way to unintentionally evict a bunch of cache entries. You might be able…

Logging the raw structured log entry and off-loading any string formatting to another system is a very interesting idea. Just push the whole "friendly message" stuff off to other logging infrastructure where the latencies matter less.

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

#46

Post by jnordwick »

dclusin wrote: post #41
paulddraper wrote: post #40

Earlier quoted context omitted.

Or you'd copy them. Unless you do something dumb (like copy a vector when you only need to print the size), copying is significantly faster than string formatting.

I think what OP is hinting at here is cache invalidation/eviction caused by the additional thread's processing and memory operations. If your requirements are down to nanosecond granularities then cache misses are probably being measured and noticeable. A third party logging thread doing memory copies and other log processing sounds like a fine way to unintentionally evict a bunch of cache entries. You might be able…

At a few places I've worked, logging and util stuff had it's own core to prevent l1/l2 cache pollution (either using threads or shared memory just as long as you got it out of the hot path).

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

#47

Post by jnordwick »

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…

What's your problem with the volatile? Using it to prevent register caching of or a value or prevent optimizing out repeated reads is perfectly fine. That is how it is supposed to be used.

The bug was that one thread was reading the gcc thought it wouldn't be update between reads. It is even used properly by grabbing a copy of the volatile value instead of reading it repeatedly.

edit: I also don't understand your aliasing issues. A `char*` can point anything and you are allowed to cast back out of it to the correct type. It is casting to int because the string is prepended by its length (the var names are "size" and "nibble").

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

#49

Post by wrs »

I did something very similar to the “preprocessor” version of this back in 2001 for Microsoft application crash reporting (the problem then being upload size, not so much logging overhead). It’s very cool to see how you can do the whole thing with constexpr now. As I recall, people really didn’t like using the preprocessor!

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

#50

Post by Matthias247 »

paulddraper wrote: post #40
Matthias247 wrote: post #33

Earlier quoted context omitted.

> That's why you are supposed to do your formatting in the background thread :). Which then has the drawback that every argument that gets transferred to the background thread must first be heap allocated or static - instead of only the final buffer being that. My gut feeling is that the additional allocation and memory management costs typically outweigh the cost of formatting in the current thread. Even if one pool…

Or you'd copy them. Unless you do something dumb (like copy a vector when you only need to print the size), copying is significantly faster than string formatting.

Yes, but you need to have a location where to copy them to. They can’t be on the stack, since the logging task runs asynchronously. So each captured argument must be in some form heap allocated. Eg passing 2 strings as arguments and one integer might require 3 additional heap allocation - where the malloc/free overhead might outweigh the string formatting costs. You can try to optimize here with specialized allocators (eg Arenas) or trying to generate dedicated structures for each logging callsite where all arguments can be carried inside a single heap allocated struct (instead of 3 here). But that might lead to other disadvantages - eg code bloat.
Post reply on HN