From 645d8fcaf04010d6d6f8ebb30367a01f47b4c3fd Mon Sep 17 00:00:00 2001 From: Chen Shen Date: Tue, 13 Jul 2021 19:14:28 -0700 Subject: [PATCH] [logging][rfc] add RAY_LOG_EVERY_N and RAY_LOG_EVERY_MS (#17018) * introduce log-every-n * add n * linter * add license --- BUILD.bazel | 1 + LICENSE | 33 +++++++++++++++++ src/ray/util/logging.h | 70 ++++++++++++++++++++++++++++++++++++ src/ray/util/logging_test.cc | 49 +++++++++++++++++++++++++ 4 files changed, 153 insertions(+) diff --git a/BUILD.bazel b/BUILD.bazel index 4959ee06e130..31faa1c3f076 100644 --- a/BUILD.bazel +++ b/BUILD.bazel @@ -998,6 +998,7 @@ cc_test( deps = [ ":ray_util", "@boost//:asio", + "@com_google_absl//absl/strings:str_format", "@com_google_googletest//:gtest_main", ], ) diff --git a/LICENSE b/LICENSE index 8d41750f9a95..fb31d24900e9 100644 --- a/LICENSE +++ b/LICENSE @@ -307,3 +307,36 @@ distributed under the License is distributed on an "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the License for the specific language governing permissions and limitations under the License. + +-------------------------------------------------------------------------------- +Code in src/ray/util/logging.h is adapted from +https://github.com/google/glog/blob/master/src/glog/logging.h.in + +Copyright (c) 2008, Google Inc. +All rights reserved. + +Redistribution and use in source and binary forms, with or without +modification, are permitted provided that the following conditions are +met: + + * Redistributions of source code must retain the above copyright +notice, this list of conditions and the following disclaimer. + * Redistributions in binary form must reproduce the above +copyright notice, this list of conditions and the following disclaimer +in the documentation and/or other materials provided with the +distribution. + * Neither the name of Google Inc. nor the names of its +contributors may be used to endorse or promote products derived from +this software without specific prior written permission. + +THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS +"AS IS" AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT +LIMITED TO, THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR +A PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT +OWNER OR CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL, +SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT +LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF USE, +DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND ON ANY +THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT +(INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE +OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE. diff --git a/src/ray/util/logging.h b/src/ray/util/logging.h index 2789fd40661a..f46d03968c2b 100644 --- a/src/ray/util/logging.h +++ b/src/ray/util/logging.h @@ -11,9 +11,45 @@ // WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. // See the License for the specific language governing permissions and // limitations under the License. +// +// -------------------------------------------------------------- +// +// RAY_LOG_EVERY_N and RAY_LOG_EVERY_MS are adapted from +// https://github.com/google/glog/blob/master/src/glog/logging.h.in +// +// Copyright (c) 2008, Google Inc. +// All rights reserved. +// +// Redistribution and use in source and binary forms, with or without +// modification, are permitted provided that the following conditions are +// met: +// +// * Redistributions of source code must retain the above copyright +// notice, this list of conditions and the following disclaimer. +// * Redistributions in binary form must reproduce the above +// copyright notice, this list of conditions and the following disclaimer +// in the documentation and/or other materials provided with the +// distribution. +// * Neither the name of Google Inc. nor the names of its +// contributors may be used to endorse or promote products derived from +// this software without specific prior written permission. +// +// THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS +// "AS IS" AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT +// LIMITED TO, THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR +// A PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT +// OWNER OR CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL, +// SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT +// LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF USE, +// DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND ON ANY +// THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT +// (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE +// OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE. #pragma once +#include +#include #include #include @@ -84,6 +120,40 @@ enum class RayLogLevel { #endif // NDEBUG +// RAY_LOG_EVERY_N/RAY_LOG_EVERY_MS, adaped from +// https://github.com/google/glog/blob/master/src/glog/logging.h.in +#define RAY_LOG_EVERY_N_VARNAME(base, line) RAY_LOG_EVERY_N_VARNAME_CONCAT(base, line) +#define RAY_LOG_EVERY_N_VARNAME_CONCAT(base, line) base##line + +#define RAY_LOG_OCCURRENCES RAY_LOG_EVERY_N_VARNAME(occurrences_, __LINE__) + +#define RAY_LOG_EVERY_N(level, n) \ + static std::atomic RAY_LOG_OCCURRENCES(0); \ + if (ray::RayLog::IsLevelEnabled(ray::RayLogLevel::level) && \ + RAY_LOG_OCCURRENCES.fetch_add(1) % n == 0) \ + RAY_LOG_INTERNAL(ray::RayLogLevel::level) << "[" << RAY_LOG_OCCURRENCES - 1 << "] " + +/// Macros for RAY_LOG_EVERY_MS +#define RAY_LOG_TIME_PERIOD RAY_LOG_EVERY_N_VARNAME(timePeriod_, __LINE__) +#define RAY_LOG_PREVIOUS_TIME_RAW RAY_LOG_EVERY_N_VARNAME(previousTimeRaw_, __LINE__) +#define RAY_LOG_TIME_DELTA RAY_LOG_EVERY_N_VARNAME(deltaTime_, __LINE__) +#define RAY_LOG_CURRENT_TIME RAY_LOG_EVERY_N_VARNAME(currentTime_, __LINE__) +#define RAY_LOG_PREVIOUS_TIME RAY_LOG_EVERY_N_VARNAME(previousTime_, __LINE__) + +#define RAY_LOG_EVERY_MS(level, ms) \ + constexpr std::chrono::milliseconds RAY_LOG_TIME_PERIOD(ms); \ + static std::atomic RAY_LOG_PREVIOUS_TIME_RAW; \ + const auto RAY_LOG_CURRENT_TIME = std::chrono::steady_clock::now().time_since_epoch(); \ + const decltype(RAY_LOG_CURRENT_TIME) RAY_LOG_PREVIOUS_TIME( \ + RAY_LOG_PREVIOUS_TIME_RAW.load(std::memory_order_relaxed)); \ + const auto RAY_LOG_TIME_DELTA = RAY_LOG_CURRENT_TIME - RAY_LOG_PREVIOUS_TIME; \ + if (RAY_LOG_TIME_DELTA > RAY_LOG_TIME_PERIOD) \ + RAY_LOG_PREVIOUS_TIME_RAW.store(RAY_LOG_CURRENT_TIME.count(), \ + std::memory_order_relaxed); \ + if (ray::RayLog::IsLevelEnabled(ray::RayLogLevel::level) && \ + RAY_LOG_TIME_DELTA > RAY_LOG_TIME_PERIOD) \ + RAY_LOG_INTERNAL(ray::RayLogLevel::level) + // To make the logging lib plugable with other logging libs and make // the implementation unawared by the user, RayLog is only a declaration // which hide the implementation into logging.cc file. diff --git a/src/ray/util/logging_test.cc b/src/ray/util/logging_test.cc index 8ec90b76171e..d1875b9f66df 100644 --- a/src/ray/util/logging_test.cc +++ b/src/ray/util/logging_test.cc @@ -18,9 +18,13 @@ #include #include +#include "absl/strings/str_format.h" +#include "gmock/gmock.h" #include "gtest/gtest.h" #include "ray/util/filesystem.h" +using namespace testing; + namespace ray { int64_t current_time_ms() { @@ -55,6 +59,51 @@ TEST(PrintLogTest, LogTestWithoutInit) { PrintLog(); } +#if GTEST_HAS_STREAM_REDIRECTION +using testing::internal::CaptureStderr; +using testing::internal::GetCapturedStderr; + +TEST(PrintLogTest, TestRayLogEveryN) { + CaptureStderr(); + for (int i = 0; i < 10; i++) { + RAY_LOG_EVERY_N(INFO, 3) << "this is a test log"; + } + std::string output = GetCapturedStderr(); + for (int i = 0; i < 10; i++) { + std::string expected_str = absl::StrFormat("[%d] this is a test log", i); + if (i % 3 == 0) { + EXPECT_THAT(output, HasSubstr(expected_str)); + } else { + EXPECT_THAT(output, Not(HasSubstr(expected_str))); + } + } +} + +TEST(PrintLogTest, TestRayLogEveryMs) { + CaptureStderr(); + const std::string kLogStr = "this is a test log"; + auto start_time = std::chrono::steady_clock::now().time_since_epoch(); + size_t num_iterations = 0; + while (std::chrono::steady_clock::now().time_since_epoch() - start_time < + std::chrono::milliseconds(100)) { + num_iterations++; + RAY_LOG_EVERY_MS(INFO, 10) << kLogStr; + } + std::string output = GetCapturedStderr(); + size_t occurrences = 0; + std::string::size_type start = 0; + + while ((start = output.find(kLogStr, start)) != std::string::npos) { + ++occurrences; + start += kLogStr.length(); + } + EXPECT_LT(occurrences, num_iterations); + EXPECT_GT(occurrences, 5); + EXPECT_LT(occurrences, 15); +} + +#endif /* GTEST_HAS_STREAM_REDIRECTION */ + TEST(PrintLogTest, LogTestWithInit) { // Test empty app name. RayLog::StartRayLog("", RayLogLevel::DEBUG, ray::GetUserTempDir() + ray::GetDirSep());