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

schema_storage: verbose DDL log #3187

Merged
merged 7 commits into from
Oct 30, 2021
Merged

schema_storage: verbose DDL log #3187

Changes from all commits
Commits
Show all changes
7 commits
Select commit Hold shift + click to select a range
2d521d2
schema_storage: verbose DDL log
overvenus Oct 28, 2021
82421fe
Apply suggestions from code review
overvenus Oct 29, 2021
cf17861
address comments
overvenus Oct 29, 2021
aa7b77a
Merge branch 'master' into verbose-ddl
ti-chi-bot Oct 29, 2021
3f0575b
Merge branch 'master' into verbose-ddl
ti-chi-bot Oct 29, 2021
fedd27c
Merge branch 'master' into verbose-ddl
ti-chi-bot Oct 29, 2021
f553e2b
Merge branch 'master' into verbose-ddl
ti-chi-bot Oct 29, 2021
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
23 changes: 16 additions & 7 deletions cdc/entry/schema_storage.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -463,7 +463,9 @@ func (s *schemaSnapshot) updatePartition(tbl *model.TableInfo) error {
for _, partition := range newPi.Definitions {
// update table info.
if _, ok := s.partitionTable[partition.ID]; ok {
log.Debug("add table partition success", zap.String("name", tbl.Name.O), zap.Int64("tid", id), zap.Reflect("add partition id", partition.ID))
log.Debug("add table partition success",
zap.String("name", tbl.Name.O), zap.Int64("tid", id),
zap.Int64("add partition id", partition.ID))
}
s.partitionTable[partition.ID] = tbl
if !tbl.IsEligible(s.explicitTables) {
Expand All @@ -477,7 +479,9 @@ func (s *schemaSnapshot) updatePartition(tbl *model.TableInfo) error {
s.truncateTableID[pid] = struct{}{}
delete(s.partitionTable, pid)
delete(s.ineligibleTableID, pid)
log.Debug("drop table partition success", zap.String("name", tbl.Name.O), zap.Int64("tid", id), zap.Reflect("truncated partition id", pid))
log.Debug("drop table partition success",
zap.String("name", tbl.Name.O), zap.Int64("tid", id),
zap.Int64("truncated partition id", pid))
}

return nil
Expand Down Expand Up @@ -545,7 +549,7 @@ func (s *schemaSnapshot) handleDDL(job *timodel.Job) error {
if err := s.FillSchemaName(job); err != nil {
return errors.Trace(err)
}
log.Debug("handle job: ", zap.String("sql query", job.Query), zap.Stringer("job", job))
log.Info("handle DDL", zap.String("DDL", job.Query), zap.Stringer("job", job))
getWrapTableInfo := func(job *timodel.Job) *model.TableInfo {
return model.WrapTableInfo(job.SchemaID, job.SchemaName,
job.BinlogInfo.FinishedTS,
Expand Down Expand Up @@ -719,11 +723,15 @@ func (s *schemaStorageImpl) GetSnapshot(ctx context.Context, ts uint64) (*schema
// The infinite retry here is a temporary solution to the `ErrSchemaStorageUnresolved` caused by
// DDL puller lagging too much.
startTime := time.Now()
Copy link
Contributor

Choose a reason for hiding this comment

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

startTime is not used somewhere else

logTime := startTime
asddongmen marked this conversation as resolved.
Show resolved Hide resolved
err := retry.Do(ctx, func() error {
var err error
snap, err = s.getSnapshot(ts)
if time.Since(startTime) >= 5*time.Minute && isRetryable(err) {
log.Warn("GetSnapshot is taking too long, DDL puller stuck?", zap.Uint64("ts", ts))
now := time.Now()
if now.Sub(logTime) >= 30*time.Second && isRetryable(err) {
Copy link
Contributor

Choose a reason for hiding this comment

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

how about use time.Since

Copy link
Member Author

Choose a reason for hiding this comment

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

time.Since calls time.Now() internally, and time.Now() invokes a syscall clock_gettime. The current approach is more performant.

log.Warn("GetSnapshot is taking too long, DDL puller stuck?",
zap.Uint64("ts", ts), zap.Duration("duration", now.Sub(startTime)))
logTime = now
}
return err
}, retry.WithBackoffBaseDelay(10), retry.WithInfiniteTries(), retry.WithIsRetryableErr(isRetryable))
Expand Down Expand Up @@ -754,7 +762,8 @@ func (s *schemaStorageImpl) HandleDDLJob(job *timodel.Job) error {
if len(s.snaps) > 0 {
lastSnap := s.snaps[len(s.snaps)-1]
if job.BinlogInfo.FinishedTS <= lastSnap.currentTs {
log.Debug("ignore foregone DDL job", zap.Reflect("job", job))
log.Info("ignore foregone DDL",
zap.Int64("jobID", job.ID), zap.String("DDL", job.Query))
return nil
}
snap = lastSnap.Clone()
Expand Down Expand Up @@ -818,7 +827,7 @@ func (s *schemaStorageImpl) DoGC(ts uint64) {
// At state *done*, it will be always and only changed to *synced*.
func (s *schemaStorageImpl) skipJob(job *timodel.Job) bool {
if s.filter != nil && s.filter.ShouldDiscardDDL(job.Type) {
log.Info("discard the ddl job", zap.Int64("jobID", job.ID), zap.String("query", job.Query))
log.Info("discard DDL", zap.Int64("jobID", job.ID), zap.String("DDL", job.Query))
return true
}
return !job.IsSynced() && !job.IsDone()
Expand Down