Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

util: add more log for expensive and global memory control #39397

Merged
merged 11 commits into from
Nov 28, 2022
Merged

util: add more log for expensive and global memory control #39397

merged 11 commits into from
Nov 28, 2022

Conversation

wshwsh12
Copy link
Contributor

@wshwsh12 wshwsh12 commented Nov 25, 2022 •
edited
Loading

What problem does this PR solve?

Issue Number: close #xxx

Problem Summary:

What is changed and how it works?

Add more logs for debug OOM.

Check List

Tests

  • Unit test
  • Integration test
  • Manual test (add detailed scripts or steps below)
    Case1: Run the sql and get the following logs.
select sleep(250);
[2022/11/25 16:58:22.742 +08:00] [WARN] [expensivequery.go:114] [expensive_query] [cost_time=60.004207298s] [conn_id=2199023255961] [user=root] [txn_start_ts=0] [mem_max="0 Bytes (0 Bytes)"] [sql="select sleep(250)"]
[2022/11/25 16:59:22.842 +08:00] [WARN] [expensivequery.go:114] [expensive_query] [cost_time=120.103998695s] [conn_id=2199023255961] [user=root] [txn_start_ts=0] [mem_max="0 Bytes (0 Bytes)"] [sql="select sleep(250)"]
[2022/11/25 17:00:22.843 +08:00] [WARN] [expensivequery.go:114] [expensive_query] [cost_time=180.104632801s] [conn_id=2199023255961] [user=root] [txn_start_ts=0] [mem_max="0 Bytes (0 Bytes)"] [sql="select sleep(250)"]
[2022/11/25 17:01:22.942 +08:00] [WARN] [expensivequery.go:114] [expensive_query] [cost_time=240.204083999s] [conn_id=2199023255961] [user=root] [txn_start_ts=0] [mem_max="0 Bytes (0 Bytes)"] [sql="select sleep(250)"]

Case2: Run the sqls and get the following log.

set @@global.tidb_mem_oom_action = "log"; # Simulate the case that sql cannot be killed in time.
set tidb_mem_quota_query = 1<<40;                # Avoid spilling.
set @@global.tidb_server_memory_limit = "1GB"; # Set global memory quota.
# Create a table t and insert 512 lines data.
desc analyze (select t2.a from t t1 join t t2 join t t3 on t1.a=t2.a and t1.a=t3.a order by t1.a) union all select sleep(30);
[2022/11/28 19:21:35.641 +08:00] [WARN] [servermemorylimit.go:126] ["global memory controller tries to kill the top1 memory consumer"] [connID=2199023255955] ["sql digest"=ae02411c0734957693eb7ef62950dce89ebb41bb7243e618cad5c7b3d6a7db95] ["sql text"="desc analyze (select t2.a from t t1 join t t2 join t t3 on t1.a=t2.a and t1.a=t3.a order by t1.a) un"] [tidb_server_memory_limit=1073741824] ["heap inuse"=1080754176] ["sql memory usage"=658629904]
[2022/11/28 19:21:35.641 +08:00] [WARN] [tracker.go:458] ["global memory controller, NeedKill signal is received successfully"] [connID=2199023255955]
[2022/11/28 19:21:40.741 +08:00] [WARN] [servermemorylimit.go:96] ["global memory controller failed to kill the top-consumer in 5s"] [connID=2199023255955] ["sql digest"=ae02411c0734957693eb7ef62950dce89ebb41bb7243e618cad5c7b3d6a7db95] ["sql text"="desc analyze (select t2.a from t t1 join t t2 join t t3 on t1.a=t2.a and t1.a=t3.a order by t1.a) un"] ["sql memory usage"=3621862107]
[2022/11/28 19:21:45.741 +08:00] [WARN] [servermemorylimit.go:96] ["global memory controller failed to kill the top-consumer in 10s"] [connID=2199023255955] ["sql digest"=ae02411c0734957693eb7ef62950dce89ebb41bb7243e618cad5c7b3d6a7db95] ["sql text"="desc analyze (select t2.a from t t1 join t t2 join t t3 on t1.a=t2.a and t1.a=t3.a order by t1.a) un"] ["sql memory usage"=3621862107]
[2022/11/28 19:21:50.742 +08:00] [WARN] [servermemorylimit.go:96] ["global memory controller failed to kill the top-consumer in 15s"] [connID=2199023255955] ["sql digest"=ae02411c0734957693eb7ef62950dce89ebb41bb7243e618cad5c7b3d6a7db95] ["sql text"="desc analyze (select t2.a from t t1 join t t2 join t t3 on t1.a=t2.a and t1.a=t3.a order by t1.a) un"] ["sql memory usage"=3621862107]
[2022/11/28 19:21:55.842 +08:00] [WARN] [servermemorylimit.go:96] ["global memory controller failed to kill the top-consumer in 20s"] [connID=2199023255955] ["sql digest"=ae02411c0734957693eb7ef62950dce89ebb41bb7243e618cad5c7b3d6a7db95] ["sql text"="desc analyze (select t2.a from t t1 join t t2 join t t3 on t1.a=t2.a and t1.a=t3.a order by t1.a) un"] ["sql memory usage"=3621862107]
[2022/11/28 19:22:00.941 +08:00] [WARN] [servermemorylimit.go:96] ["global memory controller failed to kill the top-consumer in 25s"] [connID=2199023255955] ["sql digest"=ae02411c0734957693eb7ef62950dce89ebb41bb7243e618cad5c7b3d6a7db95] ["sql text"="desc analyze (select t2.a from t t1 join t t2 join t t3 on t1.a=t2.a and t1.a=t3.a order by t1.a) un"] ["sql memory usage"=3621862107]
[2022/11/28 19:22:05.432 +08:00] [WARN] [servermemorylimit.go:112] ["global memory controller killed the top1 memory consumer successfully"]
  • 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

