common/Log.cpp | 155 +++++++++++++++++++++++++++++++++++++++++++++++++--------
common/Log.hpp | 20 ++++---
2 files changed, 148 insertions(+), 27 deletions(-)
New commits:
commit 287b70a50408d260f3c6c0d5306c081a40eea280
Author: Ashod Nakashian <ashod.nakash...@collabora.co.uk>
AuthorDate: Sat Apr 25 13:03:32 2020 -0400
Commit: Ashod Nakashian <ashnak...@gmail.com>
CommitDate: Fri May 22 00:40:37 2020 +0200
wsd: logging cleanup and improvements
We now don't need to call snprintf (which is best
for signal-safetly), and are much faster thanks
to a custom replacement.
Change-Id: Iae5861e42e8e335967499f93b71b39b0b4b09bf6
Reviewed-on: https://gerrit.libreoffice.org/c/online/+/94146
Tested-by: Jenkins CollaboraOffice <jenkinscollaboraoff...@gmail.com>
Tested-by: Jenkins
Reviewed-by: Ashod Nakashian <ashnak...@gmail.com>
diff --git a/common/Log.cpp b/common/Log.cpp
index f9d0b5578..6cb376c9e 100644
--- a/common/Log.cpp
+++ b/common/Log.cpp
@@ -70,7 +70,7 @@ namespace Log
const std::string& getName() const { return _name; }
void setLogger(Poco::Logger* logger) { _logger = logger; };
- Poco::Logger* getLogger() { return _logger; }
+ Poco::Logger* getLogger() const { return _logger; }
};
static StaticNameHelper Source;
bool IsShutdown = false;
@@ -112,38 +112,153 @@ namespace Log
signalLog(buf + i + 1);
}
- char* prefix(char* buffer, const std::size_t len, const char* level)
+ /// Convert an unsigned number to ascii with 0 padding.
+ template <int Width> void to_ascii_fixed(char* buf, size_t num)
{
- const char *threadName = Util::getThreadName();
- Poco::DateTime time;
+ buf[Width - 1] = '0' + num % 10; // Units.
+
+ if (Width > 1)
+ {
+ num /= 10;
+ buf[Width - 2] = '0' + num % 10; // Tens.
+ }
+
+ if (Width > 2)
+ {
+ num /= 10;
+ buf[Width - 3] = '0' + num % 10; // Hundreds.
+ }
+
+ if (Width > 3)
+ {
+ num /= 10;
+ buf[Width - 4] = '0' + num % 10; // Thousands.
+ }
+
+ if (Width > 4)
+ {
+ num /= 10;
+ buf[Width - 5] = '0' + num % 10; // Ten-Thousands.
+ }
+
+ if (Width > 5)
+ {
+ num /= 10;
+ buf[Width - 6] = '0' + num % 10; // Hundred-Thousands.
+ }
+
+ static_assert(Width >= 1 && Width <= 6, "Width is invalid.");
+ }
+
+ /// Copy a null-terminated string into another.
+ /// Expects the destination to be large enough.
+ /// Note: unlike strcpy, this returns the *new* out
+ /// (destination) pointer, which saves a strlen call.
+ char* strcopy(const char* in, char* out)
+ {
+ while (*in)
+ *out++ = *in++;
+ return out;
+ }
+
+ /// Convert unsigned long num to base-10 ascii in place.
+ /// Returns the *end* position.
+ char* to_ascii(char* buf, size_t num)
+ {
+ int i = 0;
+ do
+ {
+ buf[i++] = '0' + num % 10;
+ num /= 10;
+ } while (num > 0);
+
+ // Reverse.
+ for (char *front = buf, *back = buf + i - 1; back > front; ++front,
--back)
+ {
+ const char t = *front;
+ *front = *back;
+ *back = t;
+ }
+
+ return buf + i;
+ }
+
+ char* prefix(const Poco::DateTime& time, char* buffer, const char* level)
+ {
+ // Note that snprintf is deemed signal-safe in most common
implementations.
+ char* pos = strcopy((Source.getInited() ? Source.getId().c_str() :
"<shutdown>"), buffer);
+ *pos++ = '-';
+
+ // Thread ID.
#ifdef __linux
const long osTid = Util::getThreadId();
- // Note that snprintf is deemed signal-safe in most common
implementations.
- snprintf(buffer, len, "%s-%.05lu %.4u-%.2u-%.2u %.2u:%.2u:%.2u.%.6u [
%s ] %s ",
- (Source.getInited() ? Source.getId().c_str() :
"<shutdown>"),
- osTid,
- time.year(), time.month(), time.day(),
- time.hour(), time.minute(), time.second(),
- time.millisecond() * 1000 + time.microsecond(),
- threadName, level);
+ if (osTid > 99999)
+ {
+ if (osTid > 999999)
+ pos = to_ascii(pos, osTid);
+ else
+ {
+ to_ascii_fixed<6>(pos, osTid);
+ pos += 6;
+ }
+ }
+ else
+ {
+ to_ascii_fixed<5>(pos, osTid);
+ pos += 5;
+ }
#elif defined IOS
uint64_t osTid;
pthread_threadid_np(nullptr, &osTid);
- snprintf(buffer, len, "%s-%#.05llx %.4u-%.2u-%.2u %.2u:%.2u:%.2u.%.6u
[ %s ] %s ",
- (Source.getInited() ? Source.getId().c_str() :
"<shutdown>"),
- osTid,
- time.year(), time.month(), time.day(),
- time.hour(), time.minute(), time.second(),
- time.millisecond() * 1000 + time.microsecond(),
- threadName, level);
+ snprintf(pos, 32, "%#.05llx", osTid);
+ while (*pos++); // Skip to end.
#endif
+
+ // YYYY-MM-DD.
+ *pos++ = ' ';
+ to_ascii_fixed<4>(pos, time.year());
+ pos[4] = '-';
+ pos += 5;
+ to_ascii_fixed<2>(pos, time.month());
+ pos[2] = '-';
+ pos += 3;
+ to_ascii_fixed<2>(pos, time.day());
+ pos[2] = ' ';
+ pos += 3;
+
+ // HH:MM:SS.uS
+ to_ascii_fixed<2>(pos, time.hour());
+ pos[2] = ':';
+ pos += 3;
+ to_ascii_fixed<2>(pos, time.minute());
+ pos[2] = ':';
+ pos += 3;
+ to_ascii_fixed<2>(pos, time.second());
+ pos[2] = '.';
+ pos += 3;
+ to_ascii_fixed<6>(pos, time.millisecond() * 1000 + time.microsecond());
+ pos[6] = ' ';
+ pos[7] = '[';
+ pos[8] = ' ';
+ pos += 9;
+
+ pos = strcopy(Util::getThreadName(), pos);
+ pos[0] = ' ';
+ pos[1] = ']';
+ pos[2] = ' ';
+ pos += 3;
+ pos = strcopy(level, pos);
+ pos[0] = ' ';
+ pos[1] = ' ';
+ pos[2] = '\0';
+
return buffer;
}
void signalLogPrefix()
{
char buffer[1024];
- prefix(buffer, sizeof(buffer) - 1, "SIG");
+ prefix<sizeof(buffer) - 1>(buffer, "SIG");
signalLog(buffer);
}
diff --git a/common/Log.hpp b/common/Log.hpp
index bc96035e9..604c66ac7 100644
--- a/common/Log.hpp
+++ b/common/Log.hpp
@@ -67,7 +67,15 @@ namespace Log
constexpr bool isShutdownCalled() { return false; }
#endif
- char* prefix(char* buffer, std::size_t len, const char* level);
+ /// Generates log entry prefix. Example follows (without the pipes).
+ /// |wsd-07272-07298 2020-04-25 17:29:28.928697 [ websrv_poll ] TRC |
+ /// This is fully signal-safe. Buffer must be at least 128 bytes.
+ char* prefix(const Poco::DateTime& time, char* buffer, const char* level);
+ template <int Size> inline char* prefix(char buffer[Size], const char*
level)
+ {
+ static_assert(Size >= 128, "Buffer size must be at least 128 bytes.");
+ return prefix(Poco::DateTime(), buffer, level);
+ }
inline bool traceEnabled() { return logger().trace(); }
inline bool debugEnabled() { return logger().debug(); }
@@ -109,7 +117,7 @@ namespace Log
_enabled(true)
{
char buffer[1024];
- _stream << prefix(buffer, sizeof(buffer) - 1, level);
+ _stream << prefix<sizeof(buffer) - 1>(buffer, level);
}
StreamLogger(StreamLogger&& sl) noexcept
@@ -274,7 +282,7 @@ namespace Log
#define LOG_BODY_(LOG, PRIO, LVL, X, FILEP)
\
char b_[1024];
\
- std::ostringstream oss_(Log::prefix(b_, sizeof(b_) - 1, LVL),
std::ostringstream::ate); \
+ std::ostringstream oss_(Log::prefix<sizeof(b_) - 1>(b_, LVL),
std::ostringstream::ate); \
oss_ << std::boolalpha << X;
\
LOG_END(oss_, FILEP);
\
((void)__android_log_print(ANDROID_LOG_DEBUG, "loolwsd", "%s %s", LVL,
oss_.str().c_str()))
@@ -282,13 +290,11 @@ namespace Log
#else
#define LOG_BODY_(LOG, PRIO, LVL, X, FILEP)
\
- Poco::Message m_(LOG.name(), "", Poco::Message::PRIO_##PRIO);
\
char b_[1024];
\
- std::ostringstream oss_(Log::prefix(b_, sizeof(b_) - 1, LVL),
std::ostringstream::ate); \
+ std::ostringstream oss_(Log::prefix<sizeof(b_) - 1>(b_, LVL),
std::ostringstream::ate); \
oss_ << std::boolalpha << X;
\
LOG_END(oss_, FILEP);
\
- m_.setText(oss_.str());
\
- LOG.log(m_);
+ LOG.log(Poco::Message(LOG.name(), oss_.str(), Poco::Message::PRIO_##PRIO));
#endif
_______________________________________________
Libreoffice-commits mailing list
libreoffice-comm...@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/libreoffice-commits
