*: Add stacktrace logging when exceptions are thrown in `Server::main` by JaySon-Huang · Pull Request #9903 · pingcap/tiflash

JaySon-Huang · 2025-02-24T03:16:49Z

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: JaySon-Huang <tshent@qq.com>

CalvinNeo

lgtm

JaySon-Huang · 2025-02-24T05:02:40Z

/hold

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

JaySon-Huang · 2025-02-24T06:12:15Z

/unhold

JaySon-Huang · 2025-02-24T06:33:59Z

/test pull-integration-test

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

Lloyd-Pottiger

lgtm

CalvinNeo

lgtm

ti-chi-bot · 2025-02-24T09:16:31Z

[LGTM Timeline notifier]

Timeline:

2025-02-24 04:49:39.028312476 +0000 UTC m=+244926.981470727: ☑️ agreed by CalvinNeo.
2025-02-24 09:16:30.124313881 +0000 UTC m=+260938.077472158: ☑️ agreed by Lloyd-Pottiger.

ti-chi-bot · 2025-02-24T09:16:33Z

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: CalvinNeo, 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~~ [CalvinNeo,Lloyd-Pottiger]

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

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

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

In response to a cherrypick label: new pull request created to branch release-7.5: #9908.
But this PR has conflicts, please resolve them!

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

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

In response to a cherrypick label: new pull request created to branch release-8.5: #9910.
But this PR has conflicts, please resolve them!

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

In response to a cherrypick label: new pull request created to branch release-8.1: #9911.
But this PR has conflicts, please resolve them!

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

#9903) (#9908) close #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>

#9903) (#9911) close #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>

#9903) (#9910) close #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>

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>

JaySon-Huang added 2 commits February 24, 2025 10:48

Use DB::Exception instead of Poco::Exception

9536ccc

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

Add message to exception

344ce70

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

ti-chi-bot bot added do-not-merge/needs-triage-completed release-note-none Denotes a PR that doesn't merit a release note. size/M Denotes a PR that changes 30-99 lines, ignoring generated files. labels Feb 24, 2025

CalvinNeo approved these changes Feb 24, 2025

View reviewed changes

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

ti-chi-bot bot added do-not-merge/hold Indicates that a PR should not merge because someone has issued a /hold command. and removed do-not-merge/needs-triage-completed labels Feb 24, 2025

JaySon-Huang added 5 commits February 24, 2025 13:08

Add TraversePageCallback alias

35c025d

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

Add region restore progress logging

375f1e2

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

Add region_id to exception

0ff75b2

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

Refine syncSchemaWithTiDB

b27a776

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

Print stacktrace when exception is thrown on the Server::main

02ffe50

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

ti-chi-bot bot added size/L Denotes a PR that changes 100-499 lines, ignoring generated files. and removed size/M Denotes a PR that changes 30-99 lines, ignoring generated files. labels Feb 24, 2025

Fix comment

f8952ab

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

JaySon-Huang changed the title *: Use DB::Exception instead of Poco::Exception *: Add stacktrace logging when exceptions are thrown in Server::main Feb 24, 2025

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 24, 2025

Add check

a1f4e9a

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

Lloyd-Pottiger approved these changes Feb 24, 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 24, 2025

CalvinNeo approved these changes Feb 24, 2025

View reviewed changes

ti-chi-bot bot merged commit ad52116 into pingcap:master Feb 24, 2025
5 checks passed

JaySon-Huang deleted the fix_poco_exception branch February 24, 2025 09:20

ti-chi-bot bot added needs-cherry-pick-release-7.5 Should cherry pick this PR to release-7.5 branch. needs-cherry-pick-release-8.5 Should cherry pick this PR to release-8.5 branch. needs-cherry-pick-release-8.1 Should cherry pick this PR to release-8.1 branch. labels Feb 25, 2025

ti-chi-bot pushed a commit to ti-chi-bot/tiflash that referenced this pull request Feb 25, 2025

This is an automated cherry-pick of pingcap#9903

a3f1a10

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) #9908

Merged

12 tasks

ti-chi-bot pushed a commit to ti-chi-bot/tiflash that referenced this pull request Feb 25, 2025

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) #9910

Merged

12 tasks

ti-chi-bot pushed a commit to ti-chi-bot/tiflash that referenced this pull request Feb 25, 2025

This is an automated cherry-pick of pingcap#9903

6b84340

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) #9911

Merged

12 tasks

JaySon-Huang mentioned this pull request Mar 28, 2025

TiFlash fails to restart when a row is larger than 16MiB #10052

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

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

*: Add stacktrace logging when exceptions are thrown in `Server::main`#9903
ti-chi-bot[bot] merged 9 commits intopingcap:masterfrom
JaySon-Huang:fix_poco_exception

JaySon-Huang commented Feb 24, 2025 •

edited

Loading

Uh oh!

CalvinNeo left a comment

Uh oh!

JaySon-Huang commented Feb 24, 2025

Uh oh!

JaySon-Huang commented Feb 24, 2025

Uh oh!

JaySon-Huang commented Feb 24, 2025

Uh oh!

Lloyd-Pottiger left a comment

Uh oh!

CalvinNeo left a comment

Uh oh!

ti-chi-bot bot commented Feb 24, 2025

Uh oh!

ti-chi-bot bot commented Feb 24, 2025

Uh oh!

Uh oh!

ti-chi-bot commented Feb 25, 2025

Uh oh!

ti-chi-bot commented Feb 25, 2025

Uh oh!

ti-chi-bot commented Feb 25, 2025

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

4 participants

Conversation

JaySon-Huang commented Feb 24, 2025 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

What problem does this PR solve?

What is changed and how it works?

Check List

Release note

Uh oh!

CalvinNeo left a comment

Choose a reason for hiding this comment

Uh oh!

JaySon-Huang commented Feb 24, 2025

Uh oh!

JaySon-Huang commented Feb 24, 2025

Uh oh!

JaySon-Huang commented Feb 24, 2025

Uh oh!

Lloyd-Pottiger left a comment

Choose a reason for hiding this comment

Uh oh!

CalvinNeo left a comment

Choose a reason for hiding this comment

Uh oh!

ti-chi-bot bot commented Feb 24, 2025

[LGTM Timeline notifier]

Uh oh!

ti-chi-bot bot commented Feb 24, 2025

Uh oh!

Uh oh!

ti-chi-bot commented Feb 25, 2025

Uh oh!

ti-chi-bot commented Feb 25, 2025

Uh oh!

ti-chi-bot commented Feb 25, 2025

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

4 participants

JaySon-Huang commented Feb 24, 2025 •

edited

Loading