FAP: Add some logs - Githubissues

CalvinNeo commented 4 months ago

What problem does this PR solve?

Issue Number: close #9091 ref #9098

Problem Summary:

What is changed and how it works?

Check List

Tests

[ ] Unit test
[ ] Integration test
[ ] Manual test (add detailed scripts or steps below)
[ ] No code

Side effects

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

Documentation

[ ] Affects user behaviors
[ ] Contains syntax changes
[ ] Contains variable changes
[ ] Contains experimental features
[ ] Changes MySQL compatibility

Release note

None

CalvinNeo commented 4 months ago

/hold

CalvinNeo commented 4 months ago

/check-issue-triage

CalvinNeo commented 4 months ago

/check-issue-triage-complete

CalvinNeo commented 4 months ago

[       OK ] RegionKVStoreOldTest.ReadIndex (68 ms)
[----------] 1 test from RegionKVStoreOldTest (68 ms total)

[----------] Global test environment tear-down
[==========] 1 test from 1 test case ran. (68 ms total)
[  PASSED  ] 1 test.

CalvinNeo commented 4 months ago


[2024/05/29 15:45:38.264 +08:00] [WARN] [Context.cpp:1739] ["GlobalStoragePool has already been initialized."] [source=Context] [thread_id=1]

[2024/05/29 15:45:38.264 +08:00] [INFO] [PageStorageImpl.cpp:54] ["PageStorageImpl start. Config{ PageStorageConfig {blob_file_limit_size: 268435456, blob_spacemap_type: 2, blob_heavy_gc_valid_rate: 0.500, blob_heavy_gc_valid_rate_raft_data: 0.050, blob_block_alignment_bytes: 0, wal_roll_size: 2097152, wal_max_persisted_log_files: 4} }"] [source=__global__.log] [thread_id=1]

[2024/05/29 15:45:38.264 +08:00] [INFO] [PageStorageImpl.cpp:54] ["PageStorageImpl start. Config{ PageStorageConfig {blob_file_limit_size: 268435456, blob_spacemap_type: 2, blob_heavy_gc_valid_rate: 0.500, blob_heavy_gc_valid_rate_raft_data: 0.050, blob_block_alignment_bytes: 0, wal_roll_size: 2097152, wal_max_persisted_log_files: 4} }"] [source=__global__.data] [thread_id=1]

[2024/05/29 15:45:38.265 +08:00] [INFO] [PageStorageImpl.cpp:54] ["PageStorageImpl start. Config{ PageStorageConfig {blob_file_limit_size: 268435456, blob_spacemap_type: 2, blob_heavy_gc_valid_rate: 0.500, blob_heavy_gc_valid_rate_raft_data: 0.050, blob_block_alignment_bytes: 0, wal_roll_size: 2097152, wal_max_persisted_log_files: 4} }"] [source=__global__.meta] [thread_id=1]

[2024/05/29 15:45:38.265 +08:00] [INFO] [PageDirectoryFactory.cpp:68] ["PageDirectory restored, max_page_id=0 max_applied_ver=0"] [source=__global__.log] [thread_id=1]

[2024/05/29 15:45:38.265 +08:00] [INFO] [PageDirectoryFactory.cpp:68] ["PageDirectory restored, max_page_id=0 max_applied_ver=0"] [source=__global__.data] [thread_id=1]

[2024/05/29 15:45:38.265 +08:00] [INFO] [PageDirectoryFactory.cpp:68] ["PageDirectory restored, max_page_id=0 max_applied_ver=0"] [source=__global__.meta] [thread_id=1]

[2024/05/29 15:45:38.266 +08:00] [INFO] [PageStorageImpl.cpp:54] ["PageStorageImpl start. Config{ PageStorageConfig {blob_file_limit_size: 268435456, blob_spacemap_type: 2, blob_heavy_gc_valid_rate: 0.500, blob_heavy_gc_valid_rate_raft_data: 0.050, blob_block_alignment_bytes: 0, wal_roll_size: 2097152, wal_max_persisted_log_files: 4} }"] [source=test.t] [thread_id=1]

[2024/05/29 15:45:38.266 +08:00] [INFO] [BlobStore.cpp:131] ["Ignore not blob file, dir=/tmp-memfs/tiflash-tests/tmp/PageStorageTest.WriteReadGcExternalPage file=page err_msg="] [source=test.t] [thread_id=1]

[2024/05/29 15:45:38.266 +08:00] [INFO] [PageDirectoryFactory.cpp:68] ["PageDirectory restored, max_page_id=0 max_applied_ver=0"] [source=test.t] [thread_id=1]

