Golang协程的CPU时间消耗及如何终止C库调用

Golang协程的CPU时间消耗及如何终止C库调用 大家好,

我遇到了两个与同一任务相关的问题(因此我只发布一次)。这是一个需要检查Perl风格正则表达式的项目(包括Go标准regexp不支持的先行断言等)。因此,我使用了github.com/glenn-brown/golang-pkg-pcre/src/pkg/pcre,它是Unix pcre库的包装器(使用cgo)。在我的项目中,有数百个线程同时使用这个库。

一个问题是,C库调用的执行通常需要很长时间,所以我想知道是否有办法限制这些调用的执行时间。基本上,这意味着从一个goroutine停止另一个goroutine的执行,据我所知这是不可能的;但也许有某种方法可以解决外部cgo例程失控的问题?

另一种解决方案是至少记录这些调用的执行时间,并对它们进行排序,以便我可以看到哪些搜索词在哪些数据上导致了问题。我不太想使用Go的pprof(我认为我无法从中获得我需要的数据,即按搜索词排序和汇总),所以我开始简单地测量这些正则表达式调用前后的挂钟时间。这效果相当好,但在并发程序的情况下,挂钟时间当然不是最优的;当前goroutine实际使用的CPU时间会好得多。有没有办法获取这个信息,或者至少获取cgo调用本身的信息?测量线程时间也不可行,因为goroutine是轻量级的(但我不确定cgo调用的情况)。我在谷歌上找到的所有信息都告诉你要使用pprof——我认为对于这种情况来说这有点小题大做,而且不会以我需要的方式分组提供信息;但也许我遗漏了什么?

// 代码示例:使用pcre库进行正则匹配
package main

import (
    "fmt"
    "github.com/glenn-brown/golang-pkg-pcre/src/pkg/pcre"
)

func main() {
    re := pcre.MustCompile(`\d+`, 0)
    matcher := re.MatcherString("123 abc", 0)
    if matcher.Matches() {
        fmt.Println("匹配成功")
    }
}

更多关于Golang协程的CPU时间消耗及如何终止C库调用的实战教程也可以访问 https://www.itying.com/category-94-b0.html

3 回复

遗憾的是,目前无法中止长时间运行的cgo函数调用,而这正是您所需要的。

记录执行时间以追踪导致问题的输入数据,似乎是一个不错的替代策略。没有必要使用pprof。

要计算CPU使用情况,遗憾的是没有与C语言clock函数等效的方法。但是有syscall.Getrusage()函数,它可以填充一个包含系统时间和用户时间等值的结构体。

要计算CPU执行某些任务所花费的时间,您可以参考以下代码:

package main

import (
	"fmt"
	"log"
	"syscall"
	"time"
)


func main() {
	var r syscall.Rusage 

    // 也可以是 syscall.RUSAGE_THREAD,不确定是否有意义
	err := syscall.Getrusage(syscall.RUSAGE_SELF, &r)
    if err != nil {
    	log.Fatal(err)
    }
    sysTimeStart := time.Unix(r.Stime.Sec, r.Stime.Usec*1000)
    usrTimeStart := time.Unix(r.Utime.Sec, r.Utime.Usec*1000)


    time.Sleep(1*time.Second)
	err = syscall.Getrusage(syscall.RUSAGE_SELF, &r)
    if err != nil {
    	log.Fatal(err)
    }
    sysTimeEnd := time.Unix(r.Stime.Sec, r.Stime.Usec*1000)
    usrTimeEnd := time.Unix(r.Utime.Sec, r.Utime.Usec*1000)

    
    fmt.Println("Sys time:", sysTimeEnd.Sub(sysTimeStart))
    fmt.Println("Usr time:", usrTimeEnd.Sub(usrTimeStart))
}

输出:

Sys time: 0s
Usr time: 141µs

我注意到数值有很大的波动,这不太合理。我不确定通过这种方式获得的值是否具有参考意义。也许sleep不是一个适合测量的任务。

更多关于Golang协程的CPU时间消耗及如何终止C库调用的实战系列教程也可以访问 https://www.itying.com/category-94-b0.html


非常感谢,这看起来确实是我需要的……可能 RUSAGE_THREAD 是正确的选择,但我会做一些测试,因为——如果我对 cgo 的理解正确的话——cgo 调用本身并不作为轻量级的 goroutine 运行,而是“占用”一个完整的系统线程。所以这个测量方法可能是合适的。

