From 5aacdc37723529563adec04a28e2df65e1df8c5e Mon Sep 17 00:00:00 2001 From: Sergey Ponomarev Date: Tue, 17 Nov 2020 11:42:45 +0200 Subject: [PATCH 1/7] docker.go: logging of events Add log.IsEnabledFor(logging.DEBUG) guard to avoid unnecessary memory allocations. Debug level is usually disabled. Inline "destroy" --- connector/docker.go | 9 +++++++-- 1 file changed, 7 insertions(+), 2 deletions(-) diff --git a/connector/docker.go b/connector/docker.go index 6595059..8820a60 100644 --- a/connector/docker.go +++ b/connector/docker.go @@ -2,6 +2,7 @@ package connector import ( "fmt" + "github.com/op/go-logging" "strings" "sync" @@ -71,10 +72,14 @@ func (cm *Docker) watchEvents() { switch actionName { case "start", "die", "pause", "unpause", "health_status": - log.Debugf("handling docker event: action=%s id=%s", e.Action, e.ID) + if log.IsEnabledFor(logging.DEBUG) { + log.Debugf("handling docker event: action=%s id=%s", e.Action, e.ID) + } cm.needsRefresh <- e.ID case "destroy": - log.Debugf("handling docker event: action=%s id=%s", e.Action, e.ID) + if log.IsEnabledFor(logging.DEBUG) { + log.Debugf("handling docker event: action=destroy id=%s", e.ID) + } cm.delByID(e.ID) } } From 957cabba2d1485260e7fcda208d8c6a6682435b4 Mon Sep 17 00:00:00 2001 From: Sergey Ponomarev Date: Tue, 17 Nov 2020 12:06:34 +0200 Subject: [PATCH 2/7] docker.go: watchEvents() optimize actionName extraction Split(e.Action, ":") creates and array but we can avoid this. --- connector/docker.go | 8 +++++++- 1 file changed, 7 insertions(+), 1 deletion(-) diff --git a/connector/docker.go b/connector/docker.go index 8820a60..22f5758 100644 --- a/connector/docker.go +++ b/connector/docker.go @@ -68,7 +68,13 @@ func (cm *Docker) watchEvents() { continue } - actionName := strings.Split(e.Action, ":")[0] + actionName := e.Action + // Action may have additional param: "exec_create: redis-cli ping" or "health_status: healthy" + // We need to strip to have only action name + sepIdx := strings.Index(actionName, ": ") + if sepIdx != -1 { + actionName = actionName[:sepIdx] + } switch actionName { case "start", "die", "pause", "unpause", "health_status": From b65e970a83be8288adaef47ed9b6abee8df3601d Mon Sep 17 00:00:00 2001 From: Sergey Ponomarev Date: Tue, 17 Nov 2020 21:50:25 +0200 Subject: [PATCH 3/7] Improve docker events handling Firstly check health updates because it will be a lot of them especially when a container is unstable. Clearly handle create event to create a container even if it wasn't started. Instead of die event handle more precise events like oom, kill and only then trigger refresh. Lookup the state from a map. --- connector/docker.go | 29 +++++++++++++++++++++++++++-- 1 file changed, 27 insertions(+), 2 deletions(-) diff --git a/connector/docker.go b/connector/docker.go index 22f5758..a001791 100644 --- a/connector/docker.go +++ b/connector/docker.go @@ -14,6 +14,15 @@ import ( func init() { enabled["docker"] = NewDocker } +var actionToStatus = map[string]string{ + "create": "created", + "start": "running", + "kill": "exited", + "stop": "exited", + "pause": "paused", + "unpause": "running", +} + type Docker struct { client *api.Client containers map[string]*container.Container @@ -77,9 +86,16 @@ func (cm *Docker) watchEvents() { } switch actionName { - case "start", "die", "pause", "unpause", "health_status": + // most frequent event is a health checks + case "health_status": + healthStatus := e.Action[sepIdx+2:] if log.IsEnabledFor(logging.DEBUG) { - log.Debugf("handling docker event: action=%s id=%s", e.Action, e.ID) + log.Debugf("handling docker event: action=health_status id=%s %s", e.ID, healthStatus) + } + cm.needsRefresh <- e.ID + case "create": + if log.IsEnabledFor(logging.DEBUG) { + log.Debugf("handling docker event: action=create id=%s", e.ID) } cm.needsRefresh <- e.ID case "destroy": @@ -87,6 +103,15 @@ func (cm *Docker) watchEvents() { log.Debugf("handling docker event: action=destroy id=%s", e.ID) } cm.delByID(e.ID) + default: + // check if this action changes status e.g. start -> running + status := actionToStatus[actionName] + if status != "" { + if log.IsEnabledFor(logging.DEBUG) { + log.Debugf("handling docker event: action=%s id=%s %s", actionName, e.ID, status) + } + cm.needsRefresh <- e.ID + } } } log.Info("docker event listener exited") From 4c280cee5674288821d6ea2ae6b05ac8a742b41a Mon Sep 17 00:00:00 2001 From: Sergey Ponomarev Date: Tue, 17 Nov 2020 22:00:03 +0200 Subject: [PATCH 4/7] Improve docker events handling: separate channel for status updates Instead of calling a heavy inspect api call we can easily changing status just by knowing an action. Let's do this in a separate channel decouple UI update from basic event loop. --- connector/docker.go | 31 +++++++++++++++++++++++++++++-- 1 file changed, 29 insertions(+), 2 deletions(-) diff --git a/connector/docker.go b/connector/docker.go index a001791..f5c8f1b 100644 --- a/connector/docker.go +++ b/connector/docker.go @@ -23,10 +23,17 @@ var actionToStatus = map[string]string{ "unpause": "running", } +type StatusUpdate struct { + Cid string + Field string // "status" or "health" + Status string +} + type Docker struct { client *api.Client containers map[string]*container.Container needsRefresh chan string // container IDs requiring refresh + statuses chan StatusUpdate closed chan struct{} lock sync.RWMutex } @@ -41,6 +48,7 @@ func NewDocker() (Connector, error) { client: client, containers: make(map[string]*container.Container), needsRefresh: make(chan string, 60), + statuses: make(chan StatusUpdate, 60), closed: make(chan struct{}), lock: sync.RWMutex{}, } @@ -58,6 +66,7 @@ func NewDocker() (Connector, error) { log.Debugf("docker-connector ServerVersion: %s", info.ServerVersion) go cm.Loop() + go cm.LoopStatuses() cm.refreshAll() go cm.watchEvents() return cm, nil @@ -92,7 +101,7 @@ func (cm *Docker) watchEvents() { if log.IsEnabledFor(logging.DEBUG) { log.Debugf("handling docker event: action=health_status id=%s %s", e.ID, healthStatus) } - cm.needsRefresh <- e.ID + cm.statuses <- StatusUpdate{e.ID, "health", healthStatus} case "create": if log.IsEnabledFor(logging.DEBUG) { log.Debugf("handling docker event: action=create id=%s", e.ID) @@ -110,7 +119,7 @@ func (cm *Docker) watchEvents() { if log.IsEnabledFor(logging.DEBUG) { log.Debugf("handling docker event: action=%s id=%s %s", actionName, e.ID, status) } - cm.needsRefresh <- e.ID + cm.statuses <- StatusUpdate{e.ID, "status", status} } } } @@ -205,6 +214,24 @@ func (cm *Docker) Loop() { } } +func (cm *Docker) LoopStatuses() { + for { + select { + case statusUpdate := <-cm.statuses: + c, _ := cm.Get(statusUpdate.Cid) + if c != nil { + if statusUpdate.Field == "health" { + c.SetMeta("health", statusUpdate.Status) + } else { + c.SetState(statusUpdate.Status) + } + } + case <-cm.closed: + return + } + } +} + // MustGet gets a single container, creating one anew if not existing func (cm *Docker) MustGet(id string) *container.Container { c, ok := cm.Get(id) From 2c07cab59ce90662ec7d393b69bdc06eb333e7ae Mon Sep 17 00:00:00 2001 From: Sergey Ponomarev Date: Wed, 18 Nov 2020 11:25:20 +0200 Subject: [PATCH 5/7] logging: skip timer events e.g. /timer/1s Each second we receive the timer event which makes little sense but log is bloated with the event. To make logs more readable we can disable logging of this event --- debug.go | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/debug.go b/debug.go index 683c8e8..d9d6dd9 100644 --- a/debug.go +++ b/debug.go @@ -12,6 +12,10 @@ import ( var mstats = &runtime.MemStats{} func logEvent(e ui.Event) { + // skip timer events e.g. /timer/1s + if e.From == "timer" { + return + } var s string s += fmt.Sprintf("Type=%s", quote(e.Type)) s += fmt.Sprintf(" Path=%s", quote(e.Path)) From 009201ed0c21cf6b0d58e7e99d1b4a571d5d6e14 Mon Sep 17 00:00:00 2001 From: Sergey Ponomarev Date: Wed, 18 Nov 2020 22:56:33 +0200 Subject: [PATCH 6/7] actionToStatus: catch more generic die instead of kill --- connector/docker.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/connector/docker.go b/connector/docker.go index f5c8f1b..98059af 100644 --- a/connector/docker.go +++ b/connector/docker.go @@ -17,7 +17,7 @@ func init() { enabled["docker"] = NewDocker } var actionToStatus = map[string]string{ "create": "created", "start": "running", - "kill": "exited", + "die": "exited", "stop": "exited", "pause": "paused", "unpause": "running", From ba126e6e7c96bba2fd211b129c3ab20c4d0f35b6 Mon Sep 17 00:00:00 2001 From: Sergey Ponomarev Date: Wed, 18 Nov 2020 23:03:48 +0200 Subject: [PATCH 7/7] events handling: early skipping of extremely frequent exec_* events The exec_create, exec_start, exec_die and other events are generated by health checks --- connector/docker.go | 6 +++++- 1 file changed, 5 insertions(+), 1 deletion(-) diff --git a/connector/docker.go b/connector/docker.go index 98059af..4a39bf9 100644 --- a/connector/docker.go +++ b/connector/docker.go @@ -87,7 +87,11 @@ func (cm *Docker) watchEvents() { } actionName := e.Action - // Action may have additional param: "exec_create: redis-cli ping" or "health_status: healthy" + // fast skip all exec_* events: exec_create, exec_start, exec_die + if strings.HasPrefix(actionName, "exec_") { + continue + } + // Action may have additional param i.e. "health_status: healthy" // We need to strip to have only action name sepIdx := strings.Index(actionName, ": ") if sepIdx != -1 {