Skip to content

Commit 19cefbd

Browse files
Alexander MorozovAlexander Morozov
authored andcommitted
feat: send timings metrics
1 parent d81eeb7 commit 19cefbd

6 files changed

Lines changed: 195 additions & 0 deletions

File tree

internal/app/app.go

Lines changed: 13 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -640,6 +640,7 @@ func (app *App) stateManager() appState {
640640
} else {
641641
if !switchover.InitiatedAt.IsZero() && time.Since(switchover.InitiatedAt) > app.config.SwitchoverTimeout {
642642
app.logger.Error().Msgf("switchover %s => %s timed out after %s", switchover.From, switchover.To, time.Since(switchover.InitiatedAt))
643+
app.logSwitchoverFailure(switchover)
643644
err = app.FailSwitchover(switchover, fmt.Errorf("switchover timed out after %s", time.Since(switchover.InitiatedAt)))
644645
if err != nil {
645646
app.logger.Error().Err(err).Msg("failed to report switchover timeout")
@@ -710,6 +711,9 @@ func (app *App) stateManager() appState {
710711
}
711712
} else {
712713
app.t.Clean(NodeFailedAt, master)
714+
// flush timings left behind by an aborted failover/switchover
715+
app.stopTiming(timingDowntime, "")
716+
app.stopTiming(timingFailover, "")
713717
}
714718

715719
if !clusterState[master].PingOk {
@@ -1366,6 +1370,11 @@ func (app *App) performSwitchover(clusterState map[string]*nodestate.NodeState,
13661370
}
13671371
}
13681372

1373+
// downtime for failover starts at master loss (see IssueFailover); for switchover it starts here
1374+
if switchover.MasterTransition == SwitchoverTransition {
1375+
app.startTiming(timingDowntime, time.Time{})
1376+
}
1377+
13691378
// set read only everywhere (all HA-nodes) and stop replication
13701379
app.logger.Info().Msg("switchover: phase 1: enter read only")
13711380
errs := util.RunParallel(func(host string) error {
@@ -1607,6 +1616,10 @@ func (app *App) performSwitchover(clusterState map[string]*nodestate.NodeState,
16071616
}
16081617
app.logger.Info().Msgf("switchover: new master %s set writable", newMaster)
16091618

1619+
// cluster is open for writes again, failover/downtime are over
1620+
app.stopTiming(timingDowntime, "")
1621+
app.stopTiming(timingFailover, "")
1622+
16101623
// reenable events
16111624
events, err := newMasterNode.ReenableEventsRetry()
16121625
if err != nil || app.emulateError("promote_reenable_events") {

internal/app/app_dcs.go

Lines changed: 13 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -149,6 +149,12 @@ func (app *App) FinishSwitchover(switchover *Switchover, switchErr error) error
149149
switchover.Result.Error = switchErr.Error()
150150
}
151151

152+
if switchErr != nil {
153+
app.logSwitchoverFailure(switchover)
154+
} else if switchover.MasterTransition == SwitchoverTransition {
155+
app.stopTiming(timingSwitchover, "")
156+
}
157+
152158
err := app.dcs.Delete(pathCurrentSwitch)
153159
if err != nil {
154160
return err
@@ -171,6 +177,9 @@ func (app *App) StartSwitchover(switchover *Switchover) error {
171177
app.logger.Info().Msgf("switchover: %s => %s starting...", switchover.From, switchover.To)
172178
switchover.StartedAt = time.Now()
173179
switchover.StartedBy = app.config.Hostname
180+
if switchover.MasterTransition == SwitchoverTransition {
181+
app.startTiming(timingSwitchover, time.Time{})
182+
}
174183
return app.dcs.Set(pathCurrentSwitch, switchover)
175184
}
176185

@@ -199,6 +208,10 @@ func (app *App) IssueFailover(master string) error {
199208
switchover.InitiatedAt = time.Now()
200209
switchover.Cause = CauseAuto
201210
switchover.MasterTransition = FailoverTransition
211+
// downtime/failover are measured from the moment the master was lost
212+
failedAt := app.t.Get(NodeFailedAt, master)
213+
app.startTiming(timingDowntime, failedAt)
214+
app.startTiming(timingFailover, failedAt)
202215
return app.dcs.Create(pathCurrentSwitch, switchover)
203216
}
204217

internal/app/data.go

Lines changed: 3 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -65,6 +65,9 @@ const (
6565

6666
// last known timestamp from repl_mon table
6767
pathMasterReplMonTS = "master_repl_mon_ts"
68+
69+
// timing start timestamps, structure: pathTimings/<name> -> time.Time
70+
pathTimings = "timing"
6871
)
6972

7073
var (

internal/app/timing_tracker.go

Lines changed: 94 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,94 @@
1+
package app
2+
3+
import (
4+
"context"
5+
"fmt"
6+
"os/exec"
7+
"strconv"
8+
"time"
9+
10+
"github.com/yandex/mysync/internal/dcs"
11+
"github.com/yandex/mysync/internal/util"
12+
)
13+
14+
// names of tracked timings
15+
const (
16+
timingDowntime = "downtime"
17+
timingFailover = "failover"
18+
timingSwitchover = "switchover"
19+
)
20+
21+
func (app *App) timingPath(name string) string {
22+
return dcs.JoinPath(pathTimings, name)
23+
}
24+
25+
// getTimingStart returns stored start time and whether it exists
26+
func (app *App) getTimingStart(name string) (time.Time, bool) {
27+
var ts time.Time
28+
if err := app.dcs.Get(app.timingPath(name), &ts); err != nil {
29+
return time.Time{}, false
30+
}
31+
return ts, true
32+
}
33+
34+
// startTiming stores timing start in dcs (zero ts means now)
35+
func (app *App) startTiming(name string, ts time.Time) {
36+
if ts.IsZero() {
37+
ts = time.Now()
38+
}
39+
if err := app.dcs.Set(app.timingPath(name), ts); err != nil {
40+
app.logger.Warn().Err(err).Msgf("failed to start timing %s", name)
41+
}
42+
}
43+
44+
func (app *App) clearTiming(name string) {
45+
if err := app.dcs.Delete(app.timingPath(name)); err != nil {
46+
app.logger.Warn().Err(err).Msgf("failed to clear timing %s", name)
47+
}
48+
}
49+
50+
// stopTiming logs elapsed time since start as trackAs (defaults to name) and clears it
51+
func (app *App) stopTiming(name, trackAs string) {
52+
start, ok := app.getTimingStart(name)
53+
if !ok {
54+
return
55+
}
56+
app.clearTiming(name)
57+
if trackAs == "" {
58+
trackAs = name
59+
}
60+
app.logTiming(trackAs, time.Since(start))
61+
}
62+
63+
// logSwitchoverFailure records time spent on a failed switchover as a negative value.
64+
// Marker-guarded so it is logged once, and only when the switchover actually started.
65+
func (app *App) logSwitchoverFailure(sw *Switchover) {
66+
if sw.MasterTransition != SwitchoverTransition {
67+
return
68+
}
69+
start, ok := app.getTimingStart(timingSwitchover)
70+
if !ok {
71+
return
72+
}
73+
app.clearTiming(timingSwitchover)
74+
since := sw.InitiatedAt
75+
if since.IsZero() {
76+
since = start
77+
}
78+
app.logTiming(timingSwitchover+"_failure", -time.Since(since))
79+
}
80+
81+
// logTiming runs the configured log_timing command with name and elapsed seconds
82+
func (app *App) logTiming(name string, d time.Duration) {
83+
command, ok := app.config.Commands["log_timing"]
84+
if !ok || command == "" {
85+
return
86+
}
87+
command = fmt.Sprintf(command, name, strconv.FormatFloat(d.Seconds(), 'f', 3, 64))
88+
ctx, cancel := context.WithTimeout(context.Background(), 10*time.Second)
89+
defer cancel()
90+
shell := util.GetEnvVariable("SHELL", "sh")
91+
if err := exec.CommandContext(ctx, shell, "-c", command).Run(); err != nil {
92+
app.logger.Warn().Err(err).Msgf("failed to execute log_timing command for %s", name)
93+
}
94+
}

tests/features/timings.feature

Lines changed: 70 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,70 @@
1+
Feature: failover and switchover timings are logged via log_timing command
2+
3+
Scenario: failover logs downtime and failover timings
4+
Given cluster environment is
5+
"""
6+
MYSYNC_FAILOVER=true
7+
MYSYNC_FAILOVER_DELAY=0s
8+
"""
9+
Given cluster is up and running
10+
Then zookeeper node "/test/active_nodes" should match json_exactly within "20" seconds
11+
"""
12+
["mysql1","mysql2","mysql3"]
13+
"""
14+
When host "mysql1" is stopped
15+
Then mysql host "mysql1" should become unavailable within "10" seconds
16+
Then zookeeper node "/test/last_switch" should match json within "30" seconds
17+
"""
18+
{
19+
"cause": "auto",
20+
"from": "mysql1",
21+
"master_transition": "failover",
22+
"result": {
23+
"ok": true
24+
}
25+
}
26+
"""
27+
When I get zookeeper node "/test/manager"
28+
And I save zookeeper query result as "manager"
29+
When I run command on host "{{.manager.hostname}}" until result match regexp "failover:" with timeout "30" seconds
30+
"""
31+
cat /tmp/timing.log
32+
"""
33+
Then command output should match regexp
34+
"""
35+
downtime:
36+
"""
37+
38+
Scenario: switchover logs downtime and switchover timings
39+
Given cluster is up and running
40+
Then mysql host "mysql1" should be master
41+
And zookeeper node "/test/active_nodes" should match json_exactly within "30" seconds
42+
"""
43+
["mysql1","mysql2","mysql3"]
44+
"""
45+
When I run command on host "mysql1"
46+
"""
47+
mysync switch --to mysql2 --wait=0s
48+
"""
49+
Then command return code should be "0"
50+
Then zookeeper node "/test/last_switch" should match json within "120" seconds
51+
"""
52+
{
53+
"to": "mysql2",
54+
"master_transition": "switchover",
55+
"result": {
56+
"ok": true
57+
}
58+
}
59+
"""
60+
Then mysql host "mysql2" should be master
61+
When I get zookeeper node "/test/manager"
62+
And I save zookeeper query result as "manager"
63+
When I run command on host "{{.manager.hostname}}" until result match regexp "switchover:" with timeout "30" seconds
64+
"""
65+
cat /tmp/timing.log
66+
"""
67+
Then command output should match regexp
68+
"""
69+
downtime:
70+
"""

tests/images/mysql/mysync.yaml

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -37,6 +37,8 @@ mysql:
3737
error_log: /var/log/mysql/error.log
3838
queries:
3939
replication_lag: $MYSYNC_REPLICATION_LAG_QUERY
40+
commands:
41+
log_timing: echo "%s: %s" >> /tmp/timing.log
4042
disable_semi_sync_replication_on_maintenance: ${MYSYNC_DISABLE_REPLICATION_ON_MAINT:-false}
4143
rpl_semi_sync_master_wait_for_slave_count: ${MYSYNC_WAIT_FOR_SLAVE_COUNT:-1}
4244
critical_disk_usage: ${MYSYNC_CRITICAL_DISK_USAGE:-100}

0 commit comments

Comments
 (0)