metrics(ticdc): add some log and metrics to owner and processorManage… #4402

CharlesCheung96 · 2022-01-19T06:53:57Z

What problem does this PR solve?

Issue Number: close #3884

What is changed and how it works?

add some log and metrics to owner and processorManager to detect stuck scenario

Check List

Code changes

None

Side effects

Increased code complexity

Related changes

None

Release note

Add some log and metrics to owner and processorManager to detect stuck scenario

ti-chi-bot · 2022-01-19T06:53:57Z

[REVIEW NOTIFICATION]

This pull request has been approved by:

amyangfei
asddongmen

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.

3AceShowHand · 2022-01-19T11:29:54Z

/run-all-tests

CharlesCheung96 · 2022-01-20T02:50:16Z

/run-all-tests

amyangfei · 2022-01-21T03:04:35Z

cdc/owner/owner.go

+		if costTime > changefeedLogsWarnDuration {
+			log.Warn("changefeed tick took too long", zap.String("changefeed", changefeedID), zap.Duration("duration", costTime))
+		}
+		changefeedReactorTickDuration.WithLabelValues(changefeedID).Observe(costTime.Seconds())


We should avoid using WithLabelValues to create metric observer in hot path, which will cost too much CPU.
A better solution is to pre allocate prometheus labels and reuse the observer, such as what we use in processor

tiflow/cdc/processor/processor.go

Lines 240 to 248 in 99389d6

metricResolvedTsGauge: resolvedTsGauge.WithLabelValues(changefeedID, advertiseAddr),

metricResolvedTsLagGauge: resolvedTsLagGauge.WithLabelValues(changefeedID, advertiseAddr),

metricMinResolvedTableIDGuage: resolvedTsMinTableIDGauge.WithLabelValues(changefeedID, advertiseAddr),

metricCheckpointTsGauge: checkpointTsGauge.WithLabelValues(changefeedID, advertiseAddr),

metricCheckpointTsLagGauge: checkpointTsLagGauge.WithLabelValues(changefeedID, advertiseAddr),

metricMinCheckpointTableIDGuage: checkpointTsMinTableIDGauge.WithLabelValues(changefeedID, advertiseAddr),

metricSyncTableNumGauge: syncTableNumGauge.WithLabelValues(changefeedID, advertiseAddr),

metricProcessorErrorCounter: processorErrorCounter.WithLabelValues(changefeedID, advertiseAddr),

metricSchemaStorageGcTsGauge: processorSchemaStorageGcTsGauge.WithLabelValues(changefeedID, advertiseAddr),

CharlesCheung96 · 2022-01-21T13:57:07Z

/run-all-tests

CharlesCheung96 · 2022-01-22T13:40:40Z

/run-kafka-integration-tests
/run-integration-tests

asddongmen · 2022-01-25T02:53:08Z

cdc/owner/changefeed.go

@@ -128,6 +132,17 @@ func (c *changefeed) Tick(ctx cdcContext.Context, state *orchestrator.Changefeed
 			Message: err.Error(),
 		})
 		c.releaseResources(ctx)
+	} else {
+		// c.initialize(ctx)
+		costTime := time.Since(startTime)


May be it is better to rewrite the whole if block as:

err := c.tick() costTime = time.Since(startTime) // warn log here if err != nil { ... } ...

cdc/processor/manager.go

ben1009


[2022-01-25T02:45:17.902Z] === Failed

[2022-01-25T02:45:17.902Z] === FAIL: pkg/etcd TestGetOwnerRevision (11.99s)

[2022-01-25T02:45:17.902Z]     etcd_test.go:418: 

[2022-01-25T02:45:17.902Z]         	Error Trace:	etcd_test.go:418

[2022-01-25T02:45:17.902Z]         	            				asm_amd64.s:1371

[2022-01-25T02:45:17.902Z]         	Error:      	"etcdserver: request timed out" does not contain "context canceled"

[2022-01-25T02:45:17.902Z]         	Test:       	TestGetOwnerRevision

[2022-01-25T02:45:17.902Z]     etcd_test.go:418: 

[2022-01-25T02:45:17.902Z]         	Error Trace:	etcd_test.go:418

[2022-01-25T02:45:17.902Z]         	            				asm_amd64.s:1371

[2022-01-25T02:45:17.902Z]         	Error:      	"rpc error: code = Unknown desc = context deadline exceeded" does not contain "context canceled"

[2022-01-25T02:45:17.902Z]         	Test:       	TestGetOwnerRevision

[2022-01-25T02:45:17.902Z] ==================

[2022-01-25T02:45:17.902Z] WARNING: DATA RACE

[2022-01-25T02:45:17.902Z] Write at 0x00c000f03ea1 by goroutine 163:

[2022-01-25T02:45:17.902Z]   testing.(*common).FailNow()

[2022-01-25T02:45:17.902Z]       /usr/local/go/src/testing/testing.go:740 +0x4f

[2022-01-25T02:45:17.902Z]   testing.(*T).FailNow()

[2022-01-25T02:45:17.902Z]       <autogenerated>:1 +0x44

[2022-01-25T02:45:17.902Z]   github.com/stretchr/testify/require.Contains()

[2022-01-25T02:45:17.902Z]       /go/pkg/mod/github.com/stretchr/testify@v1.7.0/require/require.go:50 +0x124

[2022-01-25T02:45:17.902Z]   github.com/pingcap/tiflow/pkg/etcd.TestGetOwnerRevision.func1()

ben1009 · 2022-01-26T01:45:23Z

cdc/owner/metrics.go

@@ -65,13 +69,34 @@ var (
 			Name:      "status",
 			Help:      "The status of changefeeds",
 		}, []string{"changefeed"})
