last day (17 days later) » 

12:06 PM
Let's see if we can get this moved to chat — sehe 2 mins ago
Apparently not automatically @AdityaSihag
Ok, you commented :)
@sehe thank your for your detailed reply and critique on the design i was pursuing. A lot of the code is experimental. For instance I created the thread pool to push onto the queue cause I was observing jitter (spikes of upto 35 microsecs) and my suspicion was the original single pusher thread was still blocked working. I'm not sure what's wrong with the atomic flag load/store combination in place? Could you explain this. Isn't the acquire/release fence synchronized across all threads ? This was my first shot at variadics, that's why the clumsiness around boost::function and stuff. — Aditya Sihag 6 hours ago
@sehe I'm also trying to make enqueue a non-blocking call, even if it be called from a single thread. — Aditya Sihag 6 hours ago
I'll respond to some items separately
> I created the thread pool to push onto the queue cause I was observing jitter (spikes of upto 35 microsecs) and my suspicion was the original single pusher thread was still blocked working
Firstly, Boost Asio is not a lock free queue, AFAIK. So posting to that queue is not a way to remove jitter.
Secondly, there's the problem that I mentioned in my answer: you can't move the formatting to the "asynchronous processing" part, because you will get arguments that are by ref and will not be safe to access from another thread, unknown amount of time later.
If you want to mitigate this, you could pass all the arguments by value but this will create a lot more jitter (spurious latencies), because copying the arguments is not free (especially not if it's something like std::string or even more expensive. So you can't really remove the cost, you can only replace it by the cost of copying (which is often exactly the same amount of work as formatting in the first place)
Besides, you might have an argument that isn't even copyable in the first place.
My approach:
@InnocentBystander Just to be constructive as well, I've added my idea of what constitutes a much simpler start: Live On Coliru - (I'm pretty certain is more efficient to boot, OP)sehe 11 hours ago
looks at it from the the other side: if formatting the message introduces too much latency deviations, optimize the formatting! This is why I used a fixed size, preallocated, buffer for the formatting (it's also safe that way).
 
> I'm not sure what's wrong with the atomic flag load/store combination in place? Could you explain this
There are two. I already explained both in my answer:
> the explicit memory-order load/stores give me bad vibes too. The way they're written would make sense only if exactly two threads are involved in the flag, but this is in no way apparent to me at the moment (threads are created all around).
After I've refactored into a "cleaner" solution I realize that indeed the pop() thread was on a single thread, and iff you can prove that the Log class is used from a single thread only, this makes the synchronization on the flag flag (... use descriptive names!) safe. However, the other use:
Can't really be explained. What are you trying to achieve here? This adds no value over the thread safety guarantee of spsc_queue itself
--------------------------------------------
And, I do get the impression that you introduced the io_service thread pool in order to psuh from background threads ("make push non-blocking"). This means your design is broken (you cannot use spsc_queue in this situation) and also the memory order is wrong (same thing goes for acquire/release pairs)
--------------------------------------------
Okay, so what I would further optimize is the queue itself: I'm not convinved that boost::lockfree::detail::consume_via_copy from std::string will "do the right thing". You could, instead, store "smart" pointers to a pool allocated boost::array<char, 1000>, perhaps with the corresponding array_sink and iostream<array_sink> objects cached.
This make moving items on/off the queue extremely lightweight, at the cost of writing a "queue element" type that abstracts the complexity of managing the lifetime/free-marking of these preallocated things. Also, it might not be "okay" for your application to keep 1024*1000 bytes allocated just for logging (I don't know).
This is why I didn't continue to provide this (my rule is: make it simple and efficient; as soon as adding optimizations starts increasing complexity, WAIT for your profiler to tell you that you really need it)
room topic changed to On lockfree logging, queuing and memory order: see stackoverflow.com/q/28254996/85371 [c++] [lock-free] [memory-order] [spsc-queue]
 
1:05 PM
@sehe Hi. I'm thought process was that since spsc doesnt support multiple threads pushing to the queue, if I estiblish a spin lock around the push itself, I could trade off some occasional latency in multiple spins for the benefit of having a logging structure that is thread safe.
At the very heart of the problem, I want to have the enqueue function to be asynchronous. So it should actually take the variadic contents and copy them to a buffer (linear work), and just return while delegating the rest of the work of pushing onto the queue to a thread -> hence the io_service and post setup which I went about.
That way I can potentially have a logger that doesnt block for more than some nanoseconds on the calling thread (which is simple the time to copy the contents of the log message onto the buffer that is then handled by the thread)
 
@AdityaSihag SPSC literally doesn't support pushing from more than one thread. Iff you wanted to work around that with synchronization, you'd need full memory barriers (making your acquire/release still wrong)
I would not be comfortable guaranteeing that this is enough to make spsc safe with more than one threads pushing (note that you won't see this on all architectures, it's aperfect source for Heisenbugs)
> So it should actually take the variadic contents and copy them to a buffer (linear work),
This is what my sample achieves
> and just return while delegating the rest of the work of pushing onto the queue to a thread
This makes no sense. Lock free is already as low latency as it gets. If you don't want to block on queue full, increase the capacity or just drop the log message...
> io_service and post setup which I went about.
which ironically introduces more lock contention
 
The re-write you have posted is quite slow, I'm not sure how spsc lierally doesn't support pushing from more than one thread ? Cause if I remove the variadic arguments and make enqueue accept just a string, then I can actually print different thread id's inside the push function. And since I have the spin lock, at any given point only one thread is accessing the queue through push.
Ultimately the goal is to produce a logger that has nanosecond latency on the thread that calls enqueue for reasonably sized lines (say 20 or so words -> representated as a combination of char *, string, and nume
the nanosecond latency can be achieved provided the work of type coversion from variadic inputs to stream / string is done asynchronously. Obviously as you pointed out this requires the original variadic components at some point to be copied. I'm certain a single copy onto a char buffer that is thread local will do the job. But the call to enqueue must then return, it can't go on to even do the work of type conversion to stream / string on the calling thread
the spsc boost documentation also states that the queue is wait-free which is one step better than what they define as lockfree
 
1:31 PM
Yes. waitfree. But you make it waiting by doing while (!push());
@AdityaSihag "quite slow" - that statement is "quite funny". Do you have a benchmark that you can share (the code)
> I'm not sure how spsc lierally doesn't support pushing from more than one thread
> only one thread is allowed to push data to the spsc_queue
> only one thread is allowed to push data to the spsc_queue
Note how they do not say "one thread at a time". This is because they use optimal memory ordering on their atomic ringbuffer indices and it will go wrong if more than one thread is participating.
Note again: Not all architectures expose this (notable, Intel doesn't behave differently with acq/rel vs. cst ordering, AFAIK). But it's still the requirement
And, anecdotal evidence like
> Cause if I remove the variadic arguments and make enqueue accept just a string, then I can actually print different thread id's inside the push function.
gives me the willies.
Something tells me you've never had to debug a Heisenbug (or undefined behaviour caused by it)
 
hmm no, i'm pretty rookie, but i still want to crack this problem of sub micro second latency on the calling thread. Any suggestions on how to pursue from here ? The latency choke point is the variadic to stream conversion, and the fact that it happens on the enqueue calling thread. SPSC condition of being called by 1 thrd can be met by just limiting the thread pool size to 1, &passing the data to be logged to a buffer which then io_service posts to convert to stream and push to queue, correct ?
 
Yes. I'd share the benchmark. And read
@AdityaSihag Yes, having a single thread there would fix the undefined behaviour. However, it wouldn't buy you much, because the hard part is moving the "logging" itself to the background thread (what with moving/reference arguments).
In that case it makes way more sense to store the "log promises" in the spsc queue directly
Also. In fact you could say that the logging framework is not at fault (it can log with low latency). It's just the the caller is unable to come up with the information it wants to log in due time. Well. That's a different question and should be solved in the calling code, really.
 
1:51 PM
can't store directly right, cause it's a two step process (1) variadic ->string (2) string ->queue.
 
There's a much higher chance you can optimize this in the calling code, than generically in the logging framework (although, once you've figured out usual patterns that callers use to ottimize things you could provide facilities to make this easier)
@AdityaSihag That's like saying "I can't eat without a fork and knife, because I need to pick up the food with my fork first"
It is an n-step process. Everything is. How you logically group them and distribute across threads is a different matter
 
the question of the log info not being available in due time is not entirely true. let's say the info is available at it's theoretical earliest. Now given the information, say 20-30 words (mix of char const *, string, double, ints etc), can the calling code enqueue in less than 1 microsecond ?
 
How can I tell? It depends on the code, the hardware running it, and other external factors
10 mins ago, by sehe
Yes. I'd share the benchmark. And read
 
the benchmark is simply setting my original piece of code i supplied to have one thread in the thread pool (so i loops from 0 to 1 in the main function). In addition define enqueue to take a string instead of variadics. from main call enqueue with l.enqueue(boost::bind<std::string>(&Log::push,&l,"let's print out this line"));. Enqueu itself is just a template function template <typename G> void enqueue(G g){io_service->post(g)}
 
How can you benchmark the serialization time when you don't include it?
 
2:03 PM
doing that will produce an average over 1000000 such enqueue calls of .9 micro per call for this 5 worded single-typed sentence. However for single iteration tests it clocks about 3-5 micro.
i'm timing from start of the for loop to the end of the for loop, everything in the calling thread is timed. It's irrelevant what the popping thread (the writing thread) takes so long as the thread calling enqueue is blocking on enqueue for less one micro
model name : Intel(R) Xeon(R) CPU X5680 @ 3.33GHz
stepping : 2
cpu MHz : 3325.162
cache size : 12288 KB
 
Well. It's all cool, but you wanted to talk about optimizing the bottleneck. If you can post a relevant benchmark (pastebin, coliru) for that I'd be tempted to have a look
 
ok give me a moment to assemble the code together
 
2:17 PM
posting the benchmark, i realize i'm actually clocking 1 microsecond for a single iteration on my server, the 3-5 micro benchmark is from my laptop. But then this 1 micro second is for a single-typed log info. The moment i have multiple types, i need to convert them to a stream / string which throws this whole setup awry. Posting the code that yields 1 micro benchmark on my server, give me minute
 
:D
 
in this piece of code i don't use an enqueue function, i push from the main function itself. I introduced the enqueue cause when i have variadic arguments, i wanted to do that in the background, yada yada
 
2:33 PM
> yada yada
Maybe it's time to take a break :)
 
http://coliru.stacked-crooked.com/a/4adba95e9bedab4b
this above link is the version that uses the version of enqueue that i got to work before i switched over to variadics .. this clocks about 6-7 micro on my server for a single enqueue
 
wow. that sounds slow indeed
@AdityaSihag contains a duplicate stringer overload, I think (no big deal)
 
2:54 PM
which industry do you work in, may i ask ?
 
Software industry :)
I'm currently at Acronis
 
[aditya@W2WNSEALGO16 src]$ ../bin/emm
3 microsec
[aditya@W2WNSEALGO16 src]$ ../bin/emm
7 microsec
[aditya@W2WNSEALGO16 src]$ ../bin/emm
7 microsec
[aditya@W2WNSEALGO16 src]$ ../bin/emm
7 microsec
[aditya@W2WNSEALGO16 src]$ ../bin/emm
4 microsec
[aditya@W2WNSEALGO16 src]$ ../bin/emm
3 microsec
[aditya@W2WNSEALGO16 src]$ ../bin/emm
7 microsec
[aditya@W2WNSEALGO16 src]$ ../bin/emm
7 microsec
[aditya@W2WNSEALGO16 src]$ ../bin/emm
6 microsec
[aditya@W2WNSEALGO16 src]$ ../bin/emm
6 microsec
[aditya@W2WNSEALGO16 src]$ ../bin/emm
those are the latencies on the server for single iteration spams with the threaded version. I've replaced the thread pool with a single boost::thread pointer for the pusher, and removed the spin locks around the queue.push
 
@AdityaSihag downloads.sehe.nl/stackoverflow/q28254996/nonvariadic.html Disregard the obvious warm up (this is to "/dev/null")
 
wow, what did you do ?!
 
github.com/rmartinho/nonius, it's with exactly your code from here but wrapped in a nonius benchmark:
NONIUS_BENCHMARK("nonvariadic", [](nonius::chronometer meter) {

    std::vector<int32_t> pushCores;
    for (int i = 0; i < 1; ++i) {
        pushCores.push_back(i);
    }

    //  pushCores.push_back(16); pushCores.push_back(17), pushCores.push_back(18), pushCores.push_back(19);
    Log l("/dev/null",1,1024,pushCores);

    meter.measure([&l](int i) {
        l.enqueue(boost::bind(&Log::push,&l,"let's print out this line"));
    });
})
I'm just rigging up the versions you posted, so I can start comparing, possibly improving
 
3:04 PM
but why does my server (which is pretty beefy) clock 3-7 micro ?
 
Who will tell.
I'm not improving anything yet (although my version is clearly much faster: downloads.sehe.nl/stackoverflow/q28254996/mine.html (that's with the unmodified thing I posted yesterday, see dir). And it does use variadics:
NONIUS_BENCHMARK("devnull", [](nonius::chronometer meter) {

    Log<> l("/dev/null", 1024);
    l.enqueue("warm up maybe");

    meter.measure([&l](long i) {
        l.enqueue("hello ", i, " world");
    });
})
@AdityaSihag I'll keep doing stuff here, until I can compare things. Don't expect any verdicts/analysis from me soon. I like to prepare the benchmarks properly before starting analysis
 
wow hmm, so any ideas why it produces crappy numbers for me on my server and laptop
 
@AdityaSihag ^
 
3:27 PM
Any verdicts ?
 
3:38 PM
could it be an ssd difference or something ?
but tthis isn't really the disk write time, it's memory cache stuff and clock frequency latency ...
 
@AdityaSihag /dev/null took that out of the picture, but yeah, later I'll make it somewhat more lifelike. You said the bottleneck was in the streaming so I'll not focus on the disk IO for now (unless my profiling tells me so)
@AdityaSihag I don't expect it before 23:30 CEST - It's a sunday too. Kids deserving some attention :)
 
3:54 PM
haha, thanks a lot ! really appreciate your help, keep in touch over the problem
 

  last day (17 days later) »