[Log] new spdlog tool for ray by ashione · Pull Request #10967 · ray-project/ray

ashione · 2020-09-23T03:47:02Z

Motiviation:

For long running job, it'd better to support log rotation
For easily debug, we may change loglevel in runtime
Support multiple sinks. Ray core worker can only focus on itself log message if user want to reuse ray log tool in cpp worker, so application logs will not mixed with ray core informations.
More advanced functions: user-defined format pattern, async flush for high performace and trace session

Why are these changes needed?

A new log tool for users.

Related issue number

#10493

spdlog V.S. glog : https://docs.google.com/document/d/1pEXTLOhTFu5-va14Wj-tGoJD9tt_M_-JRMtxqd1JCyI

Checks

I've run scripts/format.sh to lint the changes in this PR.
I've included any doc changes needed for https://docs.ray.io/en/master/.
I've made sure the tests are passing. Note that there might be a few flaky tests, see the recent failures at https://flakey-tests.ray.io/
Testing Strategy
- Unit tests
- Release tests
- This PR is not tested :(

ashione · 2020-09-23T03:50:43Z

@rkooo567 @ericl

ashione · 2020-09-23T06:32:07Z

I test both glog and spdlog:
glog performance of Pertest in logging_test.cc
log file name pattern : LogPerfTest.20200923-142334.49592.log

[       OK ] LogPerfTest.PerfTest (10494 ms)
[----------] 1 test from LogPerfTest (10494 ms total)

spdlog : log file name pattern LogPerfTest_45421.log ( It can be modifed as same as glog)

Testing DEBUG log for 100000 rounds takes 0 ms.
Testing RAY_ERROR log for 100000 rounds takes 1210 ms.
Testing RAY_CHECK(true) for 100000 rounds takes 0 ms.
[       OK ] LogPerfTest.PerfTest (1239 ms)
[----------] 1 test from LogPerfTest (1239 ms total)

Only one difference is glog will produce log messages in both console(stdout) and log, but spdlog we define currently just flush them in log file.

kfstorm · 2020-09-23T06:36:03Z

Can you add some details about the motivation in the description?

ashione · 2020-09-23T06:39:22Z

Can you add some details about the motivation in the description?

More details you may find in this issue #10493 and its related event PR #10419

rkooo567 · 2020-09-23T19:48:20Z

So, does it mean spdlog is 10 times faster than glog in your workload?

Also, why don't we do this Only one difference is glog will produce log messages in both console(stdout) and log, in this PR?

rkooo567 · 2020-09-23T19:49:25Z

Can you also push the benchmarking code to this PR?

ashione · 2020-09-24T02:35:39Z

Can you also push the benchmarking code to this PR?

It is LogPerfTest in src/ray/util/logging_test.cc.

ashione · 2020-09-24T02:38:22Z

So, does it mean spdlog is 10 times faster than glog in your workload?

Also, why don't we do this Only one difference is glog will produce log messages in both console(stdout) and log, in this PR?

~ 5200ms when I remove stderr verbose of glog. (Just change google::SetStderrLogging(GetMappedSeverity(RayLogLevel::ERROR)); to google::SetStderrLogging(GetMappedSeverity(RayLogLevel::FATAL));

ashione · 2020-09-24T06:02:38Z

@rkooo567 I have pushed benchmark target commit. You may execute
bazel test logging_spdlog_test and bazel test logging_test to show their different performance.
In my MacBook Pro with 2.2 GHz Intel Core i7, 6 GB 1600 MHz DDR3

[==========] Running 3 tests from 2 test cases.
[----------] Global test environment set-up.
[----------] 2 tests from PrintLogTest
[ RUN      ] PrintLogTest.LogTestWithoutInit
WARNING: Logging before InitGoogleLogging() is written to STDERR
I0924 13:57:48.694461 39597 2729898880 logging_test.cc:40] This is the INFO message
W0924 13:57:48.696022 39597 2729898880 logging_test.cc:42] This is the WARNING message
E0924 13:57:48.696040 39597 2729898880 logging_test.cc:44] This is the ERROR message
[       OK ] PrintLogTest.LogTestWithoutInit (2 ms)
[ RUN      ] PrintLogTest.LogTestWithInit
[       OK ] PrintLogTest.LogTestWithInit (1 ms)
[----------] 2 tests from PrintLogTest (3 ms total)

