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/ref.hpp>
23 #include <boost/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
37 #include <boost/log/expressions.hpp>
38
39 #include <boost/log/attributes/scoped_attribute.hpp>
40
41 enum config
42 {
43 RECORD_COUNT = 50000000,
44 THREAD_COUNT = 8,
45 SINK_COUNT = 3
46 };
47
48 namespace logging = boost::log;
49 namespace expr = boost::log::expressions;
50 namespace sinks = boost::log::sinks;
51 namespace attrs = boost::log::attributes;
52 namespace src = boost::log::sources;
53 namespace keywords = boost::log::keywords;
54
55 enum severity_level
56 {
57 normal,
58 warning,
59 error
60 };
61
62 BOOST_LOG_ATTRIBUTE_KEYWORD(severity, "Severity", severity_level)
63
64 namespace {
65
66 //! A fake sink backend that receives log records
67 class fake_backend :
68 public sinks::basic_sink_backend< sinks::concurrent_feeding >
69 {
70 public:
consume(logging::record_view const & rec)71 void consume(logging::record_view const& rec)
72 {
73 }
74 };
75
76 } // namespace
77
test(unsigned int record_count,boost::barrier & bar)78 void test(unsigned int record_count, boost::barrier& bar)
79 {
80 BOOST_LOG_SCOPED_THREAD_TAG("ThreadID", boost::this_thread::get_id());
81 bar.wait();
82
83 src::severity_logger< severity_level > slg;
84 for (unsigned int i = 0; i < record_count; ++i)
85 {
86 BOOST_LOG_SEV(slg, warning) << "Test record";
87 }
88 }
89
main(int argc,char * argv[])90 int main(int argc, char* argv[])
91 {
92 std::cout << "Test config: " << THREAD_COUNT << " threads, " << SINK_COUNT << " sinks, " << RECORD_COUNT << " records" << std::endl;
93 //__debugbreak();
94 // typedef sinks::unlocked_sink< fake_backend > fake_sink;
95 // typedef sinks::synchronous_sink< fake_backend > fake_sink;
96 typedef sinks::asynchronous_sink< fake_backend > fake_sink;
97 for (unsigned int i = 0; i < SINK_COUNT; ++i)
98 logging::core::get()->add_sink(boost::make_shared< fake_sink >());
99
100 logging::core::get()->add_global_attribute("LineID", attrs::counter< unsigned int >(1));
101 logging::core::get()->add_global_attribute("TimeStamp", attrs::local_clock());
102 logging::core::get()->add_global_attribute("Scope", attrs::named_scope());
103
104 // logging::core::get()->set_filter(severity > normal); // all records pass the filter
105 // logging::core::get()->set_filter(severity > error); // all records don't pass the filter
106
107 // logging::core::get()->set_filter(severity > error); // all records don't pass the filter
108
109 const unsigned int record_count = RECORD_COUNT / THREAD_COUNT;
110 boost::barrier bar(THREAD_COUNT);
111 boost::thread_group threads;
112
113 for (unsigned int i = 1; i < THREAD_COUNT; ++i)
114 threads.create_thread(boost::bind(&test, record_count, boost::ref(bar)));
115
116 boost::posix_time::ptime start = boost::date_time::microsec_clock< boost::posix_time::ptime >::universal_time(), end;
117 test(record_count, bar);
118 if (THREAD_COUNT > 1)
119 threads.join_all();
120 end = boost::date_time::microsec_clock< boost::posix_time::ptime >::universal_time();
121
122 unsigned long long duration = (end - start).total_microseconds();
123
124 std::cout << "Test duration: " << duration << " us ("
125 << std::fixed << std::setprecision(3) << static_cast< double >(RECORD_COUNT) / (static_cast< double >(duration) / 1000000.0)
126 << " records per second)" << std::endl;
127
128 return 0;
129 }
130