Tracing: Add tracing_id to PageStorage snapshot #4330

JaySon-Huang · 2022-03-17T10:24:16Z

What problem does this PR solve?

Issue Number: ref #4287

Problem Summary:
After #3632, we introduce DynamicThreadPool to reuse threads for handling incoming tasks. Then the "thread_id" record in PageStorage snapshot become less useful.

Add a "tracing_id" to the PageStorage snapshot, and use "read_tso" as the "tracing_id", it is more useful for locating bugs.

What is changed and how it works?

Add tracing_id for SnapshotPtr PageStorage::getSnapshot(const String & tracing_id)
Log down the tracing_id when stale snapshot(s) exist

Not only log the oldest snapshot, for each snapshot lives for more than 60s, log a warning line

tiflash/dbms/src/Storages/Page/V2/VersionSet/PageEntriesVersionSetWithDelta.cpp

Lines 332 to 340 in 0d0b79d

    
           if (snapshot_lifetime > exist_stale_snapshot) 
        
           { 
        
               LOG_FMT_WARNING( 
        
                   log, 
        
                   "Suspicious stale snapshot detected lifetime {:.3f} seconds, created from thread_id {}, tracing_id {}", 
        
                   snapshot_lifetime, 
        
                   snapshot_or_invalid->create_thread, 
        
                   snapshot_or_invalid->tracing_id); 
        
           }

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

Release note

None

ti-chi-bot · 2022-03-17T10:24:18Z

[REVIEW NOTIFICATION]

This pull request has been approved by:

jiaqizho
lidezhu

To complete the pull request process, please ask the reviewers in the list to review by filling /cc @reviewer in the comment.
After your PR has acquired the required number of LGTMs, you can assign this pull request to the committer in the list by filling /assign @committer in the comment to help you merge this pull request.

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

Reviewer can indicate their review by submitting an approval review.
Reviewer can cancel approval by submitting a request changes review.

JaySon-Huang · 2022-03-17T11:15:17Z

/run-all-tests

sre-bot · 2022-03-17T11:34:32Z

Coverage for changed files

Filename                                                  Regions    Missed Regions     Cover   Functions  Missed Functions  Executed       Lines      Missed Lines     Cover    Branches   Missed Branches     Cover
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
DeltaMerge/Delta/DeltaValueSpace.cpp                          202                82    59.41%          16                 0   100.00%         164                36    78.05%          92                54    41.30%
DeltaMerge/Delta/DeltaValueSpace.h                             99                17    82.83%          48                 4    91.67%         121                23    80.99%          32                10    68.75%
DeltaMerge/Delta/Snapshot.cpp                                  70                 4    94.29%           7                 0   100.00%          84                 5    94.05%          52                 9    82.69%
DeltaMerge/DeltaMergeStore.cpp                               1317               484    63.25%          65                 5    92.31%        1889               434    77.02%         766               372    51.44%
DeltaMerge/DeltaMergeStore.h                                   41                13    68.29%          19                 2    89.47%          85                30    64.71%          42                11    73.81%
DeltaMerge/StoragePool.h                                       24                 4    83.33%          15                 1    93.33%          21                 1    95.24%           6                 3    50.00%
DeltaMerge/tests/gtest_dm_delta_value_space.cpp              1148               167    85.45%          18                 1    94.44%         450                 5    98.89%         354               166    53.11%
DeltaMerge/tests/gtest_dm_minmax_index.cpp                   2093               377    81.99%          16                 0   100.00%         218                 0   100.00%         588               298    49.32%
Page/PageStorage.h                                             17                 5    70.59%          17                 5    70.59%          56                13    76.79%           0                 0         -
Page/Snapshot.h                                                 1                 0   100.00%           1                 0   100.00%           1                 0   100.00%           0                 0         -
Page/V2/PageStorage.cpp                                       518               146    71.81%          36                 3    91.67%         882               163    81.52%         350               144    58.86%
Page/V2/PageStorage.h                                          45                 9    80.00%          20                 3    85.00%          48                 3    93.75%          20                 9    55.00%
Page/V2/VersionSet/PageEntriesVersionSetWithDelta.cpp         207                51    75.36%          22                 0   100.00%         409                83    79.71%         148                47    68.24%
Page/V2/VersionSet/PageEntriesVersionSetWithDelta.h            18                 1    94.44%          10                 1    90.00%          52                 3    94.23%           6                 0   100.00%
Page/V2/gc/LegacyCompactor.cpp                                109                69    36.70%           8                 3    62.50%         213               115    46.01%          84                62    26.19%
Page/V3/PageDirectory.cpp                                     441                68    84.58%          30                 3    90.00%         985               194    80.30%         364                84    76.92%
Page/V3/PageDirectory.h                                        24                 6    75.00%          24                 6    75.00%         101                21    79.21%           0                 0         -
Page/V3/PageStorageImpl.cpp                                    69                24    65.22%          19                 7    63.16%         181                70    61.33%          40                24    40.00%
Page/V3/PageStorageImpl.h                                       9                 4    55.56%           9                 4    55.56%           9                 4    55.56%           0                 0         -
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
TOTAL                                                        6452              1531    76.27%         400                48    88.00%        5969              1203    79.85%        2944              1293    56.08%

