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

JaySon-Huang · 2022-03-15T13:09:56Z

What problem does this PR solve?

Issue Number: close #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 some interface for DB::Logger to avoid lock confilct in Poco::Logger::get
Use read_tso as tracing_id
Make the log for reading data from the storage layer log with the prefix("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-15T13:10:00Z

[REVIEW NOTIFICATION]

This pull request has been approved by:

SeaRise
jiaqizho

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.

dbms/src/Flash/Coprocessor/DAGStorageInterpreter.cpp

JaySon-Huang · 2022-03-15T13:27:34Z

/run-all-tests

JaySon-Huang · 2022-03-15T15:14:49Z

/run-all-tests

JaySon-Huang · 2022-03-15T16:46:45Z

/rebuild

JaySon-Huang · 2022-03-15T17:22:53Z

/run-all-tests

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

dbms/src/Storages/DeltaMerge/DeltaMergeStore.cpp

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

/hold
split to smaller PR for review #4330

JaySon-Huang · 2022-04-02T07:42:35Z

base_4w.log.zip
detail_500m.log.zip

after this PR, here are two logging files that contain queries that scan 40,000/500,000,000 rows from the storage layer.

PTAL for this PR @fuzhe1989 @SeaRise @lidezhu

JaySon-Huang · 2022-04-02T08:19:05Z

/run-all-tests

JaySon-Huang · 2022-04-06T12:01:17Z

/run-unit-test

sre-bot · 2022-04-06T12:09:57Z

Coverage for changed files

Filename                                                     Regions    Missed Regions     Cover   Functions  Missed Functions  Executed       Lines      Missed Lines     Cover    Branches   Missed Branches     Cover
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Common/Logger.h                                                   20                 3    85.00%          18                 3    83.33%          53                13    75.47%           2                 0   100.00%
Flash/Coprocessor/DAGStorageInterpreter.cpp                      336               336     0.00%          17                17     0.00%         616               616     0.00%         220               220     0.00%
Server/tests/gtest_dttool.cpp                                    400                52    87.00%           7                 0   100.00%         216                 6    97.22%         142                61    57.04%
Storages/DeltaMerge/ColumnFile/ColumnFileBig.cpp                  68                 9    86.76%          12                 0   100.00%         170                20    88.24%          40                10    75.00%
Storages/DeltaMerge/DMContext.h                                    4                 0   100.00%           4                 0   100.00%           7                 0   100.00%           0                 0         -
Storages/DeltaMerge/DMVersionFilterBlockInputStream.h             80                12    85.00%          11                 1    90.91%         107                 1    99.07%          44                15    65.91%
Storages/DeltaMerge/Delta/Snapshot.cpp                            70                 4    94.29%           7                 0   100.00%          84                 5    94.05%          52                 9    82.69%
Storages/DeltaMerge/DeltaMergeStore.cpp                         1347               473    64.88%          64                 5    92.19%        1947               449    76.94%         790               375    52.53%
Storages/DeltaMerge/DeltaMergeStore.h                             41                13    68.29%          19                 2    89.47%          85                30    64.71%          42                11    73.81%
Storages/DeltaMerge/File/DMFileBlockInputStream.cpp               12                 2    83.33%           2                 0   100.00%          44                 6    86.36%          12                 3    75.00%
Storages/DeltaMerge/File/DMFileBlockInputStream.h                 16                 1    93.75%          16                 1    93.75%          53                 1    98.11%           0                 0         -
Storages/DeltaMerge/File/DMFilePackFilter.h                      123                14    88.62%          12                 1    91.67%         202                 7    96.53%          88                15    82.95%
Storages/DeltaMerge/File/DMFileReader.cpp                        211                13    93.84%          12                 0   100.00%         428                23    94.63%         148                18    87.84%
Storages/DeltaMerge/File/DMFileReader.h                            9                 0   100.00%           3                 0   100.00%           7                 0   100.00%           4                 0   100.00%
Storages/DeltaMerge/FilterParser/FilterParser.cpp                160                30    81.25%           6                 0   100.00%         266                58    78.20%         192                50    73.96%
Storages/DeltaMerge/RowKeyRangeUtils.cpp                          50                 9    82.00%          11                 0   100.00%         103                 1    99.03%          28                 6    78.57%
Storages/DeltaMerge/Segment.cpp                                  648               199    69.29%          47                 5    89.36%        1137               273    75.99%         340               182    46.47%
Storages/DeltaMerge/SegmentReadTaskPool.h                          7                 0   100.00%           4                 0   100.00%          11                 0   100.00%           2                 0   100.00%
Storages/DeltaMerge/StableValueSpace.cpp                         107                25    76.64%          15                 1    93.33%         277                66    76.17%          74                25    66.22%
Storages/DeltaMerge/tests/gtest_dm_delta_merge_store.cpp        6008              1604    73.30%          37                 1    97.30%        2757                95    96.55%        2002               886    55.74%
Storages/DeltaMerge/tests/gtest_dm_minmax_index.cpp             2093               377    81.99%          16                 0   100.00%         218                 0   100.00%         588               298    49.32%
Storages/SelectQueryInfo.cpp                                       4                 2    50.00%           4                 2    50.00%           4                 2    50.00%           0                 0         -
Storages/SelectQueryInfo.h                                         1                 1     0.00%           1                 1     0.00%           1                 1     0.00%           0                 0         -
Storages/StorageDeltaMerge.cpp                                   669               360    46.19%          56                29    48.21%        1294               764    40.96%         378               259    31.48%
Storages/StorageDeltaMerge.h                                      11                 7    36.36%          11                 7    36.36%          15                 9    40.00%           0                 0         -
Storages/StorageDeltaMergeHelpers.h                               11                 2    81.82%           1                 0   100.00%          27                 5    81.48%          10                 3    70.00%
Storages/tests/gtest_filter_parser.cpp                          2478               248    89.99%          12                 0   100.00%         402                 2    99.50%         826               417    49.52%
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
TOTAL                                                          14984              3796    74.67%         425                76    82.12%       10531              2453    76.71%        6024              2863    52.47%

Coverage summary

Functions  MissedFunctions  Executed  Lines   MissedLines  Cover
17012      9508             44.11%    191705  96392        49.72%

full coverage report (for internal network access only)

jiaqizho

lgtm

dbms/src/Flash/Coprocessor/DAGStorageInterpreter.cpp

JaySon-Huang · 2022-04-08T06:35:03Z

/merge

ti-chi-bot · 2022-04-08T06:35:04Z

@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-04-08T06:35:06Z

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

Commit hash: eefc658

sre-bot · 2022-04-08T07:09:02Z

Coverage for changed files

Filename                                                     Regions    Missed Regions     Cover   Functions  Missed Functions  Executed       Lines      Missed Lines     Cover    Branches   Missed Branches     Cover
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Common/Logger.h                                                   20                 3    85.00%          18                 3    83.33%          53                13    75.47%           2                 0   100.00%
Flash/Coprocessor/DAGStorageInterpreter.cpp                      336               336     0.00%          17                17     0.00%         616               616     0.00%         220               220     0.00%
Server/tests/gtest_dttool.cpp                                    400                52    87.00%           7                 0   100.00%         216                 6    97.22%         142                61    57.04%
Storages/DeltaMerge/ColumnFile/ColumnFileBig.cpp                  68                 9    86.76%          12                 0   100.00%         170                20    88.24%          40                10    75.00%
Storages/DeltaMerge/DMContext.h                                    4                 0   100.00%           4                 0   100.00%           7                 0   100.00%           0                 0         -
Storages/DeltaMerge/DMVersionFilterBlockInputStream.h             80                12    85.00%          11                 1    90.91%         107                 1    99.07%          44                15    65.91%
Storages/DeltaMerge/Delta/Snapshot.cpp                            70                 4    94.29%           7                 0   100.00%          84                 5    94.05%          52                 9    82.69%
Storages/DeltaMerge/DeltaMergeStore.cpp                         1347               482    64.22%          64                 5    92.19%        1947               453    76.73%         790               378    52.15%
Storages/DeltaMerge/DeltaMergeStore.h                             41                13    68.29%          19                 2    89.47%          85                30    64.71%          42                11    73.81%
Storages/DeltaMerge/File/DMFileBlockInputStream.cpp               12                 2    83.33%           2                 0   100.00%          44                 6    86.36%          12                 3    75.00%
Storages/DeltaMerge/File/DMFileBlockInputStream.h                 16                 1    93.75%          16                 1    93.75%          53                 1    98.11%           0                 0         -
Storages/DeltaMerge/File/DMFilePackFilter.h                      123                14    88.62%          12                 1    91.67%         202                 7    96.53%          88                13    85.23%
Storages/DeltaMerge/File/DMFileReader.cpp                        211                13    93.84%          12                 0   100.00%         428                23    94.63%         148                18    87.84%
Storages/DeltaMerge/File/DMFileReader.h                            9                 0   100.00%           3                 0   100.00%           7                 0   100.00%           4                 0   100.00%
Storages/DeltaMerge/FilterParser/FilterParser.cpp                160                30    81.25%           6                 0   100.00%         266                58    78.20%         192                50    73.96%
Storages/DeltaMerge/RowKeyRangeUtils.cpp                          50                 9    82.00%          11                 0   100.00%         103                 1    99.03%          28                 6    78.57%
Storages/DeltaMerge/Segment.cpp                                  648               199    69.29%          47                 5    89.36%        1137               273    75.99%         340               182    46.47%
Storages/DeltaMerge/SegmentReadTaskPool.h                          7                 0   100.00%           4                 0   100.00%          11                 0   100.00%           2                 0   100.00%
Storages/DeltaMerge/StableValueSpace.cpp                         107                25    76.64%          15                 1    93.33%         277                66    76.17%          74                25    66.22%
Storages/DeltaMerge/tests/gtest_dm_delta_merge_store.cpp        6008              1604    73.30%          37                 1    97.30%        2757                95    96.55%        2002               886    55.74%
Storages/DeltaMerge/tests/gtest_dm_minmax_index.cpp             2093               377    81.99%          16                 0   100.00%         218                 0   100.00%         588               298    49.32%
Storages/SelectQueryInfo.cpp                                       4                 2    50.00%           4                 2    50.00%           4                 2    50.00%           0                 0         -
Storages/SelectQueryInfo.h                                         1                 1     0.00%           1                 1     0.00%           1                 1     0.00%           0                 0         -
Storages/StorageDeltaMerge.cpp                                   669               360    46.19%          56                29    48.21%        1294               764    40.96%         378               259    31.48%
Storages/StorageDeltaMerge.h                                      11                 7    36.36%          11                 7    36.36%          15                 9    40.00%           0                 0         -
Storages/StorageDeltaMergeHelpers.h                               11                 2    81.82%           1                 0   100.00%          27                 5    81.48%          10                 3    70.00%
Storages/tests/gtest_filter_parser.cpp                          2478               248    89.99%          12                 0   100.00%         402                 2    99.50%         826               417    49.52%
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
TOTAL                                                          14984              3805    74.61%         425                76    82.12%       10531              2457    76.67%        6024              2864    52.46%

Coverage summary

Functions  MissedFunctions  Executed  Lines   MissedLines  Cover
17023      9510             44.13%    191899  96432        49.75%

full coverage report (for internal network access only)

ti-chi-bot added release-note-none Denotes a PR that doesn't merit a release note. do-not-merge/work-in-progress Indicates that a PR should not merge because it is a work in progress. labels Mar 15, 2022

JaySon-Huang requested review from lidezhu and jiaqizho March 15, 2022 13:10

ti-chi-bot added the size/XXL Denotes a PR that changes 1000+ lines, ignoring generated files. label Mar 15, 2022

JaySon-Huang requested review from fuzhe1989 and fzhedu March 15, 2022 13:10

JaySon-Huang commented Mar 15, 2022

View reviewed changes

dbms/src/Flash/Coprocessor/DAGStorageInterpreter.cpp Outdated Show resolved Hide resolved

JaySon-Huang force-pushed the tracing_logger branch from c55bd88 to 8677520 Compare March 15, 2022 13:24

JaySon-Huang force-pushed the tracing_logger branch 2 times, most recently from 947eef9 to 0d0b79d Compare March 15, 2022 16:34

JaySon-Huang changed the title ~~[WIP] Tracing: Add read_tso as tracing id to PageStorage snapshot~~ Tracing: Add read_tso as tracing id to PageStorage snapshot Mar 15, 2022

ti-chi-bot removed the do-not-merge/work-in-progress Indicates that a PR should not merge because it is a work in progress. label Mar 15, 2022

fuzhe1989 requested a review from SeaRise March 16, 2022 02:31

fuzhe1989 reviewed Mar 16, 2022

View reviewed changes

dbms/src/Storages/DeltaMerge/Delta/ColumnFilePersistedSet.cpp Outdated Show resolved Hide resolved

SeaRise reviewed Mar 16, 2022

View reviewed changes

dbms/src/Storages/DeltaMerge/DeltaMergeStore.cpp Outdated Show resolved Hide resolved

ti-chi-bot added the needs-rebase Indicates a PR cannot be merged because it has merge conflicts with HEAD. label Mar 16, 2022

JaySon-Huang force-pushed the tracing_logger branch from 5a2dfc9 to 56ffca8 Compare March 17, 2022 05:21

ti-chi-bot added do-not-merge/hold Indicates that a PR should not merge because someone has issued a /hold command. and removed needs-rebase Indicates a PR cannot be merged because it has merge conflicts with HEAD. labels Mar 17, 2022

JaySon-Huang force-pushed the tracing_logger branch from 56ffca8 to cb3fedf Compare March 18, 2022 06:14

ti-chi-bot added size/XL Denotes a PR that changes 500-999 lines, ignoring generated files. needs-rebase Indicates a PR cannot be merged because it has merge conflicts with HEAD. and removed size/XXL Denotes a PR that changes 1000+ lines, ignoring generated files. labels Mar 18, 2022

jiaqizho approved these changes Apr 7, 2022

View reviewed changes

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

SeaRise self-requested a review April 7, 2022 03:50

SeaRise reviewed Apr 7, 2022

View reviewed changes

dbms/src/Flash/Coprocessor/DAGStorageInterpreter.cpp Outdated Show resolved Hide resolved

JaySon-Huang added 9 commits April 7, 2022 15:59

Add tracing_id to snapshot

257ec4c

Add more tracing log on the storage layer by prefix logger

23f47a4

Add to system table

cd5677b

Fix compile error

422232b

add more tracing_id other than query

3b7d30a

Address comment

c960ca3

Refine some loggers

d435fb8

Add prefix for segment logging

0cb882f

Add table id for tracing_id

ed9de1a

JaySon-Huang force-pushed the tracing_logger branch from c79c4a6 to ed9de1a Compare April 7, 2022 09:12

Add epoch for segment

eefc658

SeaRise approved these changes Apr 7, 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 Apr 7, 2022

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

ti-chi-bot merged commit dec116f into pingcap:master Apr 8, 2022

JaySon-Huang deleted the tracing_logger branch April 8, 2022 07:52

JaySon-Huang mentioned this pull request Apr 12, 2022

Add read_tso as tracing id to DeltaTree engine #4287

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

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

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

JaySon-Huang commented Mar 15, 2022 •

edited

Loading

ti-chi-bot commented Mar 15, 2022 •

edited

Loading

JaySon-Huang commented Mar 15, 2022

JaySon-Huang commented Mar 15, 2022

JaySon-Huang commented Mar 15, 2022

JaySon-Huang commented Mar 15, 2022

JaySon-Huang commented Mar 17, 2022

JaySon-Huang commented Apr 2, 2022 •

edited

Loading

JaySon-Huang commented Apr 2, 2022

JaySon-Huang commented Apr 6, 2022

sre-bot commented Apr 6, 2022

jiaqizho left a comment

JaySon-Huang commented Apr 8, 2022

ti-chi-bot commented Apr 8, 2022

ti-chi-bot commented Apr 8, 2022

sre-bot commented Apr 8, 2022

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

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

Conversation

JaySon-Huang commented Mar 15, 2022 • edited Loading

What problem does this PR solve?

What is changed and how it works?

Check List

Release note

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

JaySon-Huang commented Mar 15, 2022

JaySon-Huang commented Mar 15, 2022

JaySon-Huang commented Mar 15, 2022

JaySon-Huang commented Mar 15, 2022

JaySon-Huang commented Mar 17, 2022

JaySon-Huang commented Apr 2, 2022 • edited Loading

JaySon-Huang commented Apr 2, 2022

JaySon-Huang commented Apr 6, 2022

sre-bot commented Apr 6, 2022

Coverage for changed files

Coverage summary

jiaqizho left a comment

Choose a reason for hiding this comment

JaySon-Huang commented Apr 8, 2022

ti-chi-bot commented Apr 8, 2022

ti-chi-bot commented Apr 8, 2022

sre-bot commented Apr 8, 2022

Coverage for changed files

Coverage summary

JaySon-Huang commented Mar 15, 2022 •

edited

Loading

ti-chi-bot commented Mar 15, 2022 •

edited

Loading

JaySon-Huang commented Apr 2, 2022 •

edited

Loading