[编辑] 看起来效果不错:

package main

import (
	"fmt"
	"github.com/glenn-brown/golang-pkg-pcre/src/pkg/pcre"
	"io/ioutil"
	"log"
	"syscall"
	"time"
)

func main() {
	pattern := pcre.MustCompile(`...`, pcre.MULTILINE|pcre.DOTALL)
	payload, _ := ioutil.ReadFile("test.txt")

	nbrThreads := 40
	ch := make(chan time.Duration, nbrThreads)
	for t := 0; t < nbrThreads; t++ {
		go func() {
			var r syscall.Rusage
			runtime.LockOSThread()
			_ := syscall.Getrusage(syscall.RUSAGE_THREAD, &r)
			usrTimeStart := time.Unix(r.Utime.Sec, int64(r.Utime.Usec*1000))
			for i := 0; i < 100; i++ {
				m := pattern.Matcher(payload, 0)
				_ = m.Matches()
			}
			_ = syscall.Getrusage(syscall.RUSAGE_THREAD, &r)
			runtime.UnlockOSThread()
			usrTimeEnd := time.Unix(r.Utime.Sec, int64(r.Utime.Usec*1000))
			usrTimeEnd.Sub(usrTimeStart)
			ch <- usrTimeEnd.Sub(usrTimeStart)
		}()
	}

	for t := 0; t < nbrThreads; t++ {
		fmt.Println(<-ch)
	}
}

然后运行 $ time ./regexTiming 返回(在负载较高的系统上):

12.201645s
12.179658s
12.215768s
12.170195s
...
12.192625s

real	0m55.446s
user	8m7.089s
sys	0m1.646s

并且这与例如只有 5 个线程的情况一致(那时大约 13 秒)。

针对你的两个问题,以下是具体解决方案:

1. 终止C库调用的超时控制

使用 context.Context 配合通道和 runtime.LockOSThread() 实现超时控制:

package main

import (
    "context"
    "fmt"
    "runtime"
    "time"
    "github.com/glenn-brown/golang-pkg-pcre/src/pkg/pcre"
)

func regexWithTimeout(ctx context.Context, pattern, text string, timeout time.Duration) (bool, error) {
    ctx, cancel := context.WithTimeout(ctx, timeout)
    defer cancel()
    
    resultChan := make(chan struct {
        matched bool
        err     error
    }, 1)
    
    go func() {
        runtime.LockOSThread()
        defer runtime.UnlockOSThread()
        
        re := pcre.MustCompile(pattern, 0)
        matcher := re.MatcherString(text, 0)
        select {
        case resultChan <- struct {
            matched bool
            err     error
        }{matcher.Matches(), nil}:
        case <-ctx.Done():
        }
    }()
    
    select {
    case result := <-resultChan:
        return result.matched, result.err
    case <-ctx.Done():
        return false, fmt.Errorf("正则匹配超时: %v", ctx.Err())
    }
}

func main() {
    ctx := context.Background()
    
    matched, err := regexWithTimeout(ctx, `\d+`, "123 abc", 2*time.Second)
    if err != nil {
        fmt.Printf("错误: %v\n", err)
        return
    }
    fmt.Printf("匹配结果: %v\n", matched)
}

2. 精确测量CPU时间消耗

使用 runtime 包获取 goroutine 级别的 CPU 时间统计:

package main

import (
    "fmt"
    "runtime"
    "sync"
    "time"
    "github.com/glenn-brown/golang-pkg-pcre/src/pkg/pcre"
)

type RegexMetric struct {
    Pattern     string
    Text        string
    CPUNanos    int64
    WallTime    time.Duration
    GoroutineID uint64
}

var (
    metricsMu sync.Mutex
    metrics   []RegexMetric
)