[----------] 1 test from LogPerfTest
[ RUN      ] LogPerfTest.PerfTest
Testing DEBUG log for 100000 rounds takes 0 ms.
Testing RAY_ERROR log for 100000 rounds takes 5701 ms.
Testing RAY_CHECK(true) for 100000 rounds takes 0 ms.
[       OK ] LogPerfTest.PerfTest (5721 ms)
[----------] 1 test from LogPerfTest (5721 ms total)

[----------] Global test environment tear-down
[==========] 3 tests from 2 test cases ran. (5724 ms total)
[  PASSED  ] 3 tests.

And

[==========] Running 3 tests from 2 test cases.
[----------] Global test environment set-up.
[----------] 2 tests from PrintLogTest
[ RUN      ] PrintLogTest.LogTestWithoutInit
[2020-09-24 13:58:07.811] [info] logging_test.cc:40: This is the INFO message
[2020-09-24 13:58:07.812] [warning] logging_test.cc:42: This is the WARNING message
[2020-09-24 13:58:07.812] [error] logging_test.cc:44: This is the ERROR message
[       OK ] PrintLogTest.LogTestWithoutInit (1 ms)
[ RUN      ] PrintLogTest.LogTestWithInit
[2020-09-24 13:58:07,812 D 40336 10382541] logging_test.cc:37: This is the DEBUG message
[2020-09-24 13:58:07,812 I 40336 10382541] logging_test.cc:40: This is the INFO message
[2020-09-24 13:58:07,812 W 40336 10382541] logging_test.cc:42: This is the WARNING message
[2020-09-24 13:58:07,812 E 40336 10382541] logging_test.cc:44: This is the ERROR message
[       OK ] PrintLogTest.LogTestWithInit (0 ms)
[----------] 2 tests from PrintLogTest (1 ms total)

[----------] 1 test from LogPerfTest
[ RUN      ] LogPerfTest.PerfTest
Testing DEBUG log for 100000 rounds takes 0 ms.
Testing RAY_ERROR log for 100000 rounds takes 1392 ms.
Testing RAY_CHECK(true) for 100000 rounds takes 0 ms.
[       OK ] LogPerfTest.PerfTest (1432 ms)
[----------] 1 test from LogPerfTest (1432 ms total)

[----------] Global test environment tear-down
[==========] 3 tests from 2 test cases ran. (1433 ms total)
[  PASSED  ] 3 tests.

rkooo567 · 2020-09-24T19:42:01Z

@ashione Can you remove WIP when it is ready?

ashione · 2020-10-15T10:12:58Z

@ashione Can you remove WIP when it is ready?

I remove WIP and create all same functions for spdlog.

kfstorm · 2020-10-16T08:22:28Z

@ashione Please avoid rebasing/modifying commit history in a pull request. It's hard to find out what's changed since the last review.

kfstorm

Could you paste an example output of RAY_CHECK?

kfstorm · 2020-10-16T08:29:23Z

src/ray/util/logging.cc