+	changefeedTickDuration = prometheus.NewHistogramVec(


maybe add a screenshot after the metric applied make things more clear, the dashboard template will be added later ?

pingcap#3884)

CharlesCheung96 · 2022-01-26T04:02:04Z

/run-all-tests

CharlesCheung96 · 2022-02-08T02:37:07Z

/run-all-tests

codecov-commenter · 2022-02-08T03:34:17Z

Codecov Report

Merging #4402 (8ef0148) into master (9607554) will decrease coverage by 0.2072%.
The diff coverage is 55.2425%.

Flag	Coverage Δ
cdc	`60.1109% <67.1532%> (+0.1886%)`	⬆️
dm	`51.5270% <51.9920%> (-0.5019%)`	⬇️

Flags with carried forward coverage won't be shown. Click here to find out more.

@@               Coverage Diff                @@
##             master      #4402        +/-   ##
================================================
- Coverage   55.6402%   55.4329%   -0.2073%     
================================================
  Files           494        498         +4     
  Lines         61283      61826       +543     
================================================
+ Hits          34098      34272       +174     
- Misses        23750      24109       +359     
- Partials       3435       3445        +10

amyangfei · 2022-02-08T03:45:10Z

/merge

ti-chi-bot · 2022-02-08T03:45:12Z

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

Commit hash: 8ef0148

ti-chi-bot · 2022-02-08T03:45:25Z

@CharlesCheung96: Your PR was out of date, I have automatically updated it for you.

At the same time I will also trigger all tests for you:

/run-all-tests

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.

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.

CharlesCheung96 · 2022-02-08T04:49:49Z

/run-kafka-integration-tests

CharlesCheung96 requested a review from amyangfei January 19, 2022 06:53

ti-chi-bot added release-note Denotes a PR that will be considered when it comes time to generate release notes. size/L Denotes a PR that changes 100-499 lines, ignoring generated files. labels Jan 19, 2022

3AceShowHand self-requested a review January 19, 2022 10:01

CharlesCheung96 force-pushed the fix_3884_add_log_to_detect_stuck branch from 10e35c4 to ced7a7d Compare January 20, 2022 02:12

amyangfei reviewed Jan 21, 2022

View reviewed changes

CharlesCheung96 force-pushed the fix_3884_add_log_to_detect_stuck branch from ced7a7d to ad7df9d Compare January 21, 2022 09:14

CharlesCheung96 added the area/ticdc Issues or PRs related to TiCDC. label Jan 21, 2022

CharlesCheung96 force-pushed the fix_3884_add_log_to_detect_stuck branch from d279324 to c55d844 Compare January 21, 2022 13:56

CharlesCheung96 requested a review from asddongmen January 25, 2022 02:33

asddongmen reviewed Jan 25, 2022

View reviewed changes

cdc/processor/manager.go Show resolved Hide resolved

ben1009 reviewed Jan 26, 2022

View reviewed changes

CharlesCheung96 added 3 commits January 26, 2022 10:34

metrics(ticdc): add warn log and metrics to owner and processorManager (

56d870c

pingcap#3884)

fix nil poniter bug

f63d3be

address comments

8975c79

CharlesCheung96 force-pushed the fix_3884_add_log_to_detect_stuck branch from 34108fc to 8975c79 Compare January 26, 2022 03:59

Merge branch 'master' into fix_3884_add_log_to_detect_stuck

ed82791

amyangfei approved these changes Jan 26, 2022

View reviewed changes

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

amyangfei added the component/metrics-logging Metrics and logging component. label Jan 26, 2022

asddongmen approved these changes Feb 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 Feb 7, 2022

Merge branch 'master' into fix_3884_add_log_to_detect_stuck

7bd1ded

ti-chi-bot added the do-not-merge/needs-triage-completed label Feb 7, 2022

Merge branch 'master' into fix_3884_add_log_to_detect_stuck

8858a1f

Merge branch 'master' into fix_3884_add_log_to_detect_stuck

8ef0148

ti-chi-bot removed the do-not-merge/needs-triage-completed label Feb 8, 2022

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

Merge branch 'master' into fix_3884_add_log_to_detect_stuck

f06c508

ti-chi-bot merged commit c4f8055 into pingcap:master Feb 8, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

metrics(ticdc): add some log and metrics to owner and processorManage… #4402

metrics(ticdc): add some log and metrics to owner and processorManage… #4402

CharlesCheung96 commented Jan 19, 2022 •

edited

Loading

ti-chi-bot commented Jan 19, 2022 •

edited

Loading

3AceShowHand commented Jan 19, 2022

CharlesCheung96 commented Jan 20, 2022

amyangfei Jan 21, 2022 •

edited

Loading

CharlesCheung96 commented Jan 21, 2022

CharlesCheung96 commented Jan 22, 2022

asddongmen Jan 25, 2022

ben1009 left a comment •

edited

Loading

ben1009 Jan 26, 2022

CharlesCheung96 commented Jan 26, 2022

CharlesCheung96 commented Feb 8, 2022

codecov-commenter commented Feb 8, 2022 •

edited

Loading

amyangfei commented Feb 8, 2022

ti-chi-bot commented Feb 8, 2022

ti-chi-bot commented Feb 8, 2022

CharlesCheung96 commented Feb 8, 2022

	metricResolvedTsGauge: resolvedTsGauge.WithLabelValues(changefeedID, advertiseAddr),
	metricResolvedTsLagGauge: resolvedTsLagGauge.WithLabelValues(changefeedID, advertiseAddr),
	metricMinResolvedTableIDGuage: resolvedTsMinTableIDGauge.WithLabelValues(changefeedID, advertiseAddr),
	metricCheckpointTsGauge: checkpointTsGauge.WithLabelValues(changefeedID, advertiseAddr),
	metricCheckpointTsLagGauge: checkpointTsLagGauge.WithLabelValues(changefeedID, advertiseAddr),
	metricMinCheckpointTableIDGuage: checkpointTsMinTableIDGauge.WithLabelValues(changefeedID, advertiseAddr),
	metricSyncTableNumGauge: syncTableNumGauge.WithLabelValues(changefeedID, advertiseAddr),
	metricProcessorErrorCounter: processorErrorCounter.WithLabelValues(changefeedID, advertiseAddr),
	metricSchemaStorageGcTsGauge: processorSchemaStorageGcTsGauge.WithLabelValues(changefeedID, advertiseAddr),

metrics(ticdc): add some log and metrics to owner and processorManage… #4402

metrics(ticdc): add some log and metrics to owner and processorManage… #4402

Conversation

CharlesCheung96 commented Jan 19, 2022 • edited Loading

What problem does this PR solve?

What is changed and how it works?

Check List

Release note

ti-chi-bot commented Jan 19, 2022 • edited Loading

3AceShowHand commented Jan 19, 2022

CharlesCheung96 commented Jan 20, 2022

amyangfei Jan 21, 2022 • edited Loading

Choose a reason for hiding this comment

CharlesCheung96 commented Jan 21, 2022

CharlesCheung96 commented Jan 22, 2022

asddongmen Jan 25, 2022

Choose a reason for hiding this comment

ben1009 left a comment • edited Loading

Choose a reason for hiding this comment

ben1009 Jan 26, 2022

Choose a reason for hiding this comment

CharlesCheung96 commented Jan 26, 2022

CharlesCheung96 commented Feb 8, 2022

codecov-commenter commented Feb 8, 2022 • edited Loading

Codecov Report

amyangfei commented Feb 8, 2022

ti-chi-bot commented Feb 8, 2022

ti-chi-bot commented Feb 8, 2022

CharlesCheung96 commented Feb 8, 2022

CharlesCheung96 commented Jan 19, 2022 •

edited

Loading

ti-chi-bot commented Jan 19, 2022 •

edited

Loading

amyangfei Jan 21, 2022 •

edited

Loading

ben1009 left a comment •

edited

Loading

codecov-commenter commented Feb 8, 2022 •

edited

Loading