From: Adam Simpkins Date: Tue, 20 Jun 2017 18:01:55 +0000 (-0700) Subject: logging: add a NEVER_DISCARD flag to LogWriter X-Git-Tag: v2017.06.26.00~39 X-Git-Url: http://demsky.eecs.uci.edu/git/?a=commitdiff_plain;h=84458670bb24056e0bb65d50b1653dcf0636f776;p=folly.git logging: add a NEVER_DISCARD flag to LogWriter Summary: Add a flag to the LogWriter so we can ensure that particular messages are never discarded, even when the LogWriter is throttling messages. This functionality will be necessary to implement `FB_LOG(FATAL)` to that we can avoid discarding the reason for crashing. Reviewed By: wez Differential Revision: D5189498 fbshipit-source-id: dc4322ea5ba449a341cdbdc32afb0ed466019801 --- diff --git a/folly/experimental/logging/AsyncFileWriter.cpp b/folly/experimental/logging/AsyncFileWriter.cpp index 3aab81ad..61c379fe 100644 --- a/folly/experimental/logging/AsyncFileWriter.cpp +++ b/folly/experimental/logging/AsyncFileWriter.cpp @@ -36,13 +36,14 @@ AsyncFileWriter::~AsyncFileWriter() { ioThread_.join(); } -void AsyncFileWriter::writeMessage(StringPiece buffer) { - return writeMessage(buffer.str()); +void AsyncFileWriter::writeMessage(StringPiece buffer, uint32_t flags) { + return writeMessage(buffer.str(), flags); } -void AsyncFileWriter::writeMessage(std::string&& buffer) { +void AsyncFileWriter::writeMessage(std::string&& buffer, uint32_t flags) { auto data = data_.lock(); - if (data->currentBufferSize >= data->maxBufferBytes) { + if ((data->currentBufferSize >= data->maxBufferBytes) && + !(flags & NEVER_DISCARD)) { ++data->numDiscarded; return; } diff --git a/folly/experimental/logging/AsyncFileWriter.h b/folly/experimental/logging/AsyncFileWriter.h index 0d05ccd3..890ae808 100644 --- a/folly/experimental/logging/AsyncFileWriter.h +++ b/folly/experimental/logging/AsyncFileWriter.h @@ -56,8 +56,8 @@ class AsyncFileWriter : public LogWriter { ~AsyncFileWriter(); - void writeMessage(folly::StringPiece buffer) override; - void writeMessage(std::string&& buffer) override; + void writeMessage(folly::StringPiece buffer, uint32_t flags = 0) override; + void writeMessage(std::string&& buffer, uint32_t flags = 0) override; /** * Block until the I/O thread has finished writing all messages that diff --git a/folly/experimental/logging/ImmediateFileWriter.cpp b/folly/experimental/logging/ImmediateFileWriter.cpp index 040c5c60..4135be67 100644 --- a/folly/experimental/logging/ImmediateFileWriter.cpp +++ b/folly/experimental/logging/ImmediateFileWriter.cpp @@ -29,7 +29,9 @@ ImmediateFileWriter::ImmediateFileWriter(StringPiece path) ImmediateFileWriter::ImmediateFileWriter(folly::File&& file) : file_{std::move(file)} {} -void ImmediateFileWriter::writeMessage(StringPiece buffer) { +void ImmediateFileWriter::writeMessage( + StringPiece buffer, + uint32_t /* flags */) { // Write the data. // We are doing direct file descriptor writes here, so there is no buffering // of log message data. Each message is immediately written to the output. diff --git a/folly/experimental/logging/ImmediateFileWriter.h b/folly/experimental/logging/ImmediateFileWriter.h index a029e73f..9703cca2 100644 --- a/folly/experimental/logging/ImmediateFileWriter.h +++ b/folly/experimental/logging/ImmediateFileWriter.h @@ -47,7 +47,7 @@ class ImmediateFileWriter : public LogWriter { explicit ImmediateFileWriter(folly::File&& file); using LogWriter::writeMessage; - void writeMessage(folly::StringPiece buffer) override; + void writeMessage(folly::StringPiece buffer, uint32_t flags = 0) override; private: ImmediateFileWriter(ImmediateFileWriter const&) = delete; diff --git a/folly/experimental/logging/LogWriter.h b/folly/experimental/logging/LogWriter.h index e5b2ffe5..6d6158c9 100644 --- a/folly/experimental/logging/LogWriter.h +++ b/folly/experimental/logging/LogWriter.h @@ -24,12 +24,32 @@ namespace folly { */ class LogWriter { public: + /** + * Bit flag values for use with writeMessage() + */ + enum Flags : uint32_t { + NO_FLAGS = 0x00, + /** + * Ensure that this log message never gets discarded. + * + * Some LogWriter implementations may discard messages when messages are + * being received faster than they can be written. This flag ensures that + * this message will never be discarded. + * + * This flag is used to ensure that LOG(FATAL) messages never get + * discarded, so we always report the reason for a crash. + */ + NEVER_DISCARD = 0x01, + }; + virtual ~LogWriter() {} /** * Write a serialized log message. + * + * The flags parameter is a bitwise-ORed set of Flag values defined above. */ - virtual void writeMessage(folly::StringPiece buffer) = 0; + virtual void writeMessage(folly::StringPiece buffer, uint32_t flags = 0) = 0; /** * Write a serialized message. @@ -39,8 +59,8 @@ class LogWriter { * writeMessage(), but subclasses may override this implementation if * desired. */ - virtual void writeMessage(std::string&& buffer) { - writeMessage(folly::StringPiece{buffer}); + virtual void writeMessage(std::string&& buffer, uint32_t flags = 0) { + writeMessage(folly::StringPiece{buffer}, flags); } }; } diff --git a/folly/experimental/logging/test/AsyncFileWriterTest.cpp b/folly/experimental/logging/test/AsyncFileWriterTest.cpp index d1541dc5..1f98a421 100644 --- a/folly/experimental/logging/test/AsyncFileWriterTest.cpp +++ b/folly/experimental/logging/test/AsyncFileWriterTest.cpp @@ -43,6 +43,7 @@ DEFINE_int64( "the AsyncFileWriter.discard test"); using namespace folly; +using namespace std::literals::chrono_literals; using folly::test::TemporaryFile; TEST(AsyncFileWriter, noMessages) { @@ -137,15 +138,30 @@ TEST(AsyncFileWriter, ioError) { /** * writeThread() writes a series of messages to the AsyncFileWriter */ -void writeThread(AsyncFileWriter* writer, size_t id, size_t numMessages) { +void writeThread( + AsyncFileWriter* writer, + size_t id, + size_t numMessages, + uint32_t flags) { for (size_t n = 0; n < numMessages; ++n) { writer->writeMessage( - folly::to("thread ", id, " message ", n + 1, '\n')); + folly::to("thread ", id, " message ", n + 1, '\n'), flags); } } class ReadStats { public: + ReadStats() + : readSleepUS_{static_cast( + std::min(0L, FLAGS_async_discard_read_sleep_usec))} {} + + void clearSleepDuration() { + readSleepUS_.store(0); + } + std::chrono::microseconds getSleepUS() const { + return std::chrono::microseconds{readSleepUS_.load()}; + } + void check(size_t numThreads, size_t messagesPerThread) { EXPECT_EQ("", trailingData_); EXPECT_EQ(numThreads, writers_.size()); @@ -162,6 +178,14 @@ class ReadStats { numThreads * messagesPerThread, totalMessagesReceived + numDiscarded_); } + /** + * Check that no messages were dropped from the specified thread. + */ + void checkNoDrops(size_t threadIndex, size_t messagesPerThread) { + EXPECT_EQ(writers_[threadIndex].numMessages, messagesPerThread); + EXPECT_EQ(writers_[threadIndex].lastId, messagesPerThread); + } + void messageReceived(StringPiece msg) { if (msg.endsWith(" log messages discarded: " "logging faster than we can write")) { @@ -240,6 +264,8 @@ class ReadStats { size_t numUnableToParse_{0}; size_t numOutOfOrder_{0}; size_t numDiscarded_{0}; + + std::atomic readSleepUS_; }; /** @@ -253,7 +279,7 @@ void readThread(folly::File&& file, ReadStats* stats) { size_t bufferIdx = 0; while (true) { /* sleep override */ - usleep(FLAGS_async_discard_read_sleep_usec); + usleep(stats->getSleepUS().count()); auto readResult = folly::readNoInt( file.fd(), buffer.data() + bufferIdx, buffer.size() - bufferIdx); @@ -306,6 +332,11 @@ TEST(AsyncFileWriter, discard) { folly::File readPipe{fds[0], true}; folly::File writePipe{fds[1], true}; + // This test should always be run with at least 2 writer threads. + // The last one will use the NEVER_DISCARD flag, and we want at least + // one that does discard messages. + ASSERT_GT(FLAGS_async_discard_num_writer_threads, 2); + ReadStats readStats; std::thread reader(readThread, std::move(readPipe), &readStats); { @@ -313,8 +344,18 @@ TEST(AsyncFileWriter, discard) { std::vector writeThreads; for (int n = 0; n < FLAGS_async_discard_num_writer_threads; ++n) { + uint32_t flags = 0; + // Configure the last writer thread to never drop messages + if (n == (FLAGS_async_discard_num_writer_threads - 1)) { + flags = LogWriter::NEVER_DISCARD; + } + writeThreads.emplace_back( - writeThread, &writer, n, FLAGS_async_discard_messages_per_writer); + writeThread, + &writer, + n, + FLAGS_async_discard_messages_per_writer, + flags); } for (auto& t : writeThreads) { @@ -322,8 +363,15 @@ TEST(AsyncFileWriter, discard) { } fprintf(stderr, "writers done\n"); } + // Clear the read sleep duration so the reader will finish quickly now + readStats.clearSleepDuration(); reader.join(); readStats.check( FLAGS_async_discard_num_writer_threads, FLAGS_async_discard_messages_per_writer); + // Check that no messages were dropped from the thread using the + // NEVER_DISCARD flag. + readStats.checkNoDrops( + FLAGS_async_discard_num_writer_threads - 1, + FLAGS_async_discard_messages_per_writer); } diff --git a/folly/experimental/logging/test/StandardLogHandlerTest.cpp b/folly/experimental/logging/test/StandardLogHandlerTest.cpp index c34366d7..8ea4efee 100644 --- a/folly/experimental/logging/test/StandardLogHandlerTest.cpp +++ b/folly/experimental/logging/test/StandardLogHandlerTest.cpp @@ -49,7 +49,8 @@ class TestLogFormatter : public LogFormatter { class TestLogWriter : public LogWriter { public: - void writeMessage(folly::StringPiece buffer) override { + void writeMessage(folly::StringPiece buffer, uint32_t /* flags */ = 0) + override { messages_.emplace_back(buffer.str()); }