logging: log time taken for tablet initialization only once

[deepthi]

Description

Time taken for tablet init should be logged exactly once, and not every time the tablet goes through a state transition.
The way I have chosen to make this happen is by using sync.Once. However it is open to debate whether the log line should actually be moved to some other location in the code to ensure that it is called exactly once.

With this change, even after running a PRS, no new log line appears of the form Tablet Init took 17899ms.

Related Issue(s)

Fixes #14596

Checklist

• "Backport to:" labels have been added if this change should be back-ported
• Tests were added or are not required
• Did the new or modified tests pass consistently locally and on the CI
• Documentation was added or is not required

Deployment Notes

[vitess-bot]

Review Checklist

Hello reviewers! 👋 Please follow this checklist when reviewing this Pull Request.

General

• Ensure that the Pull Request has a descriptive title.
• Ensure there is a link to an issue (except for internal cleanup and flaky test fixes), new features should have an RFC that documents use cases and test cases.

Tests

• Bug fixes should have at least one unit or end-to-end test, enhancement and new features should have a sufficient number of tests.

Documentation

• Apply the release notes (needs details) label if users need to know about this change.
• New features should be documented.
• There should be some code comments as to why things are implemented the way they are.
• There should be a comment at the top of each new or modified test to explain what the test does.

New flags

• Is this flag really necessary?
• Flag names must be clear and intuitive, use dashes (-), and have a clear help text.

If a workflow is added or modified:

• Each item in Jobs should be named in order to mark it as required.
• If the workflow needs to be marked as required, the maintainer team must be notified.

Backward compatibility

• Protobuf changes should be wire-compatible.
• Changes to _vt tables and RPCs need to be backward compatible.
• RPC changes should be compatible with vitess-operator
• If a flag is removed, then it should also be removed from vitess-operator and arewefastyet, if used there.
• vtctl command output order should be stable and awk-able.

[deepthi]

@rohit-nayak-ps WDYT?

However it is open to debate whether the log line should actually be moved to some other location in the code to ensure that it is called exactly once.

[rohit-nayak-ps]

So we don't want it to log for every transition, because the next few times are not actually "Init"s? Are these extra logs confusing and/or redundant information?

However it is open to debate whether the log line should actually be moved to some other location in the code to ensure that it is called exactly once.

I think this location is fine.

One thing that this location doesn't capture is the time taken forOpen()ing of all the components that happens in tmState.UpdateLocked(). iirc I couldn't find a better location which reliably reports it.

[deepthi]

So we don't want it to log for every transition, because the next few times are not actually "Init"s? Are these extra logs confusing and/or redundant information?

Yes. While debugging an issue in PlanetScale, this log made it seem like Initialization had been hanging for a long time, when in fact it was triggered by a change in primary.

One thing that this location doesn't capture is the time taken for Open()ing of all the components that happens in tmState.UpdateLocked(). iirc I couldn't find a better location which reliably reports it.

This is the part that I was also not able to fully understand. In the Start function, we have:

	defer func() {
		log.Infof("TabletManager Start took ~%d ms", time.Since(servenv.GetInitStartTime()).Milliseconds())
	}()

I would have expected this to print the total amount of time taken until Start finishes, which includes the time taken to execute tm.tmState.Open() at the end of that function. But somehow it does not seem to include that time.

[deepthi]

I would have expected this to print the total amount of time taken until Start finishes, which includes the time taken to execute tm.tmState.Open() at the end of that function. But somehow it does not seem to include that time.

This is because we run the example with --restore_from_backup (which defaults to true), and in that path, we do everything in a separate goroutine. This means that Start returns early and does not include time taken for the rest of initialization (like opening all the engines).
How will it be if we instead record the time taken by tmState.Open??

[deepthi]

I tried to move the logging to tmState.Open. What happens in the example is that it takes at least 4 attempts before the "transition" is successful. Each tablet logs an error like this 3 times.

E1127 12:49:49.141542   88106 state_manager.go:286] Error transitioning to the desired state: REPLICA, Serving, will keep retrying: Unknown database 'vt_commerce' (errno 1049) (sqlstate 42000)

So what we have right now is the best we can do. When we eventually call setState we record the time taken until then.
However, we should probably revisit this as part of fixing #14562.
For now, I'm going to merge this PR in its current form.