Coverage summary

Functions  MissedFunctions  Executed  Lines   MissedLines  Cover
16975      9544             43.78%    191252  96878        49.35%

full coverage report (for internal network access only)

jiaqizho

LGTM, with a suggestion

jiaqizho · 2022-03-18T03:35:23Z

dbms/src/Storages/DeltaMerge/StoragePool.h

    }
-    PageReader newMetaReader(ReadLimiterPtr read_limiter, bool snapshot_read)
+    PageReader newMetaReader(ReadLimiterPtr read_limiter, bool snapshot_read, const String & tracing_id)


How about const String & tracing_id = ""?

I would like to keep it without a default value, to let the caller and reviewer think about whether we need to add a tracing id to it or not.

lidezhu

LGTM with small comment

lidezhu · 2022-03-18T03:52:30Z

dbms/src/Storages/DeltaMerge/Delta/Snapshot.cpp

@@ -38,7 +38,8 @@ DeltaSnapshotPtr DeltaValueSpace::createSnapshot(const DMContext & context, bool
    snap->is_update = for_update;
    snap->_delta = this->shared_from_this();

-    auto storage_snap = std::make_shared<StorageSnapshot>(context.storage_pool, context.getReadLimiter(), true);
+    // TODO: Add tracing_id from mpp task or background tasks


Maybe we can distinguish mpp task from background tasks using snap->is_update? For background tasks, it's always true. And for mpp task it's always false.

good idea, i will check it in the later pr

JaySon-Huang · 2022-03-18T05:18:30Z

/merge

ti-chi-bot · 2022-03-18T05:18:30Z

@JaySon-Huang: It seems you want to merge this PR, I will help you trigger all the tests:

/run-all-tests

You only need to trigger /merge once, and if the CI test fails, you just re-trigger the test that failed and the bot will merge the PR for you after the CI passes.

If you have any questions about the PR merge process, please refer to pr process.

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the ti-community-infra/tichi repository.

ti-chi-bot · 2022-03-18T05:18:36Z

This pull request has been accepted and is ready to merge.

Commit hash: 86af5b6

sre-bot · 2022-03-18T05:34:53Z

Coverage for changed files

Filename                                                  Regions    Missed Regions     Cover   Functions  Missed Functions  Executed       Lines      Missed Lines     Cover    Branches   Missed Branches     Cover
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
DeltaMerge/Delta/DeltaValueSpace.cpp                          202                82    59.41%          16                 0   100.00%         164                36    78.05%          92                54    41.30%
DeltaMerge/Delta/DeltaValueSpace.h                             99                17    82.83%          48                 4    91.67%         121                23    80.99%          32                10    68.75%
DeltaMerge/Delta/Snapshot.cpp                                  70                 4    94.29%           7                 0   100.00%          84                 5    94.05%          52                 9    82.69%
DeltaMerge/DeltaMergeStore.cpp                               1317               466    64.62%          65                 5    92.31%        1889               426    77.45%         766               365    52.35%
DeltaMerge/DeltaMergeStore.h                                   41                13    68.29%          19                 2    89.47%          85                30    64.71%          42                11    73.81%
DeltaMerge/StoragePool.h                                       24                 4    83.33%          15                 1    93.33%          21                 1    95.24%           6                 3    50.00%
DeltaMerge/tests/gtest_dm_delta_value_space.cpp              1148               167    85.45%          18                 1    94.44%         450                 5    98.89%         354               166    53.11%
DeltaMerge/tests/gtest_dm_minmax_index.cpp                   2093               377    81.99%          16                 0   100.00%         218                 0   100.00%         588               298    49.32%
Page/PageStorage.h                                             17                 5    70.59%          17                 5    70.59%          56                13    76.79%           0                 0         -
Page/Snapshot.h                                                 1                 0   100.00%           1                 0   100.00%           1                 0   100.00%           0                 0         -
Page/V2/PageStorage.cpp                                       518               146    71.81%          36                 3    91.67%         882               163    81.52%         350               144    58.86%
Page/V2/PageStorage.h                                          45                 9    80.00%          20                 3    85.00%          48                 3    93.75%          20                 9    55.00%
Page/V2/VersionSet/PageEntriesVersionSetWithDelta.cpp         207                51    75.36%          22                 0   100.00%         409                83    79.71%         148                47    68.24%
Page/V2/VersionSet/PageEntriesVersionSetWithDelta.h            18                 1    94.44%          10                 1    90.00%          52                 3    94.23%           6                 0   100.00%
Page/V2/gc/LegacyCompactor.cpp                                109                69    36.70%           8                 3    62.50%         213               115    46.01%          84                62    26.19%
Page/V3/PageDirectory.cpp                                     441                68    84.58%          30                 3    90.00%         985               194    80.30%         364                84    76.92%
Page/V3/PageDirectory.h                                        24                 6    75.00%          24                 6    75.00%         101                21    79.21%           0                 0         -
Page/V3/PageStorageImpl.cpp                                    69                24    65.22%          19                 7    63.16%         181                70    61.33%          40                24    40.00%
Page/V3/PageStorageImpl.h                                       9                 4    55.56%           9                 4    55.56%           9                 4    55.56%           0                 0         -
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
TOTAL                                                        6452              1513    76.55%         400                48    88.00%        5969              1195    79.98%        2944              1286    56.32%

Coverage summary

Functions  MissedFunctions  Executed  Lines   MissedLines  Cover
16977      9544             43.78%    191294  96883        49.35%

full coverage report (for internal network access only)

JaySon-Huang added 2 commits March 17, 2022 18:16

Add tracing_id to PageStorage snapshot

dc7a616

format

cf8682f

ti-chi-bot added release-note-none Denotes a PR that doesn't merit a release note. size/XL Denotes a PR that changes 500-999 lines, ignoring generated files. labels Mar 17, 2022

JaySon-Huang mentioned this pull request Mar 17, 2022

Tracing: Add read_tso as tracing id to PageStorage snapshot #4288

Merged

12 tasks

Add tracing_id

ac3ad0c

JaySon-Huang requested review from jiaqizho and lidezhu March 17, 2022 11:15

jiaqizho approved these changes Mar 18, 2022

View reviewed changes

ti-chi-bot added the status/LGT1 Indicates that a PR has LGTM 1. label Mar 18, 2022

lidezhu approved these changes Mar 18, 2022

View reviewed changes

ti-chi-bot added status/LGT2 Indicates that a PR has LGTM 2. and removed status/LGT1 Indicates that a PR has LGTM 1. labels Mar 18, 2022

JaySon-Huang added 2 commits March 18, 2022 13:18

Fix tracing id for stat

fc82764

Merge branch 'master' into tracing_id_to_ps

86af5b6

ti-chi-bot added the status/can-merge Indicates a PR has been approved by a committer. label Mar 18, 2022

ti-chi-bot merged commit 706d7c3 into pingcap:master Mar 18, 2022

JaySon-Huang deleted the tracing_id_to_ps branch March 18, 2022 05:52

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Tracing: Add tracing_id to PageStorage snapshot #4330

Tracing: Add tracing_id to PageStorage snapshot #4330

JaySon-Huang commented Mar 17, 2022

ti-chi-bot commented Mar 17, 2022 •

edited

Loading

JaySon-Huang commented Mar 17, 2022

sre-bot commented Mar 17, 2022

jiaqizho left a comment

jiaqizho Mar 18, 2022

JaySon-Huang Mar 18, 2022

lidezhu left a comment

lidezhu Mar 18, 2022

JaySon-Huang Mar 18, 2022

JaySon-Huang commented Mar 18, 2022

ti-chi-bot commented Mar 18, 2022

ti-chi-bot commented Mar 18, 2022

sre-bot commented Mar 18, 2022

	if (snapshot_lifetime > exist_stale_snapshot)
	{
	LOG_FMT_WARNING(
	log,
	"Suspicious stale snapshot detected lifetime {:.3f} seconds, created from thread_id {}, tracing_id {}",
	snapshot_lifetime,
	snapshot_or_invalid->create_thread,
	snapshot_or_invalid->tracing_id);
	}

Tracing: Add tracing_id to PageStorage snapshot #4330

Tracing: Add tracing_id to PageStorage snapshot #4330

Conversation

JaySon-Huang commented Mar 17, 2022

What problem does this PR solve?

What is changed and how it works?

Check List

Release note

ti-chi-bot commented Mar 17, 2022 • edited Loading

JaySon-Huang commented Mar 17, 2022

sre-bot commented Mar 17, 2022

Coverage for changed files

Coverage summary

jiaqizho left a comment

Choose a reason for hiding this comment

jiaqizho Mar 18, 2022

Choose a reason for hiding this comment

JaySon-Huang Mar 18, 2022

Choose a reason for hiding this comment

lidezhu left a comment

Choose a reason for hiding this comment

lidezhu Mar 18, 2022

Choose a reason for hiding this comment

JaySon-Huang Mar 18, 2022

Choose a reason for hiding this comment

JaySon-Huang commented Mar 18, 2022

ti-chi-bot commented Mar 18, 2022

ti-chi-bot commented Mar 18, 2022

sre-bot commented Mar 18, 2022

Coverage for changed files

Coverage summary

ti-chi-bot commented Mar 17, 2022 •

edited

Loading