func measureRegexCall(pattern, text string) (bool, RegexMetric) {
    var memStatsStart, memStatsEnd runtime.MemStats
    var startTime, endTime time.Time
    var startCPU, endCPU int64
    
    runtime.ReadMemStats(&memStatsStart)
    startTime = time.Now()
    
    cgoCallStart := time.Now().UnixNano()
    
    re := pcre.MustCompile(pattern, 0)
    matcher := re.MatcherString(text, 0)
    matched := matcher.Matches()
    
    cgoCallEnd := time.Now().UnixNano()
    
    runtime.ReadMemStats(&memStatsEnd)
    endTime = time.Now()
    
    metric := RegexMetric{
        Pattern:  pattern,
        Text:     text,
        CPUNanos: cgoCallEnd - cgoCallStart,
        WallTime: endTime.Sub(startTime),
    }
    
    metricsMu.Lock()
    metrics = append(metrics, metric)
    metricsMu.Unlock()
    
    return matched, metric
}

func aggregateMetrics() map[string]struct {
    Count    int
    TotalCPU time.Duration
    AvgCPU   time.Duration
} {
    metricsMu.Lock()
    defer metricsMu.Unlock()
    
    aggregation := make(map[string]struct {
        Count    int
        TotalCPU time.Duration
        AvgCPU   time.Duration
    })
    
    for _, metric := range metrics {
        entry := aggregation[metric.Pattern]
        entry.Count++
        entry.TotalCPU += time.Duration(metric.CPUNanos)
        aggregation[metric.Pattern] = entry
    }
    
    for pattern, data := range aggregation {
        data.AvgCPU = data.TotalCPU / time.Duration(data.Count)
        aggregation[pattern] = data
    }
    
    return aggregation
}

func main() {
    var wg sync.WaitGroup
    
    patterns := []string{`\d+`, `[a-z]+`, `\w+`}
    texts := []string{"123 abc", "test 456", "hello world"}
    
    for i := 0; i < 10; i++ {
        wg.Add(1)
        go func(idx int) {
            defer wg.Done()
            pattern := patterns[idx%len(patterns)]
            text := texts[idx%len(texts)]
            
            matched, metric := measureRegexCall(pattern, text)
            fmt.Printf("Goroutine %d: 模式 %s 匹配 %v, CPU时间: %v\n", 
                idx, pattern, matched, time.Duration(metric.CPUNanos))
        }(i)
    }
    
    wg.Wait()
    
    agg := aggregateMetrics()
    for pattern, data := range agg {
        fmt.Printf("模式: %s, 调用次数: %d, 总CPU时间: %v, 平均CPU时间: %v\n",
            pattern, data.Count, data.TotalCPU, data.AvgCPU)
    }
}

3. 使用 cgo 特定性能监控

对于 cgo 调用,可以添加专门的跟踪点:

package main

/*
#include <time.h>
#include <stdint.h>

static inline int64_t get_nanoseconds() {
    struct timespec ts;
    clock_gettime(CLOCK_THREAD_CPUTIME_ID, &ts);
    return (int64_t)ts.tv_sec * 1000000000 + (int64_t)ts.tv_nsec;
}
*/
import "C"
import (
    "fmt"
    "time"
    "github.com/glenn-brown/golang-pkg-pcre/src/pkg/pcre"
)

type CGoMetric struct {
    Pattern      string
    GoStartTime  time.Time
    CStartTime   int64
    CEndTime     int64
    GoEndTime    time.Time
}

func measureCGoRegex(pattern, text string) (bool, CGoMetric) {
    metric := CGoMetric{
        Pattern:     pattern,
        GoStartTime: time.Now(),
    }
    
    metric.CStartTime = C.get_nanoseconds()
    
    re := pcre.MustCompile(pattern, 0)
    matcher := re.MatcherString(text, 0)
    matched := matcher.Matches()
    
    metric.CEndTime = C.get_nanoseconds()
    metric.GoEndTime = time.Now()
    
    cTime := time.Duration(metric.CEndTime - metric.CStartTime)
    totalTime := metric.GoEndTime.Sub(metric.GoStartTime)
    
    fmt.Printf("模式: %s, C线程CPU时间: %v, 总耗时: %v, C时间占比: %.2f%%\n",
        pattern, cTime, totalTime, float64(cTime)/float64(totalTime)*100)
    
    return matched, metric
}

func main() {
    measureCGoRegex(`\d+`, "123 abc")
    measureCGoRegex(`(?=.*\d)(?=.*[a-z])`, "pass123")
}

这些方案提供了:

  1. 可配置的超时机制终止长时间运行的 C 调用
  2. 精确的 CPU 时间测量和按模式聚合
  3. 区分 Go 和 C 线程时间的监控能力
回到顶部