CPU time consumed by Go routine, and stop C library call?


(klaymen) #1

Hi all,

I got 2 problems related to the same task (hence I only post it once). This is about a project that needs to check regular expressions in Perl style (including lokaheads etc, which are not supported by Go’s standard regexp). So I’m using github.com/glenn-brown/golang-pkg-pcre/src/pkg/pcre, which is a wrapper around the Unix pcre library (using cgo). In my project, hundreds of threads are using this library concurrently.

One problem is that the execution of the C library call often takes a very long time, so I’m wondering if there’s a possibility to time-limit these calls. Basically this would mean to stop the execution of a goroutine from another one, which afaik is not possible; but maybe there is some way to solve the issue for an external cgo routine that went havoc?

An alternative solution would be to at least log execution times of these calls, and also sort them such that I can see what search term caused problems on what data. I would prefer not using Go’s pprof (I don’t think I get the data I need out of it, i.e. sorted and summed after tge search terms), so I started by simply measure wallclock times before and after these regex calls. This works quite well, but of course wallclock time is not optimal in case of a concurrent program; the actual CPU time used by the current goroutine would be much better. Is there a way to get this information, or maybe at least for the cgo call itself? Measuring thread times would not work neither, as go routines are lightweight (not sure however about cgo calls). All I found on Google at some point tells you to use pprof - which I think would be overkill for this case, and would not give me the information grouped the way I’d need it; but maybe I’m missing something?


(Christophe Meessen) #2

Unfortunately, there is no way to abort the execution of a long cgo function call, which is what you want.

Logging execution time to trace down the input data causing problems looks like a good alternative strategy. There is no need to use pprof.

To compute CPU usage, there is unfortunately no equivalent of the C clock function. But there is the syscall.Getrusage() function that fills a struct with values including system and user times.

To compute the time spent by the CPU to execute some task you could inspire you of the following code:

package main

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


func main() {
	var r syscall.Rusage 

    // could be as well syscall.RUSAGE_THREAD, no sure if it would make sense
	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))
}

Output:

Sys time: 0s
Usr time: 141µs

I noticed a big variation in the values which doesn’t make much sense. I’m not sure if the values you get this way are pertinent. Maybe the sleep is not a good task to measure.


(klaymen) #3

Thanks a lot, that looks like what I need indeed… probably RUSAGE_THREAD is the way to go, but I’ll make some tests, because - if I understood cgo correctly - cgo calls themselves don’t run as lightweight goroutines, but “occupy” a full system thread. So that measure might be the right one to use.

[EDIT] seems to work nice:

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)
	}
}

Then $ time ./regexTiming returns (on a loaded system)

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

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

And it’s consistent with e.g. only 5 threads (around 13 seconds then)