- Go
Go function logging technique

Avatar
Emad Elsaid

Sometimes I just want to time a function execution. the following does so in one line added to the beginning of the function.

type logMark struct {
	name  string
	file  string
	line  int
	start time.Time
}

var wd, _ = os.Getwd()

func NewLogMark() logMark {
	pc, file, line, _ := runtime.Caller(1)
	return logMark{
		name:  runtime.FuncForPC(pc).Name(),
		file:  file,
		line:  line,
		start: time.Now(),
	}
}

func (o logMark) Log() {
	rel, _ := filepath.Rel(wd, o.file)
	log.Printf("%s:%d %s (Duration: %s)", rel, o.line, o.name, time.Now().Sub(o.start).String())
}

and can be used as follows

func writeItem(destination, inbox, urlDigest string, item []byte) error {
	defer NewLogMark().Log()

	itemDigest := fmt.Sprintf("%x", sha1.Sum(item))
	itemFile := urlDigest + "-" + itemDigest + ".rss"
	itemPath := filepath.Join(inbox, itemFile)
	itemGlobPath := filepath.Join(destination, "**", itemFile)

	if matches, err := filepath.Glob(itemGlobPath); len(matches) > 0 || err != nil {
		return nil
	}

	return os.WriteFile(itemPath, item, os.ModePerm)
}

I just needed to add defer NewLogMark().Log() at the beginning of the function.

The line creates a new log mark with all the information about the caller function writeItem in this case. then defers the execution of Log() to the end of the function.

so it nicley creates a wrapper around the function code that will write information about the function execution at the end like so:

2021/08/26 12:41:46 main.go:181 main.writeItem (Duration: 4.507373ms)

An improvement for this to reduce the logging is to print how many times the function was called and the average time.

type logMark struct {
	name  string
	file  string
	line  int
	start time.Time
	end   time.Time
}

var wd, _ = os.Getwd()
var logMarks = map[string][]*logMark{}

func LogMarks() {
	for _, ms := range logMarks {
		if len(ms) == 0 {
			continue
		}

		var c int64 = 0
		var avg time.Duration = 0

		for _, m := range ms {
			avg = (time.Duration(c)*avg + m.end.Sub(m.start)) / time.Duration(c+1)
			c++
		}

		o := ms[0]
		rel, _ := filepath.Rel(wd, o.file)
		log.Printf("%s:%d %s %d Calls (Avg Duration: %s)", rel, o.line, o.name, c, avg.String())
	}
}

func NewLogMark() *logMark {
	pc, file, line, _ := runtime.Caller(1)

	return &logMark{
		name:  runtime.FuncForPC(pc).Name(),
		file:  file,
		line:  line,
		start: time.Now(),
	}
}

func (o *logMark) Log() {
	rel, _ := filepath.Rel(wd, o.file)
	log.Printf("%s:%d %s (Duration: %s)", rel, o.line, o.name, o.end.Sub(o.start).String())
}

func (o *logMark) Done() {
	o.end = time.Now()
	key := fmt.Sprintf("%s:%d", o.file, o.line)

	ms, ok := logMarks[key]
	if !ok {
		logMarks[key] = []*logMark{}
	}

	logMarks[key] = append(ms, o)
}

So instead of defer NewLogMark().Log() we’ll call defer NewLogMark().Done() which adds the mark to a slice and we call LogMarks() at the end of our main function which will print statistics about the marks like so:

2021/08/27 11:30:58 main.go:183 main.writeItem 157 Calls (Avg Duration: 3.454063ms)

so instead of having 157 lines one for each execution we can group them together at the end.

This could be improved even more by calculating average directly in Done() to avoid cluttering memory with many logMark structures

type logMark struct {
	name  string
	file  string
	line  int
	start time.Time
	end   time.Time
}

type logStat struct {
	name  string
	file  string
	line  int
	count int64
	avg   time.Duration
}

var wd, _ = os.Getwd()
var logStats = map[string]*logStat{}

func LogMarks() {
	for _, m := range logStats {
		rel, _ := filepath.Rel(wd, m.file)
		log.Printf("%s:%d %s %d Calls (Avg Duration: %s)", rel, m.line, m.name, m.count, m.avg.String())
	}
}

func NewLogMark() *logMark {
	pc, file, line, _ := runtime.Caller(1)

	return &logMark{
		name:  runtime.FuncForPC(pc).Name(),
		file:  file,
		line:  line,
		start: time.Now(),
	}
}

func (o *logMark) Log() {
	rel, _ := filepath.Rel(wd, o.file)
	log.Printf("%s:%d %s (Duration: %s)", rel, o.line, o.name, o.end.Sub(o.start).String())
}

func (o *logMark) Done() {
	o.end = time.Now()
	key := fmt.Sprintf("%s:%d", o.file, o.line)

	m, ok := logStats[key]
	if !ok {
		m = &logStat{
			name: o.name,
			file: o.file,
			line: o.line,
		}
		logStats[key] = m
	}

	m.avg = (time.Duration(m.count)*m.avg + o.end.Sub(o.start)) / time.Duration(m.count+1)
	m.count++
}