[2024/05/29 15:45:38.266 +08:00] [INFO] [WALStore.cpp:143] ["Creating log file for writing [fullname=/tmp-memfs/tiflash-tests/tmp/PageStorageTest.WriteReadGcExternalPage/wal/log_1_0]"] [source=test.t] [thread_id=1]

[2024/05/29 15:45:38.266 +08:00] [DEBUG] [PageDirectory.cpp:2231] ["After MVCC gc in memory [lowest_seq=3] clean [invalid_snapshot_nums=0] [invalid_page_nums=0] [total_deref_counter=0] [all_del_entries=0]. Still exist [snapshot_nums=0], [page_nums=3]. Longest alive snapshot: [longest_alive_snapshot_time=0] [longest_alive_snapshot_seq=0] [stale_snapshot_nums=0]"] [source=test.t] [thread_id=1]

[2024/05/29 15:45:38.267 +08:00] [DEBUG] [BlobStore.cpp:1329] ["BlobStore gc get status done. details {ReadOnly: [null]} {Unchanged: [null]} {FullGC: [null]} {Truncated: [null]}"] [source=test.t] [thread_id=1]

[2024/05/29 15:45:38.267 +08:00] [DEBUG] [GCDefines.cpp:154] ["GC finished without full gc. [total time=0ms] [compact wal=0ms] [compact directory=0ms] [compact spacemap=0ms] [gc status=0ms] [gc entries=0ms] [gc data=0ms] [gc apply=0ms]"] [source=test.t] [thread_id=1]

[2024/05/29 15:45:38.267 +08:00] [DEBUG] [PageDirectory.cpp:2231] ["After MVCC gc in memory [lowest_seq=3] clean [invalid_snapshot_nums=1] [invalid_page_nums=0] [total_deref_counter=0] [all_del_entries=0]. Still exist [snapshot_nums=1], [page_nums=4]. Longest alive snapshot: [longest_alive_snapshot_time=0] [longest_alive_snapshot_seq=3] [stale_snapshot_nums=0]"] [source=test.t] [thread_id=1]

[2024/05/29 15:45:38.267 +08:00] [DEBUG] [BlobStore.cpp:1329] ["BlobStore gc get status done. details {ReadOnly: [null]} {Unchanged: [null]} {FullGC: [null]} {Truncated: [null]}"] [source=test.t] [thread_id=1]

[2024/05/29 15:45:38.267 +08:00] [DEBUG] [GCDefines.cpp:154] ["GC finished without full gc. [total time=0ms] [compact wal=0ms] [compact directory=0ms] [compact spacemap=0ms] [gc status=0ms] [gc entries=0ms] [gc data=0ms] [gc apply=0ms]"] [source=test.t] [thread_id=1]

/home/jenkins/agent/workspace/tiflash-build-common/tiflash/dbms/src/Storages/Page/V3/tests/gtest_page_storage.cpp:1307: Failure

Failed

Code: 49. DB::Exception: Check ref_count_delta_in_snap > 0 failed, deref_count_delta=1, ref_count_delta_in_snap=1, snap_seq=6, versions=2|1,4|1,

