Merge pull request #41733 from avitebskiy:feature/log-sinks

PiperOrigin-RevId: 343346573
Change-Id: I1432a9b5dadd8d28dc20ee223735a375e452c441
This commit is contained in:
TensorFlower Gardener 2020-11-19 12:47:15 -08:00
commit 5f9f2d21d2
6 changed files with 303 additions and 82 deletions

View File

@ -72,6 +72,14 @@ config_setting(
visibility = ["//visibility:public"],
)
# Config setting that disables the default logger, only logging
# to registered TFLogSinks
config_setting(
name = "no_default_logger",
define_values = {"no_default_logger": "true"},
visibility = ["//visibility:public"],
)
# Config setting for determining if we are building for Android.
config_setting(
name = "android",

View File

@ -202,6 +202,7 @@ cc_library(
"//tensorflow/core/platform",
"//tensorflow/core/platform:env_time",
"//tensorflow/core/platform:macros",
"//tensorflow/core/platform:mutex",
"//tensorflow/core/platform:types",
"@com_google_absl//absl/base",
"@com_google_absl//absl/strings",

View File

@ -20,6 +20,7 @@ limitations under the License.
#include "absl/base/internal/sysinfo.h"
#include "tensorflow/core/platform/env_time.h"
#include "tensorflow/core/platform/macros.h"
#include "tensorflow/core/platform/mutex.h"
#if defined(PLATFORM_POSIX_ANDROID)
#include <android/log.h>
@ -31,30 +32,135 @@ limitations under the License.
#include <string.h>
#include <time.h>
#include <string>
#include <algorithm>
#include <queue>
#include <unordered_map>
namespace tensorflow {
void TFAddLogSink(TFLogSink* sink) {
// LogSink is not implemented.
// If necessary, one can add the log sink support as follows.
// 1. Define a global vector<TFLogSink> to keep track of all registered
// TFLogSink objects. Protect the global vector with mutex to make it
// thread-safe.
// 2. Add/remove elements from the global vector<TFLogSink> in TFAddLogSink
// and TFRemoveLogSink function
// 3. Add logic in LogMessage::GenerateLogMessage() below to dispatch log
// messages to all the registered log sinks.
}
void TFRemoveLogSink(TFLogSink* sink) {
// LogSink is not implemented.
}
namespace internal {
namespace {
// This is an internal singleton class that manages the log sinks. It allows
// adding and removing the log sinks, as well as handling sending log messages
// to all the registered log sinks.
class TFLogSinks {
public:
// Gets the TFLogSinks instance. This is the entry point for using this class.
static TFLogSinks& Instance();
// Adds a log sink. The sink argument must not be a nullptr. TFLogSinks
// takes ownership of the pointer, the user must not free the pointer.
// The pointer will remain valid until the application terminates or
// until TFLogSinks::Remove is called for the same pointer value.
void Add(TFLogSink* sink);
// Removes a log sink. This will also erase the sink object. The pointer
// to the sink becomes invalid after this call.
void Remove(TFLogSink* sink);
// Gets the currently registered log sinks.
std::vector<TFLogSink*> GetSinks() const;
// Sends a log message to all registered log sinks.
//
// If there are no log sinks are registered:
//
// NO_DEFAULT_LOGGER is defined:
// Up to 128 messages will be queued until a log sink is added.
// The queue will then be logged to the first added log sink.
//
// NO_DEFAULT_LOGGER is not defined:
// The messages will be logged using the default logger. The default logger
// will log to stdout on all platforms except for Android. On Androit the
// default Android logger will be used.
void Send(const TFLogEntry& entry);
private:
TFLogSinks();
void SendToSink(TFLogSink& sink, const TFLogEntry& entry);
std::queue<TFLogEntry> log_entry_queue_;
static const size_t kMaxLogEntryQueueSize = 128;
mutable tensorflow::mutex mutex_;
std::vector<TFLogSink*> sinks_;
};
TFLogSinks::TFLogSinks() {
#ifndef NO_DEFAULT_LOGGER
static TFDefaultLogSink* default_sink = new TFDefaultLogSink();
sinks_.emplace_back(default_sink);
#endif
}
TFLogSinks& TFLogSinks::Instance() {
static TFLogSinks* instance = new TFLogSinks();
return *instance;
}
void TFLogSinks::Add(TFLogSink* sink) {
assert(sink != nullptr && "The sink must not be a nullptr");
tensorflow::mutex_lock lock(mutex_);
sinks_.emplace_back(sink);
// If this is the only sink log all the queued up messages to this sink
if (sinks_.size() == 1) {
while (!log_entry_queue_.empty()) {
for (const auto& sink : sinks_) {
SendToSink(*sink, log_entry_queue_.front());
}
log_entry_queue_.pop();
}
}
}
void TFLogSinks::Remove(TFLogSink* sink) {
assert(sink != nullptr && "The sink must not be a nullptr");
tensorflow::mutex_lock lock(mutex_);
auto it = std::find(sinks_.begin(), sinks_.end(), sink);
if (it != sinks_.end()) sinks_.erase(it);
}
std::vector<TFLogSink*> TFLogSinks::GetSinks() const {
tensorflow::mutex_lock lock(mutex_);
return sinks_;
}
void TFLogSinks::Send(const TFLogEntry& entry) {
tensorflow::mutex_lock lock(mutex_);
// If we don't have any sinks registered, queue them up
if (sinks_.empty()) {
// If we've exceeded the maximum queue size, drop the oldest entries
while (log_entry_queue_.size() >= kMaxLogEntryQueueSize) {
log_entry_queue_.pop();
}
log_entry_queue_.push(entry);
return;
}
// If we have items in the queue, push them out first
while (!log_entry_queue_.empty()) {
for (const auto& sink : sinks_) {
SendToSink(*sink, log_entry_queue_.front());
}
log_entry_queue_.pop();
}
// ... and now we can log the current log entry
for (const auto& sink : sinks_) {
SendToSink(*sink, entry);
}
}
void TFLogSinks::SendToSink(TFLogSink& sink, const TFLogEntry& entry) {
sink.Send(entry);
sink.WaitTillSent();
}
int ParseInteger(const char* str, size_t size) {
// Ideally we would use env_var / safe_strto64, but it is
// hard to use here without pulling in a lot of dependencies,
@ -197,70 +303,10 @@ LogMessage::~LogMessage() {
}
}
#if defined(PLATFORM_POSIX_ANDROID)
void LogMessage::GenerateLogMessage() {
int android_log_level;
switch (severity_) {
case INFO:
android_log_level = ANDROID_LOG_INFO;
break;
case WARNING:
android_log_level = ANDROID_LOG_WARN;
break;
case ERROR:
android_log_level = ANDROID_LOG_ERROR;
break;
case FATAL:
android_log_level = ANDROID_LOG_FATAL;
break;
default:
if (severity_ < INFO) {
android_log_level = ANDROID_LOG_VERBOSE;
} else {
android_log_level = ANDROID_LOG_ERROR;
}
break;
}
std::stringstream ss;
const char* const partial_name = strrchr(fname_, '/');
ss << (partial_name != nullptr ? partial_name + 1 : fname_) << ":" << line_
<< " " << str();
__android_log_write(android_log_level, "native", ss.str().c_str());
// Also log to stderr (for standalone Android apps).
fprintf(stderr, "native : %s\n", ss.str().c_str());
// Android logging at level FATAL does not terminate execution, so abort()
// is still required to stop the program.
if (severity_ == FATAL) {
abort();
}
TFLogSinks::Instance().Send(TFLogEntry(severity_, fname_, line_, str()));
}
#else
void LogMessage::GenerateLogMessage() {
static bool log_thread_id = EmitThreadIdFromEnv();
uint64 now_micros = EnvTime::NowMicros();
time_t now_seconds = static_cast<time_t>(now_micros / 1000000);
int32 micros_remainder = static_cast<int32>(now_micros % 1000000);
const size_t time_buffer_size = 30;
char time_buffer[time_buffer_size];
strftime(time_buffer, time_buffer_size, "%Y-%m-%d %H:%M:%S",
localtime(&now_seconds));
const size_t tid_buffer_size = 10;
char tid_buffer[tid_buffer_size] = "";
if (log_thread_id) {
snprintf(tid_buffer, sizeof(tid_buffer), " %7u",
absl::base_internal::GetTID());
}
// TODO(jeff,sanjay): Replace this with something that logs through the env.
fprintf(stderr, "%s.%06d: %c%s %s:%d] %s\n", time_buffer, micros_remainder,
"IWEF"[severity_], tid_buffer, fname_, line_, str().c_str());
}
#endif
int64 LogMessage::MinVLogLevel() {
static int64 min_vlog_level = MinVLogLevelFromEnv();
return min_vlog_level;
@ -393,4 +439,104 @@ bool LogEveryNSecState::ShouldLog(double seconds) {
}
} // namespace internal
void TFAddLogSink(TFLogSink* sink) {
internal::TFLogSinks::Instance().Add(sink);
}
void TFRemoveLogSink(TFLogSink* sink) {
internal::TFLogSinks::Instance().Remove(sink);
}
std::vector<TFLogSink*> TFGetLogSinks() {
return internal::TFLogSinks::Instance().GetSinks();
}
void TFDefaultLogSink::Send(const TFLogEntry& entry) {
#ifdef PLATFORM_POSIX_ANDROID
int android_log_level;
switch (entry.log_severity()) {
case absl::LogSeverity::kInfo:
android_log_level = ANDROID_LOG_INFO;
break;
case absl::LogSeverity::kWarning:
android_log_level = ANDROID_LOG_WARN;
break;
case absl::LogSeverity::kError:
android_log_level = ANDROID_LOG_ERROR;
break;
case absl::LogSeverity::kFatal:
android_log_level = ANDROID_LOG_FATAL;
break;
default:
if (entry.log_severity() < absl::LogSeverity::kInfo) {
android_log_level = ANDROID_LOG_VERBOSE;
} else {
android_log_level = ANDROID_LOG_ERROR;
}
break;
}
std::stringstream ss;
const auto& fname = entry.FName();
auto pos = fname.find("/");
ss << (pos != std::string::npos ? fname.substr(pos + 1) : fname) << ":"
<< entry.Line() << " " << entry.ToString();
__android_log_write(android_log_level, "native", ss.str().c_str());
// Also log to stderr (for standalone Android apps).
std::cerr << "native : " << ss.str() << std::endl;
// Android logging at level FATAL does not terminate execution, so abort()
// is still required to stop the program.
if (entry.log_severity() == absl::LogSeverity::kFatal) {
abort();
}
#else // PLATFORM_POSIX_ANDROID
static bool log_thread_id = internal::EmitThreadIdFromEnv();
uint64 now_micros = EnvTime::NowMicros();
time_t now_seconds = static_cast<time_t>(now_micros / 1000000);
int32 micros_remainder = static_cast<int32>(now_micros % 1000000);
const size_t time_buffer_size = 30;
char time_buffer[time_buffer_size];
strftime(time_buffer, time_buffer_size, "%Y-%m-%d %H:%M:%S",
localtime(&now_seconds));
const size_t tid_buffer_size = 10;
char tid_buffer[tid_buffer_size] = "";
if (log_thread_id) {
snprintf(tid_buffer, sizeof(tid_buffer), " %7u",
absl::base_internal::GetTID());
}
char sev;
switch (entry.log_severity()) {
case absl::LogSeverity::kInfo:
sev = 'I';
break;
case absl::LogSeverity::kWarning:
sev = 'W';
break;
case absl::LogSeverity::kError:
sev = 'E';
break;
case absl::LogSeverity::kFatal:
sev = 'F';
break;
default:
assert(false && "Unknown logging severity");
sev = '?';
break;
}
// TODO(jeff,sanjay): Replace this with something that logs through the env.
fprintf(stderr, "%s.%06d: %c%s %s:%d] %s\n", time_buffer, micros_remainder,
sev, tid_buffer, entry.FName().c_str(), entry.Line(),
entry.ToString().c_str());
#endif // PLATFORM_POSIX_ANDROID
}
} // namespace tensorflow

View File

@ -23,6 +23,7 @@ limitations under the License.
#include <limits>
#include <memory>
#include <sstream>
#include <vector>
#include "absl/base/log_severity.h"
#include "absl/strings/string_view.h"
@ -477,15 +478,27 @@ class TFLogEntry {
}
public:
explicit TFLogEntry(int severity, absl::string_view log_line)
: severity_(AsAbslLogSeverity(severity)), log_line_(log_line) {}
explicit TFLogEntry(int severity, absl::string_view message)
: severity_(AsAbslLogSeverity(severity)), message_(message) {}
explicit TFLogEntry(int severity, absl::string_view fname, int line,
absl::string_view message)
: severity_(AsAbslLogSeverity(severity)),
fname_(fname),
line_(line),
message_(message) {}
absl::LogSeverity log_severity() const { return severity_; }
std::string ToString() const { return std::string(log_line_); }
std::string FName() const { return fname_; }
int Line() const { return line_; }
std::string ToString() const { return message_; }
absl::string_view text_message() const { return message_; }
private:
const absl::LogSeverity severity_;
const absl::string_view log_line_;
const std::string fname_;
int line_ = -1;
const std::string message_;
};
class TFLogSink {
@ -513,10 +526,23 @@ class TFLogSink {
virtual void WaitTillSent() {}
};
// This is the default log sink. This log sink is used if there are no other
// log sinks registered. To disable the default log sink, set the
// "no_default_logger" Bazel config setting to true or define a
// NO_DEFAULT_LOGGER preprocessor symbol. This log sink will always log to
// stderr.
class TFDefaultLogSink : public TFLogSink {
public:
void Send(const TFLogEntry& entry) override;
};
// Add or remove a `LogSink` as a consumer of logging data. Thread-safe.
void TFAddLogSink(TFLogSink* sink);
void TFRemoveLogSink(TFLogSink* sink);
// Get all the log sinks. Thread-safe.
std::vector<TFLogSink*> TFGetLogSinks();
} // namespace tensorflow
#endif // TENSORFLOW_CORE_PLATFORM_DEFAULT_LOGGING_H_

View File

@ -14,6 +14,10 @@ limitations under the License.
==============================================================================*/
#include "tensorflow/core/platform/logging.h"
#include <sstream>
#include <vector>
#include "tensorflow/core/platform/test.h"
namespace tensorflow {
@ -96,4 +100,33 @@ TEST(InternalLogString, Basic) {
internal::LogString(__FILE__, __LINE__, INFO, "Hello there");
}
class TestSink : public TFLogSink {
public:
void Send(const TFLogEntry& entry) override {
ss_ << entry.text_message() << std::endl;
}
std::string Get() const { return ss_.str(); }
private:
std::stringstream ss_;
};
TEST(LogSinkTest, testLogSinks) {
const int sinks_initial_size = TFGetLogSinks().size();
TestSink sink;
TFAddLogSink(&sink);
EXPECT_EQ(TFGetLogSinks().size(), sinks_initial_size + 1);
LOG(INFO) << "Foo";
LOG(INFO) << "Bar";
EXPECT_EQ(sink.Get(), "Foo\nBar\n");
TFRemoveLogSink(&sink);
EXPECT_EQ(TFGetLogSinks().size(), sinks_initial_size);
}
} // namespace tensorflow

View File

@ -119,6 +119,12 @@ def tf_portable_full_lite_protos(full, lite):
"//conditions:default": full,
})
def if_no_default_logger(a):
return select({
clean_dep("//tensorflow:no_default_logger"): a,
"//conditions:default": [],
})
def if_android_x86(a):
return select({
clean_dep("//tensorflow:android_x86"): a,
@ -332,6 +338,7 @@ def tf_copts(
if_android_arm(["-mfpu=neon"]) +
if_linux_x86_64(["-msse3"]) +
if_ios_x86_64(["-msse4.1"]) +
if_no_default_logger(["-DNO_DEFAULT_LOGGER"]) +
select({
clean_dep("//tensorflow:framework_shared_object"): [],
"//conditions:default": ["-DTENSORFLOW_MONOLITHIC_BUILD"],