From fa0313652cc25e17e6c3151f67111fb88c62778e Mon Sep 17 00:00:00 2001 From: michael-west Date: Fri, 19 Sep 2014 18:22:13 -0700 Subject: uhd: Fixed logging bug (#476) -- UHD logging has unexplained effect on packet loss. - Removed logging from radio_ctrl_core_3000 - Changed logging facility to prevent type conversion when message is not logged --- host/include/uhd/utils/log.hpp | 29 ++++++++++++-- host/lib/usrp/cores/radio_ctrl_core_3000.cpp | 8 ---- host/lib/utils/log.cpp | 59 +++++++++++++--------------- 3 files changed, 53 insertions(+), 43 deletions(-) diff --git a/host/include/uhd/utils/log.hpp b/host/include/uhd/utils/log.hpp index 1f515c15e..5baa00108 100644 --- a/host/include/uhd/utils/log.hpp +++ b/host/include/uhd/utils/log.hpp @@ -21,8 +21,10 @@ #include #include #include +#include #include #include +#include /*! \file log.hpp * The UHD logging facility. @@ -55,7 +57,7 @@ * Usage: UHD_LOGV(very_rarely) << "the log message" << std::endl; */ #define UHD_LOGV(verbosity) \ - uhd::_log::log(uhd::_log::verbosity, __FILE__, __LINE__, BOOST_CURRENT_FUNCTION)() + uhd::_log::log(uhd::_log::verbosity, __FILE__, __LINE__, BOOST_CURRENT_FUNCTION) /*! * A UHD logger macro with default verbosity. @@ -78,7 +80,7 @@ namespace uhd{ namespace _log{ }; //! Internal logging object (called by UHD_LOG macros) - class UHD_API log{ + class UHD_API log { public: log( const verbosity_t verbosity, @@ -86,10 +88,29 @@ namespace uhd{ namespace _log{ const unsigned int line, const std::string &function ); + ~log(void); - std::ostream &operator()(void); + + // Macro for overloading insertion operators to avoid costly + // conversion of types if not logging. + #define INSERTION_OVERLOAD(x) log& operator<< (x) \ + { \ + if(_log_it) _ss << val; \ + return *this; \ + } + + // General insertion overload + template + INSERTION_OVERLOAD(T val); + + // Insertion overloads for std::ostream manipulators + INSERTION_OVERLOAD(std::ostream& (*val)(std::ostream&)); + INSERTION_OVERLOAD(std::ios& (*val)(std::ios&)); + INSERTION_OVERLOAD(std::ios_base& (*val)(std::ios_base&)); + private: - UHD_PIMPL_DECL(impl) _impl; + std::ostringstream _ss; + bool _log_it; }; }} //namespace uhd::_log diff --git a/host/lib/usrp/cores/radio_ctrl_core_3000.cpp b/host/lib/usrp/cores/radio_ctrl_core_3000.cpp index 2005bcf33..15af1888b 100644 --- a/host/lib/usrp/cores/radio_ctrl_core_3000.cpp +++ b/host/lib/usrp/cores/radio_ctrl_core_3000.cpp @@ -52,7 +52,6 @@ public: ACK_TIMEOUT), _resp_queue(128/*max response msgs*/), _resp_queue_size( _resp_xport ? _resp_xport->get_num_recv_frames() : 3) { - UHD_LOG<< "radio_ctrl_core_3000_impl() " << _name << std::endl; if (resp_xport) { while (resp_xport->get_recv_buff(0.0)) {} //flush @@ -63,7 +62,6 @@ public: ~radio_ctrl_core_3000_impl(void) { - UHD_LOG << "~radio_ctrl_core_3000_impl() " << _name << std::endl; _timeout = ACK_TIMEOUT; //reset timeout to something small UHD_SAFE_CALL( this->peek32(0);//dummy peek with the purpose of ack'ing all packets @@ -77,8 +75,6 @@ public: void poke32(const wb_addr_type addr, const boost::uint32_t data) { boost::mutex::scoped_lock lock(_mutex); - UHD_LOGV(always) << _name << std::hex << " addr 0x" << addr << " data 0x" << data << std::dec << std::endl; - this->send_pkt(addr/4, data); this->wait_for_ack(false); } @@ -86,7 +82,6 @@ public: boost::uint32_t peek32(const wb_addr_type addr) { boost::mutex::scoped_lock lock(_mutex); - UHD_LOGV(always) << _name << std::hex << " addr 0x" << addr << std::dec << std::endl; this->send_pkt(SR_READBACK, addr/8); const boost::uint64_t res = this->wait_for_ack(true); const boost::uint32_t lo = boost::uint32_t(res & 0xffffffff); @@ -97,8 +92,6 @@ public: boost::uint64_t peek64(const wb_addr_type addr) { boost::mutex::scoped_lock lock(_mutex); - UHD_LOGV(always) << _name << std::hex << " addr 0x" << addr << std::dec << std::endl; - this->send_pkt(SR_READBACK, addr/8); return this->wait_for_ack(true); } @@ -174,7 +167,6 @@ private: { while (readback or (_outstanding_seqs.size() >= _resp_queue_size)) { - UHD_LOGV(always) << _name << " wait_for_ack: " << "readback = " << readback << " outstanding_seqs.size() " << _outstanding_seqs.size() << std::endl; //get seq to ack from outstanding packets list UHD_ASSERT_THROW(not _outstanding_seqs.empty()); const size_t seq_to_ack = _outstanding_seqs.front(); diff --git a/host/lib/utils/log.cpp b/host/lib/utils/log.cpp index 31ee0c991..123b7e4e6 100644 --- a/host/lib/utils/log.cpp +++ b/host/lib/utils/log.cpp @@ -23,6 +23,7 @@ #include #include #include +#include #ifdef BOOST_MSVC //whoops! https://svn.boost.org/trac/boost/ticket/5287 //enjoy this useless dummy class instead @@ -37,7 +38,6 @@ namespace boost{ namespace interprocess{ #include #endif #include -#include #include namespace fs = boost::filesystem; @@ -70,13 +70,13 @@ public: } ~log_resource_type(void){ - boost::mutex::scoped_lock lock(_mutex); + boost::lock_guard lock(_mutex); _file_stream.close(); if (_file_lock != NULL) delete _file_lock; } void log_to_file(const std::string &log_msg){ - boost::mutex::scoped_lock lock(_mutex); + boost::lock_guard lock(_mutex); if (_file_lock == NULL){ const std::string log_path = (fs::path(uhd::get_tmp_path()) / "uhd.log").string(); _file_stream.open(log_path.c_str(), std::fstream::out | std::fstream::app); @@ -126,39 +126,40 @@ static std::string get_rel_file_path(const fs::path &file){ return rel_path.string(); } -struct uhd::_log::log::impl{ - std::ostringstream ss; - verbosity_t verbosity; -}; uhd::_log::log::log( const verbosity_t verbosity, const std::string &file, const unsigned int line, const std::string &function -){ - _impl = UHD_PIMPL_MAKE(impl, ()); - _impl->verbosity = verbosity; - const std::string time = pt::to_simple_string(pt::microsec_clock::local_time()); - const std::string header1 = str(boost::format("-- %s - level %d") % time % int(verbosity)); - const std::string header2 = str(boost::format("-- %s") % function).substr(0, 80); - const std::string header3 = str(boost::format("-- %s:%u") % get_rel_file_path(file) % line); - const std::string border = std::string(std::max(std::max(header1.size(), header2.size()), header3.size()), '-'); - _impl->ss - << std::endl - << border << std::endl - << header1 << std::endl - << header2 << std::endl - << header3 << std::endl - << border << std::endl - ; + ) +{ + _log_it = (verbosity >= log_rs().level); + if (_log_it) + { + const std::string time = pt::to_simple_string(pt::microsec_clock::local_time()); + const std::string header1 = str(boost::format("-- %s - level %d") % time % int(verbosity)); + const std::string header2 = str(boost::format("-- %s") % function).substr(0, 80); + const std::string header3 = str(boost::format("-- %s:%u") % get_rel_file_path(file) % line); + const std::string border = std::string(std::max(std::max(header1.size(), header2.size()), header3.size()), '-'); + _ss << std::endl + << border << std::endl + << header1 << std::endl + << header2 << std::endl + << header3 << std::endl + << border << std::endl + ; + } } -uhd::_log::log::~log(void){ - if (_impl->verbosity < log_rs().level) return; - _impl->ss << std::endl; +uhd::_log::log::~log(void) +{ + if (not _log_it) + return; + + _ss << std::endl; try{ - log_rs().log_to_file(_impl->ss.str()); + log_rs().log_to_file(_ss.str()); } catch(const std::exception &e){ /*! @@ -174,7 +175,3 @@ uhd::_log::log::~log(void){ ; } } - -std::ostream & uhd::_log::log::operator()(void){ - return _impl->ss; -} -- cgit v1.2.3