From 446dbde836c10159db0370c9eacf97aa3c4858a2 Mon Sep 17 00:00:00 2001 From: James Shubin Date: Fri, 26 May 2023 01:19:13 -0400 Subject: [PATCH] util: Add new blocked timer utility This adds a new *BlockedTimer struct which can be used to run a function or a printf after a short duration. It can be cancelled early. A short blog post about the topic is available here: https://purpleidea.com/blog/2023/05/26/blocked-select-logging-in-golang/ --- util/bt.go | 111 +++++++++++++++++++++++++++++++++++++++++++ util/bt_test.go | 123 ++++++++++++++++++++++++++++++++++++++++++++++++ 2 files changed, 234 insertions(+) create mode 100644 util/bt.go create mode 100644 util/bt_test.go diff --git a/util/bt.go b/util/bt.go new file mode 100644 index 00000000..c0b857b6 --- /dev/null +++ b/util/bt.go @@ -0,0 +1,111 @@ +// Mgmt +// Copyright (C) 2013-2023+ James Shubin and the project contributors +// Written by James Shubin and the project contributors +// +// This program is free software: you can redistribute it and/or modify +// it under the terms of the GNU General Public License as published by +// the Free Software Foundation, either version 3 of the License, or +// (at your option) any later version. +// +// This program is distributed in the hope that it will be useful, +// but WITHOUT ANY WARRANTY; without even the implied warranty of +// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the +// GNU General Public License for more details. +// +// You should have received a copy of the GNU General Public License +// along with this program. If not, see . + +package util + +import ( + "context" + "fmt" + "sync" + "time" +) + +// BlockedTimer is a helper facility for printing log messages when you have a +// possible deadlock. Alternatively, it can run an arbitrary function instead. +// It does this by starting a timer, and if that timer isn't cancelled soon +// enough, it executes the task. This is usually most useful before a select +// statement which should ordinarily unblock rather quickly. It's helpful to +// avoid unnecessary "waiting for select" log messages being constantly printed, +// but should those block for longer, you'd definitely like to know where to +// look first. This is safe for concurrent use. Multiple invocations of Printf +// or Run are permitted. They each have their own separate countdown timers, but +// are all cancelled when Cancel is run. It is safe to call Cancel multiple +// times. If Cancel is called before Printf or Run, then those will never run. A +// BlockedTimer must not be copied after first use. +type BlockedTimer struct { + // Duration specifies how long we should wait before we run (or print) + // the function or message. The counter starts when that respective + // function is run. For an easier method, specify the Seconds parameter + // instead. + Duration time.Duration + + // Seconds works exactly as Duration does, except it can be used as a + // shorter method to accomplish the same thing. If this value is zero, + // then Duration is used instead. + Seconds int + + ctx context.Context + cancel func() + cancelled bool + mutex sync.Mutex +} + +// Printf will print as expected when the timer expires if Cancel isn't run +// first. This can be used multiple times. +func (obj *BlockedTimer) Printf(format string, v ...interface{}) { + f := func() { + // safe Logf in case f.String contains %? chars... + s := fmt.Sprintf(format, v...) + fmt.Printf("%s", s) + } + obj.Run(f) +} + +// Run will run the passed function as expected when the timer expires if Cancel +// isn't run first. This can be used multiple times. +func (obj *BlockedTimer) Run(f func()) { + obj.mutex.Lock() + defer obj.mutex.Unlock() + + if obj.cancelled { // we already cancelled + return + } + + if obj.cancel == nil { // only do it once + obj.ctx, obj.cancel = context.WithCancel(context.Background()) + } + + d := time.Duration(obj.Seconds) * time.Second + if obj.Seconds == 0 { + d = obj.Duration + } + + go func() { + select { + case <-time.After(d): + // print! + case <-obj.ctx.Done(): + // cancel the print + return + } + f() // run it + }() +} + +// Cancel cancels the execution of any Run or Printf functions. It is safe to +// call it multiple times. It is important to call this at least once (on defer +// for example) if you've used either Printf or Run, because otherwise you will +// leak goroutines. +func (obj *BlockedTimer) Cancel() { + obj.mutex.Lock() + defer obj.mutex.Unlock() + obj.cancelled = true + if obj.cancel == nil { // race! never let it run + return + } + obj.cancel() +} diff --git a/util/bt_test.go b/util/bt_test.go new file mode 100644 index 00000000..7568213f --- /dev/null +++ b/util/bt_test.go @@ -0,0 +1,123 @@ +// Mgmt +// Copyright (C) 2013-2023+ James Shubin and the project contributors +// Written by James Shubin and the project contributors +// +// This program is free software: you can redistribute it and/or modify +// it under the terms of the GNU General Public License as published by +// the Free Software Foundation, either version 3 of the License, or +// (at your option) any later version. +// +// This program is distributed in the hope that it will be useful, +// but WITHOUT ANY WARRANTY; without even the implied warranty of +// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the +// GNU General Public License for more details. +// +// You should have received a copy of the GNU General Public License +// along with this program. If not, see . + +//go:build !root + +package util + +import ( + "testing" + "time" +) + +func TestBlockedTimer1(t *testing.T) { + bt := &BlockedTimer{Seconds: 1} + defer bt.Cancel() + ch := make(chan struct{}) + bt.Run(func() { close(ch) }) + select { + case <-time.After(time.Duration(3) * time.Second): + t.Errorf("the timer was too slow") + case <-ch: + } +} + +func TestBlockedTimer2(t *testing.T) { + bt := &BlockedTimer{Seconds: 3} + defer bt.Cancel() + ch := make(chan struct{}) + bt.Run(func() { close(ch) }) + select { + case <-time.After(time.Duration(1) * time.Second): + case <-ch: + t.Errorf("the timer was too fast") + } +} + +func TestBlockedTimer3(t *testing.T) { + bt := &BlockedTimer{Seconds: 2} + defer bt.Cancel() + ch := make(chan struct{}) + bt.Run(func() { close(ch) }) + select { + case <-time.After(time.Duration(1) * time.Second): + } + bt.Cancel() + select { + case <-time.After(time.Duration(2) * time.Second): + case <-ch: + t.Errorf("the channel should not have closed") + } +} + +func TestBlockedTimer1b(t *testing.T) { + bt := BlockedTimer{Seconds: 1} + defer bt.Cancel() + ch := make(chan struct{}) + bt.Run(func() { close(ch) }) + select { + case <-time.After(time.Duration(3) * time.Second): + t.Errorf("the timer was too slow") + case <-ch: + } +} + +func TestBlockedTimer2b(t *testing.T) { + bt := BlockedTimer{Seconds: 3} + defer bt.Cancel() + ch := make(chan struct{}) + bt.Run(func() { close(ch) }) + select { + case <-time.After(time.Duration(1) * time.Second): + case <-ch: + t.Errorf("the timer was too fast") + } +} + +func TestBlockedTimer3b(t *testing.T) { + bt := BlockedTimer{Seconds: 3} + defer bt.Cancel() + ch := make(chan struct{}) + bt.Run(func() { close(ch) }) + select { + case <-time.After(time.Duration(1) * time.Second): + } + bt.Cancel() + select { + case <-time.After(time.Duration(2) * time.Second): + case <-ch: + t.Errorf("the channel should not have closed") + } +} + +// just an example to see how to use AfterFunc instead of BlockedTimer +func TestAfterFunc1(t *testing.T) { + ch := make(chan struct{}) + af := time.AfterFunc(time.Duration(2)*time.Second, func() { close(ch) }) + defer af.Stop() + select { + case <-time.After(time.Duration(1) * time.Second): + } + af.Stop() + af.Stop() + af.Stop() + select { + case <-ch: + t.Errorf("the timer was too fast") + default: + } +}