Getting the resources you just used

Everyone knows the Go idiom for getting the time taken to do something:

 initial := time.Now()
 resp, err := httpClient.Do(req)
 latency := time.Since(initial)

But what if you want to know how much CPU that unit of work required, rather than how long it took in wall-clock time?

For example, how many of these http requests can I serve on a machine with only 8 CPUs still available?

Software Archeology

In the mainframe days, “how much resources did I use” was a huge question.

Computer-department managers had to make business cases for every new program they proposed to run, so if a program needed 120 CPU-minutes, and they only had about 10 free in the day, then either they went cap in had to the VP Financial or they didn’t even bother writing the program.

It was still a major consideration in the early days of Unix, when it was important to know if you could do a backup in the time allotted, even if you added a new disk.

Because the Berkeley team did the applications as well as the kernel of BSD, they were sensitive to this, and therefore introduced a number of resource-usage system calls that exist to this day, on BSD, Linux and the commercial Unixes.

To this day, man rusage says

struct rusage {
        struct timeval ru_utime; /* user CPU time used */
        struct timeval ru_stime; /* system CPU time used */
        long   ru_maxrss;        /* maximum resident set size */
        long   ru_ixrss;         /* integral shared memory size */
        long   ru_idrss;         /* integral unshared data size */
        long   ru_isrss;         /* integral unshared stack size */
        long   ru_minflt;        /* page reclaims (soft page faults) */
        long   ru_majflt;        /* page faults (hard page faults) */
        long   ru_nswap;         /* swaps */
        long   ru_inblock;       /* block input operations */
        long   ru_oublock;       /* block output operations */
        long   ru_msgsnd;        /* IPC messages sent */
        long   ru_msgrcv;        /* IPC messages received */
        long   ru_nsignals;      /* signals received */
        long   ru_nvcsw;         /* voluntary context switches */
        long   ru_nivcsw;        /* involuntary context switches */


We don’t always need all those metrics, although they can be handy, but CPU, memory and IO operations are just we need for basic sizing tasks. We can try a trivial benchmark of a few thousand transactions, be able to say that one has a cost of X, and then divide X into how big a machine we have.

Rusage is conventionally called at the end of a run, so in Go we write something like

func RunSomeExampleThing(f *os.File) {
        defer reportRUsage("ExampleThing", time.Now())

so that it will be called at the end of the run, and report the resources we used.

A simple implementation is

// reportRusage reports cpu-seconds, memory and IOPS used
func reportRUsage(name string, start time.Time) {
        var r syscall.Rusage
        err := syscall.Getrusage(syscall.RUSAGE_SELF, &r)
        if err != nil {
              log.Printf("%s %s %d no resource usage available\n",
                     start.Format("2006-01-02 15:04:05.000"), name, os.Getpid())
        fmt.Fprint(os.Stderr,"#date time name pid utime stime maxrss inblock outblock\n")
        fmt.Fprintf(os.Stderr,"%s %s %d %f %f %d %d %d\n", start.Format("2006-01-02 15:04:05.000"),
               name, os.Getpid(), seconds(r.Utime), 
               seconds(r.Stime), r.Maxrss * 1024,
               r.Inblock, r.Oublock)

// seconds converts a syscall.Timeval to seconds
func seconds(t syscall.Timeval) float64 {
       return float64(time.Duration(t.Sec)*time.Second + time.Duration(t.Usec)*time.Microsecond) /float64(time.Second)


This is not the only source of the information: /proc/pid/stat on Linux provides more, but this set is available in all the BDS-derived unixes, which is to say all that still exist, and gives us a nice little one-liner like

#date      time         name         pid  utime    stime    maxrss inblock outblock
2017-12-03 11:25:30.851 ExampleThing 9549 0.006515 0.006516 1596264448 0 0

In this case, we used 0.013 CPU seconds, so that if we have 8 CPUs of the same type, we will be able to handle up to 613 requests.  Or maybe 500, 80% of that (;-))






Leave a Reply

Fill in your details below or click an icon to log in: Logo

You are commenting using your account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s