time

log

log

pkg/ddl/ddl.go

@@ -1143,6 +1143,10 @@ func (*ddl) shouldCheckHistoryJob(job *model.Job) bool {
 // - context.Cancel: job has been sent to worker, but not found in history DDL job before cancel
 // - other: found in history DDL job and return that job error
 func (d *ddl) DoDDLJob(ctx sessionctx.Context, job *model.Job) error {
+	st := time.Now()
+	defer func() {
+		logutil.DDLLogger().Info("DoDDLJob cost", zap.Duration("total cost time", time.Since(st)))
+	}()
 	job.TraceInfo = &model.TraceInfo{
 		ConnectionID: ctx.GetSessionVars().ConnectionID,
 		SessionAlias: ctx.GetSessionVars().SessionAlias,
@@ -1155,6 +1159,7 @@ func (d *ddl) DoDDLJob(ctx sessionctx.Context, job *model.Job) error {
 	// Get a global job ID and put the DDL job in the queue.
 	setDDLJobQuery(ctx, job)
 	setDDLJobMode(job)
+	st2 := time.Now()
 	task := &limitJobTask{job, []chan error{make(chan error)}, nil}
 	d.deliverJobTask(task)
 
@@ -1176,6 +1181,7 @@ func (d *ddl) DoDDLJob(ctx sessionctx.Context, job *model.Job) error {
 		// The transaction of enqueuing job is failed.
 		return errors.Trace(err)
 	}
+	logutil.DDLLogger().Info("deliverJobTask and job 2 table cost", zap.Duration("total cost time", time.Since(st2)))
 
 	sessVars := ctx.GetSessionVars()
 	sessVars.StmtCtx.IsDDLJobInQueue = true
@@ -1247,7 +1253,7 @@ func (d *ddl) DoDDLJob(ctx sessionctx.Context, job *model.Job) error {
 				}
 			}
 		}
-
+		st := time.Now()
 		se, err := d.sessPool.Get()
 		if err != nil {
 			logutil.DDLLogger().Error("get session failed, check again", zap.Error(err))
@@ -1288,6 +1294,7 @@ func (d *ddl) DoDDLJob(ctx sessionctx.Context, job *model.Job) error {
 			appendMultiChangeWarningsToOwnerCtx(ctx, historyJob)
 
 			logutil.DDLLogger().Info("DDL job is finished", zap.Int64("jobID", jobID))
+			logutil.DDLLogger().Info("post DDL job", zap.Duration("total cost time", time.Since(st)))
 			return nil
 		}
 
@@ -1300,6 +1307,10 @@ func (d *ddl) DoDDLJob(ctx sessionctx.Context, job *model.Job) error {
 }
 
 func (d *ddl) callHookOnChanged(job *model.Job, err error) error {
+	st := time.Now()
+	defer func() {
+		logutil.DDLLogger().Info("callHookOnChanged cost", zap.Duration("total cost time", time.Since(st)))
+	}()
 	if job.State == model.JobStateNone {
 		// We don't call the hook if the job haven't run yet.
 		return err

pkg/ddl/ddl_api.go

@@ -2671,6 +2671,11 @@ func (d *ddl) assignPartitionIDs(defs []model.PartitionDefinition) error {
 }
 
 func (d *ddl) CreateTable(ctx sessionctx.Context, s *ast.CreateTableStmt) (err error) {
+	st := time.Now()
+	defer func() {
+		logutil.DDLLogger().Info("CreateTable cost", zap.Duration("total cost time", time.Since(st)))
+	}()
+	st2 := time.Now()
 	ident := ast.Ident{Schema: s.Table.Schema, Name: s.Table.Name}
 	is := d.GetInfoSchemaWithInterceptor(ctx)
 	schema, ok := is.SchemaByName(ident.Schema)
@@ -2713,7 +2718,7 @@ func (d *ddl) CreateTable(ctx sessionctx.Context, s *ast.CreateTableStmt) (err e
 	if s.IfNotExists {
 		onExist = OnExistIgnore
 	}
-
+	logutil.DDLLogger().Info("CreateTable CHECK cost", zap.Duration("total cost time", time.Since(st2)))
 	return d.CreateTableWithInfo(ctx, schema.Name, tbInfo, onExist)
 }
 
@@ -2744,6 +2749,10 @@ func (d *ddl) createTableWithInfoJob(
 	onExist OnExist,
 	retainID bool,
 ) (job *model.Job, err error) {
+	st := time.Now()
+	defer func() {
+		logutil.DDLLogger().Info("createTableWithInfoJob cost", zap.Duration("total cost time", time.Since(st)))
+	}()
 	is := d.GetInfoSchemaWithInterceptor(ctx)
 	schema, ok := is.SchemaByName(dbName)
 	if !ok {
@@ -2825,6 +2834,10 @@ func (d *ddl) createTableWithInfoPost(
 	tbInfo *model.TableInfo,
 	schemaID int64,
 ) error {
+	st := time.Now()
+	defer func() {
+		logutil.DDLLogger().Info("createTableWithInfoPost cost", zap.Duration("total cost time", time.Since(st)))
+	}()
 	var err error
 	var partitions []model.PartitionDefinition
 	if pi := tbInfo.GetPartitionInfo(); pi != nil {

pkg/ddl/ddl_worker.go

@@ -405,7 +405,9 @@ func (d *ddl) addBatchDDLJobs(tasks []*limitJobTask) error {
 		return errors.Trace(err)
 	}
 	defer d.sessPool.Put(se)
+	st1 := time.Now()
 	jobs, err := getJobsBySQL(sess.NewSession(se), JobTable, fmt.Sprintf("type = %d", model.ActionFlashbackCluster))
+	logutil.DDLLogger().Info("check flash back cluster job cost", zap.Duration("total cost time", time.Since(st1)))
 	if err != nil {
 		return errors.Trace(err)
 	}
@@ -452,7 +454,6 @@ func (d *ddl) addBatchDDLJobs(tasks []*limitJobTask) error {
 	if err != nil {
 		return errors.Trace(err)
 	}
-
 	jobTasks := make([]*model.Job, 0, len(tasks))
 	for i, task := range tasks {
 		job := task.job
@@ -895,6 +896,10 @@ func (w *worker) prepareTxn(job *model.Job) (kv.Transaction, error) {
 }
 
 func (w *worker) HandleDDLJobTable(d *ddlCtx, job *model.Job) (int64, error) {
+	st := time.Now()
+	defer func() {
+		logutil.DDLLogger().Info("HandleDDLJobTable cost", zap.Duration("total cost time", time.Since(st)))
+	}()
 	var (
 		err       error
 		schemaVer int64
@@ -1379,6 +1384,10 @@ func toTError(err error) *terror.Error {
 // waitSchemaChanged waits for the completion of updating all servers' schema or MDL synced. In order to make sure that happens,
 // we wait at most 2 * lease time(sessionTTL, 90 seconds).
 func waitSchemaChanged(d *ddlCtx, waitTime time.Duration, latestSchemaVersion int64, job *model.Job) error {
+	st := time.Now()
+	defer func() {
+		logutil.DDLLogger().Info("waitSchemaChanged cost", zap.Duration("total cost time", time.Since(st)))
+	}()
 	if !job.IsRunning() && !job.IsRollingback() && !job.IsDone() && !job.IsRollbackDone() {
 		return nil
 	}

pkg/ddl/job_table.go

@@ -204,7 +204,13 @@ func (d *ddl) processJobDuringUpgrade(sess *sess.Session, job *model.Job) (isRun
 	return true, nil
 }
 
-func (d *ddl) getGeneralJob(sess *sess.Session) (*model.Job, error) {
+func (d *ddl) getGeneralJob(sess *sess.Session) (job *model.Job, err error) {
+	st := time.Now()
+	defer func() {
+		if job != nil {
+			logutil.DDLLogger().Info("getGeneralJob cost", zap.Duration("total cost time", time.Since(st)))
+		}
+	}()
 	return d.getJob(sess, jobTypeGeneral, func(job *model.Job) (bool, error) {
 		if !d.runningJobs.checkRunnable(job) {
 			return false, nil
@@ -480,8 +486,10 @@ func (d *ddl) delivery2Worker(wk *worker, pool *workerPool, job *model.Job) {
 			if err != nil {
 				return
 			}
+			st := time.Now()
 			cleanMDLInfo(d.sessPool, job.ID, d.etcdCli, job.State == model.JobStateSynced)
 			d.synced(job)
+			logutil.DDLLogger().Info("cleanMDLInfo cost", zap.Duration("total cost time", time.Since(st)))
 
 			if RunInGoTest {
 				// d.mu.hook is initialed from domain / test callback, which will force the owner host update schema diff synchronously.

pkg/server/conn.go

@@ -1345,6 +1345,10 @@ func (cc *clientConn) dispatch(ctx context.Context, data []byte) error {
 			data = data[:len(data)-1]
 			dataStr = string(hack.String(data))
 		}
+		ts := time.Now()
+		defer func() {
+			logutil.BgLogger().Info("command dispatched", zap.String("sql", dataStr), zap.Duration("total cost time", time.Since(ts)))
+		}()
 		return cc.handleQuery(ctx, dataStr)
 	case mysql.ComFieldList:
 		return cc.handleFieldList(ctx, dataStr)