Skip to content
This repository has been archived by the owner on Aug 8, 2023. It is now read-only.

Move logging off the main thread #16325

Merged
merged 3 commits into from
Apr 1, 2020
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
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
4 changes: 4 additions & 0 deletions CHANGELOG.md
Original file line number Diff line number Diff line change
Expand Up @@ -2,6 +2,10 @@

## master

### ✨ New features

- [core] Move logging off the main thread ([#16325](https://github.com/mapbox/mapbox-gl-native/pull/16325))

## maps-v1.5.0

### ✨ New features
Expand Down
16 changes: 15 additions & 1 deletion include/mbgl/util/logging.hpp
Original file line number Diff line number Diff line change
Expand Up @@ -3,6 +3,7 @@
#include <mbgl/util/event.hpp>

#include <mbgl/util/noncopyable.hpp>
#include <mbgl/util/optional.hpp>

#include <memory>
#include <string>
Expand Down Expand Up @@ -36,6 +37,11 @@ class Log {
}

public:
Log();
~Log();

static void useLogThread(bool enable);

template <typename ...Args>
static void Debug(Event event, Args&& ...args) {
Record(EventSeverity::Debug, event, ::std::forward<Args>(args)...);
Expand Down Expand Up @@ -66,15 +72,23 @@ class Log {
}

private:
static Log* get() noexcept;

static void record(EventSeverity severity, Event event, const std::string &msg);
static void record(EventSeverity severity, Event event, const char* format = "", ...);
static void record(EventSeverity severity, Event event, int64_t code, const char* format = "", ...);
static void record(EventSeverity severity, Event event, int64_t code, const std::string &msg);
static void record(EventSeverity severity,
Event event,
int64_t code,
const std::string& msg,
const optional<std::string>& threadName);

// This method is the data sink that must be implemented by each platform we
// support. It should ideally output the error message in a human readable
// format to the developer.
static void platformRecord(EventSeverity severity, const std::string &msg);
class Impl;
const std::unique_ptr<Impl> impl;
};

} // namespace mbgl
53 changes: 47 additions & 6 deletions src/mbgl/util/logging.cpp
Original file line number Diff line number Diff line change
@@ -1,5 +1,7 @@
#include <mbgl/util/logging.hpp>
#include <mbgl/actor/scheduler.hpp>
#include <mbgl/platform/settings.hpp>
#include <mbgl/util/enum.hpp>
#include <mbgl/util/logging.hpp>
#include <mbgl/util/platform.hpp>

#include <cstdio>
Expand All @@ -11,21 +13,55 @@ namespace mbgl {
namespace {

std::unique_ptr<Log::Observer> currentObserver;
std::atomic<bool> useThread(true);
std::mutex mutex;

} // namespace

class Log::Impl {
public:
Impl() : scheduler(Scheduler::GetSequenced()) {}

void record(EventSeverity severity, Event event, int64_t code, const std::string& msg) {
if (useThread) {
auto threadName = platform::getCurrentThreadName();
scheduler->schedule([=]() { Log::record(severity, event, code, msg, threadName); });
} else {
Log::record(severity, event, code, msg, {});
}
}

private:
const std::shared_ptr<Scheduler> scheduler;
};

Log::Log() : impl(std::make_unique<Impl>()) {}

Log::~Log() = default;

Log* Log::get() noexcept {
static Log instance;
return &instance;
}

void Log::useLogThread(bool enable) {
useThread = enable;
}

void Log::setObserver(std::unique_ptr<Observer> observer) {
std::lock_guard<std::mutex> lock(mutex);
currentObserver = std::move(observer);
}

std::unique_ptr<Log::Observer> Log::removeObserver() {
std::lock_guard<std::mutex> lock(mutex);
std::unique_ptr<Observer> observer;
std::swap(observer, currentObserver);
return observer;
}

void Log::record(EventSeverity severity, Event event, const std::string &msg) {
record(severity, event, -1, msg);
get()->impl->record(severity, event, -1, msg);
}

void Log::record(EventSeverity severity, Event event, const char* format, ...) {
Expand All @@ -35,7 +71,7 @@ void Log::record(EventSeverity severity, Event event, const char* format, ...) {
vsnprintf(msg, sizeof(msg), format, args);
va_end(args);

record(severity, event, -1, std::string{ msg });
get()->impl->record(severity, event, -1, std::string{msg});
}

void Log::record(EventSeverity severity, Event event, int64_t code, const char* format, ...) {
Expand All @@ -45,18 +81,23 @@ void Log::record(EventSeverity severity, Event event, int64_t code, const char*
vsnprintf(msg, sizeof(msg), format, args);
va_end(args);

record(severity, event, code, std::string{ msg });
get()->impl->record(severity, event, code, std::string{msg});
}

void Log::record(EventSeverity severity, Event event, int64_t code, const std::string &msg) {
void Log::record(EventSeverity severity,
Event event,
int64_t code,
const std::string& msg,
const optional<std::string>& threadName) {
std::lock_guard<std::mutex> lock(mutex);
if (currentObserver && severity != EventSeverity::Debug &&
currentObserver->onRecord(severity, event, code, msg)) {
Copy link
Contributor

Choose a reason for hiding this comment

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

This may be a breaking behavior change. Where thread safety should be implemented? On client side or we need to post currentObserver->onRecord invocation on the thread where setObserver was called?

Copy link
Contributor

Choose a reason for hiding this comment

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

What was the outcome of this?

Copy link
Contributor

Choose a reason for hiding this comment

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

I like the idea of the developer providing the thread/queue for logging, rather than one being created, but that feels like a possible follow-on?

Copy link
Contributor Author

Choose a reason for hiding this comment

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

This question was more directed to Android and iOS, and both have now confirmed that the log observers are thread safe.

Regarding the developer providing the thread/queue, it can be a possible follow-up in case there's a need for it.

return;
}

std::stringstream logStream;

logStream << "{" << platform::getCurrentThreadName() << "}";
logStream << "{" << threadName.value_or(platform::getCurrentThreadName()) << "}";
logStream << "[" << Enum<Event>::toString(event) << "]";

if (code >= 0) {
Expand Down
1 change: 1 addition & 0 deletions test/src/mbgl/test/fixture_log_observer.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -60,6 +60,7 @@ size_t FixtureLog::Observer::count(const Message& message, bool substring) const

FixtureLog::FixtureLog() : observer(new FixtureLogObserver(this)) {
Log::setObserver(std::unique_ptr<Log::Observer>(observer));
Log::useLogThread(false);
Copy link
Contributor

Choose a reason for hiding this comment

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

Is there a test where useThread is true?

Copy link
Contributor Author

Choose a reason for hiding this comment

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

All other tests that don't count the number of log messages have useThread == true

}

bool FixtureLog::empty() const {
Expand Down