Please refer to Release Notes Language Style Guide to write a quality release note.

None

@ti-chi-bot
Copy link
Member

ti-chi-bot commented Nov 25, 2022 •
edited
Loading

[REVIEW NOTIFICATION]

This pull request has been approved by:

  • XuHuaiyu
  • hawkingrei

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.

@ti-chi-bot ti-chi-bot added release-note-none Denotes a PR that doesn't merit a release note. size/S Denotes a PR that changes 10-29 lines, ignoring generated files. labels Nov 25, 2022
@ti-chi-bot ti-chi-bot added size/M Denotes a PR that changes 30-99 lines, ignoring generated files. and removed size/S Denotes a PR that changes 10-29 lines, ignoring generated files. labels Nov 25, 2022
@hawkingrei
Copy link
Member

/run-build

1 similar comment
@hawkingrei
Copy link
Member

/run-build

XuHuaiyu
XuHuaiyu reviewed Nov 28, 2022
View reviewed changes
util/servermemorylimit/servermemorylimit.go Outdated
}

func killSessIfNeeded(s *sessionToBeKilled, bt uint64, sm util.SessionManager) {
if s.isKilling {
if info, ok := sm.GetProcessInfo(s.sessionID); ok {
if info.Time == s.sqlStartTime {
if time.Since(s.lastLogTime) > 5*time.Second {
logutil.BgLogger().Warn("Memory usage Top1 SQL can't handle the kill signal",
zap.String("sql_text", info.Info),
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

  1. connID needs to be logged.
  2. sql digest needs to be logged.
  3. info.Info needs to be truncated, I think we do not need to log the full text.

util/servermemorylimit/servermemorylimit.go Outdated
@@ -119,6 +129,13 @@ func killSessIfNeeded(s *sessionToBeKilled, bt uint64, sm util.SessionManager) {
SessionKillLast.Store(killTime)
IsKilling.Store(true)
GlobalMemoryOpsHistoryManager.recordOne(info, killTime, bt, instanceStats.HeapInuse)
s.lastLogTime = time.Now()
logutil.BgLogger().Warn("tidb-server has the risk of OOM. Try to kill the memory usage Top1 SQL.",
zap.String("sql_text", info.Info),
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

ditto

util/servermemorylimit/servermemorylimit.go Outdated
Comment on lines 94 to 97
if time.Since(s.lastLogTime) > 5*time.Second {
logutil.BgLogger().Warn("Memory usage Top1 SQL can't handle the kill signal",
zap.String("sql_text", info.Info),
zap.Int64("sql_memory_usage", info.MemTracker.BytesConsumed()))
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
if time.Since(s.lastLogTime) > 5*time.Second {
logutil.BgLogger().Warn("Memory usage Top1 SQL can't handle the kill signal",
zap.String("sql_text", info.Info),
zap.Int64("sql_memory_usage", info.MemTracker.BytesConsumed()))
if time.Since(s.lastLogTime) > 5*time.Second {
logutil.BgLogger().Warn("Memory usage Top1 SQL can't handle the kill signal",
zap.String("sql text", info.Info),
zap.Int64("sql memory usage", info.MemTracker.BytesConsumed()))

util/servermemorylimit/servermemorylimit.go Outdated
Comment on lines 133 to 137
logutil.BgLogger().Warn("tidb-server has the risk of OOM. Try to kill the memory usage Top1 SQL.",
zap.String("sql_text", info.Info),
zap.Uint64("server_memory_limit", bt),
zap.Uint64("heap_in_use", instanceStats.HeapInuse),
zap.Int64("sql_memory_usage", info.MemTracker.BytesConsumed()),
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
logutil.BgLogger().Warn("tidb-server has the risk of OOM. Try to kill the memory usage Top1 SQL.",
zap.String("sql_text", info.Info),
zap.Uint64("server_memory_limit", bt),
zap.Uint64("heap_in_use", instanceStats.HeapInuse),
zap.Int64("sql_memory_usage", info.MemTracker.BytesConsumed()),
logutil.BgLogger().Warn("tidb-server has the risk of OOM. Try to kill the top1 memory consumer",
zap.String("sql text", info.Info),
zap.Uint64("tidb_server_memory_limit", bt),
zap.Uint64("heap inuse", instanceStats.HeapInuse),
zap.Int64("sql memory usage", info.MemTracker.BytesConsumed()),

util/servermemorylimit/servermemorylimit.go Outdated
@@ -119,6 +129,13 @@ func killSessIfNeeded(s *sessionToBeKilled, bt uint64, sm util.SessionManager) {
SessionKillLast.Store(killTime)
IsKilling.Store(true)
GlobalMemoryOpsHistoryManager.recordOne(info, killTime, bt, instanceStats.HeapInuse)
s.lastLogTime = time.Now()
logutil.BgLogger().Warn("tidb-server has the risk of OOM. Try to kill the memory usage Top1 SQL.",
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
logutil.BgLogger().Warn("tidb-server has the risk of OOM. Try to kill the memory usage Top1 SQL.",
logutil.BgLogger().Warn("global memory controller tries to kill the top1 memory consumer",

util/servermemorylimit/servermemorylimit.go Outdated
}

func killSessIfNeeded(s *sessionToBeKilled, bt uint64, sm util.SessionManager) {
if s.isKilling {
if info, ok := sm.GetProcessInfo(s.sessionID); ok {
if info.Time == s.sqlStartTime {
if time.Since(s.lastLogTime) > 5*time.Second {
logutil.BgLogger().Warn("Memory usage Top1 SQL can't handle the kill signal",
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
logutil.BgLogger().Warn("Memory usage Top1 SQL can't handle the kill signal",
logutil.BgLogger().Warn(fmt.Sprintf("global memory controller failed to kill the top-consumer in %ds", now - killStartTime) ,

util/servermemorylimit/servermemorylimit.go
zap.String("sql_text", info.Info),
zap.Int64("sql_memory_usage", info.MemTracker.BytesConsumed()))
s.lastLogTime = time.Now()
}
return
}
}
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Do we need to add a log in lint 107 like "global memory controller killed the top1 memory consumer successfully"

util/servermemorylimit/servermemorylimit.go Outdated
@@ -81,12 +83,20 @@ type sessionToBeKilled struct {
sqlStartTime time.Time
sessionID uint64
sessionTracker *memory.Tracker

lastLogTime time.Time
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
lastLogTime time.Time
killStartTime time.Time
lastLogTime time.Time

@wshwsh12
Copy link
Contributor Author

/run-build
/run-unit-test

@ti-chi-bot ti-chi-bot added the status/LGT1 Indicates that a PR has LGTM 1. label Nov 28, 2022
@ti-chi-bot 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 Nov 28, 2022
@hawkingrei
Copy link
Member

/merge

@ti-chi-bot
Copy link
Member

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

Commit hash: 9a6edf0

@ti-chi-bot ti-chi-bot added the status/can-merge Indicates a PR has been approved by a committer. label Nov 28, 2022
@ti-chi-bot ti-chi-bot merged commit b3bbe96 into pingcap:master Nov 28, 2022
@sre-bot
Copy link
Contributor

sre-bot commented Nov 28, 2022

TiDB MergeCI notify

🔴 Bad News! New failing [2] after this pr merged.
These new failed integration tests seem to be caused by the current PR, please try to fix these new failed integration tests, thanks!

CI Name Result Duration Compare with Parent commit
idc-jenkins-ci/integration-cdc-test 🟥 failed 1, success 39, total 40 21 min New failing
idc-jenkins-ci-tidb/integration-ddl-test 🟥 failed 1, success 5, total 6 6 min 20 sec New failing
idc-jenkins-ci-tidb/integration-common-test 🟢 all 17 tests passed 14 min Existing passed
idc-jenkins-ci-tidb/common-test 🟢 all 11 tests passed 10 min Existing passed
idc-jenkins-ci-tidb/mybatis-test 🟢 all 1 tests passed 6 min 31 sec Existing passed
idc-jenkins-ci-tidb/tics-test 🟢 all 1 tests passed 6 min 10 sec Existing passed
idc-jenkins-ci-tidb/sqllogic-test-2 🟢 all 28 tests passed 5 min 15 sec Existing passed
idc-jenkins-ci-tidb/sqllogic-test-1 🟢 all 26 tests passed 3 min 51 sec Existing passed
idc-jenkins-ci-tidb/integration-compatibility-test 🟢 all 1 tests passed 2 min 44 sec Existing passed
idc-jenkins-ci-tidb/plugin-test 🟢 build success, plugin test success 4min Existing passed

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers

@XuHuaiyu XuHuaiyu XuHuaiyu approved these changes

@hawkingrei hawkingrei hawkingrei approved these changes

Assignees
No one assigned
Labels
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. status/can-merge Indicates a PR has been approved by a committer. status/LGT2 Indicates that a PR has LGTM 2.
Projects
None yet
Milestone
No milestone
Development

Successfully merging this pull request may close these issues.
5 participants
@wshwsh12 @ti-chi-bot @hawkingrei @sre-bot @XuHuaiyu