+  inline void Flush() {
+    auto logger = get_logger();
+    if (loglevel_ == static_cast<int>(spdlog::level::critical)) {
+      stream() << "\n" << ray::GetCallTrace();


Why we need this line? I think GLOG will fetch the stack trace for us once std::abort() is invoked.

Could you paste an example output of RAY_CHECK?

Stacktraces will be exactly produced twice with InstallFailureSignalHandler, but nothing will be catched we do not call GetCallTrace manually without InstallFailureSignalHandler for glog.

rkooo567 · 2020-10-19T06:35:39Z

I always use the merge master command and never had any trouble (and it is okay to do this because the commit history doesn't matter anyway. All of commits are merged into one by Github when merged).

kfstorm · 2020-10-19T06:42:06Z

Could you paste an example output of RAY_CHECK?

Something like that

[==========] Running 1 test from 1 test case.
[----------] Global test environment set-up.
[----------] 1 test from PrintLogTest
[ RUN      ] PrintLogTest.RayCheckAbortTest
[2020-10-19 13:55:37,743 C 37433 2749808] logging_test.cc:140:  Check failed: 0 Check for aborting
    @        0x107aae9f8  ray::SpdLogMessage::Flush()
    @        0x107aadf99  ray::RayLog::~RayLog()
    @        0x107a62393  ray::PrintLogTest_RayCheckAbortTest_Test::TestBody()
    @        0x108404ff8  testing::internal::HandleExceptionsInMethodIfSupported<>()
    @        0x108404f4e  testing::Test::Run()
    @        0x108405f10  testing::TestInfo::Run()
    @        0x1084067c7  testing::TestCase::Run()
    @        0x108412e47  testing::internal::UnitTestImpl::RunAllTests()
    @        0x108412868  testing::internal::HandleExceptionsInMethodIfSupported<>()
    @        0x1084127ed  testing::UnitTest::Run()
    @        0x107a625a1  main
    @     0x7fff7488c015  start

I can't find SIGABRT in the log. Is it intended? What does the log look like if it's a SIGSEGV?

ashione · 2020-10-19T11:57:15Z

Could you paste an example output of RAY_CHECK?

Something like that

[==========] Running 1 test from 1 test case.
[----------] Global test environment set-up.
[----------] 1 test from PrintLogTest
[ RUN      ] PrintLogTest.RayCheckAbortTest
[2020-10-19 13:55:37,743 C 37433 2749808] logging_test.cc:140:  Check failed: 0 Check for aborting
    @        0x107aae9f8  ray::SpdLogMessage::Flush()
    @        0x107aadf99  ray::RayLog::~RayLog()
    @        0x107a62393  ray::PrintLogTest_RayCheckAbortTest_Test::TestBody()
    @        0x108404ff8  testing::internal::HandleExceptionsInMethodIfSupported<>()
    @        0x108404f4e  testing::Test::Run()
    @        0x108405f10  testing::TestInfo::Run()
    @        0x1084067c7  testing::TestCase::Run()
    @        0x108412e47  testing::internal::UnitTestImpl::RunAllTests()
    @        0x108412868  testing::internal::HandleExceptionsInMethodIfSupported<>()
    @        0x1084127ed  testing::UnitTest::Run()
    @        0x107a625a1  main
    @     0x7fff7488c015  start

I can't find SIGABRT in the log. Is it intended? What does the log look like if it's a SIGSEGV?

It's shown by return value of command line.

[1]    40850 abort      sh -c "bazel-bin/logging_test --gtest_filter=*AbortTest"

kfstorm · 2020-10-20T08:10:49Z

FYI, I tested with an std::abort() and this is the log file:

tail -n 20 python-core-driver-01000000ffffffffffffffffffffffffffffffff_854.log
[2020-10-20 16:02:22,220 I 854 1015] actor_manager.cc:127: received notification on actor, state: DEPENDENCIES_UNREADY, actor_id: df5a1a8201000000, ip address: , port: 0, worker_id: NIL_ID, raylet_id: NIL_ID, num_restarts: 0
[2020-10-20 16:02:22,220 I 854 854] direct_task_transport.cc:47: Creating actor via GCS actor id = : df5a1a8201000000
[2020-10-20 16:02:22,220 E 854 1015] logging.cc:397: *** Aborted at 1603180942 (unix time) try "date -d @1603180942" if you are using GNU date ***
[2020-10-20 16:02:22,222 E 854 1015] logging.cc:397: PC: @                0x0 (unknown)
[2020-10-20 16:02:22,222 E 854 1015] logging.cc:397: *** SIGABRT (@0x70900000356) received by PID 854 (TID 0x7f6506ffd700) from PID 854; stack trace: ***
[2020-10-20 16:02:22,223 E 854 1015] logging.cc:397:     @     0x7f6526755620 (unknown)
[2020-10-20 16:02:22,224 E 854 1015] logging.cc:397:     @     0x7f6525ca5277 __GI_raise
[2020-10-20 16:02:22,225 E 854 1015] logging.cc:397:     @     0x7f6525ca6968 __GI_abort
[2020-10-20 16:02:22,226 E 854 1015] logging.cc:397:     @     0x7f65187a2c09 ray::CoreWorkerDirectActorTaskSubmitter::SendPendingTasks()
[2020-10-20 16:02:22,227 E 854 1015] logging.cc:397:     @     0x7f65187a84a5 _ZNSt17_Function_handlerIFvvEZN3ray34CoreWorkerDirectActorTaskSubmitter10SubmitTaskENS1_17TaskSpecificationEEUlvE_E9_M_invokeERKSt9_Any_data
[2020-10-20 16:02:22,228 E 854 1015] logging.cc:397:     @     0x7f65187afcb2 ray::LocalDependencyResolver::ResolveDependencies()
[2020-10-20 16:02:22,230 E 854 1015] logging.cc:397:     @     0x7f65187ae805 ray::CoreWorkerDirectActorTaskSubmitter::SubmitTask()
[2020-10-20 16:02:22,230 E 854 1015] logging.cc:397:     @     0x7f651873893c _ZN5boost4asio6detail18completion_handlerIZN3ray10CoreWorker15SubmitActorTaskERKNS3_7ActorIDERKNS3_11RayFunctionERKSt6vectorISt10unique_ptrINS3_7TaskArgESt14default_deleteISD_EESaISG_EERKNS3_11TaskOptionsEPSB_INS3_8ObjectIDESaISO_EEEUlvE_E11do_completeEPvPNS1_19scheduler_operationERKNS_6system10error_codeEm
[2020-10-20 16:02:22,232 E 854 1015] logging.cc:397:     @     0x7f6518baa6fd boost::asio::detail::scheduler::do_run_one()
[2020-10-20 16:02:22,233 E 854 1015] logging.cc:397:     @     0x7f6518bab1c1 boost::asio::detail::scheduler::run()
[2020-10-20 16:02:22,234 E 854 1015] logging.cc:397:     @     0x7f6518bacc92 boost::asio::io_context::run()
[2020-10-20 16:02:22,235 E 854 1015] logging.cc:397:     @     0x7f6518722c80 ray::CoreWorker::RunIOService()
[2020-10-20 16:02:22,236 E 854 1015] logging.cc:397:     @     0x7f65180abc60 (unknown)
[2020-10-20 16:02:22,237 E 854 1015] logging.cc:397:     @     0x7f652674de25 start_thread
[2020-10-20 16:02:22,238 E 854 1015] logging.cc:397:     @     0x7f6525d6cf1d __clone

The only difference from the glog solution is that there are many duplicated [2020-10-20 16:02:22,235 E 854 1015] logging.cc:397:.

kfstorm

LGTM.

rkooo567 · 2020-10-20T08:12:52Z

@kfstorm please don’t merge it yet. I will review it tmrw

kfstorm · 2020-10-20T08:15:32Z

@rkooo567 Don't worry. I'm not going to merge this PR without your approval.

rkooo567 · 2020-10-21T06:14:34Z

src/ray/util/logging.cc

+ public:
+  explicit SpdLogMessage(const char *file, int line, int loglevel) : loglevel_(loglevel) {
+    stream() << ConstBasename(file) << ":" << line << ": ";
+  }


Suggested change

}

}

auto-gen by clang-format

rkooo567 · 2020-10-21T06:15:39Z

src/ray/util/logging.cc

+    if (!logger) {
+      logger = spdlog::get("stderr");
+    }
+    // If no default logger we just emit all log informations to stderr.


When's the time we don't have a default logger? Can you comment it?

rkooo567 · 2020-10-21T06:21:43Z

src/ray/util/logging.cc

+        loglevel_ == static_cast<int>(spdlog::level::critical)) {
+      stream() << "\n*** StackTrace Information ***\n" << ray::GetCallTrace();
+    }
+    logger->log(static_cast<spdlog::level::level_enum>(loglevel_), "{}", str_.str());


