1 /*
2 * Copyright Andrey Semashev 2007 - 2015.
3 * Distributed under the Boost Software License, Version 1.0.
4 * (See accompanying file LICENSE_1_0.txt or copy at
5 * http://www.boost.org/LICENSE_1_0.txt)
6 */
7 /*!
8 * \file record_emission.cpp
9 * \author Andrey Semashev
10 * \date 22.03.2009
11 *
12 * \brief This code measures performance of log record emission
13 */
14
15 // #define BOOST_LOG_USE_CHAR
16 // #define BOOST_ALL_DYN_LINK 1
17 // #define BOOST_LOG_DYN_LINK 1
18 #define BOOST_NO_DYN_LINK 1
19
20 #include <iomanip>
21 #include <iostream>
22 #include <boost/core/ref.hpp>
23 #include <boost/bind/bind.hpp>
24 #include <boost/smart_ptr/shared_ptr.hpp>
25 #include <boost/smart_ptr/make_shared_object.hpp>
26 #include <boost/date_time/microsec_time_clock.hpp>
27 #include <boost/date_time/posix_time/posix_time_types.hpp>
28 #include <boost/thread/thread.hpp>
29 #include <boost/thread/barrier.hpp>
30
31 #include <boost/log/core.hpp>
32 #include <boost/log/common.hpp>
33 #include <boost/log/attributes.hpp>
34 #include <boost/log/sinks.hpp>
35 #include <boost/log/sinks/basic_sink_backend.hpp>
36 #include <boost/log/sources/logger.hpp>
37
38 #include <boost/log/expressions.hpp>
39
40 #include <boost/log/attributes/scoped_attribute.hpp>
41
42 enum config
43 {
44 RECORD_COUNT = 20000000,
45 THREAD_COUNT = 8,
46 SINK_COUNT = 3
47 };
48
49 namespace logging = boost::log;
50 namespace expr = boost::log::expressions;
51 namespace sinks = boost::log::sinks;
52 namespace attrs = boost::log::attributes;
53 namespace src = boost::log::sources;
54 namespace keywords = boost::log::keywords;
55
56 enum severity_level
57 {
58 normal,
59 warning,
60 error
61 };
62
63 BOOST_LOG_ATTRIBUTE_KEYWORD(severity, "Severity", severity_level)
64
65 namespace {
66
67 //! A fake sink backend that receives log records
68 class fake_backend :
69 public sinks::basic_sink_backend< sinks::concurrent_feeding >
70 {
71 public:
consume(logging::record_view const & rec)72 void consume(logging::record_view const& rec)
73 {
74 }
75 };
76
77 } // namespace
78
test(unsigned int record_count,boost::barrier & bar)79 void test(unsigned int record_count, boost::barrier& bar)
80 {
81 BOOST_LOG_SCOPED_THREAD_TAG("ThreadID", boost::this_thread::get_id());
82 src::severity_logger< severity_level > slg;
83 // src::logger lg;
84 bar.wait();
85
86 for (unsigned int i = 0; i < record_count; ++i)
87 {
88 BOOST_LOG_SEV(slg, warning) << "Test record";
89 // BOOST_LOG(lg) << "Test record";
90 }
91 }
92
main(int argc,char * argv[])93 int main(int argc, char* argv[])
94 {
95 std::cout << "Test config: " << THREAD_COUNT << " threads, " << SINK_COUNT << " sinks, " << RECORD_COUNT << " records" << std::endl;
96 //__debugbreak();
97 // typedef sinks::unlocked_sink< fake_backend > fake_sink;
98 // typedef sinks::synchronous_sink< fake_backend > fake_sink;
99 typedef sinks::asynchronous_sink< fake_backend > fake_sink;
100 for (unsigned int i = 0; i < SINK_COUNT; ++i)
101 logging::core::get()->add_sink(boost::make_shared< fake_sink >());
102
103 logging::core::get()->add_global_attribute("LineID", attrs::counter< unsigned int >(1));
104 logging::core::get()->add_global_attribute("TimeStamp", attrs::local_clock());
105 logging::core::get()->add_global_attribute("Scope", attrs::named_scope());
106
107 // logging::core::get()->set_filter(severity > normal); // all records pass the filter
108 // logging::core::get()->set_filter(severity > error); // all records don't pass the filter
109
110 // logging::core::get()->set_filter(severity > error); // all records don't pass the filter
111
112 const unsigned int record_count = RECORD_COUNT / THREAD_COUNT;
113 boost::barrier bar(THREAD_COUNT);
114 boost::thread_group threads;
115
116 for (unsigned int i = 1; i < THREAD_COUNT; ++i)
117 threads.create_thread(boost::bind(&test, record_count, boost::ref(bar)));
118
119 boost::posix_time::ptime start = boost::date_time::microsec_clock< boost::posix_time::ptime >::universal_time(), end;
120 test(record_count, bar);
121 if (THREAD_COUNT > 1)
122 threads.join_all();
123 end = boost::date_time::microsec_clock< boost::posix_time::ptime >::universal_time();
124
125 unsigned long long duration = (end - start).total_microseconds();
126
127 std::cout << "Test duration: " << duration << " us ("
128 << std::fixed << std::setprecision(3) << static_cast< double >(RECORD_COUNT) / (static_cast< double >(duration) / 1000000.0)
129 << " records per second)" << std::endl;
130
131 return 0;
132 }
133