go - 如何对修改其输入的函数进行基准测试？

Question

当我对修改其输入的函数进行基准测试时，我必须为基准测试的每个循环复制测试数据，并在这样做时暂停计时器。这可能意味着如果我运行 go test -bench MyTest -benchtime 1s 测试可能需要整整 2 分钟而不是 1 秒。

我是在做错什么，还是只能忍受这个？

---

更多上下文:

我正在编写一个程序来读取 syslog 日志。我的日志记录范例的一部分是，记录消息的第一行包含可读文本，后面几行包含“额外信息”，如堆栈跟踪。因此，我的日志阅读器(除其他外)在第一个换行符处拆分消息，由 rsyslog 转义为 #012。

代码如下:

// Splits the main line from extra information
func splitMessageExtra(line *string) string {
    var prev rune

    for i, char := range *line {
        if prev == 0 && char == '#' {
            prev = char
            continue
        }

        if prev == '#' && char == '0' {
            prev = char
            continue
        }

        if prev == '0' && char == '1' {
            prev = char
            continue
        }

        if prev == '1' && char == '2' {
            extra := (*line)[i+1:]
            *line = (*line)[0 : i-3]

            return extra
        }

        prev = 0
    }

    return ""
}

它最初使用 strings.Split 并返回新的字符串，但 cpu 分析表明它太慢了。

这是基准函数:

var testMessage = `Feb 10 15:16:20 foo_stats[-] (warning): [foo_stats.postfix, line 166, thread "processor_mta03"]: Skipped line because there is no context:#012Feb 10 15:16:20 mta03 postfix/qmgr[7419]: ABCDEF123: from=<>, size=24431, nrcpt=1 (queue active)`

func BenchmarkSplitMessageExtra(b *testing.B) {
    for i := 0; i < b.N; i++ {
        b.StopTimer()
        msg := string([]byte(testMessage))
        b.StartTimer()

        splitMessageExtra(&msg)
    }
}

这是一个没有暂停计时器的运行:

$ go test -bench SplitMessageExtra -benchtime 1sBenchmarkSplitMessageExtra-8     3000000           434 ns/opPASSok      github.com/Hubro/logreader  1.730s

下面是使用上述基准函数运行的结果:

$ go test -bench SplitMessageExtra -benchtime 1sBenchmarkSplitMessageExtra-8     5000000           385 ns/opPASSok      github.com/Hubro/logreader  100.563s

注意它需要 AGES 才能运行。

Answer 1

您的代码和基准测试看起来确实很慢。这是一个更快的版本。

package main

import (
    "strings"
    "testing"
)

// Splits the main line from extra information
func splitMessageExtra(line *string) string {
    const newline = "#012"
    i := strings.Index(*line, newline)
    if i < 0 {
        return ""
    }
    extra := (*line)[i+len(newline):]
    *line = (*line)[0:i]
    return extra
}

var testMessage = `Feb 10 15:16:20 foo_stats[-] (warning): [foo_stats.postfix, line 166, thread "processor_mta03"]: Skipped line because there is no context:#012Feb 10 15:16:20 mta03 postfix/qmgr[7419]: ABCDEF123: from=<>, size=24431, nrcpt=1 (queue active)`

func BenchmarkSplitMessageExtra(b *testing.B) {
    for i := 0; i < b.N; i++ {
        msg := testMessage
        splitMessageExtra(&msg)
    }
}

输出:

$ go test -bench=.
goos: linux
goarch: amd64
pkg: extra
BenchmarkSplitMessageExtra-4    50000000            32.2 ns/op
PASS
ok      extra   1.647s

为了进行比较，以下是您的代码和基准测试的结果。您的代码和基准测试比我的慢:分别为 968 ns/op 和 50.184s 与 32.2 ns/op 和 1.647s。

package main

import (
    "testing"
)

// Splits the main line from extra information
func splitMessageExtra(line *string) string {
    var prev rune
    for i, char := range *line {
        if prev == 0 && char == '#' {
            prev = char
            continue
        }
        if prev == '#' && char == '0' {
            prev = char
            continue
        }
        if prev == '0' && char == '1' {
            prev = char
            continue
        }
        if prev == '1' && char == '2' {
            extra := (*line)[i+1:]
            *line = (*line)[0 : i-3]

            return extra
        }
        prev = 0
    }
    return ""
}

var testMessage = `Feb 10 15:16:20 foo_stats[-] (warning): [foo_stats.postfix, line 166, thread "processor_mta03"]: Skipped line because there is no context:#012Feb 10 15:16:20 mta03 postfix/qmgr[7419]: ABCDEF123: from=<>, size=24431, nrcpt=1 (queue active)`

func BenchmarkSplitMessageExtra(b *testing.B) {
    for i := 0; i < b.N; i++ {
        b.StopTimer()
        msg := string([]byte(testMessage))
        b.StartTimer()
        splitMessageExtra(&msg)
    }
}

输出:

$ go test -bench=.
goos: linux
goarch: amd64
pkg: extra
BenchmarkSplitMessageExtra-4     2000000           968 ns/op    
PASS
ok      extra   50.184s

您的某些代码是不必要的；它使用 CPU 时间并触发分配。比如把utf-8字节转成runes，for i, char := range *line{}，把string转成[]byte 到 string, string([]byte(testMessage)) 。一些算法可以改进。例如，搜索换行符。