Suggested change

logger->log(static_cast<spdlog::level::level_enum>(loglevel_), "{}", str_.str());

logger->log(static_cast<spdlog::level::level_enum>(loglevel_), /*fmt*/ "{}", str_.str());

```?

Not sure if it is the correct argument. Can you specify what this argument means?

rkooo567 · 2020-10-21T06:26:28Z

src/ray/util/logging_test.cc

 #include "ray/util/logging.h"

 #include <chrono>
+#include <csignal>


Why is it added when we commented out all tests here?

rkooo567 · 2020-10-21T06:26:38Z

src/ray/util/logging_test.cc

+  exit(0);
+}
+
+TEST(PrintLogTest, RayCheckAbortTest) {


How did it work before?

I add it only for testing manually because process will abort and exit if signal catched.

rkooo567 · 2020-10-21T06:28:47Z

src/ray/util/logging.cc

+#endif
+}
+
+void WriteFailureMessage(const char *data, int size) {


rkooo567 · 2020-10-21T06:31:56Z

src/ray/util/logging.cc

+          spdlog::rotating_logger_mt("ray_log_sink",
+                                     dir_ends_with_slash + app_name_without_path + "_" +
+                                         std::to_string(pid) + ".log",
+                                     1 << 29, 10);


Can we make this part configurable?

I'll extract theses parameters from env vars.

Can we make this part configurable?

ashione · 2020-10-23T09:29:55Z

@rkooo567 Could you go over it again? I found failures are related to python travis tests.

ashione · 2020-10-28T01:28:35Z

@kfstorm @rkooo567 Any other comments about this PR? It's ready to be merged if nothing can be blocked.

rkooo567 · 2020-10-28T04:12:12Z

@ashione Can you merge the latest master? It seems like all serve tests are failing, but I think it was same for the master. But I'd like to make sure if that's the case.

rkooo567 · 2020-10-28T04:12:31Z

Remove the tag (@author-action-required) once you merge the latest master (and passes all builds)

ashione · 2020-10-28T09:50:27Z

@rkooo567 I have no idea about why //python/ray/tune:test_experiment_analysis failed in TUNE_TESTING? Is it known-issue in master.

rkooo567 · 2020-10-28T19:40:34Z

@ashione I think there were some failures on master. This must've been resolved now. Can you try merging the master one more time?

ashione · 2020-10-29T05:59:43Z

@ashione I think there were some failures on master. This must've been resolved now. Can you try merging the master one more time?

It's done and looks all green.

kfstorm · 2020-10-29T07:13:03Z

Windows CI failure seems unrelated.

rkooo567 · 2020-10-29T07:18:40Z

Windows tests seem to have weird test failures that I've never seen. Rerunning the job now...

rkooo567 · 2020-10-29T07:19:42Z

@kfstorm The test failure indeed seems unrelated, but I've never seen this error in any CI builds. So let me re-run it just in case!

kfstorm · 2020-10-29T07:24:26Z

@rkooo567 Sure. Thank you.

ashione requested a review from jovany-wang September 23, 2020 03:47

ashione changed the title ~~new spdlog tool for ray~~ [WIP] new spdlog tool for ray Sep 23, 2020

ashione mentioned this pull request Sep 23, 2020

Ray uses spdlog instead of glog #10493

Closed

rkooo567 assigned rkooo567 and edoakes Sep 23, 2020

ashione linked an issue Sep 23, 2020 that may be closed by this pull request

Ray uses spdlog instead of glog #10493

Closed

ashione requested review from ericl and rkooo567 September 24, 2020 03:04

rkooo567 added the @author-action-required The PR author is responsible for the next step. Remove tag to send back to the reviewer. label Sep 25, 2020

ashione added 2 commits October 15, 2020 12:48

spdlog support

2cbc5fd

Merge remote-tracking branch 'github/master' into support-spdlog

3d45577

ashione force-pushed the support-spdlog branch from 0f546ca to 3d45577 Compare October 15, 2020 04:51

fatal abort for spdlog

c7be2a1

ashione changed the title ~~[WIP] new spdlog tool for ray~~ [Log] new spdlog tool for ray Oct 15, 2020

ashione added 2 commits October 15, 2020 15:38

print all logs in stderr if no logger given

24fa025

fix log test

552101e

install signal handler for spdlog by reusing glog lib

5a1f6b2

kfstorm reviewed Oct 16, 2020

View reviewed changes

Avoid duplicated dump

8903ac2

kfstorm approved these changes Oct 20, 2020

View reviewed changes

rkooo567 reviewed Oct 21, 2020

View reviewed changes

ashione added 3 commits October 22, 2020 15:18

log rotation and fmt comments

3745624

fix

eabb262

Merge remote-tracking branch 'github/master' into support-spdlog

e8d9687

rkooo567 approved these changes Oct 28, 2020

View reviewed changes

Merge remote-tracking branch 'github/master' into support-spdlog

cd68840

ashione removed the @author-action-required The PR author is responsible for the next step. Remove tag to send back to the reviewer. label Oct 28, 2020

Merge remote-tracking branch 'github/master' into support-spdlog

ac9ad94

rkooo567 merged commit 0b7a3d9 into ray-project:master Oct 29, 2020

kfstorm deleted the support-spdlog branch October 30, 2020 05:57

kfstorm mentioned this pull request Nov 3, 2020

[Core] Fix ray start failure to due to bug of redis address detection #11735

Merged

	logger->log(static_cast<spdlog::level::level_enum>(loglevel_), "{}", str_.str());
	logger->log(static_cast<spdlog::level::level_enum>(loglevel_), /fmt/ "{}", str_.str());
	```?