Stack trace:

      0x116346ee    StackTrace::StackTrace() [gtests_dbms+291718894]

       0x4a252e2    DB::Exception::Exception(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, int) [gtests_dbms+77746914]

       0x7dc4d0d    DB::Exception::Exception<long&, long&, unsigned long&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > >(int, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, long&, long&, unsigned long&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >&&) [gtests_dbms+131878157]

       0x7db8ff0    DB::PS::V3::MultiVersionRefCount::decrRefCountInSnap(unsigned long, long) [gtests_dbms+131829744]

      0x107aa9c0    DB::PS::V3::VersionedPageEntries<DB::PS::V3::u128::PageDirectoryTrait>::derefAndClean(unsigned long, DB::UInt128 const&, DB::PS::V3::PageVersion const&, long, std::__1::vector<DB::PS::V3::PageEntryV3, std::__1::allocator<DB::PS::V3::PageEntryV3> >*) [gtests_dbms+276474304]

      0x107bdbc7    DB::PS::V3::PageDirectory<DB::PS::V3::u128::PageDirectoryTrait>::gcInMemEntries(DB::PS::V3::PageDirectory<DB::PS::V3::u128::PageDirectoryTrait>::InMemGCOption const&) [gtests_dbms+276552647]

      0x10814fae    DB::PS::V3::ExternalPageCallbacksManager<DB::PS::V3::u128::ExternalPageCallbacksManagerTrait>::doGC(DB::PS::V3::BlobStore<DB::PS::V3::u128::BlobStoreTrait>&, DB::PS::V3::PageDirectory<DB::PS::V3::u128::PageDirectoryTrait>&, std::__1::shared_ptr<DB::WriteLimiter> const&, std::__1::shared_ptr<DB::ReadLimiter> const&, std::__1::unordered_map<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, unsigned long, std::__1::hash<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > >, std::__1::equal_to<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > >, std::__1::allocator<std::__1::pair<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const, unsigned long> > >*) [gtests_dbms+276909998]

      0x10814cec    DB::PS::V3::ExternalPageCallbacksManager<DB::PS::V3::u128::ExternalPageCallbacksManagerTrait>::gc(DB::PS::V3::BlobStore<DB::PS::V3::u128::BlobStoreTrait>&, DB::PS::V3::PageDirectory<DB::PS::V3::u128::PageDirectoryTrait>&, std::__1::shared_ptr<DB::WriteLimiter> const&, std::__1::shared_ptr<DB::ReadLimiter> const&, std::__1::unordered_map<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, unsigned long, std::__1::hash<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > >, std::__1::equal_to<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > >, std::__1::allocator<std::__1::pair<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const, unsigned long> > >*, std::__1::shared_ptr<DB::Logger>) [gtests_dbms+276909292]

      0x1080d691    DB::PS::V3::PageStorageImpl::gcImpl(bool, std::__1::shared_ptr<DB::WriteLimiter> const&, std::__1::shared_ptr<DB::ReadLimiter> const&) [gtests_dbms+276878993]

       0x784635d    DB::PageStorage::gc(bool, std::__1::shared_ptr<DB::WriteLimiter> const&, std::__1::shared_ptr<DB::ReadLimiter> const&) [gtests_dbms+126116701]

       0x7df528f    DB::PS::V3::tests::PageStorageTest_WriteReadGcExternalPage_Test::TestBody() [gtests_dbms+132076175]

       0xe41838b    void testing::internal::HandleSehExceptionsInMethodIfSupported<testing::Test, void>(testing::Test*, void (testing::Test::*)(), char const*) [gtests_dbms+239174539]

       0xe4058ca    void testing::internal::HandleExceptionsInMethodIfSupported<testing::Test, void>(testing::Test*, void (testing::Test::*)(), char const*) [gtests_dbms+239098058]

       0xe3eae9c    testing::Test::Run() [gtests_dbms+238988956]

       0xe3eb9ba    testing::TestInfo::Run() [gtests_dbms+238991802]

       0xe3ebf73    testing::TestCase::Run() [gtests_dbms+238993267]

       0xe3f6123    testing::internal::UnitTestImpl::RunAllTests() [gtests_dbms+239034659]

       0xe41bbbb    bool testing::internal::HandleSehExceptionsInMethodIfSupported<testing::internal::UnitTestImpl, bool>(testing::internal::UnitTestImpl*, bool (testing::internal::UnitTestImpl::*)(), char const*) [gtests_dbms+239188923]

       0xe4078ca    bool testing::internal::HandleExceptionsInMethodIfSupported<testing::internal::UnitTestImpl, bool>(testing::internal::UnitTestImpl*, bool (testing::internal::UnitTestImpl::*)(), char const*) [gtests_dbms+239106250]

       0xe3f5e36    testing::UnitTest::Run() [gtests_dbms+239033910]

       0x801ac31    RUN_ALL_TESTS() [gtests_dbms+134327345]

       0x8016c64    main [gtests_dbms+134311012]

  0x7fbe67434555    __libc_start_main [libc.so.6+140629]

       0x4a1a3a9    <unknown symbol> [gtests_dbms+77702057]

[  FAILED  ] PageStorageTest.WriteReadGcExternalPage (157 ms)

[----------] 1 test from PageStorageTest (157 ms total)

[----------] Global test environment tear-down

[==========] 1 test from 1 test case ran. (157 ms total)

[  PASSED  ] 0 tests.

[  FAILED  ] 1 test, listed below:

[  FAILED  ] PageStorageTest.WriteReadGcExternalPage

CalvinNeo commented 4 months ago

/retest

ti-chi-bot[bot] commented 4 months ago

[APPROVALNOTIFIER] This PR is APPROVED

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

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

The pull request process is described here

Needs approval from an approver in each of these files: - ~~[OWNERS](https://github.com/pingcap/tiflash/blob/master/OWNERS)~~ [JinheLin,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[bot] commented 4 months ago

[LGTM Timeline notifier]

Timeline:

2024-05-30 07:13:36.582292869 +0000 UTC m=+2933370.339428442: :ballot_box_with_check: agreed by Lloyd-Pottiger.
2024-05-31 06:51:38.198332313 +0000 UTC m=+3018451.955467889: :ballot_box_with_check: agreed by JinheLin.

CalvinNeo commented 4 months ago

/unhold

pingcap / tiflash

FAP: Add some logs #9095

What problem does this PR solve?

What is changed and how it works?

Check List

Release note

[LGTM Timeline notifier]