NFD

Just for background. Boost.Log uses locks to ensure thread safety. This task may not be that important.

On the other hand, it is probably a good idea to implement thread separation for log statements and actual log writing. The latter can become a serious bottleneck in some cases. I would also think that logger can be, to some extent, lossy. In other words, when log writing is bottleneck, it could be ok to skip some messages---this property may need to be configurable, turned on by default.

Yep we need a rate limiter in the logger. I thought I already opened a ticket about that but I can't find it.

Does boost or the std library provide lock-free data structures?

Davide Pesavento wrote:

Does boost or the std library provide lock-free data structures?

Boost.Lockfree has been introduced in 1.53, so that's not an option.

Davide Pesavento wrote:

Does boost or the std library provide lock-free data structures?

Boost.Lockfree has been introduced in 1.53, so that's not an option.

Actually, this wouldn't be a problem if we dropped support for Ubuntu 12.04, because at that point our oldest supported version would be 14.04, which contains boost 1.54.0

Per platform policy, we can't drop 12.04 support until Ubuntu 16.04 release, which is still 9 months away.

I'll be okay with using Boost.Lockfree when it's available, and continue having locks when it's unavailable.

It's really unnecessary to reinvent Boost.Lockfree for one platform.

So how should I finish this task? Since Boost.lockfree is not available for boost 1.49.

Also, can you explain more about what does

separate thread that pulls log lines from both queues, and writes them into std::clog

mean?

Thanks

A few design questions:

• Why multiple queues? boost::lockfree::queue is a multi-writer/multi-reader queue, therefore one shared queue should be enough for all threads. On the other hand, we can use boost::lockfree::spsc_queue instead (one per writer thread), which is even wait-free (a stronger property than lock-free).
• Are the queues fixed-capacity or do they grow dynamically in size? If dynamic size requires memory allocation, we lose lock-freedom (shouldn't be a problem in practice if allocations are rare)
• What is contained in the queue exactly? The log messages? The problem is that boost::lockfree::queue<T> requires T to be trivially assignable and trivially destructible, which std::string is not. spsc_queue does not suffer from this limitation.

Also, I'm afraid 6 hours are too few to design and implement the solution.

Can I summarize the work as follow?

1. If boost::lockfree::queue are used, there are multiple log producer threads sharing one lock-free queue, and only one consumer thread.
2. If boost::lockfree::spsc_queue are used, there are multiple threads with multiple queues, and for each queue, these is a consumer thread getting logs out of the queue.
3. The consumer thread(s) is in charge of extracting logs from the lock-free queue, and write it to std::clog.
4. Use boost::lockfree::queue when it is available, otherwise implement a so-called 'lock-free' queue with std::lock_guard. std::lock_guard will lock on both producer pointer and consumer pointer when writing are called.

Are the queues fixed-capacity or do they grow dynamically in size?

@Davide Pesavento, could you explain more about what does 'being trivially assignable and trivially destructible' mean? I googled these words but I can not find any informative clue? Or just tell me which book should I look up to understand 'trivially ***'

Yumin Xia wrote:

1. If boost::lockfree::queue are used, there are multiple log producer threads sharing one lock-free queue, and only one consumer thread.

correct

1. If boost::lockfree::spsc_queue are used, there are multiple threads with multiple queues, and for each queue, these is a consumer thread getting logs out of the queue.

No. In this case there is exactly one queue per producer thread, and only one consumer thread in total, which pulls log lines from all queues. (question: in what order? how do we establish a total order between log messages coming from different queues?)

1. The consumer thread(s) is in charge of extracting logs from the lock-free queue, and write it to std::clog.

Yes, more specifically there is one and only one consumer thread.

1. Use boost::lockfree::queue when it is available, otherwise implement a so-called 'lock-free' queue with std::lock_guard. std::lock_guard will lock on both producer pointer and consumer pointer when writing are called.

Yes, in this case use standard locking mechanisms.

@Davide Pesavento, could you explain more about what does 'being trivially assignable and trivially destructible' mean? I googled these words but I can not find any informative clue? Or just tell me which book should I look up to understand 'trivially ***'

They are standard concepts widely used across the C++ std library. See http://en.cppreference.com/w/cpp/types/is_destructible and http://en.cppreference.com/w/cpp/types/is_copy_assignable

IOW, "trivially destructible" means that the type has a trivial destructor. "Trivial destructor" is defined here: http://en.cppreference.com/w/cpp/language/destructor

"Trivially assignable" means that the type has a trivial assignment operator. Here I'm not sure if boost means copy assignment, or if either one of copy or move assignment is enough. Assuming the former, "trivial copy assignment operator" is defined here: http://en.cppreference.com/w/cpp/language/as_operator

Another question for which I don't have an answer at the moment: how do we handle the "empty queue" situation? IOW, how do we notify the consumer thread that more messages have been enqueued? The classic solution is using a condition variable but that involves locking, which kind of defeats the purpose of a lock-free queue... Or the consumer thread can do polling, but that increases latency and/or CPU usage...

Are we sure locking is the actual bottleneck, rather than writing log messages to disk?

Huge thanks to @Davide.

So the questions are

1. Are we sure locking is the actual bottleneck, rather than writing log messages to disk?
2. in what order should customer thread pull logs from queues. And if there were no limitation on how much a customer thread could pull from one queue for once, there might be a starving issue.

Are we sure locking is the actual bottleneck, rather than writing log messages to disk?

Locking is one of the bottlenecks, as shown in note-5.

Writing log messages to disk is also a bottleneck on OSX, as shown in #2492 note-54.

Without an answer to #2492 note-58, I cannot predict whether this issue can help with #2492.

in what order should customer thread pull logs from queues. And if there were no limitation on how much a customer thread could pull from one queue for once, there might be a starving issue.

It's unlikely for NFD and RIB threads to produce logs faster than the logging thread to write logs, so this question is unimportant.

Any design would be acceptable.

Junxiao Shi wrote:

It's unlikely for NFD and RIB threads to produce logs faster than the logging thread to write logs, so this question is unimportant.

This statement contradicts the previous statement that "Writing log messages to disk is also a bottleneck on OSX". If writing can be a bottleneck it means that a thread is able to produce log messages faster than the logging thread can consume them (for an unbounded period of time). A naive solution can cause message drops from the queue that is not consumed frequently enough, or can block the thread that pushes to that queue (depending on the "full queue" behavior we choose).

Boost.Log supports async logging and seems otherwise a pretty flexible and featureful logging library.

Are we sure we want to reimplement that from scratch? If we really need lockless queuing (I'm not convinced yet), we should be able to just implement a new record queuing strategy and instantiate an asynchronous_sink with it instead of using the provided strategies.

Davide, the only problem with Boost.Log is that it is available only in the new versions of Boost. If we can make it use with older versions (e.g., when not available, fetching and building as part of NFD build process), then I will be happy to use it.

The only other option is to require at least boost 1.54, with issues on older platforms (12.04) and, I suspect, some embedded devices.

During Sept 3, 2015 call, we decided that additional investigation necessary before proceeding with this issue:

• what versions of boost are available in supported distribution, and what version are available for other distributions, including OSes for embedded devices (including, but not limited to adruino, openwrt, raspberry pi, ios, android >= 1.57).

• what is the initialization procedure of boost log and how is it compatible with the currently implemented logic

• whether it is possible to use stand-alone latest version of Boost.Log library with an older versions of core boost libraries

Boost.Log requir "boost/move/core.hpp", and this file is introduced into Boost1.49

So, for old platforms using Boost1.48 (debian7 & ubuntu12.04), it might not be possible to use stand-alone latest version of Boost.Log

Yumin Xia wrote:

Boost.Log requir "boost/move/core.hpp", and this file is introduced into Boost1.49

So, for old platforms using Boost1.48 (debian7 & ubuntu12.04), it might not be possible to use stand-alone latest version of Boost.Log

What about older versions of Boost.Log? Do they all require that header file?

I just check the source code of Boost.Logv2 in boost1.54, (the earliest version of Boost.Logv2?), it still require that header file.

Maybe we're lucky... that file includes only boost/config.hpp (plus two others that are only relevant for MSVC), so maybe we can bundle a copy of boost/move/core.hpp for platforms that don't have it, use the system-installed boost/config.hpp, and patch the standalone version of Boost.Log to use the bundled boost/move/core.hpp. This fallback would be only needed until Apr 2016 anyway.

Hi Davide,

But I guess this won't work. This "boost/move/core.hpp" file is just the one I used as an example, there are a lot of files besides this one that are required by Boost.Logv2. "boost/utility/explicit_operator_bool.hpp" is another.

Oh ok. From your comment it sounded like move/core.hpp was the only missing file... Never mind then.

note-23~27 have answered NO to note-22 question-3.

Additional investigation is needed to answer question-1 and question-2.

is this still on track for v0.4?

Sorry for the delay, I was busy with graduate school application and final exams. I will continue work on this issue now.

Before I start, there is some questions that I want to note:

Accroding to this page:

Q1:

If your application consists of more than one module (e.g. an exe and one or several dll's) that use Boost.Log, the library must be built as a shared object. If you have a single executable or a single module that works with Boost.Log, you may build the library as a static library.

so static or shared?

Q2:

The logging library uses several other Boost libraries that require building too. These are Boost.Filesystem, Boost.System, Boost.DateTime, Boost.Thread and in some configurations Boost.Regex.

In wscript, there is not Filesystem & Datetime in boost_libs, but it is required in boost.log. Is it the right way to just add it to boost_libs in wscript?

Q3:

The library requires run-time type information (RTTI) to be enabled for both the library compilation and user's code compilation.

Is RTTI disabled in NFD?

Thanks, guys.

Yumin Xia wrote:

Q1
[...]
so static or shared?

This refers to how to build libboost-log, not our code... so it's not really relevant. In any case, ubuntu provides (only) the shared libraries so we're good.

Q2:
In wscript, there is not Filesystem & Datetime in boost_libs, but it is required in boost.log. Is it the right way to just add it to boost_libs in wscript?

I believe so, but Alex is the waf expert.

Q3:
Is RTTI disabled in NFD?

No.

Q2:
In wscript, there is not Filesystem & Datetime in boost_libs, but it is required in boost.log. Is it the right way to just add it to boost_libs in wscript?

I believe so, but Alex is the waf expert.

Yes. It is enough to just add the necessary libraries in boost_libs variable.

After reading the current code, the order of logger initialization confused me. I guess the init process is like this:

1. modules loggers init (with default level)
2. onConfig(), change the level if needed.
3. Using log macros to log.

two questions:

One is that: In the current code, onConfig() change the level of the loggers mentioned in configure file. Why can it be sure that the init code of each module would run before the onConfig() function? I mean, like if NFD_LOG_INIT("test") runs after function onConfig(), things would go wrong. Is it because that the loggers are static variables (reference), so the construction happens before main() function?

The other one: is it true that, although each module use the same nfd::g_logger as variable name in those macros, actually
they are different, because that g_logger is static, so it refers to only to the g_logger in its cpp file.(after compile, in its .o file)?

Yumin Xia wrote:

One is that: In the current code, onConfig() change the level of the loggers mentioned in configure file. Why can it be sure that the init code of each module would run before the onConfig() function? I mean, like if NFD_LOG_INIT("test") runs after function onConfig(), things would go wrong. Is it because that the loggers are static variables (reference), so the construction happens before main() function?

Yes.

The other one: is it true that, although each module use the same nfd::g_logger as variable name in those macros, actually
they are different, because that g_logger is static, so it refers to only to the g_logger in its cpp file.(after compile, in its .o file)?

That's correct. g_logger is declared static therefore it has internal linkage. In other words, it is only accessible from the "current" translation unit.

I have a simple plan: to use boost.log with 'asynchronous_sink' backend to replace the orignial logger.

The asynchronous_sink use a dedicated thread to output log records, and there are two defects in this design:

there will be a latency between log emission and its actual processing.
This behavior may be inadequate in some contexts, such as debugging an application that is prone to crashes.

And another one is:

However, avoiding dynamic unloading is the only way to solve the problem completely.

There could not be any dynamic unloading in NFD.

As for the implementation details, boost.log will simplely be a private member of the original logger,
and it will behave like a stream. The initialization code of boost.log will be written in LoggerFactory constructor.

Yumin Xia wrote:

I have a simple plan: to use boost.log with 'asynchronous_sink' backend to replace the orignial logger.

And what about the platforms that don't have Boost.Log? Do we keep using the current logging system?

yes. For boost version less than 1.55, will still compile the current logging system. But I only have a naive plan about this.

1. in .wscript file, link boost log and dependencies if boost >= 1.55
2. in LoggerFactory and Logger, use macro to choose to compile old design or boost log.

I will make a commit and let it be reviewed to see if it is OK.

Hi guys,

I met a compile problem. GCC gave compiler error on this:

../daemon/face/udp-factory.cpp: In member function ‘std::shared_ptr<nfd::UdpChannel> nfd::UdpFactory::createChannel(const Endpoint&, const seconds&)’:
../daemon/face/udp-factory.cpp:113:11: error: no match for ‘operator=’ (operand types are ‘std::shared_ptr<nfd::UdpChannel>’ and ‘boost::detail::sp_if_not_array<nfd::UdpChannel>::type {aka boost::shared_ptr<nfd::UdpChannel>}’)
   channel = make_shared<UdpChannel>(endpoint, timeout);

It seems that it is using boost::make_shared instead of std::make_shared. I did not change anything in this file, so I guess it is because something wrong with my modifications in logger.hpp or logger-factory.hpp. Have you ever met this kind of problem before?

In logger.hpp, new included files are:

#include <boost/log/common.hpp>
#include <boost/log/sources/logger.hpp>

In logger-factory.hpp:

#include <boost/log/core.hpp>
#include <boost/log/expressions.hpp>
#include <boost/utility/empty_deleter.hpp>

Reply to note-41:

I've seen a similar error when I add #include <boost/thread.hpp>.

Strangely, this compilation error only occurs in UdpFactory::createChannel and StrategyInfoHost::getOrCreateStrategyInfo.

The fix is changing into std::make_shared in both places).

The problem was solved by add prefix 'std::' as Junxiao replied last time. But I think this solution is too tricky, and it might raise compile errors in later development.

Another problem is how to do the unit-test. Since it is using asynchronous logging, there is a delay between logging and writing to clog, the old unit-test could not work as expected. I tried to flush the logging explicitly, but it do not work. So I change add a explicit flush before getting buffer.

Hey guys,

I have pushed a new patch set to gerrit. According to reviews, I have made changes to most of them, but some need to be discussed:

1. where to define macro BOOST_LOG_DYN_LINK ( or BOOST_ALL_DYN_LINK). In patch set 4 I define it in the 'core/logger.hpp' file.
2. Is it Ok to use 'namespace logging = boost::log' in cpp file?
3. Building system failed in './waf confiigure' under Ubuntu 12.04. The error message is that log lib does not exist. However, it should not check boost::log if version is less than 1.54.
4. After this commit, sometimes it would be necessary to explicitly use std::make_shared<>. (One thing I found might help is that, both files, in which this problem happened, do not include "common.hpp" directly in header files).

sometimes it would be necessary to explicitly use std::make_shared<>.
One thing I found might help is that, both files, in which this problem happened, do not include "common.hpp" directly in header files

I guess the problem occurs because something in Boost is included before common.hpp.
Try including common.hpp at the top of logger.hpp, and see whether this helps.

Yumin Xia wrote:

1. where to define macro BOOST_LOG_DYN_LINK ( or BOOST_ALL_DYN_LINK). In patch set 4 I define it in the 'core/logger.hpp' file.

I think the best place would be the top-level wscript, but Alex is the build system expert.

1. Is it Ok to use 'namespace logging = boost::log' in cpp file?

Yes, but why "logging" instead of "log"? I don't see the point in changing (and lengthening) the name...

1. Building system failed in './waf confiigure' under Ubuntu 12.04. The error message is that log lib does not exist. However, it should not check boost::log if version is less than 1.54.

I guess conf.env.BOOST_VERSION_NUMBER is not initialized until conf.check_boost() is called.

Junxiao Shi wrote:

sometimes it would be necessary to explicitly use std::make_shared<>.
One thing I found might help is that, both files, in which this problem happened, do not include "common.hpp" directly in header files

I guess the problem occurs because something in Boost is included before common.hpp.
Try including common.hpp at the top of logger.hpp, and see whether this helps.

There is already common.hpp at the top of logger.hpp, but it does not help.

Davide Pesavento wrote:

Yes, but why "logging" instead of "log"? I don't see the point in changing (and lengthening) the name...

So should I just use boost::log?

I guess conf.env.BOOST_VERSION_NUMBER is not initialized until conf.check_boost() is called.

Yes, I check the .waf-tools/boost.py file, and it initialized in check_boost(). I could hack a little bit in boost.py file, but is it OK?

The easiest workaround would be to add

conf.check_boost()

prior to version checking. In other words, this would check boost twice: once for just header files, the other one for header files and necessarily libraries.

Some design decisions:

1. Why not boost.log's severity_logger: Using severity_logger will change much more code than using a basic async logger. Since the original logger will still be there for some time, I suggest using basic logger. Besides, severity_logger does not offer more functions than the already implemented one.

2. Using auto_flush. Accrording to http://www.boost.org/doc/libs/1_54_0/libs/log/doc/html/log/detailed/sink_backends.html , using auto_flush will degrade performance, but in case of an application crash, there is a good chance that last log records will be not be lost. I did a naive test of logging a string for 200000 times with and without auto_flush respectively, and use time to see its performance. The results are:

   with auto_flush: build/main 2> a.txt  7.19s user 3.74s system 133% cpu 8.184 total
   without : build/main 2> a.txt  6.69s user 3.74s system 123% cpu 8.420 total
   

Quesiton:

@Alex, Where could I define the BOOST_LOG_DYN_LINK in wscript? I tried to append it to conf.env.defines, but then ./waf configure failed.

I would say, Boost.Log did something really really strange, complicating life of users. Static single threaded, static multithreaded, shared single threaded, shared multithreaded versions of the library use their own internal namespace. Moreover, each require proper macros defined.

I have updated boost detection tool (I also submitted a pull request to the waf upstream). I also changed to force multithreaded versions of all libraries.

Hi Alex,

I have pulled the new patch-set, but it seems that it does not work correctly.

Checking boost includes : 1.55.0
Checking boost libs : ok
Checking for boost linkage : Could not link against boost libraries using supplied options
does not using boost_libs (This is a log I add when try..except...)

It fails to detect that boost.log is available in system.

Which system you're testing it on? And how boost is installed (from packages or from source)?

Also. Show build/config.log, as it shows what exactly failed.

I have reproduced the problem and now at loss what to do. This is really Boost.Log problem. Specifically, the strange decision to have different naming schemes for:

• static single-threaded version of library
• static multi-threaded
• dynamic single-threaded
• dynamic multi-threaded

Static/dynamic fact is obvious. Multi/single-thrededness is normally identified by presence or absence of "-mt" suffix. This works in OSX. However, Ubuntu packaging have only one version, which I'm guessing is multithreaded, but doesn't have -mt suffix.

I can add additional logic to do extra guessing, but I don't fully understand the grounds for Boost.Log decision.

As far as I understand, boost dropped the -mt suffix for the multi-threaded variant in 1.40.0, but most distros kept a libboost_foo-mt.so -> libboost_foo.so symlink for backward compatibility reasons... until Debian/Ubuntu dropped the symlink sometime between 12.04 and 14.04.

So I think the general logic on Linux could be that we first look for libboost_foo-mt.so, and if that doesn't exist we fallback to libboost_foo.so, and we assume it's the multi-threaded variant (we require 1.48 so it should be... unless someone manually compiled only the single-threaded variant).

Note that the above applies to all boost libraries, not just to Boost.Log

I'm not sure what you mean by "dropping support. There are still 4 versions installed, not just symlinks. At least on my system.

And this logic not going to work without some magic. On my system, libboost_log.so is single threaded and if attempted to link without BOOST_LOG_NO_THREADS, it fails. I'm really frustrated by this Boost.Log decision. I'm not aware of other boost libraries that do such crazy thing.

Are you talking about Linux or OSX? What I said applies to linux only. On OSX the situation is completely different: both single- and multi-threaded versions are built and installed separately.

Yeah. I mentioned behavior on OSX, as I was observing it.

As of Change 2707 patchset 15, code looks mostly fine, but the Assignee needs to test its execution.

The test shall include at least the following scenarios:

• normal NFD operation, default level set to INFO, light traffic (around 10 packets per second)
• normal NFD operation, default level set to TRACE, moderate traffic (around 100 packets per second)
• custom logger (it's sufficient to test the compilation with custom logger; it's unnecessary to test the operations)
• NFD integration tests (I have triggered an automated execution and will upload the results)

The test report shall be posted under this issue.

What exactly you expect to be tested? What metrics you expect to see?

Btw. I would appreciate if Yumin or somebody else point me to Boost.Log documentation where described how async logging works. Does it create thread on its own?

Is the buffer/queue infinite or finite? If the former, then we haven't really fixed much in this change :)

Alex Afanasyev wrote:

Btw. I would appreciate if Yumin or somebody else point me to Boost.Log documentation where described how async logging works. Does it create thread on its own?

http://www.boost.org/doc/libs/1_60_0/libs/log/doc/html/log/detailed/sink_frontends.html#log.detailed.sink_frontends.async

"All log records are passed to the backend in a dedicated thread, which makes it suitable for backends that may block for a considerable amount of time (network and other hardware device-related sinks, for example). The internal thread of the frontend is spawned on the frontend constructor and joined on its destructor (which implies that the frontend destruction may block)."

Is the buffer/queue infinite or finite? If the former, then we haven't really fixed much in this change :)

(I asked the same in note-11 but I guess we didn't discuss it)

Long story short, Boost.Log allows some compile-time customization via template arguments, see http://www.boost.org/doc/libs/1_60_0/libs/log/doc/html/log/detailed/sink_frontends.html#log.detailed.sink_frontends.async.customizing_record_queueing_strategy

The current patch set uses the default unbounded_fifo_queue. I think that's fine for this change. Changing the queuing policy should go in a separate commit.

Alex Afanasyev wrote:

Btw. I would appreciate if Yumin or somebody else point me to Boost.Log documentation where described how async logging works. Does it create thread on its own?

Boost.log create async thread on it's own in the front-end construction function. Here in the codes, it happens in the Line 67th in logger-factory.cpp. (m_sink = boost::make_shared<Sink>(backend);)

Is the buffer/queue infinite or finite? If the former, then we haven't really fixed much in this change :)

It is now using the default unbounded_fifo_queue strategy.

The failure of the integrated tests has nothing to do with this commit. I see that it has to do something with DNS / auto-registration.

Trying multicast discovery...
Stage 1 failed: Timeout
Sending DNS query for SRV record for _ndn._udp
ERROR: FaceUri canonization failed: Hostname resolution timed out

Thanks Davide and Yumin for clarifying. We should definitely implement limited queue and I agree to make it a separate task (I just created an issue to track it).

Since this won't be merged for 0.4.1, and 0.4.2 will presumably happen after ubuntu 16.04 is released, can we remove all preprocessor conditionals and hard-depend on Boost.Log (i.e. boost >= 1.54) ?

As Davide has replied on Gerrit, now() is not thread-safe. There are two ways to solve this problem:

one is to simply make now() thread-safe by drop 'static' of 'static char buffer[10 + 1 + 6 + 1];'(no overheads in terms of running, only sub more on ESP when entering the function).

The other is to write a custom attribute in boost.log.

Which one do you prefer?

Answer to note-73:

The first approach requires changing the return type of now() to std::string, otherwise it would return a pointer to a stack-allocated buffer which becomes invalid upon return.

Returning std::string causes a copy.

I'm unfamiliar with "custom attribute in boost.log" and will not comment on the second approach.

ndn-cxx-logging project adopts a different approach: introduce a custom type whose operator<< prints a timestamp.

This is thread-safe and does not copy the timestamp string into a std::string.
I prefer this approach, partially because I invented it.

Junxiao Shi wrote:

The first approach requires changing the return type of now() to std::string, otherwise it would return a pointer to a stack-allocated buffer which becomes invalid upon return.

Returning std::string causes a copy.

...and a memory allocation, which is very bad for performance, especially at that point in the code. I'm against this approach.

Answer to note-71:

20160414 call decides to make this commit without considering older Boost versions.