*: Add stacktrace logging when exceptions are thrown in `Server::main` (#9903) by ti-chi-bot · Pull Request #9910 · pingcap/tiflash

ti-chi-bot · 2025-02-25T02:13:58Z

This is an automated cherry-pick of #9903

What problem does this PR solve?

Issue Number: close #9902

Problem Summary:
Under some cases, we meet exception with no stacktrace

[2025/01/17 18:11:13.564 +08:00] [ERROR] [<unknown>] ["DB::Exception: Too large string size."] [source=Application] [thread_id=1]

What is changed and how it works?

* Add progress logging in `RegionPersister::restore` so that we can get more info how many region is restoring
* Add stacktrace logging when exceptions are thrown in `Server::main`
* Use DB::Exception instead of Poco::Exception to get more stacktrace info

Check List

Tests

Unit test
Integration test
Manual test (add detailed scripts or steps below)
Mock the KVStore::restore throw an exception in Server::main, and the logging can print the stacktrace info

[2025/02/24 13:01:46.197 +08:00] [INFO] [DeltaMergeStore.cpp:375] ["Release DeltaMerge Store start"] [source="keyspace=4294967295 table_id=100079"] [thread_id=1]
[2025/02/24 13:01:46.197 +08:00] [INFO] [DeltaMergeStore.cpp:379] ["Release DeltaMerge Store end"] [source="keyspace=4294967295 table_id=100079"] [thread_id=1]
[2025/02/24 13:01:46.212 +08:00] [INFO] [ProxyStateMachine.h:423] ["Unlink tiflash_instance_wrap.tmt"] [thread_id=1]
[2025/02/24 13:01:46.212 +08:00] [INFO] [LocalIndexerScheduler.cpp:94] ["LocalIndexerScheduler is destroyed"] [thread_id=1]
[2025/02/24 13:01:51.065 +08:00] [INFO] [KVStore.cpp:420] ["Destroy KVStore"] [thread_id=1]
[2025/02/24 13:01:51.065 +08:00] [INFO] [ReadIndex.cpp:388] ["KVStore shutdown, deleting read index worker"] [thread_id=1]
[2025/02/24 13:01:51.065 +08:00] [INFO] [KVStore.cpp:422] ["Destroy KVStore Finished"] [thread_id=1]
[2025/02/24 13:01:51.386 +08:00] [INFO] [JointThreadAllocInfo.cpp:194] ["Stop collecting thread alloc metrics"] [thread_id=1]
[2025/02/24 13:01:51.387 +08:00] [INFO] [Server.cpp:724] ["Destroyed global context."] [thread_id=1]
[2025/02/24 13:01:51.387 +08:00] [INFO] [ProxyStateMachine.h:436] ["Let tiflash proxy shutdown"] [thread_id=1]
[2025/02/24 13:01:51.387 +08:00] [INFO] [ProxyStateMachine.h:439] ["Wait for tiflash proxy thread to join"] [thread_id=1]
[2025/02/24 13:01:51.470 +08:00] [INFO] [ProxyStateMachine.h:441] ["tiflash proxy thread is joined"] [thread_id=1]
[2025/02/24 13:01:53.192 +08:00] [ERROR] [Exception.cpp:96] ["Code: 0, e.displayText() = DB::Exception: mock exception: restoring region_id=1890, e.what() = DB::Exception, Stack trace:\n\n\n  0x555559f0650e\tStackTrace::StackTrace() [tiflash+77276430]\n                \tdbms/src/Common/StackTrace.cpp:23\n  0x555559ef5db2\tDB::Exception::Exception(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char>> const&, int) [tiflash+77209010]\n                \tdbms/src/Common/Exception.h:46\n  0x55556547e15a\tDB::Region::deserialize(DB::ReadBuffer&, DB::TiFlashRaftProxyHelper const*) [tiflash+267559258]\n                \tdbms/src/Storages/KVStore/MultiRaft/RegionSerde.cpp:97\n  0x555565472cc8\tDB::RegionPersister::restore(DB::PathPool&, DB::TiFlashRaftProxyHelper const*, DB::PageStorageConfig)::$_3::operator()(DB::Page const&, unsigned long) const [tiflash+267513032]\n                \tdbms/src/Storages/KVStore/MultiRaft/RegionPersister.cpp:414\n  0x555565472578\tdecltype(std::declval<DB::RegionPersister::restore(DB::PathPool&, DB::TiFlashRaftProxyHelper const*, DB::PageStorageConfig)::$_3&>()(std::declval<DB::Page const&>(), std::declval<unsigned long>())) std::__1::__invoke[abi:ue170006]<DB::RegionPersister::restore(DB::PathPool&, DB::TiFlashRaftProxyHelper const*, DB::PageStorageConfig)::$_3&, DB::Page const&, unsigned long>(DB::RegionPersister::restore(DB::PathPool&, DB::TiFlashRaftProxyHelper const*, DB::PageStorageConfig)::$_3&, DB::Page const&, unsigned long&&) [tiflash+267511160]\n                \t/DATA/disk1/ra_common/tiflash-env-17/sysroot/bin/../include/c++/v1/__type_traits/invoke.h:340\n  0x555565472525\tvoid std::__1::__invoke_void_return_wrapper<void, true>::__call[abi:ue170006]<DB::RegionPersister::restore(DB::PathPool&, DB::TiFlashRaftProxyHelper const*, DB::PageStorageConfig)::$_3&, DB::Page const&, unsigned long>(DB::RegionPersister::restore(DB::PathPool&, DB::TiFlashRaftProxyHelper const*, DB::PageStorageConfig)::$_3&, DB::Page const&, unsigned long&&) [tiflash+267511077]\n                \t/DATA/disk1/ra_common/tiflash-env-17/sysroot/bin/../include/c++/v1/__type_traits/invoke.h:415\n  0x5555654724ed\tstd::__1::__function::__alloc_func<DB::RegionPersister::restore(DB::PathPool&, DB::TiFlashRaftProxyHelper const*, DB::PageStorageConfig)::$_3, std::__1::allocator<DB::RegionPersister::restore(DB::PathPool&, DB::TiFlashRaftProxyHelper const*, DB::PageStorageConfig)::$_3>, void (DB::Page const&, unsigned long)>::operator()[abi:ue170006](DB::Page const&, unsigned long&&) [tiflash+267511021]\n                \t/DATA/disk1/ra_common/tiflash-env-17/sysroot/bin/../include/c++/v1/__functional/function.h:192\n  0x555565471a39\tstd::__1::__function::__func<DB::RegionPersister::restore(DB::PathPool&, DB::TiFlashRaftProxyHelper const*, DB::PageStorageConfig)::$_3, std::__1::allocator<DB::RegionPersister::restore(DB::PathPool&, DB::TiFlashRaftProxyHelper const*, DB::PageStorageConfig)::$_3>, void (DB::Page const&, unsigned long)>::operator()(DB::Page const&, unsigned long&&) [tiflash+267508281]\n                \t/DATA/disk1/ra_common/tiflash-env-17/sysroot/bin/../include/c++/v1/__functional/function.h:363\n  0x555564760562\tstd::__1::__function::__value_func<void (DB::Page const&, unsigned long)>::operator()[abi:ue170006](DB::Page const&, unsigned long&&) const [tiflash+253805922]\n                \t/DATA/disk1/ra_common/tiflash-env-17/sysroot/bin/../include/c++/v1/__functional/function.h:517\n  0x555564760285\tstd::__1::function<void (DB::Page const&, unsigned long)>::operator()(DB::Page const&, unsigned long) const [tiflash+253805189]\n                \t/DATA/disk1/ra_common/tiflash-env-17/sysroot/bin/../include/c++/v1/__functional/function.h:1168\n  0x5555648cf0e6\tDB::PS::V3::PageStorageImpl::traverseImpl(std::__1::function<void (DB::Page const&, unsigned long)> const&, std::__1::shared_ptr<DB::PageStorageSnapshot>) [tiflash+255308006]\n                \tdbms/src/Storages/Page/V3/PageStorageImpl.cpp:299\n  0x55555a2d0054\tDB::PageStorage::traverse(std::__1::function<void (DB::Page const&, unsigned long)> const&, std::__1::shared_ptr<DB::PageStorageSnapshot>) [tiflash+81248340]\n                \tdbms/src/Storages/Page/PageStorage.h:186\n  0x55556475953a\tDB::PageReaderImplNormal::traverse(std::__1::function<void (DB::Page const&, unsigned long)> const&, bool, bool) const [tiflash+253777210]\n                \tdbms/src/Storages/Page/PageStorage.cpp:139\n  0x555564753817\tDB::PageReader::traverse(std::__1::function<void (DB::Page const&, unsigned long)> const&, bool, bool) const [tiflash+253753367]\n                \tdbms/src/Storages/Page/PageStorage.cpp:590\n  0x55556546e104\tDB::RegionPersister::restore(DB::PathPool&, DB::TiFlashRaftProxyHelper const*, DB::PageStorageConfig) [tiflash+267493636]\n                \tdbms/src/Storages/KVStore/MultiRaft/RegionPersister.cpp:445\n  0x555565303694\tDB::KVStore::restore(DB::PathPool&, DB::TiFlashRaftProxyHelper const*) [tiflash+266008212]\n                \tdbms/src/Storages/KVStore/KVStore.cpp:82\n  0x55556531de4d\tDB::TMTContext::restore(DB::PathPool&, DB::TiFlashRaftProxyHelper const*) [tiflash+266116685]\n                \tdbms/src/Storages/KVStore/TMTContext.cpp:258\n  0x555559fda534\tDB::ProxyStateMachine::restoreKVStore(DB::TMTContext&, DB::PathPool&) const [tiflash+78144820]\n                \tdbms/src/Storages/KVStore/ProxyStateMachine.h:315\n  0x555559fcd871\tDB::Server::main(std::__1::vector<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char>>, std::__1::allocator<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char>>>> const&) [tiflash+78092401]\n                \tdbms/src/Server/Server.cpp:1056\n  0x5555664c7145\tPoco::Util::Application::run() [tiflash+284635461]\n                \tcontrib/poco/Util/src/Application.cpp:335\n  0x5555664e5385\tPoco::Util::ServerApplication::run() [tiflash+284758917]\n                \tcontrib/poco/Util/src/ServerApplication.cpp:94\n  0x555559fc3bb7\tDB::Server::run() [tiflash+78052279]\n                \tdbms/src/Server/Server.cpp:176\n  0x5555664e5560\tPoco::Util::ServerApplication::run(int, char**) [tiflash+284759392]\n                \tcontrib/poco/Util/src/ServerApplication.cpp:618\n  0x555559fd0188\tmainEntryClickHouseServer(int, char**) [tiflash+78102920]\n                \tdbms/src/Server/Server.cpp:1268\n  0x555559e81761\tmain [tiflash+76732257]\n                \tdbms/src/Server/main.cpp:172\n  0x7fffe878e590\t__libc_start_call_main [libc.so.6+169360]\n  0x7fffe878e640\t__libc_start_main_alias_1 [libc.so.6+169536]\n  0x555559e81125\t_start [tiflash+76730661]"] [source=Server::main] [thread_id=1]
[2025/02/24 13:01:53.192 +08:00] [INFO] [<unknown>] ["shutting down"] [source=Application] [thread_id=1]

No code

Side effects

Performance regression: Consumes more CPU
Performance regression: Consumes more Memory
Breaking backward compatibility

Documentation

Release note

None

Signed-off-by: ti-chi-bot <ti-community-prow-bot@tidb.io>

ti-chi-bot · 2025-02-25T02:14:01Z

@JaySon-Huang This PR has conflicts, I have hold it.
Please resolve them or ask others to resolve them, then comment /unhold to remove the hold label.

Signed-off-by: JaySon-Huang <tshent@qq.com>

JaySon-Huang · 2025-02-25T06:21:42Z

/unhold

ti-chi-bot · 2025-02-25T06:27:17Z

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: JaySon-Huang, Lloyd-Pottiger

The full list of commands accepted by this bot can be found here.

The pull request process is described here

Details

Needs approval from an approver in each of these files:

~~OWNERS~~ [JaySon-Huang,Lloyd-Pottiger]

Approvers can indicate their approval by writing /approve in a comment
Approvers can cancel approval by writing /approve cancel in a comment

ti-chi-bot · 2025-02-25T06:27:19Z

[LGTM Timeline notifier]

Timeline:

2025-02-25 06:21:24.868553857 +0000 UTC m=+336832.821712123: ☑️ agreed by JaySon-Huang.
2025-02-25 06:27:18.985740623 +0000 UTC m=+337186.938898889: ☑️ agreed by Lloyd-Pottiger.

Signed-off-by: JaySon-Huang <tshent@qq.com>

pingcap#9903) (pingcap#9910) close pingcap#9902 * Add progress logging in `RegionPersister::restore` so that we can get more info how many region is restoring * Add stacktrace logging when exceptions are thrown in `Server::main` * Use DB::Exception instead of Poco::Exception to get more stacktrace info Signed-off-by: ti-chi-bot <ti-community-prow-bot@tidb.io> Signed-off-by: JaySon-Huang <tshent@qq.com> Co-authored-by: JaySon <tshent@qq.com> Co-authored-by: JaySon-Huang <tshent@qq.com>

This is an automated cherry-pick of pingcap#9903

ce1cb5f

Signed-off-by: ti-chi-bot <ti-community-prow-bot@tidb.io>

ti-chi-bot mentioned this pull request Feb 25, 2025

*: Add stacktrace logging when exceptions are thrown in Server::main #9903

Merged

12 tasks

ti-chi-bot bot added the do-not-merge/cherry-pick-not-approved label Feb 25, 2025

ti-chi-bot assigned JaySon-Huang Feb 25, 2025

Resolve conflicts

6567e60

Signed-off-by: JaySon-Huang <tshent@qq.com>

JaySon-Huang force-pushed the cherry-pick-9903-to-release-8.5 branch from a256ed6 to 6567e60 Compare February 25, 2025 06:06

JaySon-Huang approved these changes Feb 25, 2025

View reviewed changes

ti-chi-bot bot added needs-1-more-lgtm Indicates a PR needs 1 more LGTM. approved labels Feb 25, 2025

JaySon-Huang requested review from CalvinNeo, JinheLin and Lloyd-Pottiger February 25, 2025 06:21

ti-chi-bot bot removed the do-not-merge/hold Indicates that a PR should not merge because someone has issued a /hold command. label Feb 25, 2025

Merge branch 'release-8.5' into cherry-pick-9903-to-release-8.5

cca4ca6

Lloyd-Pottiger approved these changes Feb 25, 2025

View reviewed changes

ti-chi-bot bot added lgtm and removed needs-1-more-lgtm Indicates a PR needs 1 more LGTM. labels Feb 25, 2025

Fix include

a4c8274

Signed-off-by: JaySon-Huang <tshent@qq.com>

ti-chi-bot bot merged commit dd509c2 into pingcap:release-8.5 Feb 25, 2025
4 checks passed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

*: Add stacktrace logging when exceptions are thrown in `Server::main` (#9903)#9910

*: Add stacktrace logging when exceptions are thrown in `Server::main` (#9903)#9910
ti-chi-bot[bot] merged 4 commits intopingcap:release-8.5from
ti-chi-bot:cherry-pick-9903-to-release-8.5

ti-chi-bot commented Feb 25, 2025

Uh oh!

ti-chi-bot commented Feb 25, 2025

Uh oh!

JaySon-Huang commented Feb 25, 2025

Uh oh!

ti-chi-bot bot commented Feb 25, 2025

Uh oh!

ti-chi-bot bot commented Feb 25, 2025

Uh oh!

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

3 participants

Conversation

ti-chi-bot commented Feb 25, 2025

What problem does this PR solve?

What is changed and how it works?

Check List

Release note

Uh oh!

ti-chi-bot commented Feb 25, 2025

Uh oh!

JaySon-Huang commented Feb 25, 2025

Uh oh!

ti-chi-bot bot commented Feb 25, 2025

Uh oh!

ti-chi-bot bot commented Feb 25, 2025

[LGTM Timeline notifier]

Uh oh!

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

3 participants