For the basic tests, null appender, file appender and severity filtering boost log performed roughly **1.5 times slower**
Keep in mind this is **initial results**. The code needs a look over to ensure everything is equivalent and, if not (which is probable), what needs to be fixed.
I took a quick glance over the test code, here are my observations:
1. Looks like you're using the asynchronous sink frontend. AFAIK, log4cxx is synchronous, so synchronous frontend would be a fair alternative from Boost.Log. This would also remove the need to stop/feed records after the test is done.
2. boost::timer is not a good choice to measure performance. On Windows, QueryPerformanceCounter/QueryPerformanceFrequency is more precise. On Linux and other platforms microsec_clock from Boost.DateTime would suffice. Iteration count should also be high enough to run each test for at least a few seconds.
3. Poor performance of date/time formatting in Boost.Log is somewhat expected. IMO, this is due to Boost.DateTime IO implementation that is used underneath. Although I don't have numbers to support this claim. One day I hope to do something about it.
4. The null\_backend is not so null after all. Although I don't think this will change overall results, there is no need in the internal thread the backend spawns. Same for null\_formatted\_sink\_backend.
5. You may try to use streaming formatters instead of Boost.Format-style to achieve better results.
6. It would be interesting to see which library scales better. Have you run multithreaded tests?
7. Boost.Log seems to require more resources in the case when no effective job is done (i.e. no log record is written). I have thoughts on this but I doubt any significant gain can be achieved here.
I'm sorry I didn't have much time to take a deeper look. I will return to this subject once I manage to setup the environment to run the test.
If you would like to refer to this comment somewhere else in this project, copy and paste the following link:
1. I initially used synchronous but thought I'd try asynchronous to see if it performed any faster. There is a flag -synchronous to switch. I'll run some tests with both and see.
2. Okay, I'll change the timer. Why is boost::timer not good, too slow and not high enough resolution?
3. Is Boost.DateTime used / evaluated when the attribute is not used? Also, is it desirable to allow another date time lib, say via a template Even just to test? Or is this a major undertaking?
4. Righteo, I'll ammend null backends and rerun the tests. This was the kind of feedback I wanted/needed. Thanks.
5. Will do. So is no internal formatter representation? I.e., what you choose initially is the method used when generating log records?
6. I haven't run multi-threaded tests yet. I will. It shouldn't take long. I wanted to compare the basic performances first. Any preferable use cases?
7. Are these the results from the severity filtering? Or in general? For severity levels, it seems so from my results. Boost.Log only comparably when logging is disabled from the core.
No probs and thanks heaps. Look forward to hearing more.
I'll post the ammended results today sometime.
If you would like to refer to this comment somewhere else in this project, copy and paste the following link:
I've added some for comparing the two formatters (5). The streams didn't make much of a difference, about 1% faster across all the tests (for 50,000 message loops and 3 iterations per test).
Timer uses QueryPerformanceCounter (on Win32) now. I'll post the changed code soonish.
Ok, I finally managed to compile and run the test. I have modified it to compile with STLPort, as I mostly use it in my development. Log4cxx was also compiled with STLPort, so this shouldn't affect test results too much.
My initial results were similar to what you have presented. I have modified the tests according to my previous suggestions and increased messages count to 100000 and 500000 in the python script (you may find the resulting code to the trac page) and then reran the test.
The results are posted on the trac page, I'll just summarize here:
1. The performance of formatting, aside from time stamp formatting, is roughly equal to log4cxx.
2. Time stamp formatting is a lot slower. It gives the major impact on the performance (in these tests Boost.Log is up to 3.5 times slower). The reasons I have mentioned earlier.
3. Filtering, if the record does pass the filter, is roughly equal to log4cxx, although a bit slower.
4. Filtering, if the record does **not** pass the filter, is slower. That also includes the case when logging is totally disabled with set\_logging\_enabled(false). However, in these cases we're talking of almost nano-optimizations, as in both libraries dropping filtered away log records is extremely fast (millions per second).
Given the flexibility Boost.Log provides, I'm rather satisfied with the results. Honestly, I thought it would be worse. :)
> I initially used synchronous but thought I'd try asynchronous to see if it performed any faster. There is a flag -synchronous to switch. I'll run some tests with both and see.
AFAIR, that flad did not affect all tests. So I simply replaced all dink frontends in the code.
Async frontend does not do any faster, in most cases just the opposite. It is useful if the backend tend to block for a long time, in order not to block the logging thread.
> Is Boost.DateTime used / evaluated when the attribute is not used? Also, is it desirable to allow another date time lib, say via a template Even just to test? Or is this a major undertaking?
Boost.DateTime is used in two aspects. It is used to acquire the time stamp and then to format it into a string. If you add a time stamp attribute, then it is acquired for each log record you make (more precisely, unless you use a filter based on the time stamp, for each log record that passes the filter). But it will only be formatted, if you set up the formatter accordingly.
I don't think that there is much difference between how log4cxx and Boost.DateTime acquires the time stamp, in terms of performance. The major difference is in formatting, and the tests show that clearly.
You may try to craft your own formatter based, for example, on strftime, to format the time stamp and see the difference.
> So is no internal formatter representation? I.e., what you choose initially is the method used when generating log records?
I'm not sure what you meant. There is no internal formatter representation, from the library perspective it's merely a functor.
Boost.Format-based formatters are slower because they add some overhead in order to iterate through placeholders and insert formatted arguments. The difference may not be as big as I expected, that is why your results don't show a clear leader.
> Are these the results from the severity filtering? Or in general? For severity levels, it seems so from my results. Boost.Log only comparably when logging is disabled from the core.
This was my conclusion based on your results and my knowledge of Boost.Log internals.
> I haven't run multi-threaded tests yet. I will. It shouldn't take long. I wanted to compare the basic performances first. Any preferable use cases?
We can start with the most obvious ones. N threads emitting log records concurrently, where N being, say, 2, 4, 8 and 16. Sync and Async frontends may be tested on how they perform in this setting.
If you would like to refer to this comment somewhere else in this project, copy and paste the following link:
Yep, breaking up my averages, Boost.Log, for the the null appender and file tests **without** timestamps, is close enough to log4cxx (~1.0 to 1.10 time slower). However, with timestamps, about 2.8 to 3 times slower.
> I initially used synchronous but thought I'd try asynchronous to see if it performed any faster. There is a flag -synchronous to switch. I'll run some tests with both and see.
>
> AFAIR, that flad did not affect all
> tests. So I simply replaced all dink
> frontends in the code.
Yeah, I realised that after I posted. I've fixed the code to take that into account. (And merged your fixes / modifications too).
> Time stamp formatting is a lot slower. It gives the major impact on the performance (in these tests Boost.Log is up to 3.5 times slower). The reasons I have mentioned earlier.
This is a major concern for us (and for many others too, I assume) - not many people log without time stamps. Is this a known issue with Boost.DateTime, the slow formatting? I'll look into using strftime too.
> I'm not sure what you meant. There is no internal formatter representation, from the library perspective it's merely a functor.
Yep, that's what I meant. So the user interface for specifying a format (i.e, stream vs Boost.Format) also determines how it is used internally (via the functor).
> We can start with the most obvious ones. N threads emitting log records concurrently, where N being, say, 2, 4, 8 and 16. Sync and Async frontends may be tested on how they perform in this setting.
Will do. Initially one appender with N threads logging to it.
If you would like to refer to this comment somewhere else in this project, copy and paste the following link:
> This is a major concern for us (and for many others too, I assume) - not many people log without time stamps. Is this a known issue with Boost.DateTime, the slow formatting?
I don't know. My guess is that noone cared so far. You can create a ticket on the , although such optimization would be a non-trivial task and one should not expect it to be implemented soon. The ticket would highlight the problem, at least.
> So the user interface for specifying a format (i.e, stream vs Boost.Format) also determines how it is used internally (via the functor).
Multi-threaded results for logging to the one appender indicated Boost.Log is about 1.7 times slower for asynchronous and about 2.0 times slower for synchronous logging.
Updated
[1] and [results][2].
[1]: https://sourceforge.net/apps/trac/boost-log/attachment/wiki/LogFourCxxComparison/PerformanceTests.3.rar
[2]: https://sourceforge.net/apps/trac/boost-log/wiki/LogFourCxxComparison#Updatedtestsuite2-Multi-threadedresults
If you would like to refer to this comment somewhere else in this project, copy and paste the following link:
How did you run the test? I got much more optimistic results:
Test,boost_log Avg Time,log4cxx Avg Time,boost_log/log4cxx Avg Time Ratio
multithreaded_one_sink-100000-stream_formatter-synchronous-16,10.7619,11.0356,0.975198448657
multithreaded_one_sink-100000-stream_formatter-synchronous-2,1.3901,1.33777,1.03911733706
multithreaded_one_sink-100000-stream_formatter-synchronous-4,2.75301,2.86226,0.961830860928
multithreaded_one_sink-100000-stream_formatter-synchronous-8,5.4747,5.48489,0.998142168758
multithreaded_one_sink-500000-stream_formatter-synchronous-16,54.5169,54.562,0.999173417397
multithreaded_one_sink-500000-stream_formatter-synchronous-2,6.90584,6.60622,1.04535422677
multithreaded_one_sink-500000-stream_formatter-synchronous-4,13.6704,13.9394,0.980702182303
multithreaded_one_sink-500000-stream_formatter-synchronous-8,27.5994,27.3218,1.01016038475
Overall ratio is about 1.0.
Perhaps, it's a configuration issue? I have Vista 32 bit on Core 2 Duo with 2 Gb RAM. The Boost.Log is compiled with BOOST\_LOG\_USE\_WINNT6\_API macro.
If you would like to refer to this comment somewhere else in this project, copy and paste the following link:
I ran the test with the linked code and using the python script via command line, again:
<pre>Test,boost_log Avg Time,log4cxx Avg Time,boost_log/log4cxx Avg Time Ratio
multithreaded_one_sink-100000-stream_formatter-2,4.27217,2.42335,1.76291909959
multithreaded_one_sink-100000-stream_formatter-4,7.71645,4.90575,1.57293991744
multithreaded_one_sink-100000-stream_formatter-8,16.0696,9.88765,1.62521933928
multithreaded_one_sink-500000-stream_formatter-2,18.7738,12.1379,1.54670906829
multithreaded_one_sink-500000-stream_formatter-4,38.3993,24.4885,1.56805439288
multithreaded_one_sink-500000-stream_formatter-8,80.4751,49.0877,1.63941476174
multithreaded_one_sink-100000-stream_formatter-synchronous-2,6.20013,2.43141,2.5500141893
multithreaded_one_sink-100000-stream_formatter-synchronous-4,10.6520,4.88981,2.17840774999
multithreaded_one_sink-100000-stream_formatter-synchronous-8,24.8723,9.79490,2.53931127423
multithreaded_one_sink-500000-stream_formatter-synchronous-2,26.1430,12.1380,2.15381446696
multithreaded_one_sink-500000-stream_formatter-synchronous-4,51.3448,24.4356,2.10122935389
multithreaded_one_sink-500000-stream_formatter-synchronous-8,130.548,49.0799,2.65990762002
</pre>
Configuration is Windows XP, Core 2 Duo (2.4GHz), 3.5 Gb Ram. I built it with just the BOOST_LOG_USE_CHAR macro. Hmmmmm.
If you would like to refer to this comment somewhere else in this project, copy and paste the following link:
I've made a 'null formatter' for the date_time attribute by commenting out:
<pre><code>//! Formatting method for Boost.DateTime date object
template< typename T >
void operator()(T const& value)
{
//to_stream_dispatch(value, tag_of(boost::addressof(value)));
//this->m_Stream.flush();
}</code></pre>
The results for one iteration/test:
<pre><code>Without timestamp:
loggingMW_analysis_boost_log_null_backend_formatted-500000-stream_formatter-synchronous 500000 9.73082 1
loggingMW_analysis_log4cxx_null_backend_formatted-500000-stream_formatter-synchronous 500000 9.55473 1
With timestamp:
loggingMW_analysis_boost_log_null_backend_formatted-500000-stream_formatter-synchronous-timestamp 500000 14.0277 1
loggingMW_analysis_log4cxx_null_backend_formatted-500000-stream_formatter-synchronous-timestamp 500000 11.106 1
**Sorry. The above was incorrect!** I was building debug but running release hence no difference between "with timestamp" and with null timestamp". Time to go home I think.
I've re-run the test **properly** and it confirms the slow down is the Boost.DateTime formatting:
With strftime hacked time stamp:
loggingMW_analysis_boost_log_null_backend_formatted-500000-stream_formatter-synchronous-timestamp 500000 15.3058 1
loggingMW_analysis_log4cxx_null_backend_formatted-500000-stream_formatter-synchronous-timestamp 500000 11.2209 1
With no time stamp formatting (acquisition is Boost.DateTime but formatting is commented out):
loggingMW_analysis_boost_log_null_backend_formatted-500000-stream_formatter-synchronous-timestamp 500000 14.198 1
loggingMW_analysis_log4cxx_null_backend_formatted-500000-stream_formatter-synchronous-timestamp 500000 10.9011 1</pre>
(Excuse the formatting, I'm trying to figure it out…)
If you would like to refer to this comment somewhere else in this project, copy and paste the following link:
Any news/feedback on the multi-threading or time stamp issues/queries?
I've added another to the trac. Note the performance is equal when running just one extra thread _with timestamps_. Compare this to the null appender tests. I'm sure it's something I've miscoded…
To run the same tests, the time stamp attribute is hard-coded in the multithreaded tests. See SetFormat(…).
Regarding the time stamp. IIUC, you ran the test with an asynchronous sink. Considering that you have a dual core CPU, and all formatting is done in the dedicated thread, there's no surprise that the time stamp formatting did not affect the results (it was performed by another core).
What bothers me right now is the discrepancy between our multithreaded results. I have a few ideas why this could have happened.
1. I use STLPort, which might perform better than MS STL.
2. My Boost version may be different than yours. I use release branch from Boost SVN, which now should be roughly equivalent to 1.41.
3. I run Vista with its APIs. Event if I disable the new API usage, it may still perform better. I heard that heap management was optimized in Vista.
If you would like to refer to this comment somewhere else in this project, copy and paste the following link:
I did not add the time stamp attribute to the core but was asking for it via the formatter. A change - for the better - between in either your lib or Boost 1.40.0 and 1.42 (trunk) must have caused this.
If you would like to refer to this comment somewhere else in this project, copy and paste the following link:
Have you monitored the memory usage when running my test suite? Or even your own stress tests (i.e., logging many messages)?
On my build, when running Boost.Log's tests the mem usages accumulates a few MB per second. When the tests move onto log4cxx, the memory is not released.
I noticed this when during multi-threaded tests over a gig of memory was being used. These test had 500K messages for each of the 8 threads. The memory accumulated during the Boost.Log tests then remained constant after during log4cxx tests…
The loop is simply logging via the BOOST\_LOG\_SEV macros…
Have you noticed this?
If you would like to refer to this comment somewhere else in this project, copy and paste the following link:
The memory usage may grow rapidly when async frontend is used. This is not a leak, it simply means that the backend is not capable to consume records as fast as the logging theads put them into queue. There is no queue size limitation currently. The memory should be reclaimed once the backend consumes all queued records.
Other than that I did not observe any unusual memory consumption. If you see a leak on another case, please create a trac ticket with the test case attached, I'll take a look.
If you would like to refer to this comment somewhere else in this project, copy and paste the following link:
> I did not add the time stamp attribute to the core but was asking for it via the formatter. A change - for the better - between in either your lib or Boost 1.40.0 and 1.42 (trunk) must have caused this.
Yes, this was one of the recent Boost.Log improvements.
If you would like to refer to this comment somewhere else in this project, copy and paste the following link:
I've run some tests in GCC 4.3.3 on Ubuntu in VMWare.
Without the time stamp attribute, Boost.Log is outperforming log4cxx by about 10-20%, including multi-threading. This is good. However, when including the time stamp attribute it under-performs badly, it is around 4 times slower. This is not good.
I've written a custom attribute using ftime and strftime and it performance is slightly better but still 2.5 times slower.
I haven't had a chance to identify if it's the formatting still (or more so on Linux) but the current results are, again, a worry. And I'm not sure if being a VM machine will impact results.
I'll clean up the code and cmake files and upload it early next week.
Cheers,
Sam
If you would like to refer to this comment somewhere else in this project, copy and paste the following link:
Hi Guys,
I've put the code and results into .
For the basic tests, null appender, file appender and severity filtering boost log performed roughly **1.5 times slower**
Keep in mind this is **initial results**. The code needs a look over to ensure everything is equivalent and, if not (which is probable), what needs to be fixed.
Cheers,
Sam
Have a read through.
: https://sourceforge.net/apps/trac/boost-log/wiki/LogFourCxxComparison
I took a quick glance over the test code, here are my observations:
1. Looks like you're using the asynchronous sink frontend. AFAIK, log4cxx is synchronous, so synchronous frontend would be a fair alternative from Boost.Log. This would also remove the need to stop/feed records after the test is done.
2. boost::timer is not a good choice to measure performance. On Windows, QueryPerformanceCounter/QueryPerformanceFrequency is more precise. On Linux and other platforms microsec_clock from Boost.DateTime would suffice. Iteration count should also be high enough to run each test for at least a few seconds.
3. Poor performance of date/time formatting in Boost.Log is somewhat expected. IMO, this is due to Boost.DateTime IO implementation that is used underneath. Although I don't have numbers to support this claim. One day I hope to do something about it.
4. The null\_backend is not so null after all. Although I don't think this will change overall results, there is no need in the internal thread the backend spawns. Same for null\_formatted\_sink\_backend.
5. You may try to use streaming formatters instead of Boost.Format-style to achieve better results.
6. It would be interesting to see which library scales better. Have you run multithreaded tests?
7. Boost.Log seems to require more resources in the case when no effective job is done (i.e. no log record is written). I have thoughts on this but I doubt any significant gain can be achieved here.
I'm sorry I didn't have much time to take a deeper look. I will return to this subject once I manage to setup the environment to run the test.
Thanks Andrey.
1. I initially used synchronous but thought I'd try asynchronous to see if it performed any faster. There is a flag -synchronous to switch. I'll run some tests with both and see.
2. Okay, I'll change the timer. Why is boost::timer not good, too slow and not high enough resolution?
3. Is Boost.DateTime used / evaluated when the attribute is not used? Also, is it desirable to allow another date time lib, say via a template Even just to test? Or is this a major undertaking?
4. Righteo, I'll ammend null backends and rerun the tests. This was the kind of feedback I wanted/needed. Thanks.
5. Will do. So is no internal formatter representation? I.e., what you choose initially is the method used when generating log records?
6. I haven't run multi-threaded tests yet. I will. It shouldn't take long. I wanted to compare the basic performances first. Any preferable use cases?
7. Are these the results from the severity filtering? Or in general? For severity levels, it seems so from my results. Boost.Log only comparably when logging is disabled from the core.
No probs and thanks heaps. Look forward to hearing more.
I'll post the ammended results today sometime.
I've added some for comparing the two formatters (5). The streams didn't make much of a difference, about 1% faster across all the tests (for 50,000 message loops and 3 iterations per test).
Timer uses QueryPerformanceCounter (on Win32) now. I'll post the changed code soonish.
: https://sourceforge.net/apps/trac/boost-log/attachment/wiki/LogFourCxxComparison/formatting_boost_vs_stream.PNG
Sorry, Boost.Format is about 1% faster but for most tests, it is less than a percent. Either way, not really significant.
Ok, I finally managed to compile and run the test. I have modified it to compile with STLPort, as I mostly use it in my development. Log4cxx was also compiled with STLPort, so this shouldn't affect test results too much.
My initial results were similar to what you have presented. I have modified the tests according to my previous suggestions and increased messages count to 100000 and 500000 in the python script (you may find the resulting code to the trac page) and then reran the test.
The results are posted on the trac page, I'll just summarize here:
1. The performance of formatting, aside from time stamp formatting, is roughly equal to log4cxx.
2. Time stamp formatting is a lot slower. It gives the major impact on the performance (in these tests Boost.Log is up to 3.5 times slower). The reasons I have mentioned earlier.
3. Filtering, if the record does pass the filter, is roughly equal to log4cxx, although a bit slower.
4. Filtering, if the record does **not** pass the filter, is slower. That also includes the case when logging is totally disabled with set\_logging\_enabled(false). However, in these cases we're talking of almost nano-optimizations, as in both libraries dropping filtered away log records is extremely fast (millions per second).
Given the flexibility Boost.Log provides, I'm rather satisfied with the results. Honestly, I thought it would be worse. :)
: https://sourceforge.net/apps/trac/boost-log/attachment/wiki/LogFourCxxComparison/PerformanceTests.2.rar
> I initially used synchronous but thought I'd try asynchronous to see if it performed any faster. There is a flag -synchronous to switch. I'll run some tests with both and see.
AFAIR, that flad did not affect all tests. So I simply replaced all dink frontends in the code.
Async frontend does not do any faster, in most cases just the opposite. It is useful if the backend tend to block for a long time, in order not to block the logging thread.
> Is Boost.DateTime used / evaluated when the attribute is not used? Also, is it desirable to allow another date time lib, say via a template Even just to test? Or is this a major undertaking?
Boost.DateTime is used in two aspects. It is used to acquire the time stamp and then to format it into a string. If you add a time stamp attribute, then it is acquired for each log record you make (more precisely, unless you use a filter based on the time stamp, for each log record that passes the filter). But it will only be formatted, if you set up the formatter accordingly.
I don't think that there is much difference between how log4cxx and Boost.DateTime acquires the time stamp, in terms of performance. The major difference is in formatting, and the tests show that clearly.
You may try to craft your own formatter based, for example, on strftime, to format the time stamp and see the difference.
> So is no internal formatter representation? I.e., what you choose initially is the method used when generating log records?
I'm not sure what you meant. There is no internal formatter representation, from the library perspective it's merely a functor.
Boost.Format-based formatters are slower because they add some overhead in order to iterate through placeholders and insert formatted arguments. The difference may not be as big as I expected, that is why your results don't show a clear leader.
> Are these the results from the severity filtering? Or in general? For severity levels, it seems so from my results. Boost.Log only comparably when logging is disabled from the core.
This was my conclusion based on your results and my knowledge of Boost.Log internals.
> I haven't run multi-threaded tests yet. I will. It shouldn't take long. I wanted to compare the basic performances first. Any preferable use cases?
We can start with the most obvious ones. N threads emitting log records concurrently, where N being, say, 2, 4, 8 and 16. Sync and Async frontends may be tested on how they perform in this setting.
Yep, breaking up my averages, Boost.Log, for the the null appender and file tests **without** timestamps, is close enough to log4cxx (~1.0 to 1.10 time slower). However, with timestamps, about 2.8 to 3 times slower.
> I initially used synchronous but thought I'd try asynchronous to see if it performed any faster. There is a flag -synchronous to switch. I'll run some tests with both and see.
>
> AFAIR, that flad did not affect all
> tests. So I simply replaced all dink
> frontends in the code.
Yeah, I realised that after I posted. I've fixed the code to take that into account. (And merged your fixes / modifications too).
> Time stamp formatting is a lot slower. It gives the major impact on the performance (in these tests Boost.Log is up to 3.5 times slower). The reasons I have mentioned earlier.
This is a major concern for us (and for many others too, I assume) - not many people log without time stamps. Is this a known issue with Boost.DateTime, the slow formatting? I'll look into using strftime too.
> I'm not sure what you meant. There is no internal formatter representation, from the library perspective it's merely a functor.
Yep, that's what I meant. So the user interface for specifying a format (i.e, stream vs Boost.Format) also determines how it is used internally (via the functor).
> We can start with the most obvious ones. N threads emitting log records concurrently, where N being, say, 2, 4, 8 and 16. Sync and Async frontends may be tested on how they perform in this setting.
Will do. Initially one appender with N threads logging to it.
> This is a major concern for us (and for many others too, I assume) - not many people log without time stamps. Is this a known issue with Boost.DateTime, the slow formatting?
I don't know. My guess is that noone cared so far. You can create a ticket on the , although such optimization would be a non-trivial task and one should not expect it to be implemented soon. The ticket would highlight the problem, at least.
> So the user interface for specifying a format (i.e, stream vs Boost.Format) also determines how it is used internally (via the functor).
Rather, it defines the functor itself.
: https://svn.boost.org/trac/boost/
Multi-threaded results for logging to the one appender indicated Boost.Log is about 1.7 times slower for asynchronous and about 2.0 times slower for synchronous logging.
Updated
How did you run the test? I got much more optimistic results:
Test,boost_log Avg Time,log4cxx Avg Time,boost_log/log4cxx Avg Time Ratio
multithreaded_one_sink-100000-stream_formatter-synchronous-16,10.7619,11.0356,0.975198448657
multithreaded_one_sink-100000-stream_formatter-synchronous-2,1.3901,1.33777,1.03911733706
multithreaded_one_sink-100000-stream_formatter-synchronous-4,2.75301,2.86226,0.961830860928
multithreaded_one_sink-100000-stream_formatter-synchronous-8,5.4747,5.48489,0.998142168758
multithreaded_one_sink-500000-stream_formatter-synchronous-16,54.5169,54.562,0.999173417397
multithreaded_one_sink-500000-stream_formatter-synchronous-2,6.90584,6.60622,1.04535422677
multithreaded_one_sink-500000-stream_formatter-synchronous-4,13.6704,13.9394,0.980702182303
multithreaded_one_sink-500000-stream_formatter-synchronous-8,27.5994,27.3218,1.01016038475
Overall ratio is about 1.0.
Perhaps, it's a configuration issue? I have Vista 32 bit on Core 2 Duo with 2 Gb RAM. The Boost.Log is compiled with BOOST\_LOG\_USE\_WINNT6\_API macro.
I ran the test with the linked code and using the python script via command line, again:
<pre>Test,boost_log Avg Time,log4cxx Avg Time,boost_log/log4cxx Avg Time Ratio
multithreaded_one_sink-100000-stream_formatter-2,4.27217,2.42335,1.76291909959
multithreaded_one_sink-100000-stream_formatter-4,7.71645,4.90575,1.57293991744
multithreaded_one_sink-100000-stream_formatter-8,16.0696,9.88765,1.62521933928
multithreaded_one_sink-500000-stream_formatter-2,18.7738,12.1379,1.54670906829
multithreaded_one_sink-500000-stream_formatter-4,38.3993,24.4885,1.56805439288
multithreaded_one_sink-500000-stream_formatter-8,80.4751,49.0877,1.63941476174
multithreaded_one_sink-100000-stream_formatter-synchronous-2,6.20013,2.43141,2.5500141893
multithreaded_one_sink-100000-stream_formatter-synchronous-4,10.6520,4.88981,2.17840774999
multithreaded_one_sink-100000-stream_formatter-synchronous-8,24.8723,9.79490,2.53931127423
multithreaded_one_sink-500000-stream_formatter-synchronous-2,26.1430,12.1380,2.15381446696
multithreaded_one_sink-500000-stream_formatter-synchronous-4,51.3448,24.4356,2.10122935389
multithreaded_one_sink-500000-stream_formatter-synchronous-8,130.548,49.0799,2.65990762002
</pre>
Configuration is Windows XP, Core 2 Duo (2.4GHz), 3.5 Gb Ram. I built it with just the BOOST_LOG_USE_CHAR macro. Hmmmmm.
I've made a 'null formatter' for the date_time attribute by commenting out:
<pre><code>//! Formatting method for Boost.DateTime date object
template< typename T >
void operator()(T const& value)
{
//to_stream_dispatch(value, tag_of(boost::addressof(value)));
//this->m_Stream.flush();
}</code></pre>
The results for one iteration/test:
<pre><code>Without timestamp:
loggingMW_analysis_boost_log_null_backend_formatted-500000-stream_formatter-synchronous 500000 9.73082 1
loggingMW_analysis_log4cxx_null_backend_formatted-500000-stream_formatter-synchronous 500000 9.55473 1
With timestamp:
loggingMW_analysis_boost_log_null_backend_formatted-500000-stream_formatter-synchronous-timestamp 500000 14.0277 1
loggingMW_analysis_log4cxx_null_backend_formatted-500000-stream_formatter-synchronous-timestamp 500000 11.106 1
With null_timestamp:
loggingMW_analysis_boost_log_null_backend_formatted-500000-stream_formatter-synchronous-timestamp 500000 14.0163 1
loggingMW_analysis_log4cxx_null_backend_formatted-500000-stream_formatter-synchronous-timestamp 500000 11.0522 1
</code></pre>
I could quite possibly have read the code wrong but I think by commenting out those lines I avoid the Boost.DateTime to IOStream formatting…
Grr, sorry for the above formatting…
And I forgot to mention, the **slowness** seems to be **before formatting ** the Boost.DateTime obj to the stream.
**Sorry. The above was incorrect!** I was building debug but running release hence no difference between "with timestamp" and with null timestamp". Time to go home I think.
I've re-run the test **properly** and it confirms the slow down is the Boost.DateTime formatting:
<pre>Null Timestamp: loggingMW_analysis_boost_log_null_backend_formatted-500000-stream_formatter-synchronous-timestamp 500000 14.0163 1
Formatted timestamp: loggingMW_analysis_boost_log_null_backend_formatted-500000-stream_formatter-synchronous-timestamp 500000 38.7216 1</pre>
I've hacked in strftime acquisition and, more importantly, formatting into Boost.Log's time stamp attribute.
A new time trait: <pre>`typedef time_t time_type;
static time_type get_clock()
{
time_type rawtime;
time ( &rawtime );
return rawtime;
}
…
typedef basic_clock< strf_time_traits > strf_clock;`</pre>
And replaced the appropriate operator() function in basic\_date\_time\_formatter:<pre>`void operator()(std::tm const& value)
{
static char buffer ;
strftime (buffer,80,"%Y-%m-%d %H:%M:%S", &value);
this->m_Stream << buffer;
this->m_Stream.flush();
}`</pre>
Hacked, I know but I just wanted to get the same output as log4cxx.
The results are as expected, much much faster:
<pre>With Boost.DateTime time stamp:
loggingMW_analysis_boost_log_null_backend_formatted-500000-stream_formatter-synchronous-timestamp 500000 38.8134 1
loggingMW_analysis_log4cxx_null_backend_formatted-500000-stream_formatter-synchronous-timestamp 500000 10.8547 1
With strftime hacked time stamp:
loggingMW_analysis_boost_log_null_backend_formatted-500000-stream_formatter-synchronous-timestamp 500000 15.3058 1
loggingMW_analysis_log4cxx_null_backend_formatted-500000-stream_formatter-synchronous-timestamp 500000 11.2209 1
With no time stamp formatting (acquisition is Boost.DateTime but formatting is commented out):
loggingMW_analysis_boost_log_null_backend_formatted-500000-stream_formatter-synchronous-timestamp 500000 14.198 1
loggingMW_analysis_log4cxx_null_backend_formatted-500000-stream_formatter-synchronous-timestamp 500000 10.9011 1</pre>
(Excuse the formatting, I'm trying to figure it out…)
Hi Andrey,
Any news/feedback on the multi-threading or time stamp issues/queries?
I've added another to the trac. Note the performance is equal when running just one extra thread _with timestamps_. Compare this to the null appender tests. I'm sure it's something I've miscoded…
To run the same tests, the time stamp attribute is hard-coded in the multithreaded tests. See SetFormat(…).
I'll clean up and upload the latest code.
Thanks,
Sam
: https://sourceforge.net/apps/trac/boost-log/wiki/LogFourCxxComparison#Updatedtestsuite3-Newmulti-threadedresults
No, I had no chance to explore it deeper.
Regarding the time stamp. IIUC, you ran the test with an asynchronous sink. Considering that you have a dual core CPU, and all formatting is done in the dedicated thread, there's no surprise that the time stamp formatting did not affect the results (it was performed by another core).
What bothers me right now is the discrepancy between our multithreaded results. I have a few ideas why this could have happened.
1. I use STLPort, which might perform better than MS STL.
2. My Boost version may be different than yours. I use release branch from Boost SVN, which now should be roughly equivalent to 1.41.
3. I run Vista with its APIs. Event if I disable the new API usage, it may still perform better. I heard that heap management was optimized in Vista.
Thanks for the response.
The time stamp tests were with a synchronous sink. I've added asynchronous tests now.
I've checked out Boost SVN trunk and Boost.Log trunk but the multi-threaded test crashes when outputting to BOOST\_LOG\_SEV(…) with the exception:
> boost::exception\_detail::clone\_impl< boost::exception\_detail::error\_info\_injector<boost::log\_mt\_nt5::missing\_value> > at memory location …
This **only** happens when when the time stamp attribute; it **does not** occur in Debug build, and it crashes for both synchronous and asynchronous.
If possible, can you add the time stamp attribute to the above multi-thread tests and see the results?
I'll be test using STLPort soon(ish).
Okay, just another *ignore my post*.
I did not add the time stamp attribute to the core but was asking for it via the formatter. A change - for the better - between in either your lib or Boost 1.40.0 and 1.42 (trunk) must have caused this.
Andrey,
Have you monitored the memory usage when running my test suite? Or even your own stress tests (i.e., logging many messages)?
On my build, when running Boost.Log's tests the mem usages accumulates a few MB per second. When the tests move onto log4cxx, the memory is not released.
I noticed this when during multi-threaded tests over a gig of memory was being used. These test had 500K messages for each of the 8 threads. The memory accumulated during the Boost.Log tests then remained constant after during log4cxx tests…
The loop is simply logging via the BOOST\_LOG\_SEV macros…
Have you noticed this?
The memory usage may grow rapidly when async frontend is used. This is not a leak, it simply means that the backend is not capable to consume records as fast as the logging theads put them into queue. There is no queue size limitation currently. The memory should be reclaimed once the backend consumes all queued records.
Other than that I did not observe any unusual memory consumption. If you see a leak on another case, please create a trac ticket with the test case attached, I'll take a look.
> I did not add the time stamp attribute to the core but was asking for it via the formatter. A change - for the better - between in either your lib or Boost 1.40.0 and 1.42 (trunk) must have caused this.
Yes, this was one of the recent Boost.Log improvements.
The memory usage (leak?) was observed for both async and sync frontends.
I've written a basic case which demonstrates the usage: using a synchronous< text_file_backend > and logging N records via a for loop.
The memory usage grows until the loop finishes and isn't released until the program exits.
I've created the (#2).
: https://sourceforge.net/apps/trac/boost-log/attachment/ticket/2/
Andrey,
I've run some tests in GCC 4.3.3 on Ubuntu in VMWare.
Without the time stamp attribute, Boost.Log is outperforming log4cxx by about 10-20%, including multi-threading. This is good. However, when including the time stamp attribute it under-performs badly, it is around 4 times slower. This is not good.
I've written a custom attribute using ftime and strftime and it performance is slightly better but still 2.5 times slower.
I haven't had a chance to identify if it's the formatting still (or more so on Linux) but the current results are, again, a worry. And I'm not sure if being a VM machine will impact results.
I'll clean up the code and cmake files and upload it early next week.
Cheers,
Sam