Go function logging technique
Tuesday 11 October 2022
Edit on Github

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

 1type logMark struct {
 2	name  string
 3	file  string
 4	line  int
 5	start time.Time
 6}
 7
 8var wd, _ = os.Getwd()
 9
10func NewLogMark() logMark {
11	pc, file, line, _ := runtime.Caller(1)
12	return logMark{
13		name:  runtime.FuncForPC(pc).Name(),
14		file:  file,
15		line:  line,
16		start: time.Now(),
17	}
18}
19
20func (o logMark) Log() {
21	rel, _ := filepath.Rel(wd, o.file)
22	log.Printf("%s:%d %s (Duration: %s)", rel, o.line, o.name, time.Now().Sub(o.start).String())
23}

and can be used as follows

 1func writeItem(destination, inbox, urlDigest string, item []byte) error {
 2	defer NewLogMark().Log()
 3
 4	itemDigest := fmt.Sprintf("%x", sha1.Sum(item))
 5	itemFile := urlDigest + "-" + itemDigest + ".rss"
 6	itemPath := filepath.Join(inbox, itemFile)
 7	itemGlobPath := filepath.Join(destination, "**", itemFile)
 8
 9	if matches, err := filepath.Glob(itemGlobPath); len(matches) > 0 || err != nil {
10		return nil
11	}
12
13	return os.WriteFile(itemPath, item, os.ModePerm)
14}

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.

 1type logMark struct {
 2	name  string
 3	file  string
 4	line  int
 5	start time.Time
 6	end   time.Time
 7}
 8
 9var wd, _ = os.Getwd()
10var logMarks = map[string][]*logMark{}
11
12func LogMarks() {
13	for _, ms := range logMarks {
14		if len(ms) == 0 {
15			continue
16		}
17
18		var c int64 = 0
19		var avg time.Duration = 0
20
21		for _, m := range ms {
22			avg = (time.Duration(c)*avg + m.end.Sub(m.start)) / time.Duration(c+1)
23			c++
24		}
25
26		o := ms[0]
27		rel, _ := filepath.Rel(wd, o.file)
28		log.Printf("%s:%d %s %d Calls (Avg Duration: %s)", rel, o.line, o.name, c, avg.String())
29	}
30}
31
32func NewLogMark() *logMark {
33	pc, file, line, _ := runtime.Caller(1)
34
35	return &logMark{
36		name:  runtime.FuncForPC(pc).Name(),
37		file:  file,
38		line:  line,
39		start: time.Now(),
40	}
41}
42
43func (o *logMark) Log() {
44	rel, _ := filepath.Rel(wd, o.file)
45	log.Printf("%s:%d %s (Duration: %s)", rel, o.line, o.name, o.end.Sub(o.start).String())
46}
47
48func (o *logMark) Done() {
49	o.end = time.Now()
50	key := fmt.Sprintf("%s:%d", o.file, o.line)
51
52	ms, ok := logMarks[key]
53	if !ok {
54		logMarks[key] = []*logMark{}
55	}
56
57	logMarks[key] = append(ms, o)
58}

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

 1type logMark struct {
 2	name  string
 3	file  string
 4	line  int
 5	start time.Time
 6	end   time.Time
 7}
 8
 9type logStat struct {
10	name  string
11	file  string
12	line  int
13	count int64
14	avg   time.Duration
15}
16
17var wd, _ = os.Getwd()
18var logStats = map[string]*logStat{}
19
20func LogMarks() {
21	for _, m := range logStats {
22		rel, _ := filepath.Rel(wd, m.file)
23		log.Printf("%s:%d %s %d Calls (Avg Duration: %s)", rel, m.line, m.name, m.count, m.avg.String())
24	}
25}
26
27func NewLogMark() *logMark {
28	pc, file, line, _ := runtime.Caller(1)
29
30	return &logMark{
31		name:  runtime.FuncForPC(pc).Name(),
32		file:  file,
33		line:  line,
34		start: time.Now(),
35	}
36}
37
38func (o *logMark) Log() {
39	rel, _ := filepath.Rel(wd, o.file)
40	log.Printf("%s:%d %s (Duration: %s)", rel, o.line, o.name, o.end.Sub(o.start).String())
41}
42
43func (o *logMark) Done() {
44	o.end = time.Now()
45	key := fmt.Sprintf("%s:%d", o.file, o.line)
46
47	m, ok := logStats[key]
48	if !ok {
49		m = &logStat{
50			name: o.name,
51			file: o.file,
52			line: o.line,
53		}
54		logStats[key] = m
55	}
56
57	m.avg = (time.Duration(m.count)*m.avg + o.end.Sub(o.start)) / time.Duration(m.count+1)
58	m.count++
59}

See Also