Conversation

ashione commented Sep 23, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Why are these changes needed?

Related issue number

Checks

Uh oh!

ashione commented Sep 23, 2020

Uh oh!

ashione commented Sep 23, 2020

Uh oh!

kfstorm commented Sep 23, 2020

Uh oh!

ashione commented Sep 23, 2020

Uh oh!

rkooo567 commented Sep 23, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

rkooo567 commented Sep 23, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

ashione commented Sep 24, 2020

Uh oh!

ashione commented Sep 24, 2020

Uh oh!

ashione commented Sep 24, 2020

Uh oh!

rkooo567 commented Sep 24, 2020

Uh oh!

ashione commented Oct 15, 2020

Uh oh!

kfstorm commented Oct 16, 2020

Uh oh!

kfstorm left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

rkooo567 commented Oct 19, 2020

Uh oh!

kfstorm commented Oct 19, 2020

Uh oh!

ashione commented Oct 19, 2020

Uh oh!

kfstorm commented Oct 20, 2020

Uh oh!

kfstorm left a comment

Choose a reason for hiding this comment

Uh oh!

rkooo567 commented Oct 20, 2020

Uh oh!

kfstorm commented Oct 20, 2020

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

ashione commented Oct 23, 2020

Uh oh!

ashione commented Oct 28, 2020

ashione commented Sep 23, 2020 •

edited

Loading

rkooo567 commented Sep 23, 2020 •

edited

Loading

rkooo567 commented Sep 23, 2020 •

edited

Loading