Redundant log "Waiting for tidb instances ready"

[DangHT]

Bug Report

Please answer these questions before submitting your issue. Thanks!

1. What did you do?
   Run tiup playground

2. What did you expect to see?
   one line of "Waiting for tidb instances ready" log

3. What did you see instead?
   multi line of "Waiting for tidb instances ready" log

4. What version of TiUP are you using (tiup --version)?

v1.3.0 tiup
Go Version: go1.13
Git Branch: release-1.3
GitHash: edb12b8

[9547]

Actually, it's not a bug, it's a progress status bar, and will stop print out until TiDB is fully started, see more from here:

tiup/components/playground/playground.go

Lines 792 to 820 in edb12b8

	bars := progress.NewMultiBar(color.YellowString("Waiting for tidb instances ready\n"))
	for _, db := range p.tidbs {
	wg.Add(1)
	prefix := color.YellowString(db.Addr())
	bar := bars.AddBar(prefix)
	go func(dbInst *instance.TiDBInstance) {
	defer wg.Done()
	if s := checkDB(dbInst.Addr(), options.tidb.UpTimeout); s {
	{
	appendMutex.Lock()
	succ = append(succ, dbInst.Addr())
	appendMutex.Unlock()
	}
	bar.UpdateDisplay(&progress.DisplayProps{
	Prefix: prefix,
	Mode: progress.ModeDone,
	})
	} else {
	bar.UpdateDisplay(&progress.DisplayProps{
	Prefix: prefix,
	Mode: progress.ModeError,
	})
	}
	}(db)
	}
	bars.StartRenderLoop()
	wg.Wait()
	bars.StopRenderLoop()
	}

[DangHT]

I think that if only one tidb instance is started, only one line of log should be output, because the tiflash below it does this, but I see this:

Starting component `playground`: /home/danght/.tiup/components/playground/v1.3.0/tiup-playground
Use the latest stable version: v4.0.8

    Specify version manually:   tiup playground <version>
    The stable version:         tiup playground v4.0.0
    The nightly version:        tiup playground nightly

Playground Bootstrapping...
Start pd instance
Start tikv instance
Start tidb instance
Waiting for tidb instances ready
Waiting for tidb instances ready
Waiting for tidb instances ready
Waiting for tidb instances ready
Waiting for tidb instances ready
Waiting for tidb instances ready
Waiting for tidb instances ready
Waiting for tidb instances ready
Waiting for tidb instances ready
Waiting for tidb instances ready
Waiting for tidb instances ready
Waiting for tidb instances ready
Waiting for tidb instances ready
Waiting for tidb instances ready
Waiting for tidb instances ready
Waiting for tidb instances ready
Waiting for tidb instances ready
Waiting for tidb instances ready
Waiting for tidb instances ready
Waiting for tidb instances ready
Waiting for tidb instances ready
Waiting for tidb instances ready
Waiting for tidb instances ready
Waiting for tidb instances ready
Waiting for tidb instances ready
Waiting for tidb instances ready
Waiting for tidb instances ready
Waiting for tidb instances ready
Waiting for tidb instances ready
Waiting for tidb instances ready
Waiting for tidb instances ready
Waiting for tidb instances ready
Waiting for tidb instances ready
Waiting for tidb instances ready
127.0.0.1:4000 ... Done
Start tiflash instance
Waiting for tiflash instances ready
127.0.0.1:3930 ... Done
CLUSTER START SUCCESSFULLY, Enjoy it ^-^
To connect TiDB: mysql --host 127.0.0.1 --port 4000 -u root
To view the dashboard: http://127.0.0.1:2379/dashboard
To view the Prometheus: http://127.0.0.1:9090
To view the Grafana: http://127.0.0.1:3000

[9547]

First of all, the Waiting for message is based on the starting-time, not on the number of instances, and the default render time is 50ms:

tiup/pkg/cliutil/progress/progress.go

Line 34 in edb12b8

var refreshRate = time.Millisecond * 50

and you can increase this value to see if the output decreased or not by set env TIUP_CLUSTER_PROGRESS_REFRESH_RATE to have a try

tiup/pkg/cliutil/progress/progress.go

Line 42 in edb12b8

v := os.Getenv("TIUP_CLUSTER_PROGRESS_REFRESH_RATE")

But that leaves me with the question, why has TiDB taken so long to bootup?

[DangHT]

I tried to set env TIUP_CLUSTER_PROGRESS_REFRESH_RATE to 500ms and the output Waiting for tidb instances ready did decrease, but the interesting thing is that the output Waiting for tiflash instances ready increased. In the case of default 50ms, it always has only one.:joy:
Also, my test environment is WSL Ubuntu 20.04 LTS.

$ tiup playground
Starting component `playground`: /home/danght/.tiup/components/playground/v1.3.0/tiup-playground
Use the latest stable version: v4.0.8

    Specify version manually:   tiup playground <version>
    The stable version:         tiup playground v4.0.0
    The nightly version:        tiup playground nightly

Playground Bootstrapping...
Start pd instance
Start tikv instance
Start tidb instance
Waiting for tidb instances ready
Waiting for tidb instances ready
Waiting for tidb instances ready
Waiting for tidb instances ready
Waiting for tidb instances ready
Waiting for tidb instances ready
Waiting for tidb instances ready
Waiting for tidb instances ready
Waiting for tidb instances ready
Waiting for tidb instances ready
Waiting for tidb instances ready
Waiting for tidb instances ready
Waiting for tidb instances ready
127.0.0.1:4000 ... Done

Start tiflash instance
Waiting for tiflash instances ready
Waiting for tiflash instances ready
Waiting for tiflash instances ready
Waiting for tiflash instances ready
Waiting for tiflash instances ready
127.0.0.1:3930 ... Done

CLUSTER START SUCCESSFULLY, Enjoy it ^-^
To connect TiDB: mysql --host 127.0.0.1 --port 4000 -u root
To view the dashboard: http://127.0.0.1:2379/dashboard
To view the Prometheus: http://127.0.0.1:9090
To view the Grafana: http://127.0.0.1:3000

[AstroProfundis]

I think it would be better if we change those lines to a progress bar status that always refresh itself on the same line, as suggested in #1454

[c4pt0r]

Any update on this? It's really painful..