Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Optimization for Logging RAM usage #724

Open
wants to merge 1 commit into
base: master
Choose a base branch
from
Open

Optimization for Logging RAM usage #724

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
235 changes: 126 additions & 109 deletions implementation/logger/src/message.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -73,146 +73,163 @@ std::mutex message::mutex__;
message::message(level_e _level)
: std::ostream(&buffer_),
level_(_level) {

when_ = std::chrono::system_clock::now();
}

message::~message() try {
std::lock_guard<std::mutex> its_lock(mutex__);

auto its_logger = logger_impl::get();
auto its_configuration = its_logger->get_configuration();

if (!its_configuration) {
return;
}

if (!its_configuration)
if (level_ > its_configuration->get_loglevel()) {
return;
}

if (level_ > its_configuration->get_loglevel())
if (!its_configuration->has_console_log() && !its_configuration->has_file_log() && !its_configuration->has_dlt_log()) {
return;
}

buffer_.activate();

when_ = std::chrono::system_clock::now();
}

if (its_configuration->has_console_log()
|| its_configuration->has_file_log()) {

// Prepare log level
const char *its_level;
switch (level_) {
case level_e::LL_FATAL:
its_level = "fatal";
break;
case level_e::LL_ERROR:
its_level = "error";
break;
case level_e::LL_WARNING:
its_level = "warning";
break;
case level_e::LL_INFO:
its_level = "info";
break;
case level_e::LL_DEBUG:
its_level = "debug";
break;
case level_e::LL_VERBOSE:
its_level = "verbose";
break;
default:
its_level = "none";
};

// Prepare time stamp
auto its_time_t = std::chrono::system_clock::to_time_t(when_);
struct tm its_time;
message::~message() {
if (buffer_.isActive()) {
try {
std::lock_guard<std::mutex> its_lock(mutex__);
auto its_logger = logger_impl::get();
auto its_configuration = its_logger->get_configuration();

if (its_configuration->has_console_log()
|| its_configuration->has_file_log()) {

// Prepare log level
const char *its_level;
switch (level_) {
case level_e::LL_FATAL:
its_level = "fatal";
break;
case level_e::LL_ERROR:
its_level = "error";
break;
case level_e::LL_WARNING:
its_level = "warning";
break;
case level_e::LL_INFO:
its_level = "info";
break;
case level_e::LL_DEBUG:
its_level = "debug";
break;
case level_e::LL_VERBOSE:
its_level = "verbose";
break;
default:
its_level = "none";
};

// Prepare time stamp
auto its_time_t = std::chrono::system_clock::to_time_t(when_);
struct tm its_time;
#ifdef _WIN32
localtime_s(&its_time, &its_time_t);
localtime_s(&its_time, &its_time_t);
#else
localtime_r(&its_time_t, &its_time);
localtime_r(&its_time_t, &its_time);
#endif
auto its_ms = (when_.time_since_epoch().count() / 100) % 1000000;
auto its_ms = (when_.time_since_epoch().count() / 100) % 1000000;

if (its_configuration->has_console_log()) {
if (its_configuration->has_console_log()) {
#ifndef ANDROID
std::cout
<< std::dec
<< std::setw(4) << its_time.tm_year + 1900 << "-"
<< std::setfill('0')
<< std::setw(2) << its_time.tm_mon + 1 << "-"
<< std::setw(2) << its_time.tm_mday << " "
<< std::setw(2) << its_time.tm_hour << ":"
<< std::setw(2) << its_time.tm_min << ":"
<< std::setw(2) << its_time.tm_sec << "."
<< std::setw(6) << its_ms << " ["
<< its_level << "] "
<< buffer_.data_.str()
<< std::endl;
std::cout
<< std::dec
<< std::setw(4) << its_time.tm_year + 1900 << "-"
<< std::setfill('0')
<< std::setw(2) << its_time.tm_mon + 1 << "-"
<< std::setw(2) << its_time.tm_mday << " "
<< std::setw(2) << its_time.tm_hour << ":"
<< std::setw(2) << its_time.tm_min << ":"
<< std::setw(2) << its_time.tm_sec << "."
<< std::setw(6) << its_ms << " ["
<< its_level << "] "
<< buffer_.str()
<< std::endl;
#else
std::string app = runtime::get_property("LogApplication");

switch (level_) {
case level_e::LL_FATAL:
ALOGE(app.c_str(), ("VSIP: " + buffer_.data_.str()).c_str());
break;
case level_e::LL_ERROR:
ALOGE(app.c_str(), ("VSIP: " + buffer_.data_.str()).c_str());
break;
case level_e::LL_WARNING:
ALOGW(app.c_str(), ("VSIP: " + buffer_.data_.str()).c_str());
break;
case level_e::LL_INFO:
ALOGI(app.c_str(), ("VSIP: " + buffer_.data_.str()).c_str());
break;
case level_e::LL_DEBUG:
ALOGD(app.c_str(), ("VSIP: " + buffer_.data_.str()).c_str());
break;
case level_e::LL_VERBOSE:
ALOGV(app.c_str(), ("VSIP: " + buffer_.data_.str()).c_str());
break;
default:
ALOGI(app.c_str(), ("VSIP: " + buffer_.data_.str()).c_str());
};
std::string app = runtime::get_property("LogApplication");

switch (level_) {
case level_e::LL_FATAL:
ALOGE(app.c_str(), ("VSIP: " + buffer_.str()).c_str());
break;
case level_e::LL_ERROR:
ALOGE(app.c_str(), ("VSIP: " + buffer_.str()).c_str());
break;
case level_e::LL_WARNING:
ALOGW(app.c_str(), ("VSIP: " + buffer_.str()).c_str());
break;
case level_e::LL_INFO:
ALOGI(app.c_str(), ("VSIP: " + buffer_.str()).c_str());
break;
case level_e::LL_DEBUG:
ALOGD(app.c_str(), ("VSIP: " + buffer_.str()).c_str());
break;
case level_e::LL_VERBOSE:
ALOGV(app.c_str(), ("VSIP: " + buffer_.str()).c_str());
break;
default:
ALOGI(app.c_str(), ("VSIP: " + buffer_.str()).c_str());
};
#endif // !ANDROID
}

if (its_configuration->has_file_log()) {
std::ofstream its_logfile(
its_configuration->get_logfile(),
std::ios_base::app);
if (its_logfile.is_open()) {
its_logfile
<< std::dec
<< std::setw(4) << its_time.tm_year + 1900 << "-"
<< std::setfill('0')
<< std::setw(2) << its_time.tm_mon + 1 << "-"
<< std::setw(2) << its_time.tm_mday << " "
<< std::setw(2) << its_time.tm_hour << ":"
<< std::setw(2) << its_time.tm_min << ":"
<< std::setw(2) << its_time.tm_sec << "."
<< std::setw(6) << its_ms << " ["
<< its_level << "] "
<< buffer_.data_.str()
<< std::endl;
}

if (its_configuration->has_file_log()) {
std::ofstream its_logfile(
its_configuration->get_logfile(),
std::ios_base::app);
if (its_logfile.is_open()) {
its_logfile
<< std::dec
<< std::setw(4) << its_time.tm_year + 1900 << "-"
<< std::setfill('0')
<< std::setw(2) << its_time.tm_mon + 1 << "-"
<< std::setw(2) << its_time.tm_mday << " "
<< std::setw(2) << its_time.tm_hour << ":"
<< std::setw(2) << its_time.tm_min << ":"
<< std::setw(2) << its_time.tm_sec << "."
<< std::setw(6) << its_ms << " ["
<< its_level << "] "
<< buffer_.str()
<< std::endl;
}
}
}
}
}
if (its_configuration->has_dlt_log()) {
#ifdef USE_DLT
#ifndef ANDROID
its_logger->log(level_, buffer_.data_.str().c_str());
if (its_configuration->has_dlt_log()) {
its_logger->log(level_, buffer_.str().c_str());
}
#endif
#endif // USE_DLT
} catch (const std::exception& e) {
std::cout << "\nVSIP: Error destroying message class: " << e.what() << '\n';
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Wouldn't cerr be more appropriate?

}
}
} catch (const std::exception& e) {
std::cout << "\nVSIP: Error destroying message class: " << e.what() << '\n';
}

std::streambuf::int_type
message::buffer::overflow(std::streambuf::int_type c) {
if (c != EOF) {
data_ << (char)c;
if (active_ && c != EOF) {
data_ << static_cast<char>(c);
}

return c;
}

std::streamsize
message::buffer::xsputn(const char *s, std::streamsize n) {
data_.write(s, n);
if (active_) {
data_.write(s, n);
}
return n;
}

Expand Down
16 changes: 15 additions & 1 deletion interface/vsomeip/internal/logger.hpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -41,12 +41,26 @@ class message
int_type overflow(int_type);
std::streamsize xsputn(const char *, std::streamsize);

inline void activate() {
active_ = true;
}

inline bool isActive() const {
return active_;
}

inline std::string str() const {
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'm curious if a string_view would be more appropriate here.

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I am not 100% sure, std::stringstream::str() constructs a new string anyway and wouldn't std::string_view then point to a temporaray object? Maybe I am wrong ...

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I could be entirely wrong, but I think what happens here that a new std::string is constructed (with allocation) here when buffer_.str() is involved, and then the string stream copies the contents of this into the new string it is constructing. If this were a std::string_stream, we may save on one allocation. If I'm right this could be considerable on platforms like QNX.

I suppose the only way to know would be to test it out. I can try to set up something small on godbolt.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I set up a minimal example in godbolt and found exactly where I was confused. I didn't see that data_ was a stringstream. So there's no savings to be had it seems.

That said, C++20 has a stringstream::view that returns a string_view, unfortunately nothing appears to support it yet, so maybe one day...

return data_.str();
}

private:
bool active_ = false;
std::stringstream data_;
};

std::chrono::system_clock::time_point when_;
buffer buffer_;
level_e level_;
const level_e level_;
static std::mutex mutex__;
};

Expand Down